wgengine: use Tailscale-style peer identifiers in logs

Rewrite log lines on the fly, based on the set of known peers.

This enables us to use upstream wireguard-go logging,
but maintain the Tailscale-style peer public key identifiers
that the rest of our systems (and people) expect.

Fixes #1183

Signed-off-by: Josh Bleecher Snyder <josh@tailscale.com>

cmd/tailscale/depaware.txt

@@ -89,6 +89,7 @@ tailscale.com/cmd/tailscale dependencies: (generated by github.com/tailscale/dep
         tailscale.com/wgengine/router/dns                            from tailscale.com/ipn+
         tailscale.com/wgengine/tsdns                                 from tailscale.com/ipn+
         tailscale.com/wgengine/tstun                                 from tailscale.com/wgengine
+        tailscale.com/wgengine/wglog                                 from tailscale.com/wgengine
    W 💣 tailscale.com/wgengine/winnet                                from tailscale.com/wgengine/router
         golang.org/x/crypto/blake2b                                  from golang.org/x/crypto/nacl/box
         golang.org/x/crypto/blake2s                                  from github.com/tailscale/wireguard-go/device+

cmd/tailscaled/depaware.txt

@@ -130,6 +130,7 @@ tailscale.com/cmd/tailscaled dependencies: (generated by github.com/tailscale/de
         tailscale.com/wgengine/router/dns                            from tailscale.com/ipn+
         tailscale.com/wgengine/tsdns                                 from tailscale.com/ipn+
         tailscale.com/wgengine/tstun                                 from tailscale.com/wgengine+
+        tailscale.com/wgengine/wglog                                 from tailscale.com/wgengine
    W 💣 tailscale.com/wgengine/winnet                                from tailscale.com/wgengine/router
         golang.org/x/crypto/blake2b                                  from golang.org/x/crypto/nacl/box
         golang.org/x/crypto/blake2s                                  from github.com/tailscale/wireguard-go/device+

wgengine/magicsock/magicsock_test.go

@@ -46,6 +46,7 @@
 	"tailscale.com/types/wgkey"
 	"tailscale.com/wgengine/filter"
 	"tailscale.com/wgengine/tstun"
+	"tailscale.com/wgengine/wglog"
 )
 
 func init() {
@@ -127,6 +128,7 @@ type magicStack struct {
 	tun        *tuntest.ChannelTUN // TUN device to send/receive packets
 	tsTun      *tstun.TUN          // wrapped tun that implements filtering and wgengine hooks
 	dev        *device.Device      // the wireguard-go Device that connects the previous things
+	wgLogger   *wglog.Logger       // wireguard-go log wrapper
 }
 
 // newMagicStack builds and initializes an idle magicsock and
@@ -163,8 +165,9 @@ func newMagicStack(t testing.TB, logf logger.Logf, l nettype.PacketListener, der
 	tsTun := tstun.WrapTUN(logf, tun.TUN())
 	tsTun.SetFilter(filter.NewAllowAllForTest(logf))
 
+	wgLogger := wglog.NewLogger(logf)
 	dev := device.NewDevice(tsTun, &device.DeviceOptions{
-		Logger:         wireguardGoLogger(logf),
+		Logger:         wgLogger.DeviceLogger,
 		CreateEndpoint: conn.CreateEndpoint,
 		CreateBind:     conn.CreateBind,
 		SkipBindUpdate: true,
@@ -187,9 +190,15 @@ func newMagicStack(t testing.TB, logf logger.Logf, l nettype.PacketListener, der
 		tun:        tun,
 		tsTun:      tsTun,
 		dev:        dev,
+		wgLogger:   wgLogger,
 	}
 }
 
+func (s *magicStack) Reconfig(cfg *wgcfg.Config) error {
+	s.wgLogger.SetPeers(cfg.Peers)
+	return s.dev.Reconfig(cfg)
+}
+
 func (s *magicStack) String() string {
 	pub := s.Public()
 	return pub.ShortString()
@@ -290,7 +299,7 @@ func meshStacks(logf logger.Logf, ms []*magicStack) (cleanup func()) {
 				// blow up. Shouldn't happen anyway.
 				panic(fmt.Sprintf("failed to construct wgcfg from netmap: %v", err))
 			}
-			if err := m.dev.Reconfig(wg); err != nil {
+			if err := m.Reconfig(wg); err != nil {
 				panic(fmt.Sprintf("device reconfig failed: %v", err))
 			}
 		}
@@ -526,7 +535,7 @@ func TestDeviceStartStop(t *testing.T) {
 
 	tun := tuntest.NewChannelTUN()
 	dev := device.NewDevice(tun.TUN(), &device.DeviceOptions{
-		Logger:         wireguardGoLogger(t.Logf),
+		Logger:         wglog.NewLogger(t.Logf).DeviceLogger,
 		CreateEndpoint: conn.CreateEndpoint,
 		CreateBind:     conn.CreateBind,
 		SkipBindUpdate: true,
@@ -915,10 +924,10 @@ func testTwoDevicePing(t *testing.T, d *devices) {
 	}
 	cfgs := makeConfigs(t, addrs)
 
-	if err := m1.dev.Reconfig(&cfgs[0]); err != nil {
+	if err := m1.Reconfig(&cfgs[0]); err != nil {
 		t.Fatal(err)
 	}
-	if err := m2.dev.Reconfig(&cfgs[1]); err != nil {
+	if err := m2.Reconfig(&cfgs[1]); err != nil {
 		t.Fatal(err)
 	}
 
@@ -983,7 +992,7 @@ func testTwoDevicePing(t *testing.T, d *devices) {
 	t.Run("no-op dev1 reconfig", func(t *testing.T) {
 		setT(t)
 		defer setT(outerT)
-		if err := m1.dev.Reconfig(&cfgs[0]); err != nil {
+		if err := m1.Reconfig(&cfgs[0]); err != nil {
 			t.Fatal(err)
 		}
 		ping1(t)
@@ -1060,10 +1069,10 @@ func testTwoDevicePing(t *testing.T, d *devices) {
 	ep1 := cfgs[1].Peers[0].Endpoints
 	ep1 = derpEp + "," + ep1
 	cfgs[1].Peers[0].Endpoints = ep1
-	if err := m1.dev.Reconfig(&cfgs[0]); err != nil {
+	if err := m1.Reconfig(&cfgs[0]); err != nil {
 		t.Fatal(err)
 	}
-	if err := m2.dev.Reconfig(&cfgs[1]); err != nil {
+	if err := m2.Reconfig(&cfgs[1]); err != nil {
 		t.Fatal(err)
 	}
 
@@ -1076,10 +1085,10 @@ func testTwoDevicePing(t *testing.T, d *devices) {
 	// Disable real route.
 	cfgs[0].Peers[0].Endpoints = derpEp
 	cfgs[1].Peers[0].Endpoints = derpEp
-	if err := m1.dev.Reconfig(&cfgs[0]); err != nil {
+	if err := m1.Reconfig(&cfgs[0]); err != nil {
 		t.Fatal(err)
 	}
-	if err := m2.dev.Reconfig(&cfgs[1]); err != nil {
+	if err := m2.Reconfig(&cfgs[1]); err != nil {
 		t.Fatal(err)
 	}
 	time.Sleep(250 * time.Millisecond) // TODO remove
@@ -1105,10 +1114,10 @@ func testTwoDevicePing(t *testing.T, d *devices) {
 	if ep2 := cfgs[1].Peers[0].Endpoints; len(ep2) != 1 {
 		t.Errorf("unexpected peer endpoints in dev2: %v", ep2)
 	}
-	if err := m2.dev.Reconfig(&cfgs[1]); err != nil {
+	if err := m2.Reconfig(&cfgs[1]); err != nil {
 		t.Fatal(err)
 	}
-	if err := m1.dev.Reconfig(&cfgs[0]); err != nil {
+	if err := m1.Reconfig(&cfgs[0]); err != nil {
 		t.Fatal(err)
 	}
 	// Dear future human debugging a test failure here: this test is
@@ -1487,19 +1496,3 @@ func BenchmarkReceiveFrom_Native(b *testing.B) {
 		}
 	}
 }
-
-func wireguardGoLogger(logf logger.Logf) *device.Logger {
-	// wireguard-go logs as it starts and stops routines.
-	// Silence those; there are a lot of them, and they're just noise.
-	allowLogf := func(s string) bool {
-		return !strings.Contains(s, "Routine:")
-	}
-	filtered := logger.Filtered(logf, allowLogf)
-	stdLogger := logger.StdLogger(filtered)
-
-	return &device.Logger{
-		Debug: stdLogger,
-		Info:  stdLogger,
-		Error: stdLogger,
-	}
-}

wgengine/userspace.go

@@ -47,6 +47,7 @@
 	"tailscale.com/wgengine/router"
 	"tailscale.com/wgengine/tsdns"
 	"tailscale.com/wgengine/tstun"
+	"tailscale.com/wgengine/wglog"
 )
 
 // minimalMTU is the MTU we set on tailscale's TUN
@@ -84,6 +85,7 @@
 
 type userspaceEngine struct {
 	logf      logger.Logf
+	wgLogger  *wglog.Logger //a wireguard-go logging wrapper
 	reqCh     chan struct{}
 	waitCh    chan struct{} // chan is closed when first Close call completes; contrast with closing bool
 	timeNow   func() time.Time
@@ -279,23 +281,9 @@ func newUserspaceEngineAdvanced(conf EngineConfig) (_ Engine, reterr error) {
 		e.tundev.PostFilterOut = e.trackOpenPostFilterOut
 	}
 
-	// wireguard-go logs as it starts and stops routines.
+	e.wgLogger = wglog.NewLogger(logf)
-	// Silence those; there are a lot of them, and they're just noise.
-	allowLogf := func(s string) bool {
-		return !strings.Contains(s, "Routine:")
-	}
-	filtered := logger.Filtered(logf, allowLogf)
-	// flags==0 because logf is already nested in another logger.
-	// The outer one can display the preferred log prefixes, etc.
-	dlog := logger.StdLogger(filtered)
-	logger := device.Logger{
-		Debug: dlog,
-		Info:  dlog,
-		Error: dlog,
-	}
-
 	opts := &device.DeviceOptions{
-		Logger: &logger,
+		Logger: e.wgLogger.DeviceLogger,
 		HandshakeDone: func(peerKey device.NoisePublicKey, peer *device.Peer, deviceAllowedIPs *device.AllowedIPs) {
 			// Send an unsolicited status event every time a
 			// handshake completes. This makes sure our UI can
@@ -774,6 +762,7 @@ func (e *userspaceEngine) maybeReconfigWireguardLocked(discoChanged map[key.Publ
 	}
 
 	full := e.lastCfgFull
+	e.wgLogger.SetPeers(full.Peers)
 
 	// Compute a minimal config to pass to wireguard-go
 	// based on the full config. Prune off all the peers

wgengine/wglog/wglog.go

@@ -0,0 +1,89 @@
+// Copyright (c) 2020 Tailscale Inc & AUTHORS All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+// Package wglog contains logging helpers for wireguard-go.
+package wglog
+
+import (
+	"encoding/base64"
+	"fmt"
+	"strings"
+	"sync/atomic"
+
+	"github.com/tailscale/wireguard-go/device"
+	"github.com/tailscale/wireguard-go/wgcfg"
+	"tailscale.com/types/logger"
+)
+
+// A Logger is a wireguard-go log wrapper that cleans up and rewrites log lines.
+// 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
+}
+
+// NewLogger creates a new logger for use with wireguard-go.
+// This logger silences repetitive/unhelpful noisy log lines
+// and rewrites peer keys from wireguard-go into Tailscale format.
+func NewLogger(logf logger.Logf) *Logger {
+	ret := new(Logger)
+
+	wrapper := func(format string, args ...interface{}) {
+		msg := fmt.Sprintf(format, args...)
+		if strings.Contains(msg, "Routine:") {
+			// wireguard-go logs as it starts and stops routines.
+			// Drop those; there are a lot of them, and they're just noise.
+			return
+		}
+		r := ret.replacer.Load()
+		if r == 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
+		}
+		// 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)
+	}
+	std := logger.StdLogger(wrapper)
+	ret.DeviceLogger = &device.Logger{
+		Debug: std,
+		Info:  std,
+		Error: std,
+	}
+	return ret
+}
+
+// SetPeers adjusts x to rewrite the peer public keys found in peers.
+// SetPeers is safe for concurrent use.
+func (x *Logger) SetPeers(peers []wgcfg.Peer) {
+	// Construct a new peer public key log rewriter.
+	var replace []string
+	for _, peer := range peers {
+		old := "peer(" + wireguardGoString(peer.PublicKey) + ")"
+		new := peer.PublicKey.ShortString()
+		replace = append(replace, old, new)
+	}
+	r := strings.NewReplacer(replace...)
+	x.replacer.Store(r)
+}
+
+// wireguardGoString prints p in the same format used by wireguard-go.
+func wireguardGoString(k wgcfg.Key) string {
+	base64Key := base64.StdEncoding.EncodeToString(k[:])
+	abbreviatedKey := "invalid"
+	if len(base64Key) == 44 {
+		abbreviatedKey = base64Key[0:4] + "…" + base64Key[39:43]
+	}
+	return abbreviatedKey
+}

wgengine/wglog/wglog_test.go

@@ -0,0 +1,59 @@
+// Copyright (c) 2020 Tailscale Inc & AUTHORS All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package wglog_test
+
+import (
+	"fmt"
+	"testing"
+
+	"github.com/tailscale/wireguard-go/wgcfg"
+	"tailscale.com/wgengine/wglog"
+)
+
+func TestLogger(t *testing.T) {
+	tests := []struct {
+		in   string
+		want string
+		omit bool
+	}{
+		{"hi", "hi", false},
+		{"Routine: starting", "", true},
+		{"peer(IMTB…r7lM) says it misses you", "[IMTBr] says it misses you", false},
+	}
+
+	c := make(chan string, 1)
+	logf := func(format string, args ...interface{}) {
+		s := fmt.Sprintf(format, args...)
+		select {
+		case c <- s:
+		default:
+			t.Errorf("wrote %q, but shouldn't have", s)
+		}
+	}
+
+	x := wglog.NewLogger(logf)
+	key, err := wgcfg.ParseHexKey("20c4c1ae54e1fd37cab6e9a532ca20646aff496796cc41d4519560e5e82bee53")
+	if err != nil {
+		t.Fatal(err)
+	}
+	x.SetPeers([]wgcfg.Peer{{PublicKey: key}})
+
+	for _, tt := range tests {
+		if tt.omit {
+			// Write a message ourselves into the channel.
+			// Then if logf also attempts to write into the channel, it'll fail.
+			c <- ""
+		}
+		x.DeviceLogger.Info.Println(tt.in)
+		got := <-c
+		if tt.omit {
+			continue
+		}
+		tt.want += "\n"
+		if got != tt.want {
+			t.Errorf("Println(%q) = %q want %q", tt.in, got, tt.want)
+		}
+	}
+}