diff --git a/ipn/ipnlocal/loglines_test.go b/ipn/ipnlocal/loglines_test.go index 66cc60a8d..4db9b2006 100644 --- a/ipn/ipnlocal/loglines_test.go +++ b/ipn/ipnlocal/loglines_test.go @@ -15,6 +15,7 @@ "tailscale.com/tailcfg" "tailscale.com/tstest" "tailscale.com/types/key" + "tailscale.com/types/logger" "tailscale.com/types/persist" "tailscale.com/wgengine" ) @@ -30,6 +31,12 @@ func TestLocalLogLines(t *testing.T) { }) defer logListen.Close() + // Put a rate-limiter with a burst of 0 between the components below. + // This instructs the rate-limiter to eliminate all logging that + // isn't explicitly exempt from rate-limiting. + // This lets the logListen tracker verify that the rate-limiter allows these key lines. + logf := logger.RateLimitedFnWithClock(logListen.Logf, 5*time.Second, 0, 10, time.Now) + logid := func(hex byte) logtail.PublicID { var ret logtail.PublicID for i := 0; i < len(ret); i++ { @@ -41,12 +48,12 @@ func TestLocalLogLines(t *testing.T) { // set up a LocalBackend, super bare bones. No functional data. store := &ipn.MemoryStore{} - e, err := wgengine.NewFakeUserspaceEngine(logListen.Logf, 0) + e, err := wgengine.NewFakeUserspaceEngine(logf, 0) if err != nil { t.Fatal(err) } - lb, err := NewLocalBackend(logListen.Logf, idA.String(), store, e) + lb, err := NewLocalBackend(logf, idA.String(), store, e) if err != nil { t.Fatal(err) } @@ -61,6 +68,7 @@ func TestLocalLogLines(t *testing.T) { testWantRemain := func(wantRemain ...string) func(t *testing.T) { return func(t *testing.T) { if remain := logListen.Check(); !reflect.DeepEqual(remain, wantRemain) { + t.Helper() t.Errorf("remain %q, want %q", remain, wantRemain) } } @@ -75,17 +83,30 @@ func TestLocalLogLines(t *testing.T) { t.Run("after_prefs", testWantRemain("[v1] peer keys: %s", "[v1] v%v peers: %v")) // log peers, peer keys - status := &wgengine.Status{ + lb.mu.Lock() + lb.parseWgStatusLocked(&wgengine.Status{ Peers: []ipnstate.PeerStatusLite{{ TxBytes: 10, RxBytes: 10, LastHandshake: time.Now(), NodeKey: tailcfg.NodeKey(key.NewPrivate()), }}, - } - lb.mu.Lock() - lb.parseWgStatusLocked(status) + }) lb.mu.Unlock() t.Run("after_peers", testWantRemain()) + + // Log it again with different stats to ensure it's not dup-suppressed. + logListen.Reset() + lb.mu.Lock() + lb.parseWgStatusLocked(&wgengine.Status{ + Peers: []ipnstate.PeerStatusLite{{ + TxBytes: 11, + RxBytes: 12, + LastHandshake: time.Now(), + NodeKey: tailcfg.NodeKey(key.NewPrivate()), + }}, + }) + lb.mu.Unlock() + t.Run("after_second_peer_status", testWantRemain("SetPrefs: %v")) } diff --git a/tstest/log.go b/tstest/log.go index b7750cf12..8443aade1 100644 --- a/tstest/log.go +++ b/tstest/log.go @@ -107,6 +107,15 @@ func (lt *LogLineTracker) Check() []string { return notSeen } +// Reset forgets everything that it's seen. +func (lt *LogLineTracker) Reset() { + lt.mu.Lock() + defer lt.mu.Unlock() + for _, line := range lt.listenFor { + lt.seen[line] = false + } +} + // Close closes lt. After calling Close, calls to Logf become no-ops. func (lt *LogLineTracker) Close() { lt.mu.Lock() diff --git a/types/logger/logger.go b/types/logger/logger.go index bb2683395..bba5ac3eb 100644 --- a/types/logger/logger.go +++ b/types/logger/logger.go @@ -63,10 +63,15 @@ type limitData struct { var disableRateLimit = os.Getenv("TS_DEBUG_LOG_RATE") == "all" // rateFree are format string substrings that are exempt from rate limiting. -// Things should not be added to this unless they're already limited otherwise. +// Things should not be added to this unless they're already limited otherwise +// or are critical for generating important stats from the logs. var rateFree = []string{ "magicsock: disco: ", "magicsock: ParseEndpoint:", + // grinder stats lines + "SetPrefs: %v", + "peer keys: %s", + "v%v peers: %v", } // RateLimitedFn is a wrapper for RateLimitedFnWithClock that includes the @@ -179,7 +184,6 @@ func LogOnChange(logf Logf, maxInterval time.Duration, timeNow func() time.Time) // as it might contain formatting directives.) logf(format, args...) } - } // ArgWriter is a fmt.Formatter that can be passed to any Logf func to