From d5baeeed5c3c4489b0b9f2c984e8edce13d11149 Mon Sep 17 00:00:00 2001 From: Josh Bleecher Snyder Date: Thu, 21 Jan 2021 12:33:54 -0800 Subject: [PATCH] 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 --- cmd/tailscale/depaware.txt | 1 + cmd/tailscaled/depaware.txt | 1 + wgengine/magicsock/magicsock_test.go | 49 +++++++-------- wgengine/userspace.go | 21 ++----- wgengine/wglog/wglog.go | 89 ++++++++++++++++++++++++++++ wgengine/wglog/wglog_test.go | 59 ++++++++++++++++++ 6 files changed, 176 insertions(+), 44 deletions(-) create mode 100644 wgengine/wglog/wglog.go create mode 100644 wgengine/wglog/wglog_test.go diff --git a/cmd/tailscale/depaware.txt b/cmd/tailscale/depaware.txt index dd152e07f..3e76e25c5 100644 --- a/cmd/tailscale/depaware.txt +++ b/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+ diff --git a/cmd/tailscaled/depaware.txt b/cmd/tailscaled/depaware.txt index 0569b2e2a..2b4e68966 100644 --- a/cmd/tailscaled/depaware.txt +++ b/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+ diff --git a/wgengine/magicsock/magicsock_test.go b/wgengine/magicsock/magicsock_test.go index 8fc7af071..620394b12 100644 --- a/wgengine/magicsock/magicsock_test.go +++ b/wgengine/magicsock/magicsock_test.go @@ -46,6 +46,7 @@ import ( "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, - } -} diff --git a/wgengine/userspace.go b/wgengine/userspace.go index d76371e9e..b79c4dc43 100644 --- a/wgengine/userspace.go +++ b/wgengine/userspace.go @@ -47,6 +47,7 @@ import ( "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 @@ const ( 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. - // 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, - } - + e.wgLogger = wglog.NewLogger(logf) 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 diff --git a/wgengine/wglog/wglog.go b/wgengine/wglog/wglog.go new file mode 100644 index 000000000..e833bb27a --- /dev/null +++ b/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 +} diff --git a/wgengine/wglog/wglog_test.go b/wgengine/wglog/wglog_test.go new file mode 100644 index 000000000..3a899839e --- /dev/null +++ b/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) + } + } +}