From 08acb502e54d3731ccbd8c334973cece1cebd27c Mon Sep 17 00:00:00 2001
From: Avery Pennarun <apenwarr@tailscale.com>
Date: Wed, 13 May 2020 22:59:54 -0400
Subject: [PATCH] Add tstest.PanicOnLog(), and fix various problems detected by
 this.

If a test calls log.Printf, 'go test' horrifyingly rearranges the
output to no longer be in chronological order, which makes debugging
virtually impossible. Let's stop that from happening by making
log.Printf panic if called from any module, no matter how deep, during
tests.

This required us to change the default error handler in at least one
http.Server, as well as plumbing a bunch of logf functions around,
especially in magicsock and wgengine, but also in logtail and backoff.

To add insult to injury, 'go test' also rearranges the output when a
parent test has multiple sub-tests (all the sub-test's t.Logf is always
printed after all the parent tests t.Logf), so we need to screw around
with a special Logf that can point at the "current" t (current_t.Logf)
in some places. Probably our entire way of using subtests is wrong,
since 'go test' would probably like to run them all in parallel if you
called t.Parallel(), but it definitely can't because the're all
manipulating the shared state created by the parent test. They should
probably all be separate toplevel tests instead, with common
setup/teardown logic. But that's a job for another time.

Signed-off-by: Avery Pennarun <apenwarr@tailscale.com>
---
 control/controlclient/auto.go        |   4 +-
 control/controlclient/auto_test.go   |   7 +-
 ipn/e2e_test.go                      |  48 +++++++++----
 ipn/ipnserver/server.go              |   4 +-
 ipn/local.go                         |   8 +--
 ipn/message_test.go                  |   6 +-
 ipn/prefs_test.go                    |   7 ++
 ipn/store_test.go                    |   6 ++
 logpolicy/logpolicy.go               |   2 +-
 logtail/backoff/backoff.go           |  23 +++---
 logtail/logtail.go                   |   7 +-
 logtail/logtail_test.go              |   2 +-
 tstest/log.go                        |  12 ++++
 wgengine/filter/filter.go            |  36 +++++-----
 wgengine/filter/filter_test.go       |   5 +-
 wgengine/magicsock/magicsock.go      |  36 ++++------
 wgengine/magicsock/magicsock_test.go | 100 ++++++++++++++++++++-------
 wgengine/userspace.go                |   1 +
 18 files changed, 206 insertions(+), 108 deletions(-)

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,
 	}