test(wake): #918 de-flake T7 ack-no-network-block (sub-second timing) #919

jason.woltje · 2026-07-26T06:30:50Z

jason.woltje commented

2026-07-26 06:30:50 +00:00

Closes #918
Part of #892

T7 ("ack local-write NEVER blocks on network") measured timing with second-granularity date +%s around the ack call, then asserted elapsed -lt 2 against a background WAKE_ACK_SYNC_CMD="sleep 3; ...". Because date +%s truncates to whole seconds, a legitimately fast (sub-second) ack that straddles a wall-clock second boundary could read elapsed=2 and fail the assertion — a pre-existing CI-timing flake (observed on Woodpecker pipeline 2057; 20/20 local passes elsewhere, confirming it's timing-resolution, not a real regression).

Fix (test-only, no behavior change):

Switch start/end capture to date +%s.%N (sub-second resolution).
Compute elapsed in milliseconds via awk (bash [ ] can't do float/ms comparisons).
Assert elapsed_ms -lt 1500 instead of elapsed -lt 2 — still comfortably below the 3s background sync (proving the ack did not wait on it), while tolerating boundary jitter for a legitimate sub-second-to-~1s ack.
Every other T7 assertion is byte-unchanged: CONSUMED reported, local ack-ledger write, consumed_seq advance, NET_CALLED_SYNC absent (no network on the sync path), SYNC_DONE absent (background sync still in flight).

Verification:

30/30 sequential runs of test-wake-store-ack.sh pass; sampled elapsed_ms values ranged ~200-280ms (well sub-second).
Regression-proof: temporarily made the ack path run WAKE_ACK_SYNC_CMD synchronously (removed backgrounding in ack.sh) — T7 correctly went RED (elapsed_ms=3294, over the 1500ms threshold, plus the SYNC_DONE-in-flight assertion also caught it); reverted ack.sh back to original (0 diff).
pnpm run test:framework-shell passes (rc=0) both normally and with openssl masked from PATH (verified command -v openssl empty in that environment; two openssl-gated HMAC subtests correctly SKIP).
shellcheck 0.11.0 clean on the modified file.
git diff --stat: only test-wake-store-ack.sh touched. No manifest bump (following precedent of prior test-only de-flake commit b0d78d8/#861, which also did not bump any manifest).

Closes #918 Part of #892 T7 ("ack local-write NEVER blocks on network") measured timing with second-granularity `date +%s` around the ack call, then asserted `elapsed -lt 2` against a background `WAKE_ACK_SYNC_CMD="sleep 3; ..."`. Because `date +%s` truncates to whole seconds, a legitimately fast (sub-second) ack that straddles a wall-clock second boundary could read elapsed=2 and fail the assertion — a pre-existing CI-timing flake (observed on Woodpecker pipeline 2057; 20/20 local passes elsewhere, confirming it's timing-resolution, not a real regression). Fix (test-only, no behavior change): - Switch start/end capture to `date +%s.%N` (sub-second resolution). - Compute elapsed in milliseconds via `awk` (bash `[ ]` can't do float/ms comparisons). - Assert elapsed_ms -lt 1500 instead of elapsed -lt 2 — still comfortably below the 3s background sync (proving the ack did not wait on it), while tolerating boundary jitter for a legitimate sub-second-to-~1s ack. - Every other T7 assertion is byte-unchanged: CONSUMED reported, local ack-ledger write, consumed_seq advance, NET_CALLED_SYNC absent (no network on the sync path), SYNC_DONE absent (background sync still in flight). Verification: - 30/30 sequential runs of test-wake-store-ack.sh pass; sampled elapsed_ms values ranged ~200-280ms (well sub-second). - Regression-proof: temporarily made the ack path run WAKE_ACK_SYNC_CMD synchronously (removed backgrounding in ack.sh) — T7 correctly went RED (elapsed_ms=3294, over the 1500ms threshold, plus the SYNC_DONE-in-flight assertion also caught it); reverted ack.sh back to original (0 diff). - `pnpm run test:framework-shell` passes (rc=0) both normally and with openssl masked from PATH (verified `command -v openssl` empty in that environment; two openssl-gated HMAC subtests correctly SKIP). - shellcheck 0.11.0 clean on the modified file. - git diff --stat: only test-wake-store-ack.sh touched. No manifest bump (following precedent of prior test-only de-flake commit b0d78d8/#861, which also did not bump any manifest).

jason.woltje added 1 commit 2026-07-26 06:30:51 +00:00

test(wake): T7 sub-second timing — de-flake ack-no-network-block (date +%s.%N vs <1.5s); #918

ci/woodpecker/pr/ci Pipeline was successful

Details

b3dbab6c88

jason.woltje commented

2026-07-26 06:45:52 +00:00

Record of Review — PR #919 (issue #918): T7 sub-second timing de-flake — FINAL, CI-GREEN

VERDICT: APPROVE — GO. REVIEWED-HEAD (full-40): b3dbab6c889a7255769011bbbadd1f8c05d93858. CI: TERMINAL-GREEN at this exact head.

Review basis

Independent reviewer aa1e81ef (≠ builder mosaic-coder) — APPROVE, all 4 criteria PASS, verified against runtime (reproduced, not narrative-trusted):

Scope/provenance — head==b3dbab6c…; mergeable (no conflicts); PR-author id2 ≠ commit-author mosaic-coder; body Closes #918 + Part of #892; delta touches ONLY test-wake-store-ack.sh (12+/4−); no manifest bump (consistent with test-only precedent b0d78d86/#861).
De-flake correct — T7 now measures date +%s.%N → elapsed_ms via awk (e-s)*1000, asserts <1500ms (genuine sub-second resolution; 1500ms is well below the 3000ms background sync and well above real ack latency). Reviewer reran the harness 26/26 green, sampled elapsed 26–58ms.
Invariant NOT weakened — reviewer forced the ack to run WAKE_ACK_SYNC_CMD synchronously (mutated _ship_async to foreground) → T7 went RED ("ack path blocked 3273ms" AND the independent SYNC_DONE-in-flight assertion), then reverted (sha256-verified byte-identical). The other T7 assertions (CONSUMED reported; ack-ledger synchronous write; consumed_seq advance; NET_CALLED_SYNC absent; SYNC_DONE absent) are byte-unchanged — only the timing lines changed. So it still catches a genuine block; this is a determinism fix, not threshold-hiding.
Gates @ head — shellcheck 0.11 clean; test:framework-shell rc=0 normal AND openssl-masked (HMAC subtests SKIP correctly); firewall jason|woltje|jarvis=0 on added lines.

Non-blocking follow-ups (reviewer)

awk %d truncates vs rounds (negligible at the 1500/3000ms margins); env timing variance (25× under threshold either way). Neither blocks.

6-check — GO

open/mergeable base main ✓ · 2. CI TERMINAL-GREEN @ full-40 b3dbab6c889a7255769011bbbadd1f8c05d93858 ✓ · 3. reviewer(aa1e81ef)≠builder durable RoR ✓ · 4. reviewed==CI==merge-head all b3dbab6c ✓ · 5. body Closes #918 + Part of #892 ✓ · 6. queue-guard at merge.
GO for id-11 + squash-merge at FULL-40 b3dbab6c889a7255769011bbbadd1f8c05d93858. Closes #918 (pre-existing store-ack timing flake, sub-second de-flaked). On merge, mains T7 is deterministic → #916 union-updates onto it next. Non-executor.

# Record of Review — PR #919 (issue #918): T7 sub-second timing de-flake — FINAL, CI-GREEN **VERDICT: APPROVE — GO.** **REVIEWED-HEAD (full-40):** `b3dbab6c889a7255769011bbbadd1f8c05d93858`. **CI: TERMINAL-GREEN** at this exact head. ## Review basis Independent reviewer `aa1e81ef` (≠ builder `mosaic-coder`) — **APPROVE, all 4 criteria PASS**, verified against runtime (reproduced, not narrative-trusted): 1. **Scope/provenance** — head==`b3dbab6c…`; mergeable (no conflicts); PR-author id2 ≠ commit-author `mosaic-coder`; body `Closes #918` + `Part of #892`; delta touches ONLY `test-wake-store-ack.sh` (12+/4−); no manifest bump (consistent with test-only precedent `b0d78d86`/#861). 2. **De-flake correct** — T7 now measures `date +%s.%N` → `elapsed_ms` via awk `(e-s)*1000`, asserts `<1500`ms (genuine sub-second resolution; 1500ms is well below the 3000ms background sync and well above real ack latency). Reviewer reran the harness **26/26 green**, sampled elapsed 26–58ms. 3. **Invariant NOT weakened** — reviewer forced the ack to run `WAKE_ACK_SYNC_CMD` synchronously (mutated `_ship_async` to foreground) → T7 went **RED** ("ack path blocked 3273ms" AND the independent SYNC_DONE-in-flight assertion), then reverted (sha256-verified byte-identical). The other T7 assertions (CONSUMED reported; ack-ledger synchronous write; consumed_seq advance; NET_CALLED_SYNC absent; SYNC_DONE absent) are byte-unchanged — only the timing lines changed. So it still catches a genuine block; this is a determinism fix, not threshold-hiding. 4. **Gates @ head** — shellcheck 0.11 clean; `test:framework-shell` rc=0 normal AND openssl-masked (HMAC subtests SKIP correctly); firewall `jason|woltje|jarvis`=0 on added lines. ## Non-blocking follow-ups (reviewer) awk `%d` truncates vs rounds (negligible at the 1500/3000ms margins); env timing variance (25× under threshold either way). Neither blocks. ## 6-check — GO 1. open/mergeable base main ✓ · 2. **CI TERMINAL-GREEN @ full-40 `b3dbab6c889a7255769011bbbadd1f8c05d93858`** ✓ · 3. reviewer(`aa1e81ef`)≠builder durable RoR ✓ · 4. reviewed==CI==merge-head all `b3dbab6c` ✓ · 5. body `Closes #918` + `Part of #892` ✓ · 6. queue-guard at merge. **GO for id-11 + squash-merge at FULL-40 `b3dbab6c889a7255769011bbbadd1f8c05d93858`. Closes #918 (pre-existing store-ack timing flake, sub-second de-flaked). On merge, mains T7 is deterministic → #916 union-updates onto it next. Non-executor.**

Mos approved these changes 2026-07-26 06:46:28 +00:00

Mos left a comment

First-time contributor

GO — Gate-16 id-11 stamp, pinned to exact FULL head b3dbab6c88.
Basis: verbatim FINAL RoR (comment 19058) — independent review APPROVE 4/4: determinism reproduced 26/26 at millisecond precision, the real-block regression fires RED at 3273ms (the invariant keeps teeth — a de-flake, not a threshold-hide), revert-integrity sha256-verified. CI terminal-green. Closes #918; with this merge main's T7 is deterministic and #916 rides it next. Part of #892. Named executor: Mos (id-11), squash pinned.

GO — Gate-16 id-11 stamp, pinned to exact FULL head b3dbab6c889a7255769011bbbadd1f8c05d93858. Basis: verbatim FINAL RoR (comment 19058) — independent review APPROVE 4/4: determinism reproduced 26/26 at millisecond precision, the real-block regression fires RED at 3273ms (the invariant keeps teeth — a de-flake, not a threshold-hide), revert-integrity sha256-verified. CI terminal-green. Closes #918; with this merge main's T7 is deterministic and #916 rides it next. Part of #892. Named executor: Mos (id-11), squash pinned.

Mos merged commit c585ac3326 into main

2026-07-26 06:46:29 +00:00

Mos deleted branch fix/wake-918-t7-deflake

2026-07-26 06:46:30 +00:00

Mos referenced this issue from a commit

2026-07-26 06:46:30 +00:00

test(wake): #918 de-flake T7 ack-no-network-block (sub-second timing) (#919)

jason.woltje referenced this pull request

2026-07-26 07:12:30 +00:00

fix(wake): #914 digest renderer — WAKE_AGENT-prefixed ack line + digest-class locator threading #916

Mos referenced this pull request

2026-07-26 07:13:06 +00:00