@@ -117,7 +117,10 @@ function prepare_policy_repo {
117117
118118 # Wait for Gitea to be ready and initialized
119119 echo " Waiting for Gitea to be ready..."
120- timeout=120
120+ # Generous budget: gitea can take minutes to bring the web listener up on slow
121+ # bind-mount I/O (e.g. Docker Desktop) — the loop exits as soon as it is ready,
122+ # so fast environments (CI) pay nothing for the headroom.
123+ timeout=300
121124 counter=0
122125 while ! curl -sf http://localhost:3000 > /dev/null 2>&1 ; do
123126 counter=$(( counter + 1 ))
@@ -223,10 +226,17 @@ function compose {
223226 docker compose -f ./docker-compose-app-tests.yml --env-file .env " $@ "
224227}
225228
229+ # The positive assertions must exit explicitly on a miss: `main` runs on the
230+ # left of `&&` (see the retry loop), which suppresses `set -e` throughout it,
231+ # so a helper that merely returns grep's status can never fail the run.
226232function check_clients_logged {
227233 echo " - Looking for msg '$1 ' in client's logs"
228- compose logs --index 1 opal_client | grep -q " $1 "
229- compose logs --index 2 opal_client | grep -q " $1 "
234+ for index in 1 2; do
235+ if ! compose logs --index " $index " opal_client | grep -q " $1 " ; then
236+ echo " - '$1 ' not found in client $index logs"
237+ exit 1
238+ fi
239+ done
230240}
231241
232242function check_no_error {
@@ -240,18 +250,85 @@ function check_no_error {
240250
241251function check_servers_logged {
242252 echo " - Looking for msg '$1 ' in server's logs"
243- compose logs opal_server | grep -q " $1 "
253+ if ! compose logs opal_server | grep -q " $1 " ; then
254+ echo " - '$1 ' not found in server logs"
255+ exit 1
256+ fi
244257}
245258
259+ # The negative assertions capture the logs first: piped directly into grep, a
260+ # failing `compose logs` (daemon hiccup, renamed service) is indistinguishable
261+ # from "message absent" and the check silently passes. (pipefail wouldn't help —
262+ # the `if pipeline; then fail; fi` shape falls through on ANY pipeline failure.)
246263function check_servers_not_logged {
247264 echo " - Ensuring msg '$1 ' is absent from server's logs"
248- if compose logs opal_server | grep -q " $1 " ; then
265+ local logs
266+ logs=$( compose logs opal_server)
267+ if [[ -z " $logs " ]]; then
268+ echo " - Could not retrieve any server logs"
269+ exit 1
270+ fi
271+ if grep -q " $1 " <<< " $logs" ; then
249272 echo " - Unexpectedly found '$1 ' in server logs:"
250- compose logs opal_server | grep " $1 "
273+ grep " $1 " <<< " $logs "
251274 exit 1
252275 fi
253276}
254277
278+ function check_clients_not_logged {
279+ echo " - Ensuring msg '$1 ' is absent from client's logs"
280+ local logs
281+ logs=$( compose logs opal_client)
282+ if [[ -z " $logs " ]]; then
283+ echo " - Could not retrieve any client logs"
284+ exit 1
285+ fi
286+ if grep -q " $1 " <<< " $logs" ; then
287+ echo " - Unexpectedly found '$1 ' in client logs:"
288+ grep " $1 " <<< " $logs"
289+ exit 1
290+ fi
291+ }
292+
293+ function wait_for_servers_logged {
294+ # Poll (up to $2 seconds) until a server logs $1 — for assertions whose
295+ # timing depends on periodic tasks rather than the just-issued request.
296+ echo " - Waiting (up to ${2} s) for msg '$1 ' in server's logs"
297+ for _ in $( seq 1 " $2 " ) ; do
298+ if compose logs opal_server 2> /dev/null | grep -q " $1 " ; then
299+ return 0
300+ fi
301+ sleep 1
302+ done
303+ echo " - Timed out waiting for '$1 ' in server logs"
304+ exit 1
305+ }
306+
307+ function count_backbone_drops {
308+ # Lines the reconnecting reader logs when an established backbone subscription
309+ # ends (clean close or error) — i.e. the moments the publish-freeze gate closes.
310+ compose logs opal_server 2> /dev/null \
311+ | grep -cE " Broadcast subscriber ended|Broadcaster listener error" || true
312+ }
313+
314+ function wait_for_backbone_drop {
315+ # Wait until a server worker OBSERVES the backbone drop (a drop-log line past
316+ # the pre-kill baseline in $1): the freeze only engages once the reader's read
317+ # cycle exits and clears its connected flag, so publishing after a fixed sleep
318+ # races that observation.
319+ echo " - Waiting for a server to observe the backbone drop"
320+ local baseline=$1
321+ for _ in $( seq 1 30) ; do
322+ if (( $(count_backbone_drops) > baseline )) ; then
323+ echo " backbone drop observed"
324+ return 0
325+ fi
326+ sleep 1
327+ done
328+ echo " no server observed the backbone drop in time"
329+ exit 1
330+ }
331+
255332function wait_for_broadcaster {
256333 echo " - Waiting for broadcast_channel to accept connections"
257334 for _ in $( seq 1 30) ; do
@@ -402,24 +479,43 @@ function main {
402479 check_servers_not_logged " list.remove(x): x not in list"
403480
404481 # Cross-instance consistency: publish an update WHILE the backbone is down, then
405- # recover. The two clients connect to different server replicas via the service VIP,
406- # so for BOTH to end up with the value the missed cross-server update must converge
407- # after recovery (via the replay buffer and/or the resync-on-reconnect path).
482+ # recover. The two clients connect to different server replicas via the service VIP.
483+ # With BROADCAST_FREEZE_ON_DISCONNECT (the default), a client-facing publish that
484+ # cannot fan out to the whole fleet is FROZEN — applied by NO client — so the fleet
485+ # never splits (one replica's clients seeing the update while the other's don't).
486+ # One-off updates like this one are not part of the clients' configured data
487+ # sources, so the freeze DROPS them (documented trade); freshness is restored by
488+ # re-publishing after recovery, and the fleet converges together.
408489 echo " - Testing cross-instance consistency across a backbone outage"
490+ drops_before=$( count_backbone_drops)
409491 compose kill broadcast_channel
410- sleep 3
492+ wait_for_backbone_drop " $drops_before "
411493 publish_data " consistency_user"
412494 sleep 2
495+ # The receiving server must have frozen the publish at the gate...
496+ check_servers_logged " freezing publish to preserve fleet consistency"
413497 compose up -d broadcast_channel
414498 wait_for_broadcaster
415- # allow buffered replay + (if needed) client resync + full refetch to settle
499+ # allow recovery: exempt-topic replay + client resync + full refetch to settle
416500 sleep 15
417- # The server that received the publish while the backbone was down must have
418- # buffered it and replayed it on recovery (proves the replay path actually ran,
419- # not just a client refetch).
501+ # Internal (exempt) topics still ride the pre-freeze buffer+replay path during the
502+ # gap — these lines prove that path stayed intact alongside the freeze.
420503 check_servers_logged " buffered for replay"
421504 check_servers_logged " Replaying"
422- # BOTH clients (on different replicas via the VIP) must end up with the value.
505+ # Recovery resynced this worker's clients (the freeze's convergence path).
506+ check_servers_logged " resyncing this worker's clients"
507+ # THE consistency assertion: the frozen update reached NO client — neither during
508+ # the gap nor via replay after it. No fleet split.
509+ check_clients_not_logged " PUT /v1/data/users/consistency_user/location -> 204"
510+ # After recovery the fleet is fully functional: re-publish and BOTH clients
511+ # (on different replicas via the VIP) converge on the value together.
512+ publish_data " consistency_user"
513+ sleep 5
514+ # The freeze-episode summary is logged by the WORKER that froze, on its next
515+ # delivered publish — and the re-publish above lands on 1 of N workers. In
516+ # practice the exempt statistics keepalive (~10s, exercising every worker)
517+ # delivers it; poll rather than assume one fixed delay covers that coupling.
518+ wait_for_servers_logged " publish(es) during the gap" 30
423519 check_clients_logged " PUT /v1/data/users/consistency_user/location -> 204"
424520 # TODO: Test statistics feature again after broadcaster restart (should first fix statistics bug)
425521}
@@ -430,7 +526,10 @@ RETRY_COUNT=0
430526
431527while [ $RETRY_COUNT -lt $MAX_RETRIES ]; do
432528 echo " Running test (attempt $(( RETRY_COUNT+ 1 )) of $MAX_RETRIES )..."
433- main && break
529+ # Run main in a subshell: the assertion helpers fail via `exit 1` (see
530+ # check_clients_logged), which would otherwise terminate the whole script
531+ # through the EXIT trap and skip these retries entirely.
532+ (main) && break
434533 RETRY_COUNT=$(( RETRY_COUNT + 1 ))
435534 echo " Test failed, retrying..."
436535 # Tear the stack down before retrying so the next attempt starts clean:
0 commit comments