femboy/yip

Watch

Fork 0

netns-tunnel-test: two intermittent failures (cert-revocation budget vs documented discovery time; ARQ floor inside noise band) #157

New issue

Closed

opened 2026-08-03 20:58:33 +00:00 by vxfemboy · 2 comments

vxfemboy commented

2026-08-03 20:58:33 +00:00

Owner

What happened

Two tests in netns-tunnel-test fail intermittently on the privileged runner: hardening.41 cert-revocation and arq_recovers_bulk_loss.

Both became visible only after #156 fixed the missing iproute2 — the job previously died at run-netns-tunnel.sh:86 with ip: command not found before reaching either. Newly-observed, not newly-broken.

Expected: a green job on an unchanged tree. Observed: the same commit failing two different tests on two runs.

run	commit	result
299	`41c2b3a`	PASS (all 26 tests)
305	`3cf588f`	FAIL — `hardening.41` cert-revocation
306	`3cf588f`	FAIL — `arq_recovers_bulk_loss`

305 and 306 are the same tree. That is flakiness, not a regression.

1. cert-revocation: the budget is smaller than the documented need

bin/yipd/tests/run-netns-cert-revocation.sh mints a 60s cert, then retries discovery until 5s before expiry:

CERT_A_SECS=60
...
if [ "$NOW" -ge "$((EXPIRY_TIME - 5))" ]; then break; fi

That is 55 seconds of usable convergence window.

bin/yipd/tests/run-netns-discovery.sh:287 — the sibling this was forked from — documents what discovery needs:

# count/timeout (60s budget) absorbs this

55s allocated for something documented to need up to 60s. The comment above CERT_A_SECS asserts 60s is "generous enough to comfortably cover ... gossip discovery warm-up (run-netns-discovery.sh documents up to a 60s budget for that warm-up)" — which contradicts itself: the cert lifetime equals the warm-up it is meant to contain, and the retry loop then gives back another 5s. Runner load does not cause this; it only decides which side of the line a run lands on.

Suggested fix: raise CERT_A_SECS to ~150. Semantics unchanged — the cert still expires mid-test, which is the point of the revocation assertion. Cost ~+90s on a job already running ~31 min, since the later "wait for expiry" phase grows too.

Alternative worth considering: establish A<->B first, then start the expiry clock — decoupling the assertion (revocation works) from the load-dependent part (discovery convergence) rather than budgeting around it.

2. `arq_recovers_bulk_loss`: the threshold sits inside the noise band

Delivery against a min: 98% floor, same code each run:

run	delivered	result
290	81.5%	FAIL
296	99.4%	pass
305	99.3% / 99.4%	pass
306	96.4%	FAIL

ARQ demonstrably fires (72 retransmits in the 290 run), so the machinery works. A spread of 81.5%–99.4% under a nominally identical 5% bulk-loss profile is too wide for a fixed 98% floor to gate on.

Two readings, and which one is true changes the fix:

The floor is mis-calibrated for randomized netem loss at this sample size → widen it, or raise the sample count until variance is small against the margin.
Recovery genuinely is inconsistent → 98% is the right assertion and the 81.5% run is a real defect.

Worth deciding before touching the number: moving a threshold to make a test green is only correct under the first reading.

Repro

Run netns-tunnel-test (poll driver) on the privileged runner repeatedly against an unchanged tree; expect an intermittent failure in one of the two tests above. Config is the workflow's own — no local changes.

Environment

yip commit: 3cf588f (also seen on a207ba1, 01b307f)
kernel / distro: catthehacker/ubuntu:act-22.04 container on a Void Linux host, kernel 6.18.35_1, 24 threads, other CI jobs running concurrently
I/O driver: poll (default) — this test is poll-only by design

Logs

cert-revocation failure:

[setup] A's cert minted at 1785709214, expires at 1785709274 (+60s)
[check] 60s remain on A's cert before it expires — establishing now
[FAIL] ping A->B did not converge — could not establish A<->B before cert expiry

The failing run's root-node log also carries a large volume of:

dataplane ingress: control open error: decryption failed
dataplane ingress: control open error: replayed message
poll: tun write error: Invalid argument (os error 22)

