log rate limiting: reformat limiter messages, and use nonempty burst size.

- Reformat the warning about a message being rate limited to print the
  format string, rather than the formatted message. This helps give a
  clue what "type" of message is being limited.

- Change the rate limit warning to be [RATE LIMITED] in all caps. This
  uses less space on each line, plus is more noticeable.

- In tailscaled, change the frequency to be less often (once every 5
  seconds per format string) but to allow bursts of up to 5 messages.
  This greatly reduces the number of messages that are rate limited
  during startup, but allows us to tighten the limit even further during
  normal runtime.

Signed-off-by: Avery Pennarun <apenwarr@tailscale.com>

cmd/tailscaled/tailscaled.go

@@ -60,7 +60,7 @@ func main() {
 	socketpath := getopt.StringLong("socket", 's', paths.DefaultTailscaledSocket(), "Path of the service unix socket")
 
 	logf := wgengine.RusagePrefixLog(log.Printf)
-	logf = logger.RateLimitedFn(logf, 1*time.Second, 1, 100)
+	logf = logger.RateLimitedFn(logf, 5*time.Second, 5, 100)
 
 	err := fixconsole.FixConsoleIfNeeded()
 	if err != nil {

types/logger/logger.go

@@ -85,7 +85,10 @@ func RateLimitedFn(logf Logf, f time.Duration, burst int, maxCache int) Logf {
 		if ok {
 			msgCache.MoveToFront(rl.ele)
 		} else {
-			rl = &limitData{lim: rate.NewLimiter(r, burst), ele: msgCache.PushFront(format)}
+			rl = &limitData{
+				lim: rate.NewLimiter(r, burst),
+				ele: msgCache.PushFront(format),
+			}
 			msgLim[format] = rl
 			if msgCache.Len() > maxCache {
 				delete(msgLim, msgCache.Back().Value.(string))
@@ -108,8 +111,8 @@ func RateLimitedFn(logf Logf, f time.Duration, burst int, maxCache int) Logf {
 		case allow:
 			logf(format, args...)
 		case warn:
-			logf("Repeated messages were suppressed by rate limiting. Original message: %s",
-				fmt.Sprintf(format, args...))
+			// For the warning, log the specific format string
+			logf("[RATE LIMITED] %s", format)
 		}
 	}
 }

types/logger/logger_test.go

@@ -31,7 +31,7 @@ func logTester(want []string, t *testing.T, i *int) Logf {
 			t.Fatalf("Logging continued past end of expected input: %s", got)
 		}
 		if got != want[*i] {
-			t.Fatalf("wanted: %s \n got: %s", want[*i], got)
+			t.Fatalf("\nwanted: %s\n   got: %s", want[*i], got)
 		}
 		t.Log(got)
 		*i++
@@ -39,21 +39,20 @@ func logTester(want []string, t *testing.T, i *int) Logf {
 }
 
 func TestRateLimiter(t *testing.T) {
-
 	want := []string{
 		"boring string with constant formatting (constant)",
 		"templated format string no. 0",
 		"boring string with constant formatting (constant)",
 		"templated format string no. 1",
-		"Repeated messages were suppressed by rate limiting. Original message: boring string with constant formatting (constant)",
-		"Repeated messages were suppressed by rate limiting. Original message: templated format string no. 2",
+		"[RATE LIMITED] boring string with constant formatting %s",
+		"[RATE LIMITED] templated format string no. %d",
 		"Make sure this string makes it through the rest (that are blocked) 4",
 		"4 shouldn't get filtered.",
 	}
 
 	testsRun := 0
 	lgtest := logTester(want, t, &testsRun)
-	lg := RateLimitedFn(lgtest, 1*time.Second, 2, 50)
+	lg := RateLimitedFn(lgtest, 1*time.Minute, 2, 50)
 	var prefixed Logf
 	for i := 0; i < 10; i++ {
 		lg("boring string with constant formatting %s", "(constant)")