ipn/ipnlocal: add back a watchdog after earlier removal from engine

Commit 2b338dd6a8 removed watchdogEngine because it was weird
(so many methods) and increasingly unnecessary after we'd cleaned up
and simplified so much of the locking.

This adds back a watchdog, but an easier to maintain one that's more
idiomatic.

Updates #19759

Change-Id: I86c458473e126c0809f37696446ce7acf4cc4eb9
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>

ipn/ipnlocal/local.go

@@ -281,6 +281,11 @@ type LocalBackend struct {
 	shouldInterceptTCPPortAtomic            syncs.AtomicValue[func(uint16) bool]         // TODO(nickkhyl): move to nodeBackend
 	shouldInterceptVIPServicesTCPPortAtomic syncs.AtomicValue[func(netip.AddrPort) bool] // TODO(nickkhyl): move to nodeBackend
 	numClientStatusCalls                    atomic.Uint32                                // TODO(nickkhyl): move to nodeBackend
+	lastDeadlockCheckUnix                   atomic.Int64
+	deadlockChecksInFlight                  atomic.Int64
+	deadlockTimerMu                         sync.Mutex
+	deadlockTimer                           *time.Timer
+	deadlockProbeTimer                      *time.Timer
 
 	// goTracker accounts for all goroutines started by LocalBacked, primarily
 	// for testing and graceful shutdown purposes.
@@ -1269,6 +1274,8 @@ func (b *LocalBackend) ClearCaptureSink() {
 // Shutdown halts the backend and all its sub-components. The backend
 // can no longer be used after Shutdown returns.
 func (b *LocalBackend) Shutdown() {
+	defer b.CheckDeadlocks()()
+
 	// Close the [eventbus.Client] to wait for subscribers to
 	// return before acquiring b.mu:
 	//  1. Event handlers also acquire b.mu, they can deadlock with c.Shutdown().
@@ -1786,6 +1793,8 @@ func (b *LocalBackend) GetFilterForTest() *filter.Filter {
 // SetControlClientStatus is the callback invoked by the control client whenever it posts a new status.
 // Among other things, this is where we update the netmap, packet filters, DNS and DERP maps.
 func (b *LocalBackend) SetControlClientStatus(c controlclient.Client, st controlclient.Status) {
+	defer b.CheckDeadlocks()()
+
 	if b.ignoreControlClientUpdates.Load() {
 		b.logf("ignoring SetControlClientStatus during controlclient shutdown")
 		return
@@ -2330,6 +2339,8 @@ func (b *LocalBackend) reconcilePrefs() (_ ipn.PrefsView, anyChange bool) {
 // sysPolicyChanged is a callback triggered by syspolicy when it detects
 // a change in one or more syspolicy settings.
 func (b *LocalBackend) sysPolicyChanged(policy policyclient.PolicyChange) {
+	defer b.CheckDeadlocks()()
+
 	if policy.HasChangedAnyOf(pkey.AlwaysOn, pkey.AlwaysOnOverrideWithReason) {
 		// If the AlwaysOn or the AlwaysOnOverrideWithReason policy has changed,
 		// we should reset the overrideAlwaysOn flag, as the override might
@@ -2370,6 +2381,8 @@ var (
 
 // UpdateNetmapDelta implements controlclient.NetmapDeltaUpdater.
 func (b *LocalBackend) UpdateNetmapDelta(muts []netmap.NodeMutation) (handled bool) {
+	defer b.CheckDeadlocks()()
+
 	var notify *ipn.Notify // non-nil if we need to send a Notify
 	defer func() {
 		if notify != nil {
@@ -2504,6 +2517,8 @@ func peerRouteConfigChanged(old, new tailcfg.NodeView) bool {
 // filter. Avoiding a full netmap rebuild matters here because the packet
 // filter currently changes on every peer add on large tailnets.
 func (b *LocalBackend) UpdatePacketFilter(rules views.Slice[tailcfg.FilterRule], parsed []filter.Match) bool {
+	defer b.CheckDeadlocks()()
+
 	b.mu.Lock()
 	defer b.mu.Unlock()
 	cn := b.currentNode()
@@ -2533,6 +2548,8 @@ func (b *LocalBackend) UpdatePacketFilter(rules views.Slice[tailcfg.FilterRule],
 // caller's tracking map; nodeBackend stores them as-is, and per-bus
 // sessions can dedup via [UserProfileView.Equal] without copying.
 func (b *LocalBackend) UpdateUserProfiles(profiles map[tailcfg.UserID]tailcfg.UserProfileView) bool {
+	defer b.CheckDeadlocks()()
+
 	if len(profiles) == 0 {
 		return true
 	}
@@ -2885,6 +2902,8 @@ func (b *LocalBackend) controlDebugFlags() []string {
 // actually a supported operation (it should be, but it's very unclear
 // from the following whether or not that is a safe transition).
 func (b *LocalBackend) Start(opts ipn.Options) error {
+	defer b.CheckDeadlocks()()
+
 	b.mu.Lock()
 	defer b.mu.Unlock()
 	return b.startLocked(opts)
@@ -3601,6 +3620,10 @@ func (b *LocalBackend) WatchNotificationsAs(ctx context.Context, actor ipnauth.A
 		b.e.UpdateStatus(statusSB)
 	}
 
+	// Watch for deadlocks only during the registration phase below; the rest
+	// of this method blocks on ctx (often for hours) and shouldn't trip the
+	// watchdog.
+	deadlockDone := b.CheckDeadlocks()
 	b.mu.Lock()
 
 	const initialBits = ipn.NotifyInitialState | ipn.NotifyInitialPrefs | ipn.NotifyInitialNetMap | ipn.NotifyInitialStatus | ipn.NotifyInitialDriveShares | ipn.NotifyInitialSuggestedExitNode | ipn.NotifyInitialClientVersion
@@ -3661,6 +3684,7 @@ func (b *LocalBackend) WatchNotificationsAs(ctx context.Context, actor ipnauth.A
 	}
 	mak.Set(&b.notifyWatchers, sessionID, session)
 	b.mu.Unlock()
+	deadlockDone()
 
 	metricCurrentWatchIPNBus.Add(1)
 	defer metricCurrentWatchIPNBus.Add(-1)

ipn/ipnlocal/watchdog.go

@@ -0,0 +1,159 @@
+// Copyright (c) Tailscale Inc & contributors
+// SPDX-License-Identifier: BSD-3-Clause
+
+package ipnlocal
+
+import (
+	"log"
+	"net/netip"
+	"runtime"
+	"time"
+
+	"tailscale.com/tstime"
+)
+
+// deadlockProbeDelay is how long a watched call must be in flight before we
+// start probing locks to check for a deadlock. Calls that complete sooner do
+// not trigger any probing.
+const deadlockProbeDelay = 5 * time.Second
+
+// deadlockTimeout is how long the lock-probing goroutine is allowed to run
+// before we declare a deadlock and panic with goroutine stacks. That is, it's
+// the maximum total time we allow any of the probed locks to be held.
+const deadlockTimeout = 30 * time.Second
+
+// CheckDeadlocks schedules a delayed deadlock probe and returns a function to
+// call when the operation being watched is done. Callers typically use it as
+// "defer b.CheckDeadlocks()()" to bracket a region of code that should not
+// take more than [deadlockProbeDelay].
+//
+// This is a backstop for detecting and debugging deadlocks in the process, replacing
+// the earlier watchdogEngine removed in 2b338dd6a8dbd.
+func (b *LocalBackend) CheckDeadlocks() (done func()) {
+	// Bump the in-flight count. If a watched region is already open, the
+	// probe timer is already armed, so the bump is all we need to do: the
+	// matching doneDeadlockCheck will decrement when this caller returns and
+	// only the last one out will stop the timer.
+	if b.deadlockChecksInFlight.Add(1) != 1 {
+		return b.doneDeadlockCheck
+	}
+
+	// Fast path to avoid the deadlockTimerMu+Timer.Reset cost when
+	// CheckDeadlocks is called many times per second by non-overlapping
+	// callers: re-arm the probe timer at most once per wall-clock second.
+	// We use a unix-seconds timestamp (+1 so 0 can mean "never") and a CAS
+	// so that only one caller per second proceeds to touch the timer; the
+	// rest return early.
+	nowUnix := tstime.DefaultClock{Clock: b.Clock()}.Now().Unix() + 1
+	lastUnix := b.lastDeadlockCheckUnix.Load()
+	if lastUnix == nowUnix || !b.lastDeadlockCheckUnix.CompareAndSwap(lastUnix, nowUnix) {
+		return b.doneDeadlockCheck
+	}
+
+	// Slow path: (re)arm the probe timer. Lazily create it on first use.
+	b.deadlockTimerMu.Lock()
+	defer b.deadlockTimerMu.Unlock()
+
+	t := b.deadlockProbeTimer
+	if t == nil {
+		t = time.AfterFunc(deadlockProbeDelay, b.runDeadlockProbe)
+		b.deadlockProbeTimer = t
+	} else {
+		t.Reset(deadlockProbeDelay)
+	}
+	return b.doneDeadlockCheck
+}
+
+func (b *LocalBackend) doneDeadlockCheck() {
+	switch n := b.deadlockChecksInFlight.Add(-1); {
+	case n > 0:
+		return
+	case n < 0:
+		panic("ipnlocal: doneDeadlockCheck called without matching CheckDeadlocks")
+	}
+
+	b.deadlockTimerMu.Lock()
+	defer b.deadlockTimerMu.Unlock()
+	if b.deadlockProbeTimer == nil {
+		return
+	}
+	b.deadlockProbeTimer.Stop()
+}
+
+func (b *LocalBackend) runDeadlockProbe() {
+	b.deadlockTimerMu.Lock()
+	defer b.deadlockTimerMu.Unlock()
+
+	if b.deadlockChecksInFlight.Load() == 0 {
+		return
+	}
+
+	t := b.deadlockTimer
+	if t == nil {
+		t = time.AfterFunc(deadlockTimeout, b.reportDeadlock)
+		b.deadlockTimer = t
+	} else {
+		t.Reset(deadlockTimeout)
+	}
+	defer t.Stop()
+
+	b.probeLocks()
+}
+
+func (b *LocalBackend) probeLocks() {
+	b.probeLocalBackendLock()
+
+	sys := b.sys
+	if sys == nil {
+		return
+	}
+	if bus, ok := sys.Bus.GetOK(); ok && bus != nil {
+		bus.ProbeLocks()
+	}
+	if dialer, ok := sys.Dialer.GetOK(); ok && dialer != nil {
+		dialer.ProbeLocks()
+	}
+	if dm, ok := sys.DNSManager.GetOK(); ok && dm != nil {
+		dm.ProbeLocks()
+	}
+	if e, ok := sys.Engine.GetOK(); ok && e != nil {
+		e.PeerForIP(netip.Addr{}) // acquires e.mu and e.wgLock
+	}
+	if nm, ok := sys.NetMon.GetOK(); ok && nm != nil {
+		nm.ProbeLocks()
+	}
+	if mc, ok := sys.MagicSock.GetOK(); ok && mc != nil {
+		mc.ProbeLocks()
+	}
+	if tun, ok := sys.Tun.GetOK(); ok && tun != nil {
+		tun.ProbeLocks()
+	}
+	if ht, ok := sys.HealthTracker.GetOK(); ok && ht != nil {
+		ht.ProbeLocks()
+	}
+}
+
+func (b *LocalBackend) probeLocalBackendLock() {
+	b.mu.Lock()
+	defer b.mu.Unlock()
+}
+
+func (b *LocalBackend) reportDeadlock() {
+	logf := b.logf
+	if logf == nil {
+		logf = log.Printf
+	}
+	logf("ipnlocal watchdog goroutine stacks:\n%s", goroutineStacks())
+	panic("ipnlocal: watchdog timeout")
+}
+
+func goroutineStacks() []byte {
+	buf := make([]byte, 256<<10)
+	for {
+		n := runtime.Stack(buf, true)
+		if n < len(buf) {
+			return buf[:n]
+		}
+		buf = make([]byte, 2*len(buf))
+	}
+}

ipn/ipnlocal/watchdog_test.go

@@ -0,0 +1,64 @@
+// Copyright (c) Tailscale Inc & contributors
+// SPDX-License-Identifier: BSD-3-Clause
+
+package ipnlocal
+
+import (
+	"testing"
+	"time"
+
+	"tailscale.com/tstest"
+)
+
+func TestCheckDeadlocksRateLimitAndTimerReuse(t *testing.T) {
+	clock := tstest.NewClock(tstest.ClockOpts{Start: time.Unix(123, 0)})
+	b := &LocalBackend{clock: clock}
+
+	done := b.CheckDeadlocks()
+	if b.lastDeadlockCheckUnix.Load() != 124 {
+		t.Fatalf("lastDeadlockCheckUnix = %v, want 124", b.lastDeadlockCheckUnix.Load())
+	}
+	timer := b.deadlockProbeTimer
+	if timer == nil {
+		t.Fatal("deadlockProbeTimer is nil")
+	}
+	if b.deadlockTimer != nil {
+		t.Fatal("deadlockTimer is non-nil before delayed probe fires")
+	}
+	if got := b.deadlockChecksInFlight.Load(); got != 1 {
+		t.Fatalf("deadlockChecksInFlight = %v, want 1", got)
+	}
+	done()
+	if b.deadlockChecksInFlight.Load() != 0 {
+		t.Fatalf("deadlockChecksInFlight after DoneDeadlockCheck = %v, want 0", b.deadlockChecksInFlight.Load())
+	}
+
+	doneCh := make(chan struct{})
+	go func() {
+		b.CheckDeadlocks()()
+		close(doneCh)
+	}()
+	select {
+	case <-doneCh:
+	case <-time.After(1 * time.Second):
+		t.Fatal("same-second CheckDeadlocks did not take the rate-limit fast path")
+	}
+	if b.deadlockProbeTimer != timer {
+		t.Fatal("same-second CheckDeadlocks allocated a new probe timer")
+	}
+
+	clock.Advance(time.Second)
+	done = b.CheckDeadlocks()
+	if b.deadlockProbeTimer != timer {
+		t.Fatal("CheckDeadlocks allocated a new probe timer instead of reusing the existing one")
+	}
+	if got := b.deadlockChecksInFlight.Load(); got != 1 {
+		t.Fatalf("deadlockChecksInFlight = %v, want 1", got)
+	}
+
+	b.runDeadlockProbe()
+	if b.deadlockTimer == nil {
+		t.Fatal("runDeadlockProbe did not allocate the deadlock timer")
+	}
+	done()
+}

ipn/localapi/localapi.go

@@ -267,6 +267,7 @@ func (h *Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 			return
 		}
 	}
+	defer h.b.CheckDeadlocks()()
 	if fn, route, ok := handlerForPath(r.URL.Path); ok {
 		h.logRequest(r.Method, route)
 		fn(h, w, r)