From ca6675386bad4fd43f131b63a7a45433f628b1c3 Mon Sep 17 00:00:00 2001 From: Wendi Yu Date: Wed, 6 May 2020 17:27:32 -0600 Subject: [PATCH] Implement rate limiting on log messages Addresses issue #317, where logs can get spammed with the same message nonstop. Created a rate limiting closure on logging functions, which limits the number of messages being logged per second based on format string. Signed-off-by: Wendi Yu --- cmd/tailscaled/tailscaled.go | 4 ++- ipn/e2e_test.go | 9 ++++-- ipn/ipnserver/server_test.go | 6 +++- types/logger/logger.go | 62 ++++++++++++++++++++++++++++++++++++ types/logger/logger_test.go | 17 ++++++++++ 5 files changed, 94 insertions(+), 4 deletions(-) diff --git a/cmd/tailscaled/tailscaled.go b/cmd/tailscaled/tailscaled.go index 7cded7647..554c4a1bd 100644 --- a/cmd/tailscaled/tailscaled.go +++ b/cmd/tailscaled/tailscaled.go @@ -21,6 +21,7 @@ import ( "tailscale.com/ipn/ipnserver" "tailscale.com/logpolicy" "tailscale.com/paths" + "tailscale.com/types/logger" "tailscale.com/wgengine" "tailscale.com/wgengine/magicsock" ) @@ -50,7 +51,8 @@ func main() { statepath := getopt.StringLong("state", 0, paths.DefaultTailscaledStateFile(), "Path of state file") socketpath := getopt.StringLong("socket", 's', paths.DefaultTailscaledSocket(), "Path of the service unix socket") - logf := wgengine.RusagePrefixLog(log.Printf) + rlPrint := logger.RateLimitedFn(log.Printf, 1, 1) + logf := wgengine.RusagePrefixLog(rlPrint) err := fixconsole.FixConsoleIfNeeded() if err != nil { diff --git a/ipn/e2e_test.go b/ipn/e2e_test.go index f1bdcf1e9..fa31a786c 100644 --- a/ipn/e2e_test.go +++ b/ipn/e2e_test.go @@ -23,6 +23,7 @@ import ( "tailscale.com/control/controlclient" "tailscale.com/tailcfg" "tailscale.com/tstest" + "tailscale.com/types/logger" "tailscale.com/wgengine" "tailscale.com/wgengine/magicsock" "tailscale.com/wgengine/router" @@ -191,12 +192,16 @@ type testNode struct { // Create a new IPN node. func newNode(t *testing.T, prefix string, https *httptest.Server, weirdPrefs bool) testNode { t.Helper() - logfe := func(fmt string, args ...interface{}) { + + ulogfe := func(fmt string, args ...interface{}) { t.Logf(prefix+".e: "+fmt, args...) } - logf := func(fmt string, args ...interface{}) { + logfe := logger.RateLimitedFn(ulogfe, 1, 1) + + ulogf := func(fmt string, args ...interface{}) { t.Logf(prefix+": "+fmt, args...) } + logf := logger.RateLimitedFn(ulogf, 1, 1) var err error httpc := https.Client() diff --git a/ipn/ipnserver/server_test.go b/ipn/ipnserver/server_test.go index 549b617c3..965c4236e 100644 --- a/ipn/ipnserver/server_test.go +++ b/ipn/ipnserver/server_test.go @@ -13,6 +13,8 @@ import ( "strings" "testing" + "tailscale.com/types/logger" + "tailscale.com/ipn" "tailscale.com/ipn/ipnserver" "tailscale.com/safesocket" @@ -32,12 +34,14 @@ func TestRunMultipleAccepts(t *testing.T) { defer os.RemoveAll(td) socketPath := filepath.Join(td, "tailscale.sock") - logf := func(format string, args ...interface{}) { + ulogf := func(format string, args ...interface{}) { format = strings.TrimRight(format, "\n") println(fmt.Sprintf(format, args...)) t.Logf(format, args...) } + logf := logger.RateLimitedFn(ulogf, 1, 1) + connect := func() { for i := 1; i <= 2; i++ { logf("connect %d ...", i) diff --git a/types/logger/logger.go b/types/logger/logger.go index 51b69fcf8..3701a178a 100644 --- a/types/logger/logger.go +++ b/types/logger/logger.go @@ -8,8 +8,12 @@ package logger import ( + "fmt" "io" "log" + "time" + + "golang.org/x/time/rate" ) // Logf is the basic Tailscale logger type: a printf-like func. @@ -42,3 +46,61 @@ func (w funcWriter) Write(p []byte) (int, error) { // Discard is a Logf that throws away the logs given to it. func Discard(string, ...interface{}) {} + +type limitData struct { + lim *rate.Limiter + lastAccessed time.Time + msgBlocked bool +} + +// RateLimitedFn implements rate limiting by fstring on a given Logf. +// Messages are allowed through at a maximum of r messages/second, in +// bursts of up to b messages at a time. +func RateLimitedFn(logf Logf, f float64, b int) Logf { + r := rate.Limit(f) + msgList := make(map[string]limitData) + lastPurge := time.Now() + + rlLogf := func(s string, args ...interface{}) { + if rl, ok := msgList[s]; ok { + + // Fields of structs contained in maps can't be modified; this is + // the workaround. See issue https://github.com/golang/go/issues/3117 + temp := msgList[s] + temp.lastAccessed = time.Now() + msgList[s] = temp + + if rl.lim.Allow() { + rl.msgBlocked = false + logf(s, args) + } else { + if !rl.msgBlocked { + temp = msgList[s] + temp.msgBlocked = true + msgList[s] = temp + logf("Repeated messages were suppressed by rate limiting. Original message: " + + fmt.Sprintf(s, args)) + } + } + } else { + msgList[s] = limitData{rate.NewLimiter(r, b), time.Now(), false} + msgList[s].lim.Allow() + logf(s, args) + } + + // Purge msgList of outdated keys to reduce overhead. Must be done by copying + // over to a new map, since deleting in maps is done through a zombie flag + if time.Since(lastPurge) >= time.Minute { + newList := make(map[string]limitData) + for k, v := range msgList { + if time.Since(v.lastAccessed) < 5*time.Second { + newList[k] = v + } + } + msgList = nil + msgList = newList + } + } + + return rlLogf +} diff --git a/types/logger/logger_test.go b/types/logger/logger_test.go index b6ecee403..98df83d94 100644 --- a/types/logger/logger_test.go +++ b/types/logger/logger_test.go @@ -7,6 +7,7 @@ package logger import ( "log" "testing" + "time" ) func TestFuncWriter(t *testing.T) { @@ -19,3 +20,19 @@ func TestStdLogger(t *testing.T) { lg := StdLogger(t.Logf) lg.Printf("plumbed through") } + +func TestRateLimiter(t *testing.T) { + lg := RateLimitedFn(t.Logf, 1, 1) + var prefixed Logf + for i := 0; i < 10; i++ { + lg("boring string with no formatting") + lg("templated format string no. %d", i) + if i == 4 { + lg("Make sure this string makes it through the rest (that are blocked) %d", i) + } + prefixed = WithPrefix(lg, string('0'+i)) + prefixed(" shouldn't get filtered.") + time.Sleep(200 * time.Millisecond) + } + +}