types/logger: add key grinder stats lines to rate-limiting exemption list

Updates #1749

Co-authored-by: Brad Fitzpatrick <bradfitz@tailscale.com>
Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>

ipn/ipnlocal/loglines_test.go

@@ -15,6 +15,7 @@ import (
 	"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"))
 }

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()

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