Skip to content

fix(wg): escalate the relay-stuck coord re-fetch backoff (90 s -> 30 min cap) - #117

Open
iliabaranov wants to merge 3 commits into
mainfrom
fix/relay-refetch-backoff
Open

fix(wg): escalate the relay-stuck coord re-fetch backoff (90 s -> 30 min cap)#117
iliabaranov wants to merge 3 commits into
mainfrom
fix/relay-refetch-backoff

Conversation

@iliabaranov

Copy link
Copy Markdown
Contributor

Symptom

A remote whose machine peer is relay-bound (no direct WireGuard path; DERP only) reconnects to the Tailscale control plane every ~97 s, indefinitely. Found during the #115 soak on PSTOP06 with a laptop ROS 2 node as the machine:

  • ml_reconnects 1822 in 46 h (39.5/h), on both feat/lifetime-health and plain main (A/B done), on both USB tether and Ethernet (A/B done by the bench-host session; 43.6/h vs 44.4/h).
  • Each reconnect: ml_state 4→5→3→4, 5–7 s, full netmap re-ingest → peer_table_full_count +225/cycle (8900/h vs 23/h on a unit with a direct path), wg_tx_no_valid_keys +350/cycle.
  • One of them coincided with a heartbeat gap > 2 s and latched the machine's need_stop (10:50:32, 2026-09-04). The rest were absorbed by the 2 s timeout.

Root cause

ml_wg_mgr.c relay-stuck safety-peer recovery: after the first failed relay-retry round it sends ML_CMD_FORCE_RECONNECT so coord re-pulls the peer's current endpoints, rate-limited by a flat ML_RELAY_REFETCH_MIN_MS = 90000. Correct for the transient case it was written for (NAT mapping died in an outage). For a peer that is permanently relay-bound it never succeeds and never stops.

Confirmed on the DUT with the two diag exports in this PR: relay_refetch_reqs tracks ml_reconnects 1:1, and coord_disc_causes = [0 goaway, 86 recv_err, 0 watchdog, 0 ping_fail, 0 refresh] over 1822 reconnects, i.e. 95 % were self-inflicted, none were control-plane initiated.

Fix

Interval doubles after every re-fetch that does not lead to a direct regain: 90 → 180 → 360 → 720 → 1440 → 1800 s cap; reset to 90 s on the safety-peer direct-regain edge (has_direct_path promotion, where relay_retry_count already resets). Transient outages keep four fast rounds in the first ~10 min (unchanged); permanently relay-bound drops from ~40/h to ~2/h. The per-peer disco-session reset (local, no control-plane cost) is unchanged.

Verification (PSTOP06, OTA'd v1.2-18-g6f51532, machine bonded + armed over DERP)

14:17:40 reconn=1  refetch_reqs 1 interval_s 180
14:20:38 reconn=2 (+178 s) refetch_reqs 2 interval_s 360
14:26:49 reconn=3 (+371 s) refetch_reqs 3 interval_s 720
14:34:48 reconn=4 (+480 s) refetch_reqs 3   <- genuine recv_err (errno 128), disc[1]=1, NOT a re-fetch
14:38:56 reconn=5 (+727 s) refetch_reqs 4 interval_s 1440

Bond held throughout; both roles build clean; pre-commit passes.

Diagnostics kept

/admin/api/monitor: coord_disc_causes[6], relay_refetch_reqs, relay_refetch_interval_s. Worth a MONITORING.md row each; I can add those here or in #114, your call.

Follow-ups not in this PR

  • Whether the re-fetch should fire at all when the DERP-carried heartbeat is healthy (it disturbs the coord session the comment claims it does not).
  • Why laptop↔DUT never gets a direct path (bench pcap: DUT sends no direct UDP toward the laptop; asymmetric). Separate investigation.
  • heap_min_int reached 855 B with Ethernet + USB tether both live (seen during the iface switching test). Separate issue.

Independent of #114/#115; those remain clean (health feature exonerated by the A/B).

…ses in /admin/api/monitor)

