Skip to content

Commit 03c1189

Browse files
TeoSlayerteovlclaude
authored
daemon: rx-watchdog also detects the partial (outbound-dial) wedge (#387)
The v1.12.5 watchdog catches a FULL inbound wedge (PktsRecv fully stalls) and is production-proven. But 2026-07-15 the overlay went dark in a way it missed: pilot-director and list-agents both failed with dial timeouts while PktsRecv kept *trickling* forward from a couple of peer keepalives — so the rx-silence timer reset every tick and the watchdog stayed quiet. Only a manual daemon restart cleared it (its re-registration re-punched the NAT mapping). Add an outbound signal: DialConnection records a success (clears the counter) or a full-budget timeout (increments consecutiveDialTimeouts). The watchdog now treats dialTimeouts >= dialWedgeThreshold (4 back-to-back dial failures, zero successes between — implausible unless our own send path is dead) as a wedge, even while rx trickles: rx progress no longer counts as healthy in that state. It runs the same soft-recovery (beacon + registry re-register) and, if it persists, the same guarded hard-exit → supervisor respawn. The soft path resets the dial counter so the next real dial re-tests, avoiding a stale-counter false exit when no dials have happened. Co-authored-by: Teodor Calin <teodor@vulturelabs.io> Co-authored-by: Claude Fable 5 <noreply@anthropic.com>
1 parent 6290271 commit 03c1189

3 files changed

Lines changed: 138 additions & 7 deletions

File tree

pkg/daemon/daemon.go

Lines changed: 23 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -350,6 +350,21 @@ type Daemon struct {
350350
// signature) from "whole network unreachable" (restart just loops).
351351
lastRegistryOKNano atomic.Int64
352352

353+
// lastDialOKNano / consecutiveDialTimeouts feed the rx watchdog's
354+
// PARTIAL-wedge detector. A daemon can be "up" with rx trickling —
355+
// a couple of keepalive packets from existing peers keep PktsRecv
356+
// advancing, so the rx-silence check stays quiet — yet be unable to
357+
// open a single new outbound data-exchange connection: every
358+
// DialConnection returns ErrDialTimeout. Observed 2026-07-15, the
359+
// overlay went dark (pilot-director + list-agents both unreachable)
360+
// and the watchdog did NOT fire because the keepalive trickle reset
361+
// its silence timer every tick; only a manual daemon restart cleared
362+
// it. consecutiveDialTimeouts counts back-to-back dial timeouts
363+
// (reset to 0 on any successful dial); a run of them to distinct
364+
// peers means our outbound path is wedged, not that one peer is dead.
365+
lastDialOKNano atomic.Int64
366+
consecutiveDialTimeouts atomic.Uint64
367+
353368
startTime time.Time
354369
stopCh chan struct{} // closed on Stop() to signal goroutines
355370
beaconSelection *beaconSelectionState // multi-beacon discovery state
@@ -3674,6 +3689,10 @@ func (d *Daemon) dialConnectionLocked(ctx context.Context, dstAddr protocol.Addr
36743689
if st == StateEstablished {
36753690
d.startRetxLoop(conn)
36763691
}
3692+
// A completed handshake proves the outbound path is alive —
3693+
// clears the rx-watchdog's partial-wedge signal.
3694+
d.lastDialOKNano.Store(time.Now().UnixNano())
3695+
d.consecutiveDialTimeouts.Store(0)
36773696
return conn, nil
36783697
}
36793698
if st == StateClosed {
@@ -3720,6 +3739,10 @@ func (d *Daemon) dialConnectionLocked(ctx context.Context, dstAddr protocol.Addr
37203739
if relayActivatedHere && !d.tunnels.IsRelayPinned(dstAddr.Node) {
37213740
d.tunnels.SetRelayPeer(dstAddr.Node, false)
37223741
}
3742+
// Full direct+relay retry budget exhausted with no SYN-ACK.
3743+
// Feeds the rx-watchdog's partial-wedge detector: a run of
3744+
// these to distinct peers means our outbound is wedged.
3745+
d.consecutiveDialTimeouts.Add(1)
37233746
return nil, protocol.ErrDialTimeout
37243747
}
37253748
// Resend SYN (uses relay if relayActive)

pkg/daemon/rxwatchdog.go

Lines changed: 60 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -55,6 +55,16 @@ const (
5555
// nothing to send) never triggers.
5656
rxSilenceMinSentDelta = 30
5757

58+
// dialWedgeThreshold: consecutive DialConnection timeouts (each a full
59+
// direct+relay retry budget with no SYN-ACK) that mark the outbound
60+
// path as wedged. A run this long means separate dials to (typically)
61+
// distinct peers all failed — implausible unless our own send path is
62+
// dead, not the peers. This is the PARTIAL wedge the rx-silence check
63+
// misses: rx keeps trickling (keepalives) so silence never trips, but
64+
// no new connection can be opened. 4 = at least four back-to-back
65+
// user-visible dial failures with zero successes in between.
66+
dialWedgeThreshold = 4
67+
5868
// rxWatchdogSoftMax is how many consecutive soft recoveries run
5969
// before the watchdog considers the hard exit.
6070
rxWatchdogSoftMax = 3
@@ -136,10 +146,18 @@ func (d *Daemon) rxWatchdogTick(st *rxWatchdogState, now time.Time) (action rxWa
136146

137147
recv := atomic.LoadUint64(&d.tunnels.PktsRecv)
138148
sent := atomic.LoadUint64(&d.tunnels.PktsSent)
149+
dialTimeouts := d.consecutiveDialTimeouts.Load()
150+
151+
rxProgressed := recv != st.recvSeen
152+
// PARTIAL wedge: the outbound path is dead — a run of DialConnection
153+
// timeouts to (typically) distinct peers with zero successes between
154+
// them — even though rx is still trickling. rx progress alone no
155+
// longer counts as healthy while this holds.
156+
dialWedged := dialTimeouts >= dialWedgeThreshold
139157

140-
if recv != st.recvSeen {
158+
if rxProgressed && !dialWedged {
141159
if st.softAttempts > 0 {
142-
slog.Info("inbound path recovered",
160+
slog.Info("transport recovered",
143161
"silent_for", now.Sub(st.lastProgress).Truncate(time.Second).String(),
144162
"soft_attempts", st.softAttempts)
145163
d.publishEvent("tunnel.rx_recovered", map[string]any{
@@ -154,12 +172,31 @@ func (d *Daemon) rxWatchdogTick(st *rxWatchdogState, now time.Time) (action rxWa
154172
return rxActionProgress
155173
}
156174

175+
// Keep the rx-silence measure honest even when we don't reset the soft
176+
// counter: if rx trickled forward (dial-wedged case), advance the
177+
// baseline so `silence` reflects real inbound stall, not the trickle.
178+
if rxProgressed {
179+
st.recvSeen = recv
180+
st.sentAtProgress = sent
181+
st.lastProgress = now
182+
}
183+
157184
silence := now.Sub(st.lastProgress)
158185
sentDelta := sent - st.sentAtProgress
159-
if silence < rxSilenceThreshold || sentDelta < rxSilenceMinSentDelta {
186+
rxSilentWedge := silence >= rxSilenceThreshold && sentDelta >= rxSilenceMinSentDelta
187+
188+
if !rxSilentWedge && !dialWedged {
160189
return rxActionNone
161190
}
162191

192+
wedgeReason := "inbound-silent"
193+
if dialWedged {
194+
wedgeReason = "outbound-dial-wedged"
195+
if rxSilentWedge {
196+
wedgeReason = "inbound-silent+outbound-dial-wedged"
197+
}
198+
}
199+
163200
// rawRxAge separates "socket path dead" (old) from "session layer
164201
// dead" (fresh — datagrams arrive but nothing decrypts/delivers).
165202
rawRxAge := time.Duration(0)
@@ -169,24 +206,36 @@ func (d *Daemon) rxWatchdogTick(st *rxWatchdogState, now time.Time) (action rxWa
169206

170207
if st.softAttempts < rxWatchdogSoftMax {
171208
st.softAttempts++
172-
slog.Warn("inbound path silent while transmitting — attempting soft recovery",
209+
slog.Warn("transport wedged while transmitting — attempting soft recovery",
210+
"reason", wedgeReason,
173211
"silent_for", silence.Truncate(time.Second).String(),
174212
"pkts_sent_during_silence", sentDelta,
213+
"dial_timeouts", dialTimeouts,
175214
"raw_rx_age", rawRxAge.Truncate(time.Second).String(),
176215
"attempt", st.softAttempts,
177216
"max_soft_attempts", rxWatchdogSoftMax)
178217
d.publishEvent("tunnel.rx_silence", map[string]any{
218+
"reason": wedgeReason,
179219
"silent_for_seconds": int64(silence.Seconds()),
180220
"pkts_sent_during_silence": sentDelta,
221+
"dial_timeouts": dialTimeouts,
181222
"raw_rx_age_seconds": int64(rawRxAge.Seconds()),
182223
"attempt": st.softAttempts,
183224
})
184-
// The beacon's discover reply is itself an inbound datagram, so
185-
// this doubles as an active probe of the rx path.
225+
// Re-register with the beacon (re-punches our NAT mapping; the
226+
// discover reply also doubles as an active inbound probe) and the
227+
// registry. This is what a manual restart effectively did to clear
228+
// the partial wedge.
186229
d.tunnels.RegisterWithBeacon()
187230
if d.regConn != nil {
188231
d.reRegister()
189232
}
233+
// Reset the dial counter so the next real dial re-tests the path:
234+
// if recovery worked the next dial succeeds (counter stays 0); if
235+
// not, failures re-accumulate to threshold and softAttempts climbs
236+
// toward the hard exit. Avoids a stale counter forcing an exit when
237+
// no new dials have happened to confirm the wedge persists.
238+
d.consecutiveDialTimeouts.Store(0)
190239
return rxActionSoftRecover
191240
}
192241

@@ -212,15 +261,19 @@ func (d *Daemon) rxWatchdogTick(st *rxWatchdogState, now time.Time) (action rxWa
212261
"silent_for", silence.Truncate(time.Second).String(),
213262
"uptime", uptime.Truncate(time.Second).String())
214263
default:
215-
slog.Error("inbound path wedged — exiting for supervisor respawn",
264+
slog.Error("transport wedged — exiting for supervisor respawn",
265+
"reason", wedgeReason,
216266
"silent_for", silence.Truncate(time.Second).String(),
217267
"pkts_sent_during_silence", sentDelta,
268+
"dial_timeouts", dialTimeouts,
218269
"raw_rx_age", rawRxAge.Truncate(time.Second).String(),
219270
"soft_attempts", st.softAttempts,
220271
"exit_code", rxWedgeExitCode)
221272
d.publishEvent("tunnel.rx_wedged_exit", map[string]any{
273+
"reason": wedgeReason,
222274
"silent_for_seconds": int64(silence.Seconds()),
223275
"pkts_sent_during_silence": sentDelta,
276+
"dial_timeouts": dialTimeouts,
224277
"soft_attempts": st.softAttempts,
225278
"exit_code": rxWedgeExitCode,
226279
})

pkg/daemon/zz_rx_watchdog_test.go

Lines changed: 55 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -173,3 +173,58 @@ func TestRxWatchdogHardExitWithheldWhenNeverProgressedOrYoung(t *testing.T) {
173173
t.Fatalf("exit fired despite guards (code %d)", *exitCode)
174174
}
175175
}
176+
177+
// TestRxWatchdogPartialWedgeDialTimeouts pins the 2026-07-15 regression:
178+
// rx keeps trickling (PktsRecv advances every tick from keepalives) so the
179+
// rx-silence check never fires, but every outbound DialConnection times out
180+
// — the overlay is dark and the old watchdog stayed quiet. The dial-timeout
181+
// counter must now drive the same soft-recovery, and rx trickle must NOT be
182+
// treated as healthy while the outbound path is wedged.
183+
func TestRxWatchdogPartialWedgeDialTimeouts(t *testing.T) {
184+
t.Parallel()
185+
d := newRxWatchdogTestDaemon(t)
186+
now := time.Now()
187+
188+
atomic.StoreUint64(&d.tunnels.PktsRecv, 50)
189+
st := &rxWatchdogState{lastProgress: now, recvSeen: 49}
190+
if got := d.rxWatchdogTick(st, now); got != rxActionProgress {
191+
t.Fatalf("baseline healthy: action = %q, want %q", got, rxActionProgress)
192+
}
193+
194+
d.consecutiveDialTimeouts.Store(dialWedgeThreshold)
195+
atomic.AddUint64(&d.tunnels.PktsRecv, 3) // trickle: recv advanced
196+
if got := d.rxWatchdogTick(st, now.Add(30*time.Second)); got != rxActionSoftRecover {
197+
t.Fatalf("partial wedge (rx trickle + dial timeouts): action = %q, want %q", got, rxActionSoftRecover)
198+
}
199+
if c := d.consecutiveDialTimeouts.Load(); c != 0 {
200+
t.Fatalf("dial counter after soft recovery = %d, want 0", c)
201+
}
202+
203+
d.consecutiveDialTimeouts.Store(dialWedgeThreshold - 1)
204+
atomic.AddUint64(&d.tunnels.PktsRecv, 3)
205+
if got := d.rxWatchdogTick(st, now.Add(60*time.Second)); got != rxActionProgress {
206+
t.Fatalf("post-recovery (dial timeouts below threshold): action = %q, want %q", got, rxActionProgress)
207+
}
208+
}
209+
210+
// TestRxWatchdogPartialWedgeHardExit verifies a persistent dial-wedge (rx
211+
// healthy, registry reachable) escalates to the supervisor-respawn exit.
212+
func TestRxWatchdogPartialWedgeHardExit(t *testing.T) {
213+
d := newRxWatchdogTestDaemon(t)
214+
exitCode := swapExitForTest(t)
215+
now := time.Now()
216+
d.lastRegistryOKNano.Store(now.UnixNano())
217+
218+
atomic.StoreUint64(&d.tunnels.PktsRecv, 100)
219+
d.consecutiveDialTimeouts.Store(dialWedgeThreshold)
220+
st := &rxWatchdogState{
221+
lastProgress: now, recvSeen: 100, sentAtProgress: 0,
222+
softAttempts: rxWatchdogSoftMax,
223+
}
224+
if got := d.rxWatchdogTick(st, now); got != rxActionExit {
225+
t.Fatalf("persistent dial wedge: action = %q, want %q", got, rxActionExit)
226+
}
227+
if *exitCode != rxWedgeExitCode {
228+
t.Fatalf("exit code = %d, want %d", *exitCode, rxWedgeExitCode)
229+
}
230+
}

0 commit comments

Comments
 (0)