diff --git a/ipn/local.go b/ipn/local.go index 85043c946..bddf1db0a 100644 --- a/ipn/local.go +++ b/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 { diff --git a/ipn/loglines_test.go b/ipn/loglines_test.go new file mode 100644 index 000000000..4cec82b4f --- /dev/null +++ b/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])) +} diff --git a/tstest/log.go b/tstest/log.go index 201aae757..887521793 100644 --- a/tstest/log.go +++ b/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 +} diff --git a/tstest/log_test.go b/tstest/log_test.go new file mode 100644 index 000000000..d864b9b9a --- /dev/null +++ b/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()") + } +}