wgengine/wglog: improve wireguard-go logging rate limiting

Prior to wireguard-go using printf-style logging,
all wireguard-go logging occurred using format string "%s".
We fixed that but continued to use %s when we rewrote
peer identifiers into Tailscale style.

This commit removes that %sl, which makes rate limiting work correctly.
As a happy side-benefit, it should generate less garbage.

Instead of replacing all wireguard-go peer identifiers
that might occur anywhere in a fully formatted log string,
assume that they only come from args.
Check all args for things that look like *device.Peers
and replace them with appropriately reformatted strings.

There is a variety of ways that this could go wrong
(unusual format verbs or modifiers, peer identifiers
occurring as part of a larger printed object, future API changes),
but none of them occur now, are likely to be added,
or would be hard to work around if they did.

Signed-off-by: Josh Bleecher Snyder <josharian@gmail.com>

wgengine/wglog/wglog.go

@@ -21,7 +21,7 @@ import (
 // It can be modified at run time to adjust to new wireguard-go configurations.
 type Logger struct {
 	DeviceLogger *device.Logger
-	replacer     atomic.Value // of *strings.Replacer
+	replace      atomic.Value // of map[string]string
 }
 
 // NewLogger creates a new logger for use with wireguard-go.
@@ -44,25 +44,33 @@ func NewLogger(logf logger.Logf) *Logger {
 			// See https://github.com/tailscale/tailscale/issues/1388.
 			return
 		}
-		msg := fmt.Sprintf(format, args...)
+		replace, _ := ret.replace.Load().(map[string]string)
-		r := ret.replacer.Load()
+		if replace == nil {
-		if r == nil {
 			// No replacements specified; log as originally planned.
 			logf(format, args...)
 			return
 		}
-		// Do the replacements.
+		// Duplicate the args slice so that we can modify it.
-		new := r.(*strings.Replacer).Replace(msg)
+		// This is not always required, but the code required to avoid it is not worth the complexity.
-		if new == msg {
+		newargs := make([]interface{}, len(args))
-			// No replacements. Log as originally planned.
+		copy(newargs, args)
-			logf(format, args...)
+		for i, arg := range newargs {
-			return
+			// We want to replace *device.Peer args with the Tailscale-formatted version of themselves.
+			// Using *device.Peer directly makes this hard to test, so we string any fmt.Stringers,
+			// and if the string ends up looking exactly like a known Peer, we replace it.
+			// This is slightly imprecise, in that we don't check the formatting verb. Oh well.
+			s, ok := arg.(fmt.Stringer)
+			if !ok {
+				continue
+			}
+			wgStr := s.String()
+			tsStr, ok := replace[wgStr]
+			if !ok {
+				continue
+			}
+			newargs[i] = tsStr
 		}
-		// We made some replacements. Log the new version.
+		logf(format, newargs...)
-		// This changes the format string,
-		// which is somewhat unfortunate as it impacts rate limiting,
-		// but there's not much we can do about that.
-		logf("%s", new)
 	}
 	ret.DeviceLogger = &device.Logger{
 		Verbosef: logger.WithPrefix(wrapper, "[v2] "),
@@ -75,14 +83,13 @@ func NewLogger(logf logger.Logf) *Logger {
 // SetPeers is safe for concurrent use.
 func (x *Logger) SetPeers(peers []wgcfg.Peer) {
 	// Construct a new peer public key log rewriter.
-	var replace []string
+	replace := make(map[string]string)
 	for _, peer := range peers {
 		old := "peer(" + wireguardGoString(peer.PublicKey) + ")"
 		new := peer.PublicKey.ShortString()
-		replace = append(replace, old, new)
+		replace[old] = new
 	}
-	r := strings.NewReplacer(replace...)
+	x.replace.Store(replace)
-	x.replacer.Store(r)
 }
 
 // wireguardGoString prints p in the same format used by wireguard-go.

wgengine/wglog/wglog_test.go

@@ -15,22 +15,27 @@ import (
 
 func TestLogger(t *testing.T) {
 	tests := []struct {
-		in   string
+		format string
-		want string
+		args   []interface{}
-		omit bool
+		want   string
+		omit   bool
 	}{
-		{"hi", "hi", false},
+		{"hi", nil, "hi", false},
-		{"Routine: starting", "", true},
+		{"Routine: starting", nil, "", true},
-		{"peer(IMTB…r7lM) says it misses you", "[IMTBr] says it misses you", false},
+		{"%v says it misses you", []interface{}{stringer("peer(IMTB…r7lM)")}, "[IMTBr] says it misses you", false},
 	}
 
-	c := make(chan string, 1)
+	type log struct {
+		format string
+		args   []interface{}
+	}
+
+	c := make(chan log, 1)
 	logf := func(format string, args ...interface{}) {
-		s := fmt.Sprintf(format, args...)
 		select {
-		case c <- s:
+		case c <- log{format, args}:
 		default:
-			t.Errorf("wrote %q, but shouldn't have", s)
+			t.Errorf("wrote %q, but shouldn't have", fmt.Sprintf(format, args...))
 		}
 	}
 
@@ -45,15 +50,23 @@ func TestLogger(t *testing.T) {
 		if tt.omit {
 			// Write a message ourselves into the channel.
 			// Then if logf also attempts to write into the channel, it'll fail.
-			c <- ""
+			c <- log{}
 		}
-		x.DeviceLogger.Errorf(tt.in)
+		x.DeviceLogger.Errorf(tt.format, tt.args...)
-		got := <-c
+		gotLog := <-c
 		if tt.omit {
 			continue
 		}
-		if got != tt.want {
+		if got := fmt.Sprintf(gotLog.format, gotLog.args...); got != tt.want {
-			t.Errorf("Println(%q) = %q want %q", tt.in, got, tt.want)
+			t.Errorf("Printf(%q, %v) = %q want %q", tt.format, tt.args, got, tt.want)
 		}
 	}
 }
+
+func stringer(s string) stringerString {
+	return stringerString(s)
+}
+
+type stringerString string
+
+func (s stringerString) String() string { return string(s) }