From 52400dc6f47e1b03f886b41c795871b14e03673e Mon Sep 17 00:00:00 2001 From: Brad Fitzpatrick Date: Tue, 2 Jun 2026 09:16:56 -0700 Subject: [PATCH] ipn/ipnlocal: add back a watchdog after earlier removal from engine Commit 2b338dd6a8dbd7 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 --- health/health.go | 9 ++ ipn/ipnlocal/local.go | 24 +++++ ipn/ipnlocal/watchdog.go | 159 ++++++++++++++++++++++++++++++++ ipn/ipnlocal/watchdog_test.go | 64 +++++++++++++ ipn/localapi/localapi.go | 1 + net/dns/manager.go | 10 ++ net/dns/resolver/forwarder.go | 5 + net/dns/resolver/tsdns.go | 10 ++ net/netmon/netmon.go | 6 ++ net/tsdial/tsdial.go | 6 ++ net/tstun/wrap.go | 9 ++ util/eventbus/bus.go | 9 ++ wgengine/magicsock/magicsock.go | 6 ++ wgengine/userspace.go | 11 +++ 14 files changed, 329 insertions(+) create mode 100644 ipn/ipnlocal/watchdog.go create mode 100644 ipn/ipnlocal/watchdog_test.go diff --git a/health/health.go b/health/health.go index 7e2878159..00dbe9979 100644 --- a/health/health.go +++ b/health/health.go @@ -353,6 +353,15 @@ func (t *Tracker) nil() bool { return true } +// ProbeLocks acquires and releases the tracker's internal mutex. +func (t *Tracker) ProbeLocks() { + if t.nil() { + return + } + t.mu.Lock() + t.mu.Unlock() +} + // Severity represents how serious an error is. Each GUI interprets this severity value in different ways, // to surface the error in a more or less visible way. For instance, the macOS GUI could change its menubar // icon to display an exclamation mark and present a modal notification for SeverityHigh warnings, but not diff --git a/ipn/ipnlocal/local.go b/ipn/ipnlocal/local.go index 31ca7f941..7b2b00b50 100644 --- a/ipn/ipnlocal/local.go +++ b/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) diff --git a/ipn/ipnlocal/watchdog.go b/ipn/ipnlocal/watchdog.go new file mode 100644 index 000000000..676852cd4 --- /dev/null +++ b/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)) + } +} diff --git a/ipn/ipnlocal/watchdog_test.go b/ipn/ipnlocal/watchdog_test.go new file mode 100644 index 000000000..b93a09b2b --- /dev/null +++ b/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() +} diff --git a/ipn/localapi/localapi.go b/ipn/localapi/localapi.go index 8ce9acfd0..d4aca16b6 100644 --- a/ipn/localapi/localapi.go +++ b/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) diff --git a/net/dns/manager.go b/net/dns/manager.go index 0010905a5..6c574659b 100644 --- a/net/dns/manager.go +++ b/net/dns/manager.go @@ -131,6 +131,16 @@ func (m *Manager) Resolver() *resolver.Resolver { return m.resolver } +// ProbeLocks acquires and releases the manager's internal mutexes. +func (m *Manager) ProbeLocks() { + m.mu.Lock() + m.mu.Unlock() + + if r := m.Resolver(); r != nil { + r.ProbeLocks() + } +} + // RecompileDNSConfig recompiles the last attempted DNS configuration, which has // the side effect of re-querying the OS's interface nameservers. This should be used // on platforms where the interface nameservers can change. Darwin, for example, diff --git a/net/dns/resolver/forwarder.go b/net/dns/resolver/forwarder.go index 3f586b60f..d1d880af4 100644 --- a/net/dns/resolver/forwarder.go +++ b/net/dns/resolver/forwarder.go @@ -347,6 +347,11 @@ type forwarder struct { acceptDNS bool } +func (f *forwarder) probeLocks() { + f.mu.Lock() + f.mu.Unlock() +} + func newForwarder(logf logger.Logf, netMon *netmon.Monitor, linkSel ForwardLinkSelector, dialer *tsdial.Dialer, health *health.Tracker, knobs *controlknobs.Knobs) *forwarder { if !buildfeatures.HasDNS { return nil diff --git a/net/dns/resolver/tsdns.go b/net/dns/resolver/tsdns.go index 4b2db5705..8a0ce2f48 100644 --- a/net/dns/resolver/tsdns.go +++ b/net/dns/resolver/tsdns.go @@ -266,6 +266,16 @@ func New(logf logger.Logf, linkSel ForwardLinkSelector, dialer *tsdial.Dialer, h func (r *Resolver) TestOnlySetHook(hook func(Config)) { r.saveConfigForTests = hook } +// ProbeLocks acquires and releases the resolver's internal mutexes. +func (r *Resolver) ProbeLocks() { + r.mu.Lock() + r.mu.Unlock() + + if r.forwarder != nil { + r.forwarder.probeLocks() + } +} + func (r *Resolver) SetConfig(cfg Config) error { if !buildfeatures.HasDNS { return nil diff --git a/net/netmon/netmon.go b/net/netmon/netmon.go index a7120cdd3..ba75870c9 100644 --- a/net/netmon/netmon.go +++ b/net/netmon/netmon.go @@ -418,6 +418,12 @@ func (m *Monitor) InterfaceState() *State { return m.ifState } +// ProbeLocks acquires and releases the monitor's internal mutex. +func (m *Monitor) ProbeLocks() { + m.mu.Lock() + m.mu.Unlock() +} + func (m *Monitor) interfaceStateUncached() (*State, error) { return getState(tsIfProps.tsIfName()) } diff --git a/net/tsdial/tsdial.go b/net/tsdial/tsdial.go index 53fc97d0f..09c4da73f 100644 --- a/net/tsdial/tsdial.go +++ b/net/tsdial/tsdial.go @@ -136,6 +136,12 @@ func (d *Dialer) TUNName() string { return d.tunName } +// ProbeLocks acquires and releases the dialer's internal mutex. +func (d *Dialer) ProbeLocks() { + d.mu.Lock() + d.mu.Unlock() +} + // SetExitDNSDoH sets (or clears) the exit node DNS DoH server base URL to use. // The doh URL should contain the scheme, authority, and path, but without // a '?' and/or query parameters. diff --git a/net/tstun/wrap.go b/net/tstun/wrap.go index cd75aff5c..ef4c98fd2 100644 --- a/net/tstun/wrap.go +++ b/net/tstun/wrap.go @@ -945,6 +945,15 @@ func (t *Wrapper) IdleDuration() time.Duration { return mono.Since(t.lastActivityAtomic.LoadAtomic()) } +// ProbeLocks acquires and releases Wrapper's internal mutexes. +func (t *Wrapper) ProbeLocks() { + t.bufferConsumedMu.Lock() + t.bufferConsumedMu.Unlock() + + t.outboundMu.Lock() + t.outboundMu.Unlock() +} + func (t *Wrapper) awaitStart() { for { select { diff --git a/util/eventbus/bus.go b/util/eventbus/bus.go index 1bc8aaed6..56738e76d 100644 --- a/util/eventbus/bus.go +++ b/util/eventbus/bus.go @@ -103,6 +103,15 @@ func (b *Bus) Debugger() *Debugger { return &Debugger{b} } +// ProbeLocks acquires and releases the bus's internal mutexes. +func (b *Bus) ProbeLocks() { + b.topicsMu.Lock() + b.topicsMu.Unlock() + + b.clientsMu.Lock() + b.clientsMu.Unlock() +} + // Close closes the bus. It implicitly closes all clients, publishers and // subscribers attached to the bus. // diff --git a/wgengine/magicsock/magicsock.go b/wgengine/magicsock/magicsock.go index 4fe0fa29f..f4f5f94f4 100644 --- a/wgengine/magicsock/magicsock.go +++ b/wgengine/magicsock/magicsock.go @@ -1151,6 +1151,12 @@ func (c *Conn) LastRecvActivityOfNodeKey(nk key.NodePublic) string { return mono.Since(saw).Round(time.Second).String() } +// ProbeLocks acquires and releases Conn's internal mutex. +func (c *Conn) ProbeLocks() { + c.mu.Lock() + c.mu.Unlock() +} + // Ping handles a "tailscale ping" CLI query. func (c *Conn) Ping(peer tailcfg.NodeView, res *ipnstate.PingResult, size int, cb func(*ipnstate.PingResult)) { c.mu.Lock() diff --git a/wgengine/userspace.go b/wgengine/userspace.go index e064487ef..397096c0c 100644 --- a/wgengine/userspace.go +++ b/wgengine/userspace.go @@ -1541,6 +1541,17 @@ func (e *userspaceEngine) PeerForIP(ip netip.Addr) (ret PeerForIP, ok bool) { e.mu.Lock() nm := e.netMap e.mu.Unlock() + + if !ip.IsValid() { + // Treat invalid IPs as just a mutex probe to detect deadlocks. + // TODO(bradfitz): extend the Engine interface to have an explicit method for + // this purpose, instead of overloading PeerForIP with this special case. + // But I'd rather do that at the beginning of a dev cycle. + e.wgLock.Lock() + defer e.wgLock.Unlock() + return ret, false + } + if nm == nil { return ret, false }