[goaway, recv_err, watchdog, ping_fail, stream_refresh, last_errno]. Bench
diagnostic for the ~97 s control-plane reconnect cadence seen on PSTOP06;
not for merge as-is.
…min cap)

The relay-bound safety-peer recovery asks coord for a full reconnect
(ML_CMD_FORCE_RECONNECT) every ML_RELAY_REFETCH_MIN_MS = 90 s so the peer's
CURRENT endpoints get re-pulled and the hole-punch can land. That is the
right cure for the transient case it was built for (mapping died during an
outage). For a peer that is permanently relay-bound it never succeeds, and
at a flat 90 s it never stops:

  PSTOP06 bench, 2026-09-04..06, machine = laptop over DERP with no direct
  path: ml_reconnects 1822 in 46 h (39.5/h), relay_refetch_reqs tracks it
  1:1; coord_disc_causes shows 0 GOAWAY / 0 watchdog / 86 ECONNRESET, i.e.
  95 % of reconnects were self-inflicted. Each is a 5-7 s coord blackout
  (ml_state 4->5->3->4) plus a full netmap re-ingest: peer_table_full_count
  +225 and wg_tx_no_valid_keys +~350 per cycle. One of them coincided with
  a heartbeat gap long enough to latch the machine's need_stop.

Fix: double the interval after every re-fetch that does not lead to a direct
regain, cap at ML_RELAY_REFETCH_MAX_MS (30 min), reset to 90 s on the
safety-peer direct-regain edge. Transient outages keep four fast rounds in
the first 10 min; steady-state relay-bound drops from ~40/h to ~2/h.

Diagnostics kept (cheap, and they proved the case): /admin/api/monitor
coord_disc_causes[6] = [goaway, recv_err, watchdog, ping_fail,
stream_refresh, last_errno], relay_refetch_reqs, relay_refetch_interval_s.

@claude claude Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nothing blocking. The comments below are optional suggestions. There is no need to push a fix for them before merging.

Comment on lines +4253 to +4257
ESP_LOGW(
TAG,
"relay-stuck safety peer %s: coord re-fetch (reconnect) for endpoint refresh (next in %llu s)",
p->hostname,
(unsigned long long)(s_relay_refetch_interval_ms / 1000u));

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🟡 nit (optional): the new re-fetch log prints the interval BEFORE it is doubled, so "next in %llu s" always reports the interval that just elapsed, not the one that will actually gate the next re-fetch (e.g. logs 90s on the fetch that just escalated the wait to 180s). Fix: log after computing the doubled/capped value, or print both the interval just used and the new one.

Extended reasoning...

