From af9328c1b7d6702251d6db23c8e77fa83273ae31 Mon Sep 17 00:00:00 2001 From: Avery Pennarun Date: Wed, 20 May 2020 11:49:35 -0400 Subject: [PATCH] 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 --- cmd/tailscaled/tailscaled.go | 2 +- types/logger/logger.go | 9 ++++++--- types/logger/logger_test.go | 9 ++++----- 3 files changed, 11 insertions(+), 9 deletions(-) diff --git a/cmd/tailscaled/tailscaled.go b/cmd/tailscaled/tailscaled.go index 17d17bef5..6e66979d1 100644 --- a/cmd/tailscaled/tailscaled.go +++ b/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 { diff --git a/types/logger/logger.go b/types/logger/logger.go index f82f0b2d8..d73c4e264 100644 --- a/types/logger/logger.go +++ b/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) } } } diff --git a/types/logger/logger_test.go b/types/logger/logger_test.go index 8bb38477f..6d4608734 100644 --- a/types/logger/logger_test.go +++ b/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)")