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 }