At ml_wg_mgr.c:4253-4264, ESP_LOGW uses s_relay_refetch_interval_ms before the *= 2u / cap on lines 4261-4264 runs, so the printed value is always one escalation step stale. An engineer correlating serial logs with reconnect timestamps during a field soak (the exact use case this PR's diagnostics target) will misjudge when the next re-fetch is due by a full doubling step.

Verification: nit. At ml_wg_mgr.c:4253-4257 the ESP_LOGW formats "next in %llu s" using (s_relay_refetch_interval_ms / 1000u), and only afterward (lines 4261-4264) does s_relay_refetch_interval_ms *= 2u with the ML_RELAY_REFETCH_MAX_MS cap run. So the message reports the interval that just elapsed, not the one that will actually gate the next re-fetch: e.g. on the first fetch it logs "next in 90 s"…

Comment on lines 2338 to +2342
int saved_errno = errno;
/* EAGAIN/EWOULDBLOCK = no data yet = not an error */
if (saved_errno == EAGAIN || saved_errno == EWOULDBLOCK) return 0;
s_diag_disc_cause[1]++;
s_diag_disc_cause[5] = (uint32_t)saved_errno;

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🟡 (optional) The new recv_err/last_errno diagnostic (s_diag_disc_cause[1]/[5]) is fed by errno on every noise_recv()<=0 path, but noise_recv() returns -1 for several non-socket failures (bad frame type, ct_len<16, malloc failure, decrypt failure) that never touch errno — so those get bucketed as "recv_err" with a stale/unrelated errno left over from an earlier syscall. Fix: only attribute to recv_err/last_errno the branch where coord_recv() itself failed (i.e. where noise_recv actually set errno via the socket read), and count protocol/decrypt failures in a separate cause so the exported diagnostic is not misleading.

Extended reasoning...

poll_map_update() at ml_coord.c:2334 calls frame_len = noise_recv(ml, noise, ...); on any frame_len<=0 it now does saved_errno=errno; s_diag_disc_cause[1]++; s_diag_disc_cause[5]=saved_errno (lines 2338-2342). noise_recv() (line 221) returns -1 without setting errno for 'Unexpected Noise frame type' (228), ct_len<16 (233), malloc failure (241), and 'Noise decrypt failed' (258) — only the coord_recv()-based paths (225, 247-254) actually set errno from a socket call. If any of those non-socket -1 returns fire (e.g. a nonce-desync decrypt failure), the exported /monitor coord_disc_causes[5] reports whatever errno happened to be left over from an unrelated prior libc call, and coord_disc_causes[1] silently merges a protocol/crypto failure into the 'recv_err' bucket the PR itself relies on to attribute reconnect causes.

Verification: nit. The mechanism is real: poll_map_update() lines 2338-2342 do int saved_errno = errno; ... s_diag_disc_cause[1]++; s_diag_disc_cause[5] = (uint32_t)saved_errno; on any non-EAGAIN frame_len <= 0. noise_recv() (line 221) returns -1 without touching errno on several paths: unexpected frame type (228-229), ct_len < 16 (233), frame-too-large (237), psram malloc failure (241), and decrypt…

Comment on lines 2993 to +2996
if (is_prio) {
/* A safety peer got its direct path back: the coord re-fetch did its
* job (or was not needed). The next outage starts the cadence at 90 s. */
s_relay_refetch_interval_ms = ML_RELAY_REFETCH_MIN_MS;

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🟣 The escalation backoff (s_relay_refetch_interval_ms) is a single global shared across ALL safety peers, but is_safety_peer() covers the priority peer plus up to 16 independently health-tracked peers. A direct-path regain on any ONE safety peer resets the shared interval to 90 s for every OTHER peer's relay-stuck backoff too, so a fleet machine tracking a flapping remote alongside a permanently relay-bound one never escalates past 90 s for the stuck peer -- reproducing exactly the ~40 reconnects/h this PR aims to fix. Fix: key s_relay_refetch_interval_ms (and s_last_relay_refetch_ms) per-peer (e.g. store on ml_peer_t) instead of as one process-wide static.

Extended reasoning...

is_safety_peer() (ml_wg_mgr.c:770-773) returns true for ml->config.priority_peer_ip OR any of the up to ML_EXTRA_PINS=16 health-tracked peers (line 615/652). disco_periodic_probes (line 4245-4265) gates and escalates the SAME s_relay_refetch_interval_ms/s_last_relay_refetch_ms for whichever safety peer's relay_retry_count>=1 hits the loop first. process_disco_pong (line 2993-2996) resets that same global to ML_RELAY_REFETCH_MIN_MS the instant ANY is_prio peer's has_direct_path flips false->true. With two health-tracked peers, one intermittently flapping direct and one permanently symmetric-NAT/relay-bound, every flap of the first resets the second's backoff to 90s, so the stuck peer keeps re-fetching (and control-plane reconnecting) every 90s indefinitely -- the same 39.5/h reconnect storm the PR's own soak data is trying to eliminate, just now hidden behind a diagnostic that reports a low 'relay_refetch_interval_s' because it reflects the wrong peer's state.

Verification: pre-existing (nit). The mechanism the candidate describes is real: is_safety_peer (ml_wg_mgr.c:770-772) matches the priority peer OR any of up to 16 health-tracked peers, and both the escalation site (is_priority at 4044, using shared s_relay_refetch_interval_ms at 4247/4261) and the reset site (is_prio at 2954, resetting s_relay_refetch_interval_ms = ML_RELAY_REFETCH_MIN_MS at 2996) key off…

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant