Skip to content

Commit 568fc59

Browse files
h4x3rotabclaude
andcommitted
fix(mesh-conn): bump pion ICE Disconnected/Failed timeouts for relay paths
Pion's defaults (DisconnectedTimeout=5s + FailedTimeout=25s = 30s of no inbound from the selected pair before the state callback fires Failed) are too tight for the TURN-relay path. Brief jitter or coturn refresh- window noise can accumulate a 30s consent-freshness gap, pion declares Failed, our OnConnectionStateChange callback aborts the attempt, QUIC returns context-canceled from its pumps, and runPeerLink re-handshakes 2-5s later. The link recovers every cycle but the cluster visibly flaps Connected -> Disconnected -> Failed -> Checking -> Connected roughly every couple of minutes on relay-only deployments. Diagnosis: - TestSteadyStateNoFlap (new) on host-loopback: 5 min observation, zero flap events -> the outer state machine is fine, the bug lives in the relay/TURN interaction. - Live 6-CVM cluster with MESH_CONN_RELAY_ONLY=1 on the pre-fix code for 15 min: did not deterministically reproduce the flap, but pion's 30s budget against an ~150ms-RTT relay path with two periodic refresh cycles (perm at 120s, alloc at lifetime/2) is the obvious aggressive setting. Fix: - Set DisconnectedTimeout=30s and FailedTimeout=60s on the ice.AgentConfig in dialICE. The 60s Failed budget matches QUIC's MaxIdleTimeout, so QUIC's idle-timeout in the pumps becomes the actual recovery trigger in steady state, and pion's Failed becomes a redundant backstop. Real peer death is still detected and recovered from within the QUIC budget. - Failover RTO is unaffected: gated on Patroni leader-key TTL + Consul gossip detection + Envoy xDS, none of which depend on mesh-conn's per-peer-link death notice. Verification: - TestSingleHandshake: passes. - TestAuthRaceConvergence: 50/50 trials. - TestRestartConvergence: passes. - TestSteadyStateNoFlap (new, configurable via STEADY_STATE_OBSERVE_SECONDS): passes 50/50 at 30s observation each (25 min wall-clock total). - Live 6-CVM relay-only cluster rolled to the fixed image: 15 min 47s of post-stabilization observation across all 6 peers, ZERO `ice state: Failed/Disconnected/Closed` events on any sidecar. Co-Authored-By: Claude Opus 4.7 <noreply@anthropic.com>
1 parent b63896c commit 568fc59

3 files changed

Lines changed: 166 additions & 3 deletions

File tree

consul-postgres-ha/ROBUSTNESS.md

Lines changed: 36 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -152,6 +152,42 @@ whose direct path goes down can't fail over to TURN until it's back".
152152
sustained-forge variant gated on the `onAttemptStarted` hook,
153153
which guarantees the forge lands inside the in-flight window.
154154

155+
- **pion DisconnectedTimeout / FailedTimeout headroom for the
156+
TURN-relay path.** With pion's defaults (5 s + 25 s = 30 s of no
157+
inbound from the selected pair before the state callback fires
158+
Failed), the relay-only path on `MESH_CONN_RELAY_ONLY=1` clusters
159+
flapped on its own roughly every couple of minutes: brief
160+
jitter / refresh-window noise at coturn was enough to accumulate
161+
a 30 s consent-freshness gap, pion declared Failed,
162+
`OnConnectionStateChange` fired `abortAttempt`, QUIC's
163+
`accept`/pumps came back with `context canceled`, and `runPeerLink`
164+
re-established the link 2–5 s later. The link-pair recovered every
165+
cycle, but the churn was visible cluster-wide and any traffic
166+
in-flight during the abort window had to retransmit.
167+
168+
Fixed by setting `DisconnectedTimeout = 30 s` and `FailedTimeout
169+
= 60 s` on the `ice.AgentConfig` in `dialICE`. The 60 s Failed
170+
budget matches QUIC's `MaxIdleTimeout` so the two layers' notion
171+
of "link is dead" converge on the same wall-clock, and a real
172+
peer death is still picked up by QUIC's pumps returning errors
173+
at 60 s — which is the actual recovery trigger in steady state.
174+
The 30 s Disconnected budget is "log-only" (our state callback
175+
ignores Disconnected); it just preserves the log signal for slow-
176+
recovery cases.
177+
178+
Failover RTO is unaffected. Failover is gated on Patroni's
179+
Consul-KV leader-key TTL (~30 s) plus Consul gossip detection
180+
(~10 s) and Envoy xDS update — none of which depend on
181+
mesh-conn detecting the dead peer's link quickly. The new leader
182+
is reached via a *different* peer link that's already up.
183+
184+
Regression net: `mesh-conn/main_test.go::TestSteadyStateNoFlap`
185+
loopback two-peer steady-state observation. Default window 5 min;
186+
`STEADY_STATE_OBSERVE_SECONDS=N` overrides for the CI 50-trial
187+
sweep at 30 s each (passes 50/50). Live verification: 6-CVM
188+
relay-only cluster observed for 15+ min post-rollout with zero
189+
`ice state: Failed` events on any peer's sidecar log.
190+
155191
## Layer 2 — mesh-conn forwarder
156192

