Replace time-dependent cache limiting with LRU

To keep memory usage as constant as possible, the previous cache
purging at periodic time intervals has been replaced by an LRU that
discards the oldest string when the capacity of the cache is reached.

Also fixed some formatting and commenting issues, and added better
testing for the rate limiter.

Signed-off-by: Wendi Yu <wendi.yu@yahoo.ca>

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 {

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()

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++ {

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
 }

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)
 	}
 
 }