Skip to content

Poll for container log lines in the smoke test instead of grepping once - #10

Merged
JB09 merged 1 commit into
mainfrom
claude/new-session-4z240d
Aug 24, 2026
Merged

JB09 merged 1 commit into
mainfrom
claude/new-session-4z240d

Conversation

@JB09

@JB09 JB09 commented Aug 24, 2026

Copy link
Copy Markdown
Owner

Both log assertions in scripts/smoke_test.sh sampled docker logs exactly once, immediately after /healthz answered. The app writes those lines before uvicorn binds, so they have certainly been written by then — but the daemon's log pipeline lags by a few milliseconds, and a one-shot grep loses that race under load.

It lost in smtp-mcp-wrapper's weekly rebuild on 2026-08-24: the guard grep missed a line the failure dump printed 12ms later, in a run whose behavioural checks (foreign Host → 421) proved the guard was working. This script has the same two greps, and because fail() exits, a lost race aborts the run and takes every later phase with it.

Change

Replaces both one-shot greps with wait_for_log, which polls for up to 10s. A line that genuinely never appears still fails, just at the timeout instead of instantly. The allowlist-value assertion is unchanged — it still greps the full line including ${ROUTE_HOST}, so a guard that comes up with the wrong allowlist is still caught.

Verification

The concern with any fix for flakiness is that it stops asserting anything. Both halves were checked by extracting wait_for_log from the script and driving it against a fake docker logs that withholds the line for a set interval:

Case Result
Line present immediately returns 0 instantly, no added latency
Line lags 3s polls through, returns 0 after ~3s
Same 3s lag, original one-shot grep returns 1 — reproduces the abort
Line never appears still fails at the timeout — not a vacuous pass

The third row is direct evidence the race can abort a run rather than only a plausible story; the fourth is what keeps the assertion honest.

The full smoke test also passes all four phases with the patch applied, including the 2026-07-28 stateless path and cache-hint phases.

Note for the reviewer — a latent hazard left alone

docker logs | grep -q under set -o pipefail has a pre-existing subtlety: grep -q exits at the first match, and if the producer is still writing it takes SIGPIPE, so the pipeline returns 141 even though the match succeeded.

{ echo MATCH; seq 1 20000000; } | grep -q MATCH   → rc=141
{ echo MATCH; seq 1 20; }       | grep -q MATCH   → rc=0

This only bites once output exceeds the 64KB pipe buffer. These containers emit roughly 20 lines, so it cannot trigger here — the logs would need to grow by about three orders of magnitude. It is also not introduced by this change: the original assertions and fail() have the same shape, and inside wait_for_log the pipeline sits in an if condition, so the worst case would be a 10s timeout rather than an abort. Deliberately not changed here; noted in case the pattern gets reused somewhere logs are voluminous.


Generated by Claude Code

Both log assertions sampled `docker logs` exactly once, immediately after
/healthz answered. The app writes those lines before uvicorn binds, so they
have certainly been written by then — but the daemon's log pipeline lags by a
few milliseconds, and a one-shot grep loses that race under load.

It lost in smtp-mcp-wrapper's weekly rebuild on 2026-08-24: the guard grep
missed a line the failure dump printed 12ms later, in a run whose behavioural
checks (foreign Host -> 421) proved the guard was working. This script has the
same two greps, and because fail() exits, a lost race aborts the run and takes
every later phase with it.

Replace them with wait_for_log, which polls for up to 10s. A line that
genuinely never appears still fails, just at the timeout instead of instantly.
The allowlist-value assertion is unchanged — it still greps the full line
including ${ROUTE_HOST}.

Verified by extracting wait_for_log from the script and driving it against a
fake `docker logs`: with the line withheld for 3s the original one-shot grep
returns 1 (reproducing the abort) while wait_for_log returns 0 after ~3s; with
the line permanently absent wait_for_log still fails at its timeout, so the
assertion has not become vacuous. Full smoke test passes all four phases with
the patch applied.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01QoUUHzB1EGb9BMjbqG2kqn
@JB09
JB09 merged commit 32d26b6 into main Aug 24, 2026
2 checks passed
@JB09
JB09 deleted the claude/new-session-4z240d branch August 25, 2026 01:19
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.

2 participants