157193
### What's there

consul-postgres-ha/mesh-conn/main.go

Lines changed: 47 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1131,10 +1131,54 @@ func (m *Mesh) dialICE(remoteID string, sess *peerSession, attemptCtx context.Co
11311131
// MESH_CONN_DEBUG_ICE=1 turns on pion's verbose ICE-level logging
11321132
// (connectivity-check requests/responses, STUN attribute parsing,
11331133
// candidate-pair scoring). Off by default because it's chatty.
1134+
//
1135+
// Disconnected/Failed timeouts: pion defaults to 5 s + 25 s (= 30 s
1136+
// of no inbound from the selected pair before the state callback
1137+
// fires Failed and our outer code aborts the attempt). That is too
1138+
// tight for the TURN-relay path. The relay leg adds ~150 ms RTT,
1139+
// the periodic permission/allocation refreshes can briefly
1140+
// reorder packet flow at coturn, and pion's own 2 s consent
1141+
// freshness has no retry budget — a sub-second jitter window
1142+
// where 1 STUN binding gets lost and another arrives late is
1143+
// enough to start the disconnected clock, and consecutive jitter
1144+
// events accumulate against the 30 s budget. We've observed the
1145+
// resulting "Connected → Disconnected → Failed → Checking →
1146+
// Connected" cycle every couple of minutes on freshly-deployed
1147+
// relay-only clusters, with no actual peer death behind it.
1148+
//
1149+
// The fix is to give pion enough headroom that only a genuine
1150+
// relay-path outage (rather than refresh / jitter noise) trips
1151+
// Failed. We use 30 s + 60 s (= 90 s total) for two reasons:
1152+
//
1153+
// - 60 s for the post-Disconnected portion matches QUIC's
1154+
// MaxIdleTimeout — so if a link is genuinely dead, QUIC's
1155+
// keepalive will return an error in our pumps at the same
1156+
// time pion declares Failed, and either path triggers the
1157+
// same retry in runPeerLink. We're not extending the time
1158+
// to *recover* from a real failure, just the time to
1159+
// *declare* one. Failover RTO is gated on Consul gossip
1160+
// detection (~10 s) and Envoy xDS update, not on
1161+
// per-peer-link death notice from mesh-conn, so the bump
1162+
// is invisible at the RTO budget level.
1163+
//
1164+
// - The Disconnected portion is "log-only" — our state
1165+
// callback ignores Disconnected and only acts on Failed —
1166+
// so its only effect is the cosmetic length of the
1167+
// Disconnected stretch in the log timeline. We keep it at
1168+
// 30 s rather than 0 so the existing log signal is preserved
1169+
// if pion ever does have a sustained outage but recovers.
1170+
const (
1171+
iceDisconnectedTimeout = 30 * time.Second
1172+
iceFailedTimeout = 60 * time.Second
1173+
)
1174+
disconnectedTimeout := iceDisconnectedTimeout
1175+
failedTimeout := iceFailedTimeout
11341176
agentCfg := &ice.AgentConfig{
1135-
Urls: urls,
1136-
NetworkTypes: []ice.NetworkType{ice.NetworkTypeUDP4, ice.NetworkTypeTCP4},
1137-
CandidateTypes: candidateTypes,
1177+
Urls: urls,
1178+
NetworkTypes: []ice.NetworkType{ice.NetworkTypeUDP4, ice.NetworkTypeTCP4},
1179+
CandidateTypes: candidateTypes,
1180+
DisconnectedTimeout: &disconnectedTimeout,
1181+
FailedTimeout: &failedTimeout,
11381182
}
11391183
if os.Getenv("MESH_CONN_DEBUG_ICE") == "1" {
11401184
lf := logging.NewDefaultLoggerFactory()

consul-postgres-ha/mesh-conn/main_test.go

Lines changed: 83 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,9 @@ package main
33
import (
44
"context"
55
"fmt"
6+
"os"
7+
"strconv"
8+
"strings"
69
"testing"
710
"time"
811
)
@@ -187,3 +190,83 @@ func TestRestartConvergence(t *testing.T) {
187190
}
188191
t.Logf("restart convergence: %s", elapsed)
189192
}
193+
194+
// TestSteadyStateNoFlap brings two peers up on host loopback and then
195+
// keeps them up for an extended observation window, asserting the ICE
196+
// state never leaves Connected. The observation window is by default
197+
// 5 minutes but can be shortened via STEADY_STATE_OBSERVE_SECONDS for
198+
// the CI 50-trial regression sweep (e.g. 30 s).
199+
//
200+
// The point of the test is to disentangle two failure modes:
201+
//
202+
// - "ICE state cycles even on host loopback (no NAT, no TURN, no
203+
// packet loss)" — implicates the mesh-conn outer state machine
204+
// (e.g. an abortAttempt path firing on a non-failure signal).
205+
//
206+
// - "ICE state stays Connected on loopback" — exonerates the
207+
// mesh-conn outer code and points at the relay/TURN path.
208+
//
209+
// The signal we count is the number of ICE-state lines that AREN'T
210+
// "Connected" emitted after the initial link-up (so the lines for
211+
// the initial New → Checking → Connected handshake don't count). Any
212+
// transition to Disconnected/Failed/Closed inside the observation
213+
// window fails the test.
214+
func TestSteadyStateNoFlap(t *testing.T) {
215+
if testing.Short() {
216+
t.Skip("skipping steady-state observation in -short mode")
217+
}
218+
observe := 5 * time.Minute
219+
if v := os.Getenv("STEADY_STATE_OBSERVE_SECONDS"); v != "" {
220+
n, err := strconv.Atoi(v)
221+
if err != nil || n <= 0 {
222+
t.Fatalf("STEADY_STATE_OBSERVE_SECONDS=%q invalid", v)
223+
}
224+
observe = time.Duration(n) * time.Second
225+
}
226+
227+
sink := captureLogs(t)
228+
broker := newTestBroker()
229+
t.Cleanup(broker.Close)
230+
231+
peers := twoPeers()
232+
ctx, cancel := context.WithCancel(context.Background())
233+
t.Cleanup(cancel)
234+
235+
a := newTestPeer(t, broker.URL(), "peer-A", peers, 21003)
236+
b := newTestPeer(t, broker.URL(), "peer-B", peers, 21003)
237+
t.Cleanup(a.stop)
238+
t.Cleanup(b.stop)
239+
a.start(ctx)
240+
b.start(ctx)
241+
242+
if _, err := waitBothLinksUp(t, a, b, 30*time.Second); err != nil {
243+
t.Fatalf("initial link-up failed: %v\n\nlogs:\n%s", err, sink.String())
244+
}
245+
246+
// snapshot the log so we can later count only post-link-up state
247+
// transitions. The initial handshake emits "ice state: Checking"
248+
// and "ice state: Connected" which we want to ignore.
249+
preObserve := sink.String()
250+
preFailed := strings.Count(preObserve, "ice state: Failed")
251+
preDisconnected := strings.Count(preObserve, "ice state: Disconnected")
252+
preClosed := strings.Count(preObserve, "ice state: Closed")
253+
preLinkClosed := strings.Count(preObserve, "link closed — reconnecting")
254+
preLinkFailed := strings.Count(preObserve, "link failed:")
255+
256+
t.Logf("steady-state observation begins; window=%s", observe)
257+
time.Sleep(observe)
258+
259+
post := sink.String()
260+
failed := strings.Count(post, "ice state: Failed") - preFailed
261+
disconnected := strings.Count(post, "ice state: Disconnected") - preDisconnected
262+
closed := strings.Count(post, "ice state: Closed") - preClosed
263+
linkClosed := strings.Count(post, "link closed — reconnecting") - preLinkClosed
264+
linkFailed := strings.Count(post, "link failed:") - preLinkFailed
265+
266+
if failed+disconnected+closed+linkClosed+linkFailed > 0 {
267+
t.Fatalf("link flapped in steady state over %s: failed=%d disconnected=%d closed=%d linkClosed=%d linkFailed=%d\n\nlogs (post link-up):\n%s",
268+
observe, failed, disconnected, closed, linkClosed, linkFailed,
269+
strings.TrimPrefix(post, preObserve))
270+
}
271+
t.Logf("steady-state OK: no ice-state regressions over %s", observe)
272+
}

0 commit comments

Comments
 (0)