From e9dd3167f231cd8df12809334d780fbcbb878bd1 Mon Sep 17 00:00:00 2001 From: Johnathan Corgan Date: Thu, 14 May 2026 17:07:32 +0000 Subject: [PATCH] test(acl-allowlist): poll log assertion to absorb XX-handshake timing race Convert assert_log_contains from a one-shot grep snapshot into a bounded poll that retries until the pattern appears or the timeout elapses (default 15s). Same wait-with-timeout shape as wait_for_peers_exact above it in the file. The pre-existing flake on next-branch CI is structural: under XX handshake, the cross-connection tie-breaker selects which side reaches its ACL-check point first. When container-a wins the tie-breaker on the first attempt against c and d, only the outbound-handshake-context rejection fires immediately, and the inbound-handshake-context rejection only emits on a later retry when c or d's msg1 lands while a has no pending outbound. On one 2026-05-14 run the inbound rejection appeared 63ms after the test had given up. The race window is small but real. Polling the log instead of one-shot reading absorbs the millisecond-to-second variance without slowing the success path (the helper returns as soon as the pattern appears). --- testing/acl-allowlist/test.sh | 24 ++++++++++++++++++------ 1 file changed, 18 insertions(+), 6 deletions(-) diff --git a/testing/acl-allowlist/test.sh b/testing/acl-allowlist/test.sh index 2bf8565..f56438c 100755 --- a/testing/acl-allowlist/test.sh +++ b/testing/acl-allowlist/test.sh @@ -98,13 +98,25 @@ wait_for_peers_exact() { assert_log_contains() { local container="$1" local pattern="$2" + local timeout="${3:-15}" local logs - logs="$(docker logs "$container" 2>&1 | python3 -c 'import re,sys; print(re.sub(r"\x1b\[[0-9;]*m", "", sys.stdin.read()), end="")' || true)" - if ! printf '%s' "$logs" | grep -F "$pattern" >/dev/null; then - echo "FAIL: missing log pattern in $container: $pattern" >&2 - exit 1 - fi - echo "PASS: $container logs contain expected ACL rejection" + + # Poll docker logs instead of one-shot reading: under XX handshake, + # the cross-connection tie-breaker determines which side reaches + # its ACL-check point first, so the inbound-handshake-context + # rejection may not emit until a later retry. Same wait-with-timeout + # shape as wait_for_peers_exact above. + for _ in $(seq 1 "$timeout"); do + logs="$(docker logs "$container" 2>&1 | python3 -c 'import re,sys; print(re.sub(r"\x1b\[[0-9;]*m", "", sys.stdin.read()), end="")' || true)" + if printf '%s' "$logs" | grep -F "$pattern" >/dev/null; then + echo "PASS: $container logs contain expected ACL rejection" + return 0 + fi + sleep 1 + done + + echo "FAIL: missing log pattern in $container: $pattern (waited ${timeout}s)" >&2 + exit 1 } if [ "$SKIP_BUILD" = false ]; then