From 59026a291dfe187d9d72c6fa31575b443f63798b Mon Sep 17 00:00:00 2001 From: Josh Bleecher Snyder Date: Tue, 27 Apr 2021 10:03:13 -0700 Subject: [PATCH] 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 --- wgengine/wglog/wglog.go | 45 +++++++++++++++++++++--------------- wgengine/wglog/wglog_test.go | 43 ++++++++++++++++++++++------------ 2 files changed, 54 insertions(+), 34 deletions(-) diff --git a/wgengine/wglog/wglog.go b/wgengine/wglog/wglog.go index c11cb6c4c..9e7cc5482 100644 --- a/wgengine/wglog/wglog.go +++ b/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...) - r := ret.replacer.Load() - if r == nil { + replace, _ := ret.replace.Load().(map[string]string) + if replace == nil { // No replacements specified; log as originally planned. logf(format, args...) return } - // Do the replacements. - new := r.(*strings.Replacer).Replace(msg) - if new == msg { - // No replacements. Log as originally planned. - logf(format, args...) - return + // Duplicate the args slice so that we can modify it. + // This is not always required, but the code required to avoid it is not worth the complexity. + newargs := make([]interface{}, len(args)) + copy(newargs, args) + for i, arg := range newargs { + // 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. - // 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) + logf(format, newargs...) } 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.replacer.Store(r) + x.replace.Store(replace) } // wireguardGoString prints p in the same format used by wireguard-go. diff --git a/wgengine/wglog/wglog_test.go b/wgengine/wglog/wglog_test.go index 80ea67449..b804b5959 100644 --- a/wgengine/wglog/wglog_test.go +++ b/wgengine/wglog/wglog_test.go @@ -15,22 +15,27 @@ import ( func TestLogger(t *testing.T) { tests := []struct { - in string - want string - omit bool + format string + args []interface{} + want string + omit bool }{ - {"hi", "hi", false}, - {"Routine: starting", "", true}, - {"peer(IMTB…r7lM) says it misses you", "[IMTBr] says it misses you", false}, + {"hi", nil, "hi", false}, + {"Routine: starting", nil, "", true}, + {"%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) - got := <-c + x.DeviceLogger.Errorf(tt.format, tt.args...) + gotLog := <-c if tt.omit { continue } - if got != tt.want { - t.Errorf("Println(%q) = %q want %q", tt.in, got, tt.want) + if got := fmt.Sprintf(gotLog.format, gotLog.args...); 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) }