ipn: tag and test for grinder log lines (#711)

Signed-off-by: Wendi <wendi.yu@yahoo.ca>

ipn/local.go

@@ -776,7 +776,9 @@ func (b *LocalBackend) parseWgStatus(s *wgengine.Status) (ret EngineStatus) {
 		ret.WBytes += p.TxBytes
 	}
 	if len(peerStats) > 0 {
+		// [GRINDER STATS LINE] - please don't remove (used for log parsing)
 		b.keyLogf("peer keys: %s", strings.Join(peerKeys, " "))
+		// [GRINDER STATS LINE] - please don't remove (used for log parsing)
 		b.logf("v%v peers: %v", version.LONG, strings.Join(peerStats, " "))
 	}
 	return ret
@@ -827,6 +829,7 @@ func (b *LocalBackend) SetPrefs(new *Prefs) {
 		}
 	}
 
+	// [GRINDER STATS LINE] - please don't remove (used for log parsing)
 	b.logf("SetPrefs: %v", new.Pretty())
 
 	if old.ShieldsUp != new.ShieldsUp || hostInfoChanged {

ipn/loglines_test.go

@@ -0,0 +1,107 @@
+// Copyright (c) 2020 Tailscale Inc & AUTHORS All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package ipn
+
+import (
+	"testing"
+	"time"
+
+	"tailscale.com/control/controlclient"
+	"tailscale.com/logtail"
+	"tailscale.com/tailcfg"
+	"tailscale.com/tstest"
+	"tailscale.com/types/key"
+	"tailscale.com/wgengine"
+)
+
+// TestLocalLogLines tests to make sure that the log lines required for log parsing are
+// being logged by the expected functions. Update these tests if moving log lines between
+// functions.
+func TestLocalLogLines(t *testing.T) {
+	logListen := tstest.ListenFor(t.Logf, []string{
+		"SetPrefs: %v",
+		"peer keys: %s",
+		"v%v peers: %v",
+	})
+
+	logid := func(hex byte) logtail.PublicID {
+		var ret logtail.PublicID
+		for i := 0; i < len(ret); i++ {
+			ret[i] = hex
+		}
+		return ret
+	}
+	idA := logid(0xaa)
+
+	// set up a LocalBackend, super bare bones. No functional data.
+	store := &MemoryStore{
+		cache: make(map[StateKey][]byte),
+	}
+	e, err := wgengine.NewFakeUserspaceEngine(logListen.Logf, 0)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	lb, err := NewLocalBackend(logListen.Logf, idA.String(), store, e)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	// custom adjustments for required non-nil fields
+	lb.prefs = NewPrefs()
+	lb.hostinfo = &tailcfg.Hostinfo{}
+	// hacky manual override of the usual log-on-change behaviour of keylogf
+	lb.keyLogf = logListen.Logf
+
+	// testing infrastructure
+	type linesTest struct {
+		name string
+		want []string
+	}
+
+	tests := []linesTest{
+		{
+			name: "after prefs",
+			want: []string{
+				"peer keys: %s",
+				"v%v peers: %v",
+			},
+		},
+		{
+			name: "after peers",
+			want: []string{},
+		},
+	}
+
+	testLogs := func(want linesTest) func(t *testing.T) {
+		return func(t *testing.T) {
+			if linesLeft := logListen.Check(); len(linesLeft) != len(want.want) {
+				t.Errorf("got %v, expected %v", linesLeft, want)
+			}
+		}
+	}
+
+	// log prefs line
+	persist := &controlclient.Persist{}
+	prefs := NewPrefs()
+	prefs.Persist = persist
+	lb.SetPrefs(prefs)
+
+	t.Run(tests[0].name, testLogs(tests[0]))
+
+	// log peers, peer keys
+	status := &wgengine.Status{
+		Peers: []wgengine.PeerStatus{wgengine.PeerStatus{
+			TxBytes:       10,
+			RxBytes:       10,
+			LastHandshake: time.Now(),
+			NodeKey:       tailcfg.NodeKey(key.NewPrivate()),
+		}},
+		LocalAddrs: []string{"idk an address"},
+	}
+	lb.parseWgStatus(status)
+
+	t.Run(tests[1].name, testLogs(tests[1]))
+}

tstest/log.go

@@ -7,7 +7,10 @@ package tstest
 import (
 	"log"
 	"os"
+	"sync"
 	"testing"
+
+	"tailscale.com/types/logger"
 )
 
 type testLogWriter struct {
@@ -41,3 +44,48 @@ func (panicLogWriter) Write(b []byte) (int, error) {
 func PanicOnLog() {
 	log.SetOutput(panicLogWriter{})
 }
+
+// ListenFor produces a LogListener wrapping a given logf with the given logStrings
+func ListenFor(logf logger.Logf, logStrings []string) *LogListener {
+	ret := LogListener{
+		logf:      logf,
+		listenFor: logStrings,
+		seen:      make(map[string]bool),
+	}
+	for _, line := range logStrings {
+		ret.seen[line] = false
+	}
+	return &ret
+}
+
+// LogListener takes a list of log lines to listen for
+type LogListener struct {
+	logf      logger.Logf
+	listenFor []string
+
+	mu   sync.Mutex
+	seen map[string]bool
+}
+
+// Logf records and logs a given line
+func (ll *LogListener) Logf(format string, args ...interface{}) {
+	ll.mu.Lock()
+	if _, ok := ll.seen[format]; ok {
+		ll.seen[format] = true
+	}
+	ll.mu.Unlock()
+	ll.logf(format, args)
+}
+
+// Check returns which lines haven't been logged yet
+func (ll *LogListener) Check() []string {
+	ll.mu.Lock()
+	defer ll.mu.Unlock()
+	var notSeen []string
+	for _, line := range ll.listenFor {
+		if !ll.seen[line] {
+			notSeen = append(notSeen, line)
+		}
+	}
+	return notSeen
+}

tstest/log_test.go

@@ -0,0 +1,46 @@
+// Copyright (c) 2020 Tailscale Inc & AUTHORS All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package tstest
+
+import "testing"
+
+func TestLogListener(t *testing.T) {
+	var (
+		l1 = "line 1: %s"
+		l2 = "line 2: %s"
+		l3 = "line 3: %s"
+
+		lineList = []string{l1, l2}
+	)
+
+	ll := ListenFor(t.Logf, lineList)
+
+	if len(ll.Check()) != len(lineList) {
+		t.Errorf("expected %v, got %v", lineList, ll.Check())
+	}
+
+	ll.Logf(l3, "hi")
+
+	if len(ll.Check()) != len(lineList) {
+		t.Errorf("expected %v, got %v", lineList, ll.Check())
+	}
+
+	ll.Logf(l1, "hi")
+
+	if len(ll.Check()) != len(lineList)-1 {
+		t.Errorf("expected %v, got %v", lineList, ll.Check())
+	}
+
+	ll.Logf(l1, "bye")
+
+	if len(ll.Check()) != len(lineList)-1 {
+		t.Errorf("expected %v, got %v", lineList, ll.Check())
+	}
+
+	ll.Logf(l2, "hi")
+	if ll.Check() != nil {
+		t.Errorf("expected empty list, got ll.Check()")
+	}
+}