I could not establish whether this is normal for this test: the passing run's log (task 1660) has log_in_storage=f in Forgejo's DB — 4689 lines recorded, never flushed to disk — so there is no baseline to compare against. Flagging rather than diagnosing. The tun write error: Invalid argument looks least like noise; EINVAL on a TUN write usually means a malformed packet reached the device.

**What happened** Two tests in `netns-tunnel-test` fail intermittently on the privileged runner: `hardening.41` cert-revocation and `arq_recovers_bulk_loss`. Both became visible only after #156 fixed the missing `iproute2` — the job previously died at `run-netns-tunnel.sh:86` with `ip: command not found` before reaching either. Newly-*observed*, not newly-broken. Expected: a green job on an unchanged tree. Observed: the same commit failing two different tests on two runs. | run | commit | result | |---|---|---| | 299 | `41c2b3a` | PASS (all 26 tests) | | 305 | `3cf588f` | FAIL — `hardening.41` cert-revocation | | 306 | `3cf588f` | FAIL — `arq_recovers_bulk_loss` | 305 and 306 are the same tree. That is flakiness, not a regression. --- ### 1. cert-revocation: the budget is smaller than the documented need `bin/yipd/tests/run-netns-cert-revocation.sh` mints a 60s cert, then retries discovery until 5s before expiry: ```bash CERT_A_SECS=60 ... if [ "$NOW" -ge "$((EXPIRY_TIME - 5))" ]; then break; fi ``` That is **55 seconds** of usable convergence window. `bin/yipd/tests/run-netns-discovery.sh:287` — the sibling this was forked from — documents what discovery needs: ``` # count/timeout (60s budget) absorbs this ``` **55s allocated for something documented to need up to 60s.** The comment above `CERT_A_SECS` asserts 60s is "generous enough to comfortably cover ... gossip discovery warm-up (run-netns-discovery.sh documents up to a 60s budget for that warm-up)" — which contradicts itself: the cert lifetime equals the warm-up it is meant to contain, and the retry loop then gives back another 5s. Runner load does not cause this; it only decides which side of the line a run lands on. Suggested fix: raise `CERT_A_SECS` to ~150. Semantics unchanged — the cert still expires mid-test, which is the point of the revocation assertion. Cost ~+90s on a job already running ~31 min, since the later "wait for expiry" phase grows too. Alternative worth considering: establish A<->B *first*, then start the expiry clock — decoupling the assertion (revocation works) from the load-dependent part (discovery convergence) rather than budgeting around it. ### 2. `arq_recovers_bulk_loss`: the threshold sits inside the noise band Delivery against a `min: 98%` floor, same code each run: | run | delivered | result | |---|---|---| | 290 | 81.5% | FAIL | | 296 | 99.4% | pass | | 305 | 99.3% / 99.4% | pass | | 306 | 96.4% | FAIL | ARQ demonstrably fires (72 retransmits in the 290 run), so the machinery works. A spread of 81.5%–99.4% under a nominally identical 5% bulk-loss profile is too wide for a fixed 98% floor to gate on. Two readings, and which one is true changes the fix: - The floor is **mis-calibrated** for randomized netem loss at this sample size → widen it, or raise the sample count until variance is small against the margin. - Recovery genuinely **is inconsistent** → 98% is the right assertion and the 81.5% run is a real defect. Worth deciding before touching the number: moving a threshold to make a test green is only correct under the first reading. **Repro** Run `netns-tunnel-test` (poll driver) on the privileged runner repeatedly against an unchanged tree; expect an intermittent failure in one of the two tests above. Config is the workflow's own — no local changes. **Environment** - yip commit: `3cf588f` (also seen on `a207ba1`, `01b307f`) - kernel / distro: `catthehacker/ubuntu:act-22.04` container on a Void Linux host, kernel 6.18.35_1, 24 threads, other CI jobs running concurrently - I/O driver: poll (default) — this test is poll-only by design **Logs** cert-revocation failure: ``` [setup] A's cert minted at 1785709214, expires at 1785709274 (+60s) [check] 60s remain on A's cert before it expires — establishing now [FAIL] ping A->B did not converge — could not establish A<->B before cert expiry ``` The failing run's root-node log also carries a large volume of: ``` dataplane ingress: control open error: decryption failed dataplane ingress: control open error: replayed message poll: tun write error: Invalid argument (os error 22) ``` I could not establish whether this is normal for this test: the passing run's log (task 1660) has `log_in_storage=f` in Forgejo's DB — 4689 lines recorded, never flushed to disk — so there is no baseline to compare against. Flagging rather than diagnosing. The `tun write error: Invalid argument` looks least like noise; EINVAL on a TUN write usually means a malformed packet reached the device.

