diff --git a/control/controlclient/auto.go b/control/controlclient/auto.go index d54f0e911..febacb215 100644 --- a/control/controlclient/auto.go +++ b/control/controlclient/auto.go @@ -239,7 +239,7 @@ func (c *Client) cancelMapSafely() { func (c *Client) authRoutine() { defer close(c.authDone) - bo := backoff.Backoff{Name: "authRoutine"} + bo := backoff.NewBackoff("authRoutine", c.logf) for { c.mu.Lock() @@ -384,7 +384,7 @@ func (c *Client) authRoutine() { func (c *Client) mapRoutine() { defer close(c.mapDone) - bo := backoff.Backoff{Name: "mapRoutine"} + bo := backoff.NewBackoff("mapRoutine", c.logf) for { c.mu.Lock() diff --git a/control/controlclient/auto_test.go b/control/controlclient/auto_test.go index 1483c87cf..04bd80d1d 100644 --- a/control/controlclient/auto_test.go +++ b/control/controlclient/auto_test.go @@ -980,7 +980,10 @@ const segmentKey = "segkey" func newServer(t *testing.T) *server { t.Helper() - tstest.FixLogs(t) + tstest.PanicOnLog() + + logf := t.Logf + s := &server{ t: t, check: tstest.NewResourceCheck(), @@ -1036,7 +1039,7 @@ func newServer(t *testing.T) *server { s.control.ServeHTTP(w, r) } })) - s.control, err = control.New(tmpdir, tmpdir, tmpdir, s.http.URL, true, t.Logf) + s.control, err = control.New(tmpdir, tmpdir, tmpdir, s.http.URL, true, logf) if err != nil { t.Fatal(err) } diff --git a/ipn/e2e_test.go b/ipn/e2e_test.go index 596c6cd02..8308593e3 100644 --- a/ipn/e2e_test.go +++ b/ipn/e2e_test.go @@ -39,8 +39,15 @@ func init() { } func TestIPN(t *testing.T) { - tstest.FixLogs(t) - defer tstest.UnfixLogs(t) + tstest.PanicOnLog() + + // This gets reassigned inside every test, so that the connections + // all log using the "current" t.Logf function. Sigh. + current_t := t + logf := func(s string, args ...interface{}) { + current_t.Helper() + current_t.Logf(s, args...) + } // Turn off STUN for the test to make it hermetic. // TODO(crawshaw): add a test that runs against a local STUN server. @@ -67,7 +74,7 @@ func TestIPN(t *testing.T) { if err != nil { t.Fatalf("create tempdir: %v\n", err) } - ctl, err = control.New(tmpdir, tmpdir, tmpdir, serverURL, true, t.Logf) + ctl, err = control.New(tmpdir, tmpdir, tmpdir, serverURL, true, logf) if err != nil { t.Fatalf("create control server: %v\n", ctl) } @@ -75,18 +82,20 @@ func TestIPN(t *testing.T) { t.Fatal(err) } - n1 := newNode(t, "n1", https, false) + n1 := newNode(t, logf, "n1", https, false) defer n1.Backend.Shutdown() n1.Backend.StartLoginInteractive() - n2 := newNode(t, "n2", https, true) + n2 := newNode(t, logf, "n2", https, true) defer n2.Backend.Shutdown() n2.Backend.StartLoginInteractive() t.Run("login", func(t *testing.T) { + current_t = t + var s1, s2 State for { - t.Logf("\n\nn1.state=%v n2.state=%v\n\n", s1, s2) + logf("\n\nn1.state=%v n2.state=%v\n\n", s1, s2) // TODO(crawshaw): switch from || to &&. To do this we need to // transmit some data so that the handshake completes on both @@ -102,7 +111,7 @@ func TestIPN(t *testing.T) { select { case n := <-n1.NotifyCh: - t.Logf("n1n: %v\n", n) + logf("n1n: %v\n", n) if n.State != nil { s1 = *n.State if s1 == NeedsMachineAuth { @@ -110,7 +119,7 @@ func TestIPN(t *testing.T) { } } case n := <-n2.NotifyCh: - t.Logf("n2n: %v\n", n) + logf("n2n: %v\n", n) if n.State != nil { s2 = *n.State if s2 == NeedsMachineAuth { @@ -122,10 +131,13 @@ func TestIPN(t *testing.T) { } } }) + current_t = t n1addr := n1.Backend.NetMap().Addresses[0].IP n2addr := n2.Backend.NetMap().Addresses[0].IP + t.Run("ping n2", func(t *testing.T) { + current_t = t t.Skip("TODO(crawshaw): skipping ping test, it is flaky") msg := tuntest.Ping(n2addr.IP(), n1addr.IP()) n1.ChannelTUN.Outbound <- msg @@ -138,7 +150,10 @@ func TestIPN(t *testing.T) { t.Error("no ping seen") } }) + current_t = t + t.Run("ping n1", func(t *testing.T) { + current_t = t t.Skip("TODO(crawshaw): skipping ping test, it is flaky") msg := tuntest.Ping(n1addr.IP(), n2addr.IP()) n2.ChannelTUN.Outbound <- msg @@ -151,6 +166,7 @@ func TestIPN(t *testing.T) { t.Error("no ping seen") } }) + current_t = t drain: for { @@ -165,6 +181,8 @@ drain: n1.Backend.Logout() t.Run("logout", func(t *testing.T) { + current_t = t + var s State for { select { @@ -173,7 +191,7 @@ drain: continue } s = *n.State - t.Logf("n.State=%v", s) + logf("n.State=%v", s) if s == NeedsLogin { return } @@ -182,6 +200,7 @@ drain: } } }) + current_t = t } type testNode struct { @@ -191,12 +210,11 @@ type testNode struct { } // Create a new IPN node. -func newNode(t *testing.T, prefix string, https *httptest.Server, weirdPrefs bool) testNode { +func newNode(t *testing.T, logfx logger.Logf, prefix string, https *httptest.Server, weirdPrefs bool) testNode { t.Helper() - logfe := logger.WithPrefix(t.Logf, prefix+"e: ") - - logf := logger.WithPrefix(t.Logf, prefix+": ") + logfe := logger.WithPrefix(logfx, prefix+"e: ") + logf := logger.WithPrefix(logfx, prefix+": ") var err error httpc := https.Client() @@ -241,7 +259,7 @@ func newNode(t *testing.T, prefix string, https *httptest.Server, weirdPrefs boo Notify: func(n Notify) { // Automatically visit auth URLs if n.BrowseToURL != nil { - t.Logf("BrowseToURL: %v", *n.BrowseToURL) + logf("BrowseToURL: %v", *n.BrowseToURL) authURL := *n.BrowseToURL i := strings.Index(authURL, "/a/") @@ -258,7 +276,7 @@ func newNode(t *testing.T, prefix string, https *httptest.Server, weirdPrefs boo req.Header.Add("Content-Type", "application/x-www-form-urlencoded") if _, err := httpc.Do(req); err != nil { - t.Logf("BrowseToURL: %v\n", err) + logf("BrowseToURL: %v\n", err) } } nch <- n diff --git a/ipn/ipnserver/server.go b/ipn/ipnserver/server.go index f999f85b8..e184d4f50 100644 --- a/ipn/ipnserver/server.go +++ b/ipn/ipnserver/server.go @@ -164,7 +164,7 @@ func Run(rctx context.Context, logf logger.Logf, logid string, opts Options, e w } } - bo := backoff.Backoff{Name: "ipnserver"} + bo := backoff.NewBackoff("ipnserver", logf) for i := 1; rctx.Err() == nil; i++ { s, err = listen.Accept() @@ -229,7 +229,7 @@ func BabysitProc(ctx context.Context, args []string, logf logger.Logf) { proc.mu.Unlock() }() - bo := backoff.Backoff{Name: "BabysitProc"} + bo := backoff.NewBackoff("BabysitProc", logf) for { startTime := time.Now() diff --git a/ipn/local.go b/ipn/local.go index c280c78e8..4513d8ee6 100644 --- a/ipn/local.go +++ b/ipn/local.go @@ -73,7 +73,7 @@ func NewLocalBackend(logf logger.Logf, logid string, store StateStore, e wgengin } // Default filter blocks everything, until Start() is called. - e.SetFilter(filter.NewAllowNone()) + e.SetFilter(filter.NewAllowNone(logf)) ctx, cancel := context.WithCancel(context.Background()) portpoll, err := portlist.NewPoller() @@ -360,11 +360,11 @@ func (b *LocalBackend) updateFilter(netMap *controlclient.NetworkMap) { if netMap == nil { // Not configured yet, block everything b.logf("netmap packet filter: (not ready yet)") - b.e.SetFilter(filter.NewAllowNone()) + b.e.SetFilter(filter.NewAllowNone(b.logf)) } else if b.Prefs().ShieldsUp { // Shields up, block everything b.logf("netmap packet filter: (shields up)") - b.e.SetFilter(filter.NewAllowNone()) + b.e.SetFilter(filter.NewAllowNone(b.logf)) } else { now := time.Now() if now.Sub(b.lastFilterPrint) > 1*time.Minute { @@ -373,7 +373,7 @@ func (b *LocalBackend) updateFilter(netMap *controlclient.NetworkMap) { } else { b.logf("netmap packet filter: (length %d)", len(netMap.PacketFilter)) } - b.e.SetFilter(filter.New(netMap.PacketFilter, b.e.GetFilter())) + b.e.SetFilter(filter.New(netMap.PacketFilter, b.e.GetFilter(), b.logf)) } } diff --git a/ipn/message_test.go b/ipn/message_test.go index ced17d8e9..4b0ebd9f5 100644 --- a/ipn/message_test.go +++ b/ipn/message_test.go @@ -13,8 +13,7 @@ import ( ) func TestReadWrite(t *testing.T) { - tstest.FixLogs(t) - defer tstest.UnfixLogs(t) + tstest.PanicOnLog() rc := tstest.NewResourceCheck() defer rc.Assert(t) @@ -62,8 +61,7 @@ func TestReadWrite(t *testing.T) { } func TestClientServer(t *testing.T) { - tstest.FixLogs(t) - defer tstest.UnfixLogs(t) + tstest.PanicOnLog() rc := tstest.NewResourceCheck() defer rc.Assert(t) diff --git a/ipn/prefs_test.go b/ipn/prefs_test.go index ff3f69e83..b6d320f37 100644 --- a/ipn/prefs_test.go +++ b/ipn/prefs_test.go @@ -10,6 +10,7 @@ import ( "github.com/tailscale/wireguard-go/wgcfg" "tailscale.com/control/controlclient" + "tailscale.com/tstest" ) func fieldsOf(t reflect.Type) (fields []string) { @@ -20,6 +21,8 @@ func fieldsOf(t reflect.Type) (fields []string) { } func TestPrefsEqual(t *testing.T) { + tstest.PanicOnLog() + prefsHandles := []string{"ControlURL", "RouteAll", "AllowSingleHosts", "CorpDNS", "WantRunning", "ShieldsUp", "AdvertiseRoutes", "AdvertiseTags", "NoSNAT", "NotepadURLs", "DisableDERP", "Persist"} if have := fieldsOf(reflect.TypeOf(Prefs{})); !reflect.DeepEqual(have, prefsHandles) { t.Errorf("Prefs.Equal check might be out of sync\nfields: %q\nhandled: %q\n", @@ -231,6 +234,8 @@ func checkPrefs(t *testing.T, p Prefs) { } func TestBasicPrefs(t *testing.T) { + tstest.PanicOnLog() + p := Prefs{ ControlURL: "https://login.tailscale.com", } @@ -238,6 +243,8 @@ func TestBasicPrefs(t *testing.T) { } func TestPrefsPersist(t *testing.T) { + tstest.PanicOnLog() + c := controlclient.Persist{ LoginName: "test@example.com", } diff --git a/ipn/store_test.go b/ipn/store_test.go index c1f52a725..6dc08d0d9 100644 --- a/ipn/store_test.go +++ b/ipn/store_test.go @@ -8,6 +8,8 @@ import ( "io/ioutil" "os" "testing" + + "tailscale.com/tstest" ) func testStoreSemantics(t *testing.T, store StateStore) { @@ -76,11 +78,15 @@ func testStoreSemantics(t *testing.T, store StateStore) { } func TestMemoryStore(t *testing.T) { + tstest.PanicOnLog() + store := &MemoryStore{} testStoreSemantics(t, store) } func TestFileStore(t *testing.T) { + tstest.PanicOnLog() + f, err := ioutil.TempFile("", "test_ipn_store") if err != nil { t.Fatal(err) diff --git a/logpolicy/logpolicy.go b/logpolicy/logpolicy.go index 1af689892..2a69325eb 100644 --- a/logpolicy/logpolicy.go +++ b/logpolicy/logpolicy.go @@ -196,7 +196,7 @@ func New(collection string) *Policy { if filchBuf != nil { c.Buffer = filchBuf } - lw := logtail.Log(c) + lw := logtail.Log(c, log.Printf) log.SetFlags(0) // other logflags are set on console, not here log.SetOutput(lw) diff --git a/logtail/backoff/backoff.go b/logtail/backoff/backoff.go index d2c057eb5..b0d7908d4 100644 --- a/logtail/backoff/backoff.go +++ b/logtail/backoff/backoff.go @@ -6,9 +6,10 @@ package backoff import ( "context" - "log" "math/rand" "time" + + "tailscale.com/types/logger" ) const MAX_BACKOFF_MSEC = 30000 @@ -16,7 +17,9 @@ const MAX_BACKOFF_MSEC = 30000 type Backoff struct { n int // Name is the name of this backoff timer, for logging purposes. - Name string + name string + // logf is the function used for log messages when backing off. + logf logger.Logf // NewTimer is the function that acts like time.NewTimer(). // You can override this in unit tests. NewTimer func(d time.Duration) *time.Timer @@ -25,6 +28,14 @@ type Backoff struct { LogLongerThan time.Duration } +func NewBackoff(name string, logf logger.Logf) Backoff { + return Backoff{ + name: name, + logf: logf, + NewTimer: time.NewTimer, + } +} + func (b *Backoff) BackOff(ctx context.Context, err error) { if ctx.Err() == nil && err != nil { b.n++ @@ -39,13 +50,9 @@ func (b *Backoff) BackOff(ctx context.Context, err error) { msec = rand.Intn(msec) + msec/2 dur := time.Duration(msec) * time.Millisecond if dur >= b.LogLongerThan { - log.Printf("%s: backoff: %d msec\n", b.Name, msec) - } - newTimer := b.NewTimer - if newTimer == nil { - newTimer = time.NewTimer + b.logf("%s: backoff: %d msec\n", b.name, msec) } - t := newTimer(dur) + t := b.NewTimer(dur) select { case <-ctx.Done(): t.Stop() diff --git a/logtail/logtail.go b/logtail/logtail.go index 33cf78a37..169897f54 100644 --- a/logtail/logtail.go +++ b/logtail/logtail.go @@ -17,6 +17,7 @@ import ( "time" "tailscale.com/logtail/backoff" + tslogger "tailscale.com/types/logger" ) // DefaultHost is the default host name to upload logs to when @@ -73,7 +74,7 @@ type Config struct { DrainLogs <-chan struct{} } -func Log(cfg Config) Logger { +func Log(cfg Config, logf tslogger.Logf) Logger { if cfg.BaseURL == "" { cfg.BaseURL = "https://" + DefaultHost } @@ -104,9 +105,7 @@ func Log(cfg Config) Logger { sentinel: make(chan int32, 16), drainLogs: cfg.DrainLogs, timeNow: cfg.TimeNow, - bo: backoff.Backoff{ - Name: "logtail", - }, + bo: backoff.NewBackoff("logtail", logf), shutdownStart: make(chan struct{}), shutdownDone: make(chan struct{}), diff --git a/logtail/logtail_test.go b/logtail/logtail_test.go index d26252479..71bdfc43d 100644 --- a/logtail/logtail_test.go +++ b/logtail/logtail_test.go @@ -16,7 +16,7 @@ func TestFastShutdown(t *testing.T) { l := Log(Config{ BaseURL: "http://localhost:1234", - }) + }, t.Logf) l.Shutdown(ctx) } diff --git a/tstest/log.go b/tstest/log.go index 33e7bc439..c6900a75a 100644 --- a/tstest/log.go +++ b/tstest/log.go @@ -28,3 +28,15 @@ func FixLogs(t *testing.T) { func UnfixLogs(t *testing.T) { defer log.SetOutput(os.Stderr) } + +type panicLogWriter struct { + t *testing.T +} + +func (w *panicLogWriter) Write(b []byte) (int, error) { + panic("please use tailscale.com/logger.Logf instead of the log module") +} + +func PanicOnLog() { + log.SetOutput(&panicLogWriter{}) +} diff --git a/wgengine/filter/filter.go b/wgengine/filter/filter.go index 52dcd3275..300dc8c35 100644 --- a/wgengine/filter/filter.go +++ b/wgengine/filter/filter.go @@ -7,12 +7,12 @@ package filter import ( "fmt" - "log" "sync" "time" "github.com/golang/groupcache/lru" "golang.org/x/time/rate" + "tailscale.com/types/logger" "tailscale.com/wgengine/packet" ) @@ -23,6 +23,7 @@ type filterState struct { // Filter is a stateful packet filter. type Filter struct { + logf logger.Logf matches Matches state *filterState } @@ -75,20 +76,20 @@ var MatchAllowAll = Matches{ } // NewAllowAll returns a packet filter that accepts everything. -func NewAllowAll() *Filter { - return New(MatchAllowAll, nil) +func NewAllowAll(logf logger.Logf) *Filter { + return New(MatchAllowAll, nil, logf) } // NewAllowNone returns a packet filter that rejects everything. -func NewAllowNone() *Filter { - return New(nil, nil) +func NewAllowNone(logf logger.Logf) *Filter { + return New(nil, nil, logf) } // New creates a new packet Filter with the given Matches rules. // If shareStateWith is non-nil, the returned filter shares state // with the previous one, to enable rules to be changed at runtime // without breaking existing flows. -func New(matches Matches, shareStateWith *Filter) *Filter { +func New(matches Matches, shareStateWith *Filter, logf logger.Logf) *Filter { var state *filterState if shareStateWith != nil { state = shareStateWith.state @@ -98,6 +99,7 @@ func New(matches Matches, shareStateWith *Filter) *Filter { } } f := &Filter{ + logf: logf, matches: matches, state: state, } @@ -119,7 +121,7 @@ func maybeHexdump(flag RunFlags, b []byte) string { var acceptBucket = rate.NewLimiter(rate.Every(10*time.Second), 3) var dropBucket = rate.NewLimiter(rate.Every(5*time.Second), 10) -func logRateLimit(runflags RunFlags, b []byte, q *packet.QDecode, r Response, why string) { +func (f *Filter) logRateLimit(runflags RunFlags, b []byte, q *packet.QDecode, r Response, why string) { if r == Drop && (runflags&LogDrops) != 0 && dropBucket.Allow() { var qs string if q == nil { @@ -127,32 +129,32 @@ func logRateLimit(runflags RunFlags, b []byte, q *packet.QDecode, r Response, wh } else { qs = q.String() } - log.Printf("Drop: %v %v %s\n%s", qs, len(b), why, maybeHexdump(runflags&HexdumpDrops, b)) + f.logf("Drop: %v %v %s\n%s", qs, len(b), why, maybeHexdump(runflags&HexdumpDrops, b)) } else if r == Accept && (runflags&LogAccepts) != 0 && acceptBucket.Allow() { - log.Printf("Accept: %v %v %s\n%s", q, len(b), why, maybeHexdump(runflags&HexdumpAccepts, b)) + f.logf("Accept: %v %v %s\n%s", q, len(b), why, maybeHexdump(runflags&HexdumpAccepts, b)) } } func (f *Filter) RunIn(b []byte, q *packet.QDecode, rf RunFlags) Response { - r := pre(b, q, rf) + r := f.pre(b, q, rf) if r == Accept || r == Drop { // already logged return r } r, why := f.runIn(q) - logRateLimit(rf, b, q, r, why) + f.logRateLimit(rf, b, q, r, why) return r } func (f *Filter) RunOut(b []byte, q *packet.QDecode, rf RunFlags) Response { - r := pre(b, q, rf) + r := f.pre(b, q, rf) if r == Drop || r == Accept { // already logged return r } r, why := f.runOut(q) - logRateLimit(rf, b, q, r, why) + f.logRateLimit(rf, b, q, r, why) return r } @@ -216,25 +218,25 @@ func (f *Filter) runOut(q *packet.QDecode) (r Response, why string) { return Accept, "ok out" } -func pre(b []byte, q *packet.QDecode, rf RunFlags) Response { +func (f *Filter) pre(b []byte, q *packet.QDecode, rf RunFlags) Response { if len(b) == 0 { // wireguard keepalive packet, always permit. return Accept } if len(b) < 20 { - logRateLimit(rf, b, nil, Drop, "too short") + f.logRateLimit(rf, b, nil, Drop, "too short") return Drop } q.Decode(b) if q.IPProto == packet.Junk { // Junk packets are dangerous; always drop them. - logRateLimit(rf, b, q, Drop, "junk!") + f.logRateLimit(rf, b, q, Drop, "junk!") return Drop } else if q.IPProto == packet.Fragment { // Fragments after the first always need to be passed through. // Very small fragments are considered Junk by QDecode. - logRateLimit(rf, b, q, Accept, "fragment") + f.logRateLimit(rf, b, q, Accept, "fragment") return Accept } diff --git a/wgengine/filter/filter_test.go b/wgengine/filter/filter_test.go index 2eaa3e797..8a2b25756 100644 --- a/wgengine/filter/filter_test.go +++ b/wgengine/filter/filter_test.go @@ -55,7 +55,7 @@ func TestFilter(t *testing.T) { {Srcs: []Net{NetAny}, Dsts: netpr(0, 0, 443, 443)}, {Srcs: nets([]IP{0x99010101, 0x99010102, 0x99030303}), Dsts: ippr(0x01020304, 999, 999)}, } - acl := New(mm, nil) + acl := New(mm, nil, t.Logf) for _, ent := range []Matches{Matches{mm[0]}, mm} { b, err := json.Marshal(ent) @@ -119,8 +119,9 @@ func TestPreFilter(t *testing.T) { {"udp", noVerdict, rawpacket(UDP, 200)}, {"icmp", noVerdict, rawpacket(ICMP, 200)}, } + f := NewAllowNone(t.Logf) for _, testPacket := range packets { - got := pre([]byte(testPacket.b), &QDecode{}, LogDrops|LogAccepts) + got := f.pre([]byte(testPacket.b), &QDecode{}, LogDrops|LogAccepts) if got != testPacket.want { t.Errorf("%q got=%v want=%v packet:\n%s", testPacket.desc, got, testPacket.want, packet.Hexdump(testPacket.b)) } diff --git a/wgengine/magicsock/magicsock.go b/wgengine/magicsock/magicsock.go index a95a6c5f3..d177a01f4 100644 --- a/wgengine/magicsock/magicsock.go +++ b/wgengine/magicsock/magicsock.go @@ -14,7 +14,6 @@ import ( "errors" "fmt" "hash/fnv" - "log" "math/rand" "net" "os" @@ -189,7 +188,7 @@ var DisableSTUNForTesting bool // Options contains options for Listen. type Options struct { // Logf optionally provides a log function to use. - // If nil, log.Printf is used. + // Must not be nil. Logf logger.Logf // Port is the port to listen on. @@ -207,10 +206,10 @@ type Options struct { } func (o *Options) logf() logger.Logf { - if o.Logf != nil { - return o.Logf + if o.Logf == nil { + panic("must provide magicsock.Options.logf") } - return log.Printf + return o.Logf } func (o *Options) endpointsFunc() func([]string) { @@ -652,7 +651,7 @@ func (as *AddrSet) appendDests(dsts []*net.UDPAddr, b []byte) (_ []*net.UDPAddr, dsts = append(dsts, as.roamAddr) case as.curAddr != -1: if as.curAddr >= len(as.addrs) { - log.Printf("[unexpected] magicsock bug: as.curAddr >= len(as.addrs): %d >= %d", as.curAddr, len(as.addrs)) + as.Logf("[unexpected] magicsock bug: as.curAddr >= len(as.addrs): %d >= %d", as.curAddr, len(as.addrs)) break } // No roaming addr, but we've seen packets from a known peer @@ -668,7 +667,7 @@ func (as *AddrSet) appendDests(dsts []*net.UDPAddr, b []byte) (_ []*net.UDPAddr, } if logPacketDests { - log.Printf("spray=%v; roam=%v; dests=%v", spray, as.roamAddr, dsts) + as.Logf("spray=%v; roam=%v; dests=%v", spray, as.roamAddr, dsts) } return dsts, as.roamAddr } @@ -1581,7 +1580,7 @@ type AddrSet struct { // clock, if non-nil, is used in tests instead of time.Now. clock func() time.Time - Logf logger.Logf // Logf, if non-nil, is used instead of log.Printf + Logf logger.Logf // must not be nil mu sync.Mutex // guards following fields @@ -1622,14 +1621,6 @@ func (as *AddrSet) timeNow() time.Time { return time.Now() } -func (as *AddrSet) logf(format string, args ...interface{}) { - if as.Logf != nil { - as.Logf(format, args...) - } else { - log.Printf(format, args...) - } -} - var noAddr = &net.UDPAddr{ IP: net.ParseIP("127.127.127.127"), Port: 127, @@ -1720,26 +1711,26 @@ func (a *AddrSet) UpdateDst(new *net.UDPAddr) error { switch { case index == -1: if a.roamAddr == nil { - a.logf("magicsock: rx %s from roaming address %s, set as new priority", pk, new) + a.Logf("magicsock: rx %s from roaming address %s, set as new priority", pk, new) } else { - a.logf("magicsock: rx %s from roaming address %s, replaces roaming address %s", pk, new, a.roamAddr) + a.Logf("magicsock: rx %s from roaming address %s, replaces roaming address %s", pk, new, a.roamAddr) } a.roamAddr = new case a.roamAddr != nil: - a.logf("magicsock: rx %s from known %s (%d), replaces roaming address %s", pk, new, index, a.roamAddr) + a.Logf("magicsock: rx %s from known %s (%d), replaces roaming address %s", pk, new, index, a.roamAddr) a.roamAddr = nil a.curAddr = index case a.curAddr == -1: - a.logf("magicsock: rx %s from %s (%d/%d), set as new priority", pk, new, index, len(a.addrs)) + a.Logf("magicsock: rx %s from %s (%d/%d), set as new priority", pk, new, index, len(a.addrs)) a.curAddr = index case index < a.curAddr: - a.logf("magicsock: rx %s from low-pri %s (%d), keeping current %s (%d)", pk, new, index, old, a.curAddr) + a.Logf("magicsock: rx %s from low-pri %s (%d), keeping current %s (%d)", pk, new, index, old, a.curAddr) default: // index > a.curAddr - a.logf("magicsock: rx %s from %s (%d/%d), replaces old priority %s", pk, new, index, len(a.addrs), old) + a.Logf("magicsock: rx %s from %s (%d/%d), replaces old priority %s", pk, new, index, len(a.addrs), old) a.curAddr = index } @@ -1806,6 +1797,7 @@ func (c *Conn) CreateEndpoint(pubKey [32]byte, addrs string) (conn.Endpoint, err pk := key.Public(pubKey) c.logf("magicsock: CreateEndpoint: key=%s: %s", pk.ShortString(), strings.ReplaceAll(addrs, "127.3.3.40:", "derp-")) a := &AddrSet{ + Logf: c.logf, publicKey: pk, curAddr: -1, } diff --git a/wgengine/magicsock/magicsock_test.go b/wgengine/magicsock/magicsock_test.go index ba9935343..c3f87591c 100644 --- a/wgengine/magicsock/magicsock_test.go +++ b/wgengine/magicsock/magicsock_test.go @@ -26,6 +26,7 @@ import ( "tailscale.com/derp/derphttp" "tailscale.com/derp/derpmap" "tailscale.com/stun/stuntest" + "tailscale.com/tstest" "tailscale.com/types/key" "tailscale.com/types/logger" "tailscale.com/wgengine/filter" @@ -33,6 +34,7 @@ import ( ) func TestListen(t *testing.T) { + tstest.PanicOnLog() epCh := make(chan string, 16) epFunc := func(endpoints []string) { @@ -94,6 +96,8 @@ func pickPort(t *testing.T) uint16 { } func TestDerpIPConstant(t *testing.T) { + tstest.PanicOnLog() + if DerpMagicIP != derpMagicIP.String() { t.Errorf("str %q != IP %v", DerpMagicIP, derpMagicIP) } @@ -103,6 +107,8 @@ func TestDerpIPConstant(t *testing.T) { } func TestPickDERPFallback(t *testing.T) { + tstest.PanicOnLog() + c := &Conn{ derps: derpmap.Prod(), } @@ -203,18 +209,19 @@ func parseCIDR(t *testing.T, addr string) wgcfg.CIDR { return cidr } -func runDERP(t *testing.T) (s *derp.Server, addr string, cleanupFn func()) { +func runDERP(t *testing.T, logf logger.Logf) (s *derp.Server, addr string, cleanupFn func()) { var serverPrivateKey key.Private if _, err := crand.Read(serverPrivateKey[:]); err != nil { t.Fatal(err) } - s = derp.NewServer(serverPrivateKey, t.Logf) + s = derp.NewServer(serverPrivateKey, logf) httpsrv := httptest.NewUnstartedServer(derphttp.Handler(s)) + httpsrv.Config.ErrorLog = logger.StdLogger(logf) httpsrv.Config.TLSNextProto = make(map[string]func(*http.Server, *tls.Conn, http.Handler)) httpsrv.StartTLS() - t.Logf("DERP server URL: %s", httpsrv.URL) + logf("DERP server URL: %s", httpsrv.URL) addr = strings.TrimPrefix(httpsrv.URL, "https://") cleanupFn = func() { @@ -228,11 +235,11 @@ func runDERP(t *testing.T) (s *derp.Server, addr string, cleanupFn func()) { // devLogger returns a wireguard-go device.Logger that writes // wireguard logs to the test logger. -func devLogger(t *testing.T, prefix string) *device.Logger { +func devLogger(t *testing.T, prefix string, logfx logger.Logf) *device.Logger { pfx := []interface{}{prefix} logf := func(format string, args ...interface{}) { t.Helper() - t.Logf("%s: "+format, append(pfx, args...)...) + logfx("%s: "+format, append(pfx, args...)...) } return &device.Logger{ Debug: logger.StdLogger(logf), @@ -248,6 +255,8 @@ func devLogger(t *testing.T, prefix string) *device.Logger { // or shutdown. It may be an infrequent flake, so run with // -count=10000 to be sure. func TestDeviceStartStop(t *testing.T) { + tstest.PanicOnLog() + conn, err := Listen(Options{ EndpointsFunc: func(eps []string) {}, Logf: t.Logf, @@ -259,7 +268,7 @@ func TestDeviceStartStop(t *testing.T) { tun := tuntest.NewChannelTUN() dev := device.NewDevice(tun.TUN(), &device.DeviceOptions{ - Logger: devLogger(t, "dev"), + Logger: devLogger(t, "dev", t.Logf), CreateEndpoint: conn.CreateEndpoint, CreateBind: conn.CreateBind, SkipBindUpdate: true, @@ -269,9 +278,19 @@ func TestDeviceStartStop(t *testing.T) { } func TestTwoDevicePing(t *testing.T) { + tstest.PanicOnLog() + + // This gets reassigned inside every test, so that the connections + // all log using the "current" t.Logf function. Sigh. + current_t := t + logf := func(s string, args ...interface{}) { + current_t.Helper() + current_t.Logf(s, args...) + } + // Wipe default DERP list, add local server. // (Do it now, or derpHost will try to connect to derp1.tailscale.com.) - derpServer, derpAddr, derpCleanupFn := runDERP(t) + derpServer, derpAddr, derpCleanupFn := runDERP(t, logf) defer derpCleanupFn() stunAddr, stunCleanupFn := stuntest.Serve(t) @@ -286,7 +305,7 @@ func TestTwoDevicePing(t *testing.T) { epCh1 := make(chan []string, 16) conn1, err := Listen(Options{ - Logf: logger.WithPrefix(t.Logf, "conn1: "), + Logf: logger.WithPrefix(logf, "conn1: "), DERPs: derps, EndpointsFunc: func(eps []string) { epCh1 <- eps @@ -300,7 +319,7 @@ func TestTwoDevicePing(t *testing.T) { epCh2 := make(chan []string, 16) conn2, err := Listen(Options{ - Logf: logger.WithPrefix(t.Logf, "conn2: "), + Logf: logger.WithPrefix(logf, "conn2: "), DERPs: derps, EndpointsFunc: func(eps []string) { epCh2 <- eps @@ -323,15 +342,15 @@ func TestTwoDevicePing(t *testing.T) { } //uapi1, _ := cfgs[0].ToUAPI() - //t.Logf("cfg0: %v", uapi1) + //logf("cfg0: %v", uapi1) //uapi2, _ := cfgs[1].ToUAPI() - //t.Logf("cfg1: %v", uapi2) + //logf("cfg1: %v", uapi2) tun1 := tuntest.NewChannelTUN() - tstun1 := tstun.WrapTUN(t.Logf, tun1.TUN()) - tstun1.SetFilter(filter.NewAllowAll()) + tstun1 := tstun.WrapTUN(logf, tun1.TUN()) + tstun1.SetFilter(filter.NewAllowAll(logf)) dev1 := device.NewDevice(tstun1, &device.DeviceOptions{ - Logger: devLogger(t, "dev1"), + Logger: devLogger(t, "dev1", logf), CreateEndpoint: conn1.CreateEndpoint, CreateBind: conn1.CreateBind, SkipBindUpdate: true, @@ -343,10 +362,10 @@ func TestTwoDevicePing(t *testing.T) { defer dev1.Close() tun2 := tuntest.NewChannelTUN() - tstun2 := tstun.WrapTUN(t.Logf, tun2.TUN()) - tstun2.SetFilter(filter.NewAllowAll()) + tstun2 := tstun.WrapTUN(logf, tun2.TUN()) + tstun2.SetFilter(filter.NewAllowAll(logf)) dev2 := device.NewDevice(tstun2, &device.DeviceOptions{ - Logger: devLogger(t, "dev2"), + Logger: devLogger(t, "dev2", logf), CreateEndpoint: conn2.CreateEndpoint, CreateBind: conn2.CreateBind, SkipBindUpdate: true, @@ -387,9 +406,19 @@ func TestTwoDevicePing(t *testing.T) { } } - t.Run("ping 1.0.0.1", func(t *testing.T) { ping1(t) }) - t.Run("ping 1.0.0.2", func(t *testing.T) { ping2(t) }) + t.Run("ping 1.0.0.1", func(t *testing.T) { + current_t = t + ping1(t) + }) + current_t = t + + t.Run("ping 1.0.0.2", func(t *testing.T) { + ping2(t) + }) + current_t = t + t.Run("ping 1.0.0.2 via SendPacket", func(t *testing.T) { + current_t = t msg1to2 := tuntest.Ping(net.ParseIP("1.0.0.2"), net.ParseIP("1.0.0.1")) if err := tstun1.InjectOutbound(msg1to2); err != nil { t.Fatal(err) @@ -403,14 +432,17 @@ func TestTwoDevicePing(t *testing.T) { t.Error("return ping did not transit") } }) + current_t = t t.Run("no-op dev1 reconfig", func(t *testing.T) { + current_t = t if err := dev1.Reconfig(&cfgs[0]); err != nil { t.Fatal(err) } ping1(t) ping2(t) }) + current_t = t if os.Getenv("RUN_CURSED_TESTS") == "" { t.Skip("test is very broken, don't run in CI until it's reliable.") @@ -469,8 +501,10 @@ func TestTwoDevicePing(t *testing.T) { } t.Run("ping 1.0.0.1 x50", func(t *testing.T) { + current_t = t pingSeq(t, 50, 0, true) }) + current_t = t // Add DERP relay. derpEp := wgcfg.Endpoint{Host: "127.3.3.40", Port: 1} @@ -488,11 +522,13 @@ func TestTwoDevicePing(t *testing.T) { } t.Run("add DERP", func(t *testing.T) { + current_t = t defer func() { - t.Logf("DERP vars: %s", derpServer.ExpVar().String()) + logf("DERP vars: %s", derpServer.ExpVar().String()) }() pingSeq(t, 20, 0, true) }) + current_t = t // Disable real route. cfgs[0].Peers[0].Endpoints = []wgcfg.Endpoint{derpEp} @@ -506,17 +542,19 @@ func TestTwoDevicePing(t *testing.T) { time.Sleep(250 * time.Millisecond) // TODO remove t.Run("all traffic over DERP", func(t *testing.T) { + current_t = t defer func() { - t.Logf("DERP vars: %s", derpServer.ExpVar().String()) + logf("DERP vars: %s", derpServer.ExpVar().String()) if t.Failed() || true { uapi1, _ := cfgs[0].ToUAPI() - t.Logf("cfg0: %v", uapi1) + logf("cfg0: %v", uapi1) uapi2, _ := cfgs[1].ToUAPI() - t.Logf("cfg1: %v", uapi2) + logf("cfg1: %v", uapi2) } }() pingSeq(t, 20, 0, true) }) + current_t = t dev1.RemoveAllPeers() dev2.RemoveAllPeers() @@ -540,6 +578,7 @@ func TestTwoDevicePing(t *testing.T) { // // TODO(danderson): finish root-causing and de-flake this test. t.Run("one real route is enough thanks to spray", func(t *testing.T) { + current_t = t pingSeq(t, 50, 700*time.Millisecond, false) ep2 := dev2.Config().Peers[0].Endpoints @@ -547,10 +586,21 @@ func TestTwoDevicePing(t *testing.T) { t.Error("handshake spray failed to find real route") } }) + current_t = t } // TestAddrSet tests AddrSet appendDests and UpdateDst. func TestAddrSet(t *testing.T) { + tstest.PanicOnLog() + + // This gets reassigned inside every test, so that the connections + // all log using the "current" t.Logf function. Sigh. + current_t := t + logf := func(s string, args ...interface{}) { + current_t.Helper() + current_t.Logf(s, args...) + } + mustUDPAddr := func(s string) *net.UDPAddr { t.Helper() ua, err := net.ResolveUDPAddr("udp", s) @@ -674,8 +724,9 @@ func TestAddrSet(t *testing.T) { } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { + current_t = t faket := time.Unix(0, 0) - tt.as.Logf = t.Logf + tt.as.Logf = logf tt.as.clock = func() time.Time { return faket } for i, st := range tt.steps { faket = faket.Add(st.advance) @@ -692,5 +743,6 @@ func TestAddrSet(t *testing.T) { } } }) + current_t = t } } diff --git a/wgengine/userspace.go b/wgengine/userspace.go index 9f65dbf3b..1e51f2013 100644 --- a/wgengine/userspace.go +++ b/wgengine/userspace.go @@ -145,6 +145,7 @@ func newUserspaceEngineAdvanced(logf logger.Logf, tundev *tstun.TUN, routerGen R e.RequestStatus() } magicsockOpts := magicsock.Options{ + Logf: logf, Port: listenPort, EndpointsFunc: endpointsFn, }