WIP log rate limiting test

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,11 @@ func TestLocalLogLines(t *testing.T) {
 	})
 	defer logListen.Close()
 
+	// Put a rate-limiter between the components below and the
+	// logListen tracker to verify that the rate-limiter isn't
+	// eating these.
+	logf := logger.RateLimitedFnWithClock(logListen.Logf, 5*time.Second, 1, 10, time.Now)
+
 	logid := func(hex byte) logtail.PublicID {
 		var ret logtail.PublicID
 		for i := 0; i < len(ret); i++ {
@@ -41,12 +47,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)
 	}
@@ -75,17 +81,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 to see whether it's 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())
 }

tstest/log.go

@@ -107,6 +107,13 @@ 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()
+	lt.seen = map[string]bool{}
+}
+
 // Close closes lt. After calling Close, calls to Logf become no-ops.
 func (lt *LogLineTracker) Close() {
 	lt.mu.Lock()

types/logger/logger.go

@@ -67,6 +67,8 @@ var disableRateLimit = os.Getenv("TS_DEBUG_LOG_RATE") == "all"
 var rateFree = []string{
 	"magicsock: disco: ",
 	"magicsock: CreateEndpoint:",
+	"peer keys: %s",
+	"v%v peers: %v",
 }
 
 // RateLimitedFn is a wrapper for RateLimitedFnWithClock that includes the