vxfemboy referenced this issue from a commit

2026-08-03 21:00:08 +00:00

fix(test): give cert-revocation more cert life than discovery needs

vxfemboy referenced this issue

2026-08-03 21:00:28 +00:00

fix(test): give cert-revocation more cert life than discovery needs #158

vxfemboy commented

2026-08-03 22:23:49 +00:00

Author

Owner

Third intermittent failure in this job, seen on PR #158's run (commit 49bdcc6): flowshape_not_obviously_constant.

[result] per-session handshake-phase counts: 4 17 10 23 11 17 15 18
[FAIL] gate (a): session 1 count=4 is <= 4 — junk burst did not reach the wire
[PASS] gate (b): 7 distinct handshake-phase counts across 8 sessions

The run's own gate (b) contradicts gate (a)'s diagnosis. 7 distinct counts means the Jc junk burst is reaching the wire and randomizing the opener. If it genuinely were not, all 8 sessions would sit at the baseline — not 1 of 8.

Session 1 is the outlier (4 against 10-23 for the rest, mean ~16), and session 1 is the cold one. run-flowshape-check.sh:194-197 starts tcpdump and then waits a flat sleep 0.3 before launching the daemons:

ip netns exec "$NS_A" tcpdump -i "$VETH_A" -w "$PCAP" -U "udp port $PORT" &
TCPDUMP_PID=$!
sleep 0.3

The comment above it states the intent exactly — tcpdump must be capturing "BEFORE either daemon starts, so packet zero ... is captured" — but 300ms is a guess, not a readiness check. On the first iteration (tcpdump not in page cache, netns freshly created, pcap being created) that can be short; iterations 2-8 are warm. Missing the opening datagrams shows up precisely as a low count on session 1.

Suggested fix: wait for readiness instead of guessing. tcpdump writes listening on <iface> to stderr once attached, and the script already redirects that to $TMPDIR_TEST/tcpdump-$i.log — poll that file for the line with a timeout, then start the daemons.

Same shape as the cert-revocation item above: a fixed time budget standing in for a condition that should be waited on.

Also from that run, for the record: arq_recovers_bulk_loss passed at 99.3% with 137 retransmits, and cert-revocation never ran — flowshape aborts the step before it.

Third intermittent failure in this job, seen on PR #158's run (commit `49bdcc6`): **`flowshape_not_obviously_constant`**. ``` [result] per-session handshake-phase counts: 4 17 10 23 11 17 15 18 [FAIL] gate (a): session 1 count=4 is <= 4 — junk burst did not reach the wire [PASS] gate (b): 7 distinct handshake-phase counts across 8 sessions ``` **The run's own gate (b) contradicts gate (a)'s diagnosis.** 7 distinct counts means the Jc junk burst *is* reaching the wire and randomizing the opener. If it genuinely were not, all 8 sessions would sit at the baseline — not 1 of 8. Session 1 is the outlier (4 against 10-23 for the rest, mean ~16), and session 1 is the cold one. `run-flowshape-check.sh:194-197` starts tcpdump and then waits a flat `sleep 0.3` before launching the daemons: ```bash ip netns exec "$NS_A" tcpdump -i "$VETH_A" -w "$PCAP" -U "udp port $PORT" & TCPDUMP_PID=$! sleep 0.3 ``` The comment above it states the intent exactly — tcpdump must be capturing "BEFORE either daemon starts, so packet zero ... is captured" — but 300ms is a guess, not a readiness check. On the first iteration (tcpdump not in page cache, netns freshly created, pcap being created) that can be short; iterations 2-8 are warm. Missing the opening datagrams shows up precisely as a low count on session 1. Suggested fix: wait for readiness instead of guessing. tcpdump writes `listening on <iface>` to stderr once attached, and the script already redirects that to `$TMPDIR_TEST/tcpdump-$i.log` — poll that file for the line with a timeout, then start the daemons. Same shape as the cert-revocation item above: a fixed time budget standing in for a condition that should be waited on. Also from that run, for the record: `arq_recovers_bulk_loss` passed at 99.3% with 137 retransmits, and cert-revocation never ran — flowshape aborts the step before it.

