diff --git a/cmd/tailscaled/tailscaled.go b/cmd/tailscaled/tailscaled.go index 554c4a1bd..63b4d3a0d 100644 --- a/cmd/tailscaled/tailscaled.go +++ b/cmd/tailscaled/tailscaled.go @@ -51,8 +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") - rlPrint := logger.RateLimitedFn(log.Printf, 1, 1) - logf := wgengine.RusagePrefixLog(rlPrint) + logf := wgengine.RusagePrefixLog(log.Printf) + logf = logger.RateLimitedFn(logf, 1, 1, 100) err := fixconsole.FixConsoleIfNeeded() if err != nil { diff --git a/ipn/e2e_test.go b/ipn/e2e_test.go index fa31a786c..00058c493 100644 --- a/ipn/e2e_test.go +++ b/ipn/e2e_test.go @@ -193,15 +193,15 @@ type testNode struct { func newNode(t *testing.T, prefix string, https *httptest.Server, weirdPrefs bool) testNode { t.Helper() - ulogfe := func(fmt string, args ...interface{}) { + logfe := func(fmt string, args ...interface{}) { t.Logf(prefix+".e: "+fmt, args...) } - logfe := logger.RateLimitedFn(ulogfe, 1, 1) + logfe := logger.RateLimitedFn(logfe, 1, 1) - ulogf := func(fmt string, args ...interface{}) { + logf := func(fmt string, args ...interface{}) { t.Logf(prefix+": "+fmt, args...) } - logf := logger.RateLimitedFn(ulogf, 1, 1) + logf := logger.RateLimitedFn(logf, 1, 1, 100) var err error httpc := https.Client() diff --git a/ipn/ipnserver/server_test.go b/ipn/ipnserver/server_test.go index 965c4236e..582f53a53 100644 --- a/ipn/ipnserver/server_test.go +++ b/ipn/ipnserver/server_test.go @@ -40,7 +40,7 @@ func TestRunMultipleAccepts(t *testing.T) { t.Logf(format, args...) } - logf := logger.RateLimitedFn(ulogf, 1, 1) + logf := logger.RateLimitedFn(ulogf, 1, 1, 100) connect := func() { for i := 1; i <= 2; i++ { diff --git a/types/logger/logger.go b/types/logger/logger.go index 3701a178a..2c18cda10 100644 --- a/types/logger/logger.go +++ b/types/logger/logger.go @@ -8,16 +8,18 @@ package logger import ( + "container/list" "fmt" "io" "log" - "time" + "sync" "golang.org/x/time/rate" ) // Logf is the basic Tailscale logger type: a printf-like func. // Like log.Printf, the format need not end in a newline. +// Logf functions should be safe for concurrent use. type Logf func(format string, args ...interface{}) // WithPrefix wraps f, prefixing each format with the provided prefix. @@ -47,60 +49,66 @@ func (w funcWriter) Write(p []byte) (int, error) { // Discard is a Logf that throws away the logs given to it. func Discard(string, ...interface{}) {} +// limitData is used to keep track of each format string's associated +// rate-limiting data. type limitData struct { - lim *rate.Limiter - lastAccessed time.Time - msgBlocked bool + lim *rate.Limiter // the token bucket associated with this string + msgBlocked bool // whether a "duplicate error" message has already been logged + ele *list.Element // list element used to access this string in the cache } // 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 { +// Messages are allowed through at a maximum of f messages/second, in +// bursts of up to b messages at a time. Up to m strings will be held at a time. +func RateLimitedFn(logf Logf, f float64, b int, m 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 + msgLim := make(map[string]*limitData) + msgCache := list.New() // a rudimentary LRU that limits the size of the map + mu := &sync.Mutex{} + return func(format string, args ...interface{}) { + mu.Lock() + rl, ok := msgLim[format] + if ok { + msgCache.MoveToFront(rl.ele) if rl.lim.Allow() { + mu.Lock() rl.msgBlocked = false - logf(s, args) + mu.Unlock() + logf(format, 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)) + rl.msgBlocked = true + mu.Unlock() + logf("Repeated messages were suppressed by rate limiting. Original message: %s", + fmt.Sprintf(format, args...)) + } else { + mu.Unlock() } } } else { - msgList[s] = limitData{rate.NewLimiter(r, b), time.Now(), false} - msgList[s].lim.Allow() - logf(s, args) + msgLim[format] = &limitData{rate.NewLimiter(r, b), false, msgCache.PushFront(format)} + msgLim[format].lim.Allow() + mu.Unlock() + logf(format, 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 - } + mu.Lock() + if msgCache.Len() > m { + msgCache.Remove(msgCache.Back()) + } + + // Purge msgLim of outdated keys to reduce overhead. Must be done by copying + // over to a new map and allowing the garbage collector to eat the entire old one, + // since deleting keys in maps is done through a "zombie flag" on the data rather than + // actually clearing it from memory. See https://github.com/golang/go/issues/20135 + if len(msgLim)-msgCache.Len() > 100 { + newList := make(map[string]*limitData) + for e := msgCache.Front(); e != nil; e = e.Next() { + newList[e.Value.(string)] = msgLim[e.Value.(string)] } - msgList = nil - msgList = newList + msgLim = newList } + mu.Unlock() } - - return rlLogf } diff --git a/types/logger/logger_test.go b/types/logger/logger_test.go index 98df83d94..f1a5be2cf 100644 --- a/types/logger/logger_test.go +++ b/types/logger/logger_test.go @@ -5,9 +5,9 @@ package logger import ( + "fmt" "log" "testing" - "time" ) func TestFuncWriter(t *testing.T) { @@ -22,17 +22,41 @@ func TestStdLogger(t *testing.T) { } func TestRateLimiter(t *testing.T) { - lg := RateLimitedFn(t.Logf, 1, 1) + + // Testing function. args[0] should indicate what should + logTester := func(want []string) Logf { + i := 0 + return func(format string, args ...interface{}) { + got := fmt.Sprintf(format, args...) + if i >= len(want) { + 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) + } + i++ + } + } + + want := []string{ + "boring string with constant formatting (constant)", + "templated format string no. 0", + "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. 1", + "Make sure this string makes it through the rest (that are blocked) 4", + "4 shouldn't get filtered.", + } + + lg := RateLimitedFn(logTester(want), 1, 1, 50) var prefixed Logf for i := 0; i < 10; i++ { - lg("boring string with no formatting") + lg("boring string with constant formatting %s", "(constant)") 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.") } - prefixed = WithPrefix(lg, string('0'+i)) - prefixed(" shouldn't get filtered.") - time.Sleep(200 * time.Millisecond) } }