wake/store T7 CI-timing flake: date +%s second-granularity vs <2s threshold (de-flake to sub-second) #918

Closed
opened 2026-07-26 06:06:44 +00:00 by jason.woltje · 0 comments
Owner

Pre-existing CI-runner timing flake in the W2 store/ack harness, surfaced (NOT caused) by #916's CI run.

T7 ('ack local-write NEVER blocks on network') in test-wake-store-ack.sh measures start=$(date +%s) ... end=$(date +%s); elapsed=end-start; asserts elapsed -lt 2 while a background WAKE_ACK_SYNC_CMD="sleep 3" runs — proving the synchronous ack detaches the slow sync and returns fast. date +%s is SECOND-granularity, so a legitimate sub-second ack that straddles a wall-clock second boundary reads elapsed=2 and FAILS. Independent diagnosis (20 sequential local runs at d0bdad93): 20/20 PASS, observed elapsed 0-1s, never hit 2 — but on a busier/slower Woodpecker runner it flips (T7 passed at pipeline 2056, failed at 2057 with byte-identical ack.sh). Confirmed NOT a product/format regression (ack.sh #916 diff is confined to cmd_embed; cmd_consumed + the async-detach path are unchanged; the T7 file is byte-identical to main).

FIX (test-only, determinism): measure with sub-second resolution — date +%s.%N and compare against a float threshold via awk (e.g. elapsed < ~1.5s), OR nanosecond diff < ~1500ms. Preserve ALL of T7's invariants unchanged (CONSUMED reported; local ledger written synchronously; consumed_seq advanced; NET_CALLED_SYNC absent; SYNC_DONE absent). The point — ack returns well before the 3s sync — is proven robustly by a sub-second measurement; do NOT just bump the threshold to hide a real block, and do NOT re-run red (the flake recurs). Refs: #892, #916 CI 2057.

Pre-existing CI-runner timing flake in the W2 store/ack harness, surfaced (NOT caused) by #916's CI run. **T7** ('ack local-write NEVER blocks on network') in `test-wake-store-ack.sh` measures `start=$(date +%s)` ... `end=$(date +%s)`; `elapsed=end-start`; asserts `elapsed -lt 2` while a background `WAKE_ACK_SYNC_CMD="sleep 3"` runs — proving the synchronous ack detaches the slow sync and returns fast. `date +%s` is SECOND-granularity, so a legitimate sub-second ack that straddles a wall-clock second boundary reads `elapsed=2` and FAILS. Independent diagnosis (20 sequential local runs at d0bdad93): 20/20 PASS, observed elapsed 0-1s, never hit 2 — but on a busier/slower Woodpecker runner it flips (T7 passed at pipeline 2056, failed at 2057 with byte-identical ack.sh). Confirmed NOT a product/format regression (ack.sh #916 diff is confined to cmd_embed; cmd_consumed + the async-detach path are unchanged; the T7 file is byte-identical to main). **FIX (test-only, determinism):** measure with sub-second resolution — `date +%s.%N` and compare against a float threshold via awk (e.g. elapsed < ~1.5s), OR nanosecond diff < ~1500ms. Preserve ALL of T7's invariants unchanged (CONSUMED reported; local ledger written synchronously; consumed_seq advanced; NET_CALLED_SYNC absent; SYNC_DONE absent). The point — ack returns well before the 3s sync — is proven robustly by a sub-second measurement; do NOT just bump the threshold to hide a real block, and do NOT re-run red (the flake recurs). Refs: #892, #916 CI 2057.
Mos closed this issue 2026-07-26 06:46:29 +00:00
Sign in to join this conversation.
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: mosaicstack/stack#918