vxfemboy referenced this issue

2026-08-03 23:53:58 +00:00

fix(test): robust flowshape check (dense-cluster span) #159

vxfemboy commented

2026-08-04 05:52:40 +00:00

Author

Owner

Resolved — both intermittent netns-tunnel-test failures tracked here are fixed:

cert-revocation budget → #158 (merged): CERT_A_SECS 60→150, so the convergence window (~145s) comfortably exceeds the documented ~60s discovery warm-up. Assertion unchanged (cert still expires mid-test).
arq_recovers_bulk_loss "inside the noise band" → #161 (merged). Root cause was NOT a too-tight 98% threshold but a real io_uring RX drop: the driver kept only UDP_RECV_DEPTH=16 single-shot recvs outstanding, so under the CI container's contention the underlay socket receive queue overflowed (UdpRcvbufErrors climbing) while the poll driver — which drains the whole backlog per wakeup — did not. Confirmed via /proc/net/snmp instrumentation (#160 → #161) and an independent driver review. Fix: UDP_RECV_DEPTH 16→256 (+ ring headroom). Post-fix CI: uring delivery 80.1% → 99.2%, RcvbufErrors=0; poll 98.7%.

A third flake in the same job, flowshape_not_obviously_constant, was fixed alongside: #159 (dense-cluster span replacing a stall-fragile gap cutoff) and #161 (spread-based gate replacing an absolute floor that CI contention violated).

netns-tunnel-test is green on the post-#161 tree (all 26 tests, both poll and uring drivers).

Follow-ups found during the io_uring investigation (NOT fixed here) are worth tracking separately — chiefly: a single bad UDP recv CQE tears down the whole driver and drops the rest of the batch, reachable by any peer sending a >2048-byte datagram.

Resolved — both intermittent `netns-tunnel-test` failures tracked here are fixed: 1. **cert-revocation budget** → #158 (merged): `CERT_A_SECS` 60→150, so the convergence window (~145s) comfortably exceeds the documented ~60s discovery warm-up. Assertion unchanged (cert still expires mid-test). 2. **`arq_recovers_bulk_loss` "inside the noise band"** → #161 (merged). Root cause was NOT a too-tight 98% threshold but a real **io_uring RX drop**: the driver kept only `UDP_RECV_DEPTH=16` single-shot recvs outstanding, so under the CI container's contention the underlay socket receive queue overflowed (`UdpRcvbufErrors` climbing) while the poll driver — which drains the whole backlog per wakeup — did not. Confirmed via `/proc/net/snmp` instrumentation (#160 → #161) and an independent driver review. Fix: `UDP_RECV_DEPTH` 16→256 (+ ring headroom). Post-fix CI: uring delivery **80.1% → 99.2%, `RcvbufErrors=0`**; poll 98.7%. A third flake in the same job, `flowshape_not_obviously_constant`, was fixed alongside: #159 (dense-cluster span replacing a stall-fragile gap cutoff) and #161 (spread-based gate replacing an absolute floor that CI contention violated). `netns-tunnel-test` is green on the post-#161 tree (all 26 tests, both poll and uring drivers). Follow-ups found during the io_uring investigation (NOT fixed here) are worth tracking separately — chiefly: a single bad UDP recv CQE tears down the whole driver and drops the rest of the batch, reachable by any peer sending a >2048-byte datagram.

vxfemboy closed this issue

2026-08-04 05:52:45 +00:00