From e4973eb8a49b72167a66b643cc3148f18cb3fac3 Mon Sep 17 00:00:00 2001 From: Dai Ha Date: Sat, 5 Sep 2026 05:29:53 +0700 Subject: [PATCH 1/3] Classify recovered AMQP redeploy errors --- scripts/redeploy-fleetd.sh | 53 +++++++++++++++-- scripts/test-redeploy-fleetd.sh | 102 ++++++++++++++++++++++++++++++++ 2 files changed, 149 insertions(+), 6 deletions(-) create mode 100755 scripts/test-redeploy-fleetd.sh diff --git a/scripts/redeploy-fleetd.sh b/scripts/redeploy-fleetd.sh index a2ee281..f6322ab 100755 --- a/scripts/redeploy-fleetd.sh +++ b/scripts/redeploy-fleetd.sh @@ -116,6 +116,41 @@ check_log_path_matches_plist() { ok "log path check: script and plist agree ($resolved_out)" } +# Classify ERROR lines in one fresh log region. RabbitMQ's client reports a lost TCP connection +# through ForgivingExceptionHandler. We only quiet its exact "Connection reset" error after one of +# fleetd's own recovery listeners later reports a completed AMQP recovery. Every other ERROR, and +# every unmatched reset, stays unexplained so a failed broker link remains loud. +classify_amqp_connection_errors() { + local log_file="$1" line pending_resets=0 + REDEPLOY_ERROR_COUNT=0 + REDEPLOY_RECOVERED_AMQP_ERRORS=0 + REDEPLOY_UNEXPLAINED_ERRORS=0 + + while IFS= read -r line || [ -n "$line" ]; do + case "$line" in + *' ERROR '*|*' SEVERE '*) + REDEPLOY_ERROR_COUNT=$((REDEPLOY_ERROR_COUNT + 1)) + case "$line" in + *'com.rabbitmq.client.impl.ForgivingExceptionHandler'*'Connection reset'*) + pending_resets=$((pending_resets + 1)) + ;; + *) + REDEPLOY_UNEXPLAINED_ERRORS=$((REDEPLOY_UNEXPLAINED_ERRORS + 1)) + ;; + esac + ;; + *'AMQP connection recovered; cleared held replies for fresh redelivery'*|*'AMQP lead mailbox connection recovered; cleared held messages for fresh redelivery'*) + if [ "$pending_resets" -gt 0 ]; then + pending_resets=$((pending_resets - 1)) + REDEPLOY_RECOVERED_AMQP_ERRORS=$((REDEPLOY_RECOVERED_AMQP_ERRORS + 1)) + fi + ;; + esac + done < "$log_file" + + REDEPLOY_UNEXPLAINED_ERRORS=$((REDEPLOY_UNEXPLAINED_ERRORS + pending_resets)) +} + # CB-600: sourceable for testing. When this file is SOURCED (not executed) it stops here — nothing # below runs — so a test harness can `source` it to call check_log_path_matches_plist (or the # other pure helpers above) against a throwaway plist fixture without ever reaching the mutating @@ -361,15 +396,21 @@ tail -n "+$((RESTART_MARK + 1))" "$OUT" 2>/dev/null \ | grep -iE 'deferred|classification:|fleet health:|coverage' | tail -8 | sed 's/^/ /' \ || echo " (nothing reported)" -# Errors since the restart, anchored to the marker so old noise cannot leak in. -ERRS="$(tail -n "+$((RESTART_MARK + 1))" "$OUT" 2>/dev/null | grep -cE ' (ERROR|SEVERE) ' || true)" +# Errors since the restart, anchored to the marker so old noise cannot leak in. Keep the fresh +# region in a file because the classifier must preserve the order of errors and recoveries. +FRESH_LOG="$(mktemp -t fleetd-fresh-log)" +trap 'rm -f "$FRESH_LOG"' EXIT +tail -n "+$((RESTART_MARK + 1))" "$OUT" > "$FRESH_LOG" 2>/dev/null || true +classify_amqp_connection_errors "$FRESH_LOG" say "result" ok "pid $NEW_PID, jar $(jar_id)" -if [ "${ERRS:-0}" -gt 0 ]; then - warn "$ERRS ERROR lines since restart:" - tail -n "+$((RESTART_MARK + 1))" "$OUT" | grep -E ' (ERROR|SEVERE) ' | tail -5 | sed 's/^/ /' -else +if [ "$REDEPLOY_ERROR_COUNT" -eq 0 ]; then ok "no ERROR lines since restart" +elif [ "$REDEPLOY_UNEXPLAINED_ERRORS" -eq 0 ]; then + ok "$REDEPLOY_RECOVERED_AMQP_ERRORS AMQP connection reset ERROR lines recovered since restart" +else + warn "$REDEPLOY_ERROR_COUNT ERROR lines since restart:" + grep -E ' (ERROR|SEVERE) ' "$FRESH_LOG" | tail -5 | sed 's/^/ /' fi echo echo " Next: call fleet_whoami and confirm it still answers 'primary'. A lead whose tab label" diff --git a/scripts/test-redeploy-fleetd.sh b/scripts/test-redeploy-fleetd.sh new file mode 100755 index 0000000..d16b8e1 --- /dev/null +++ b/scripts/test-redeploy-fleetd.sh @@ -0,0 +1,102 @@ +#!/usr/bin/env bash +# Self-contained checks for the pure log classifier in redeploy-fleetd.sh. + +set -euo pipefail + +ROOT="$(cd "$(dirname "${BASH_SOURCE[0]}")/.." && pwd)" +TMP="$(mktemp -d "$ROOT/.redeploy-log-test.XXXXXX")" +trap 'rm -rf "$TMP"' EXIT + +# Sourcing stops before redeploy-fleetd.sh can build, stop, or start the daemon. +source "$ROOT/scripts/redeploy-fleetd.sh" + +fail() { + printf 'FAIL: %s\n' "$*" >&2 + return 1 +} + +assert_equals() { + local expected="$1" actual="$2" description="$3" + [ "$expected" = "$actual" ] || fail "$description: expected $expected, got $actual" +} + +classify_fixture() { + local name="$1" + classify_amqp_connection_errors "$TMP/$name" +} + +test_no_errors() { + cat > "$TMP/no-errors.log" <<'LOG' +2026-09-05 12:00:00 INFO fleetd listening +LOG + classify_fixture no-errors.log + assert_equals 0 "$REDEPLOY_ERROR_COUNT" "no-errors total" + assert_equals 0 "$REDEPLOY_UNEXPLAINED_ERRORS" "no-errors unexplained" +} + +test_recovered_connection_error() { + cat > "$TMP/recovered.log" <<'LOG' +2026-09-05 12:00:00 ERROR com.rabbitmq.client.impl.ForgivingExceptionHandler - An unexpected connection driver error occurred (Exception message: Connection reset) +2026-09-05 12:00:01 INFO dev.ltms.fleet.msg.AmqpReplyInbox - AMQP connection recovered; cleared held replies for fresh redelivery +LOG + classify_fixture recovered.log + assert_equals 1 "$REDEPLOY_ERROR_COUNT" "recovered total" + assert_equals 1 "$REDEPLOY_RECOVERED_AMQP_ERRORS" "recovered AMQP errors" + assert_equals 0 "$REDEPLOY_UNEXPLAINED_ERRORS" "recovered unexplained" +} + +test_unrecovered_connection_error() { + cat > "$TMP/unrecovered.log" <<'LOG' +2026-09-05 12:00:00 ERROR com.rabbitmq.client.impl.ForgivingExceptionHandler - An unexpected connection driver error occurred (Exception message: Connection reset) +LOG + classify_fixture unrecovered.log + assert_equals 1 "$REDEPLOY_ERROR_COUNT" "unrecovered total" + assert_equals 0 "$REDEPLOY_RECOVERED_AMQP_ERRORS" "unrecovered AMQP errors" + assert_equals 1 "$REDEPLOY_UNEXPLAINED_ERRORS" "unrecovered unexplained" +} + +test_other_error_is_unexplained() { + cat > "$TMP/other-error.log" <<'LOG' +2026-09-05 12:00:00 ERROR dev.ltms.fleet.Fleetd - startup failed +2026-09-05 12:00:01 INFO dev.ltms.fleet.msg.AmqpReplyInbox - AMQP connection recovered; cleared held replies for fresh redelivery +LOG + classify_fixture other-error.log + assert_equals 1 "$REDEPLOY_ERROR_COUNT" "other-error total" + assert_equals 1 "$REDEPLOY_UNEXPLAINED_ERRORS" "other-error unexplained" +} + +test_mutation_is_caught() { + classify_amqp_connection_errors() { + local log_file="$1" line + REDEPLOY_ERROR_COUNT=0 + REDEPLOY_RECOVERED_AMQP_ERRORS=0 + REDEPLOY_UNEXPLAINED_ERRORS=0 + while IFS= read -r line || [ -n "$line" ]; do + case "$line" in + *' ERROR '*|*' SEVERE '*) + REDEPLOY_ERROR_COUNT=$((REDEPLOY_ERROR_COUNT + 1)) + case "$line" in + *'com.rabbitmq.client.impl.ForgivingExceptionHandler'*'Connection reset'*) + REDEPLOY_RECOVERED_AMQP_ERRORS=$((REDEPLOY_RECOVERED_AMQP_ERRORS + 1)) + ;; + *) REDEPLOY_UNEXPLAINED_ERRORS=$((REDEPLOY_UNEXPLAINED_ERRORS + 1)) ;; + esac + ;; + esac + done < "$log_file" + } + + if test_unrecovered_connection_error > "$TMP/mutation-output" 2>&1; then + fail "mutation accepted an unrecovered connection error" + fi + grep -F 'FAIL: unrecovered AMQP errors: expected 0, got 1' "$TMP/mutation-output" > /dev/null \ + || fail "mutation failed without the expected assertion" + printf 'Mutation check: FAIL: unrecovered AMQP errors: expected 0, got 1\n' +} + +test_no_errors +test_recovered_connection_error +test_unrecovered_connection_error +test_other_error_is_unexplained +test_mutation_is_caught +printf 'PASS: redeploy log classifier\n' From 0241e0d3a8fefd9ff36e25392f85d5195fc88fb8 Mon Sep 17 00:00:00 2001 From: Dai Ha Date: Sat, 5 Sep 2026 05:36:53 +0700 Subject: [PATCH 2/3] Keep unattributed AMQP errors loud --- scripts/redeploy-fleetd.sh | 37 +++++---- scripts/test-redeploy-fleetd.sh | 138 +++++++++++++++++++++++++++----- 2 files changed, 143 insertions(+), 32 deletions(-) diff --git a/scripts/redeploy-fleetd.sh b/scripts/redeploy-fleetd.sh index f6322ab..d2ce73f 100755 --- a/scripts/redeploy-fleetd.sh +++ b/scripts/redeploy-fleetd.sh @@ -116,12 +116,13 @@ check_log_path_matches_plist() { ok "log path check: script and plist agree ($resolved_out)" } -# Classify ERROR lines in one fresh log region. RabbitMQ's client reports a lost TCP connection -# through ForgivingExceptionHandler. We only quiet its exact "Connection reset" error after one of -# fleetd's own recovery listeners later reports a completed AMQP recovery. Every other ERROR, and -# every unmatched reset, stays unexplained so a failed broker link remains loud. +# Classify ERROR lines in one fresh log region. The logging layout abbreviates logger packages, so +# match simple class names and the handler's actual ERROR messages. An error can be quiet only when +# its own line names AmqpReplyInbox or LeadMailbox; the handler lines now seen in fleetd.out name +# neither connection, so they deliberately stay unexplained. This avoids letting one connection's +# recovery hide a failure in the other connection. classify_amqp_connection_errors() { - local log_file="$1" line pending_resets=0 + local log_file="$1" line pending_inbox=0 pending_lead_mailbox=0 REDEPLOY_ERROR_COUNT=0 REDEPLOY_RECOVERED_AMQP_ERRORS=0 REDEPLOY_UNEXPLAINED_ERRORS=0 @@ -131,24 +132,32 @@ classify_amqp_connection_errors() { *' ERROR '*|*' SEVERE '*) REDEPLOY_ERROR_COUNT=$((REDEPLOY_ERROR_COUNT + 1)) case "$line" in - *'com.rabbitmq.client.impl.ForgivingExceptionHandler'*'Connection reset'*) - pending_resets=$((pending_resets + 1)) - ;; - *) - REDEPLOY_UNEXPLAINED_ERRORS=$((REDEPLOY_UNEXPLAINED_ERRORS + 1)) + *'ForgivingExceptionHandler'*'An unexpected connection driver error occurred'*|*'ForgivingExceptionHandler'*'Caught an exception during connection recovery!'*) + case "$line" in + *'AmqpReplyInbox'*) pending_inbox=$((pending_inbox + 1)) ;; + *'LeadMailbox'*) pending_lead_mailbox=$((pending_lead_mailbox + 1)) ;; + *) REDEPLOY_UNEXPLAINED_ERRORS=$((REDEPLOY_UNEXPLAINED_ERRORS + 1)) ;; + esac ;; + *) REDEPLOY_UNEXPLAINED_ERRORS=$((REDEPLOY_UNEXPLAINED_ERRORS + 1)) ;; esac ;; - *'AMQP connection recovered; cleared held replies for fresh redelivery'*|*'AMQP lead mailbox connection recovered; cleared held messages for fresh redelivery'*) - if [ "$pending_resets" -gt 0 ]; then - pending_resets=$((pending_resets - 1)) + *'AMQP connection recovered; cleared held replies for fresh redelivery'*) + if [ "$pending_inbox" -gt 0 ]; then + pending_inbox=$((pending_inbox - 1)) + REDEPLOY_RECOVERED_AMQP_ERRORS=$((REDEPLOY_RECOVERED_AMQP_ERRORS + 1)) + fi + ;; + *'AMQP lead mailbox connection recovered; cleared held messages for fresh redelivery'*) + if [ "$pending_lead_mailbox" -gt 0 ]; then + pending_lead_mailbox=$((pending_lead_mailbox - 1)) REDEPLOY_RECOVERED_AMQP_ERRORS=$((REDEPLOY_RECOVERED_AMQP_ERRORS + 1)) fi ;; esac done < "$log_file" - REDEPLOY_UNEXPLAINED_ERRORS=$((REDEPLOY_UNEXPLAINED_ERRORS + pending_resets)) + REDEPLOY_UNEXPLAINED_ERRORS=$((REDEPLOY_UNEXPLAINED_ERRORS + pending_inbox + pending_lead_mailbox)) } # CB-600: sourceable for testing. When this file is SOURCED (not executed) it stops here — nothing diff --git a/scripts/test-redeploy-fleetd.sh b/scripts/test-redeploy-fleetd.sh index d16b8e1..4ff1d95 100755 --- a/scripts/test-redeploy-fleetd.sh +++ b/scripts/test-redeploy-fleetd.sh @@ -34,20 +34,78 @@ LOG assert_equals 0 "$REDEPLOY_UNEXPLAINED_ERRORS" "no-errors unexplained" } -test_recovered_connection_error() { - cat > "$TMP/recovered.log" <<'LOG' -2026-09-05 12:00:00 ERROR com.rabbitmq.client.impl.ForgivingExceptionHandler - An unexpected connection driver error occurred (Exception message: Connection reset) -2026-09-05 12:00:01 INFO dev.ltms.fleet.msg.AmqpReplyInbox - AMQP connection recovered; cleared held replies for fresh redelivery -LOG - classify_fixture recovered.log - assert_equals 1 "$REDEPLOY_ERROR_COUNT" "recovered total" - assert_equals 1 "$REDEPLOY_RECOVERED_AMQP_ERRORS" "recovered AMQP errors" - assert_equals 0 "$REDEPLOY_UNEXPLAINED_ERRORS" "recovered unexplained" +test_recovery_patterns_match_source() { + grep -F 'AMQP connection recovered; cleared held replies for fresh redelivery' \ + "$ROOT/fleetd/src/main/java/dev/ltms/fleet/msg/AmqpReplyInbox.java" > /dev/null \ + || fail "reply-inbox recovery pattern no longer matches source" + grep -F 'AMQP lead mailbox connection recovered; cleared held messages for fresh redelivery' \ + "$ROOT/fleetd/src/main/java/dev/ltms/fleet/msg/LeadMailbox.java" > /dev/null \ + || fail "lead-mailbox recovery pattern no longer matches source" } -test_unrecovered_connection_error() { +test_attributed_recovered_connection_error() { + cat > "$TMP/attributed-recovered.log" <<'LOG' +2026-09-05 12:00:00 ERROR AmqpReplyInbox ForgivingExceptionHandler - An unexpected connection driver error occurred +2026-09-05 12:00:01 INFO AmqpReplyInbox - AMQP connection recovered; cleared held replies for fresh redelivery +LOG + classify_fixture attributed-recovered.log + assert_equals 1 "$REDEPLOY_ERROR_COUNT" "attributed-recovered total" + assert_equals 1 "$REDEPLOY_RECOVERED_AMQP_ERRORS" "attributed-recovered errors" + assert_equals 0 "$REDEPLOY_UNEXPLAINED_ERRORS" "attributed-recovered unexplained" +} + +test_real_error_shape_is_loud_when_unattributable() { + # The real handler ERROR lines name neither inbox nor lead mailbox. Even though both connections + # later recover, this region must stay loud because the recovery cannot be assigned safely. + cat > "$TMP/real-error-shape.log" <<'LOG' +17:37:53.537 ERROR [AMQP Connection 10.10.20.13:5672] c.r.c.i.ForgivingExceptionHandler - An unexpected connection driver error occurred +18:20:33.027 ERROR [AMQP Connection 10.10.20.13:5672] c.r.c.i.ForgivingExceptionHandler - Caught an exception during connection recovery! +18:30:00.000 ERROR [AMQP Connection 10.10.20.13:5672] c.r.c.i.ForgivingExceptionHandler - An unexpected connection driver error occurred +19:00:00.000 ERROR [AMQP Connection 10.10.20.13:5672] c.r.c.i.ForgivingExceptionHandler - Caught an exception during connection recovery! +20:00:00.000 ERROR [AMQP Connection 10.10.20.13:5672] c.r.c.i.ForgivingExceptionHandler - An unexpected connection driver error occurred +21:00:00.000 ERROR [AMQP Connection 10.10.20.13:5672] c.r.c.i.ForgivingExceptionHandler - Caught an exception during connection recovery! +21:41:39.329 INFO [AMQP Connection 10.10.20.13:5672] d.ltms.fleet.msg.LeadMailbox - AMQP lead mailbox connection recovered; cleared held messages for fresh redelivery +21:41:48.693 INFO [AMQP Connection 10.10.20.13:5672] d.l.fleet.msg.AmqpReplyInbox - AMQP connection recovered; cleared held replies for fresh redelivery +LOG + classify_fixture real-error-shape.log + assert_equals 6 "$REDEPLOY_ERROR_COUNT" "real-error-shape total" + assert_equals 0 "$REDEPLOY_RECOVERED_AMQP_ERRORS" "real-error-shape recovered" + assert_equals 6 "$REDEPLOY_UNEXPLAINED_ERRORS" "real-error-shape unexplained" +} + +test_cross_connection_unattributable_errors_stay_loud() { + # This is the reported unsafe shape. Both handler lines lack a connection kind, so LeadMailbox + # recoveries must not consume either one. + cat > "$TMP/cross-unattributable.log" <<'LOG' +2026-09-05 12:00:00 ERROR [AMQP Connection 10.10.20.13:5672] c.r.c.i.ForgivingExceptionHandler - An unexpected connection driver error occurred +2026-09-05 12:00:01 ERROR [AMQP Connection 10.10.20.13:5672] c.r.c.i.ForgivingExceptionHandler - An unexpected connection driver error occurred +2026-09-05 12:00:02 INFO [AMQP Connection 10.10.20.13:5672] d.ltms.fleet.msg.LeadMailbox - AMQP lead mailbox connection recovered; cleared held messages for fresh redelivery +2026-09-05 12:00:03 INFO [AMQP Connection 10.10.20.13:5672] d.ltms.fleet.msg.LeadMailbox - AMQP lead mailbox connection recovered; cleared held messages for fresh redelivery +LOG + classify_fixture cross-unattributable.log + assert_equals 2 "$REDEPLOY_ERROR_COUNT" "cross-unattributable total" + assert_equals 0 "$REDEPLOY_RECOVERED_AMQP_ERRORS" "cross-unattributable recovered" + assert_equals 2 "$REDEPLOY_UNEXPLAINED_ERRORS" "cross-unattributable unexplained" +} + +test_attributed_cross_connection_errors_stay_loud() { + # This fixture exercises the per-kind pending state should a future layout include a simple class + # name on the handler line. LeadMailbox recovery cannot heal AmqpReplyInbox errors. + cat > "$TMP/cross-attributed.log" <<'LOG' +2026-09-05 12:00:00 ERROR AmqpReplyInbox ForgivingExceptionHandler - An unexpected connection driver error occurred +2026-09-05 12:00:01 ERROR AmqpReplyInbox ForgivingExceptionHandler - An unexpected connection driver error occurred +2026-09-05 12:00:02 INFO LeadMailbox - AMQP lead mailbox connection recovered; cleared held messages for fresh redelivery +2026-09-05 12:00:03 INFO LeadMailbox - AMQP lead mailbox connection recovered; cleared held messages for fresh redelivery +LOG + classify_fixture cross-attributed.log + assert_equals 2 "$REDEPLOY_ERROR_COUNT" "cross-attributed total" + assert_equals 0 "$REDEPLOY_RECOVERED_AMQP_ERRORS" "cross-attributed recovered" + assert_equals 2 "$REDEPLOY_UNEXPLAINED_ERRORS" "cross-attributed unexplained" +} + +test_attributed_unrecovered_connection_error() { cat > "$TMP/unrecovered.log" <<'LOG' -2026-09-05 12:00:00 ERROR com.rabbitmq.client.impl.ForgivingExceptionHandler - An unexpected connection driver error occurred (Exception message: Connection reset) +2026-09-05 12:00:00 ERROR AmqpReplyInbox ForgivingExceptionHandler - An unexpected connection driver error occurred LOG classify_fixture unrecovered.log assert_equals 1 "$REDEPLOY_ERROR_COUNT" "unrecovered total" @@ -65,7 +123,7 @@ LOG assert_equals 1 "$REDEPLOY_UNEXPLAINED_ERRORS" "other-error unexplained" } -test_mutation_is_caught() { +test_recovery_requirement_mutation_is_caught() { classify_amqp_connection_errors() { local log_file="$1" line REDEPLOY_ERROR_COUNT=0 @@ -76,7 +134,7 @@ test_mutation_is_caught() { *' ERROR '*|*' SEVERE '*) REDEPLOY_ERROR_COUNT=$((REDEPLOY_ERROR_COUNT + 1)) case "$line" in - *'com.rabbitmq.client.impl.ForgivingExceptionHandler'*'Connection reset'*) + *'ForgivingExceptionHandler'*'An unexpected connection driver error occurred'*) REDEPLOY_RECOVERED_AMQP_ERRORS=$((REDEPLOY_RECOVERED_AMQP_ERRORS + 1)) ;; *) REDEPLOY_UNEXPLAINED_ERRORS=$((REDEPLOY_UNEXPLAINED_ERRORS + 1)) ;; @@ -86,17 +144,61 @@ test_mutation_is_caught() { done < "$log_file" } - if test_unrecovered_connection_error > "$TMP/mutation-output" 2>&1; then + if test_attributed_unrecovered_connection_error > "$TMP/mutation-output" 2>&1; then fail "mutation accepted an unrecovered connection error" fi grep -F 'FAIL: unrecovered AMQP errors: expected 0, got 1' "$TMP/mutation-output" > /dev/null \ || fail "mutation failed without the expected assertion" - printf 'Mutation check: FAIL: unrecovered AMQP errors: expected 0, got 1\n' + printf 'Recovery mutation: FAIL: unrecovered AMQP errors: expected 0, got 1\n' +} + +test_shared_counter_mutation_is_caught() { + classify_amqp_connection_errors() { + local log_file="$1" line pending=0 + REDEPLOY_ERROR_COUNT=0 + REDEPLOY_RECOVERED_AMQP_ERRORS=0 + REDEPLOY_UNEXPLAINED_ERRORS=0 + while IFS= read -r line || [ -n "$line" ]; do + case "$line" in + *' ERROR '*|*' SEVERE '*) + REDEPLOY_ERROR_COUNT=$((REDEPLOY_ERROR_COUNT + 1)) + case "$line" in + *'ForgivingExceptionHandler'*'An unexpected connection driver error occurred'*|*'ForgivingExceptionHandler'*'Caught an exception during connection recovery!'*) + case "$line" in + *'AmqpReplyInbox'*|*'LeadMailbox'*) pending=$((pending + 1)) ;; + *) REDEPLOY_UNEXPLAINED_ERRORS=$((REDEPLOY_UNEXPLAINED_ERRORS + 1)) ;; + esac + ;; + *) REDEPLOY_UNEXPLAINED_ERRORS=$((REDEPLOY_UNEXPLAINED_ERRORS + 1)) ;; + esac + ;; + *'AMQP connection recovered; cleared held replies for fresh redelivery'*|*'AMQP lead mailbox connection recovered; cleared held messages for fresh redelivery'*) + if [ "$pending" -gt 0 ]; then + pending=$((pending - 1)) + REDEPLOY_RECOVERED_AMQP_ERRORS=$((REDEPLOY_RECOVERED_AMQP_ERRORS + 1)) + fi + ;; + esac + done < "$log_file" + REDEPLOY_UNEXPLAINED_ERRORS=$((REDEPLOY_UNEXPLAINED_ERRORS + pending)) + } + + if test_attributed_cross_connection_errors_stay_loud > "$TMP/shared-mutation-output" 2>&1; then + fail "shared counter mutation accepted cross-connection recovery" + fi + grep -F 'FAIL: cross-attributed recovered: expected 0, got 2' "$TMP/shared-mutation-output" > /dev/null \ + || fail "shared counter mutation failed without the expected assertion" + printf 'Shared-counter mutation: FAIL: cross-attributed recovered: expected 0, got 2\n' } test_no_errors -test_recovered_connection_error -test_unrecovered_connection_error +test_recovery_patterns_match_source +test_attributed_recovered_connection_error +test_real_error_shape_is_loud_when_unattributable +test_cross_connection_unattributable_errors_stay_loud +test_attributed_cross_connection_errors_stay_loud +test_attributed_unrecovered_connection_error test_other_error_is_unexplained -test_mutation_is_caught +test_recovery_requirement_mutation_is_caught +test_shared_counter_mutation_is_caught printf 'PASS: redeploy log classifier\n' From 09159f2857d0bd131da91cfff51a43e80f20a887 Mon Sep 17 00:00:00 2001 From: Dai Ha Date: Sat, 5 Sep 2026 06:05:52 +0700 Subject: [PATCH 3/3] Classify named AMQP recovery errors --- scripts/redeploy-fleetd.sh | 22 ++++---- scripts/test-redeploy-fleetd.sh | 96 ++++++++++++++++++++++----------- 2 files changed, 76 insertions(+), 42 deletions(-) diff --git a/scripts/redeploy-fleetd.sh b/scripts/redeploy-fleetd.sh index d2ce73f..2a32ac5 100755 --- a/scripts/redeploy-fleetd.sh +++ b/scripts/redeploy-fleetd.sh @@ -116,11 +116,9 @@ check_log_path_matches_plist() { ok "log path check: script and plist agree ($resolved_out)" } -# Classify ERROR lines in one fresh log region. The logging layout abbreviates logger packages, so -# match simple class names and the handler's actual ERROR messages. An error can be quiet only when -# its own line names AmqpReplyInbox or LeadMailbox; the handler lines now seen in fleetd.out name -# neither connection, so they deliberately stay unexplained. This avoids letting one connection's -# recovery hide a failure in the other connection. +# Classify ERROR lines in one fresh log region. AMQP failure messages now include the connection +# name, so a recovery can clear only errors for its own connection. A candidate with neither name +# remains unexplained: it must never be quieted by a recovery on the other connection. classify_amqp_connection_errors() { local log_file="$1" line pending_inbox=0 pending_lead_mailbox=0 REDEPLOY_ERROR_COUNT=0 @@ -132,12 +130,14 @@ classify_amqp_connection_errors() { *' ERROR '*|*' SEVERE '*) REDEPLOY_ERROR_COUNT=$((REDEPLOY_ERROR_COUNT + 1)) case "$line" in - *'ForgivingExceptionHandler'*'An unexpected connection driver error occurred'*|*'ForgivingExceptionHandler'*'Caught an exception during connection recovery!'*) - case "$line" in - *'AmqpReplyInbox'*) pending_inbox=$((pending_inbox + 1)) ;; - *'LeadMailbox'*) pending_lead_mailbox=$((pending_lead_mailbox + 1)) ;; - *) REDEPLOY_UNEXPLAINED_ERRORS=$((REDEPLOY_UNEXPLAINED_ERRORS + 1)) ;; - esac + *'AMQP connection fleetd-reply-inbox: An unexpected connection driver error occurred'*|*'AMQP connection fleetd-reply-inbox: Caught an exception during connection recovery!'*) + pending_inbox=$((pending_inbox + 1)) + ;; + *'AMQP connection fleetd-lead-mailbox: An unexpected connection driver error occurred'*|*'AMQP connection fleetd-lead-mailbox: Caught an exception during connection recovery!'*) + pending_lead_mailbox=$((pending_lead_mailbox + 1)) + ;; + *'AMQP connection'*'An unexpected connection driver error occurred'*|*'AMQP connection'*'Caught an exception during connection recovery!'*) + REDEPLOY_UNEXPLAINED_ERRORS=$((REDEPLOY_UNEXPLAINED_ERRORS + 1)) ;; *) REDEPLOY_UNEXPLAINED_ERRORS=$((REDEPLOY_UNEXPLAINED_ERRORS + 1)) ;; esac diff --git a/scripts/test-redeploy-fleetd.sh b/scripts/test-redeploy-fleetd.sh index 4ff1d95..9423e2c 100755 --- a/scripts/test-redeploy-fleetd.sh +++ b/scripts/test-redeploy-fleetd.sh @@ -35,6 +35,8 @@ LOG } test_recovery_patterns_match_source() { + grep -F 'AMQP connection {}: {}' "$ROOT/fleetd/src/main/java/dev/ltms/fleet/msg/AmqpReplyInbox.java" > /dev/null \ + || fail "AMQP failure pattern no longer matches source" grep -F 'AMQP connection recovered; cleared held replies for fresh redelivery' \ "$ROOT/fleetd/src/main/java/dev/ltms/fleet/msg/AmqpReplyInbox.java" > /dev/null \ || fail "reply-inbox recovery pattern no longer matches source" @@ -45,8 +47,8 @@ test_recovery_patterns_match_source() { test_attributed_recovered_connection_error() { cat > "$TMP/attributed-recovered.log" <<'LOG' -2026-09-05 12:00:00 ERROR AmqpReplyInbox ForgivingExceptionHandler - An unexpected connection driver error occurred -2026-09-05 12:00:01 INFO AmqpReplyInbox - AMQP connection recovered; cleared held replies for fresh redelivery +2026-09-05 12:00:00 ERROR [AMQP Connection broker:5672] d.l.fleet.msg.AmqpReplyInbox - AMQP connection fleetd-reply-inbox: An unexpected connection driver error occurred +2026-09-05 12:00:01 INFO [AMQP Connection broker:5672] d.l.fleet.msg.AmqpReplyInbox - AMQP connection recovered; cleared held replies for fresh redelivery LOG classify_fixture attributed-recovered.log assert_equals 1 "$REDEPLOY_ERROR_COUNT" "attributed-recovered total" @@ -54,31 +56,34 @@ LOG assert_equals 0 "$REDEPLOY_UNEXPLAINED_ERRORS" "attributed-recovered unexplained" } -test_real_error_shape_is_loud_when_unattributable() { - # The real handler ERROR lines name neither inbox nor lead mailbox. Even though both connections - # later recover, this region must stay loud because the recovery cannot be assigned safely. - cat > "$TMP/real-error-shape.log" <<'LOG' -17:37:53.537 ERROR [AMQP Connection 10.10.20.13:5672] c.r.c.i.ForgivingExceptionHandler - An unexpected connection driver error occurred -18:20:33.027 ERROR [AMQP Connection 10.10.20.13:5672] c.r.c.i.ForgivingExceptionHandler - Caught an exception during connection recovery! -18:30:00.000 ERROR [AMQP Connection 10.10.20.13:5672] c.r.c.i.ForgivingExceptionHandler - An unexpected connection driver error occurred -19:00:00.000 ERROR [AMQP Connection 10.10.20.13:5672] c.r.c.i.ForgivingExceptionHandler - Caught an exception during connection recovery! -20:00:00.000 ERROR [AMQP Connection 10.10.20.13:5672] c.r.c.i.ForgivingExceptionHandler - An unexpected connection driver error occurred -21:00:00.000 ERROR [AMQP Connection 10.10.20.13:5672] c.r.c.i.ForgivingExceptionHandler - Caught an exception during connection recovery! -21:41:39.329 INFO [AMQP Connection 10.10.20.13:5672] d.ltms.fleet.msg.LeadMailbox - AMQP lead mailbox connection recovered; cleared held messages for fresh redelivery -21:41:48.693 INFO [AMQP Connection 10.10.20.13:5672] d.l.fleet.msg.AmqpReplyInbox - AMQP connection recovered; cleared held replies for fresh redelivery +test_source_derived_error_shapes_recover_by_connection() { + # These ERROR shapes come from AmqpConnectionFailureLogger on main. They need a live-log check + # after redeploy because the new code has not yet written a production line. + cat > "$TMP/source-derived.log" <<'LOG' +17:37:53.537 ERROR [AMQP Connection broker:5672] d.l.fleet.msg.AmqpReplyInbox - AMQP connection fleetd-reply-inbox: An unexpected connection driver error occurred +17:37:54.537 ERROR [AMQP Connection broker:5672] d.l.fleet.msg.AmqpReplyInbox - AMQP connection fleetd-reply-inbox: Caught an exception during connection recovery! +17:37:55.537 ERROR [AMQP Connection broker:5672] d.l.fleet.msg.AmqpReplyInbox - AMQP connection fleetd-reply-inbox: An unexpected connection driver error occurred +17:37:56.537 ERROR [AMQP Connection broker:5672] d.ltms.fleet.msg.LeadMailbox - AMQP connection fleetd-lead-mailbox: An unexpected connection driver error occurred +17:37:57.537 ERROR [AMQP Connection broker:5672] d.ltms.fleet.msg.LeadMailbox - AMQP connection fleetd-lead-mailbox: Caught an exception during connection recovery! +17:37:58.537 ERROR [AMQP Connection broker:5672] d.ltms.fleet.msg.LeadMailbox - AMQP connection fleetd-lead-mailbox: An unexpected connection driver error occurred +17:38:00.000 INFO [AMQP Connection broker:5672] d.l.fleet.msg.AmqpReplyInbox - AMQP connection recovered; cleared held replies for fresh redelivery +17:38:01.000 INFO [AMQP Connection broker:5672] d.l.fleet.msg.AmqpReplyInbox - AMQP connection recovered; cleared held replies for fresh redelivery +17:38:02.000 INFO [AMQP Connection broker:5672] d.l.fleet.msg.AmqpReplyInbox - AMQP connection recovered; cleared held replies for fresh redelivery +17:38:03.000 INFO [AMQP Connection broker:5672] d.ltms.fleet.msg.LeadMailbox - AMQP lead mailbox connection recovered; cleared held messages for fresh redelivery +17:38:04.000 INFO [AMQP Connection broker:5672] d.ltms.fleet.msg.LeadMailbox - AMQP lead mailbox connection recovered; cleared held messages for fresh redelivery +17:38:05.000 INFO [AMQP Connection broker:5672] d.ltms.fleet.msg.LeadMailbox - AMQP lead mailbox connection recovered; cleared held messages for fresh redelivery LOG - classify_fixture real-error-shape.log - assert_equals 6 "$REDEPLOY_ERROR_COUNT" "real-error-shape total" - assert_equals 0 "$REDEPLOY_RECOVERED_AMQP_ERRORS" "real-error-shape recovered" - assert_equals 6 "$REDEPLOY_UNEXPLAINED_ERRORS" "real-error-shape unexplained" + classify_fixture source-derived.log + assert_equals 6 "$REDEPLOY_ERROR_COUNT" "source-derived total" + assert_equals 6 "$REDEPLOY_RECOVERED_AMQP_ERRORS" "source-derived recovered" + assert_equals 0 "$REDEPLOY_UNEXPLAINED_ERRORS" "source-derived unexplained" } test_cross_connection_unattributable_errors_stay_loud() { - # This is the reported unsafe shape. Both handler lines lack a connection kind, so LeadMailbox - # recoveries must not consume either one. + # This candidate has neither stable connection name, so LeadMailbox recovery must not consume it. cat > "$TMP/cross-unattributable.log" <<'LOG' -2026-09-05 12:00:00 ERROR [AMQP Connection 10.10.20.13:5672] c.r.c.i.ForgivingExceptionHandler - An unexpected connection driver error occurred -2026-09-05 12:00:01 ERROR [AMQP Connection 10.10.20.13:5672] c.r.c.i.ForgivingExceptionHandler - An unexpected connection driver error occurred +2026-09-05 12:00:00 ERROR [AMQP Connection broker:5672] unknown - AMQP connection: An unexpected connection driver error occurred +2026-09-05 12:00:01 ERROR [AMQP Connection broker:5672] unknown - AMQP connection: An unexpected connection driver error occurred 2026-09-05 12:00:02 INFO [AMQP Connection 10.10.20.13:5672] d.ltms.fleet.msg.LeadMailbox - AMQP lead mailbox connection recovered; cleared held messages for fresh redelivery 2026-09-05 12:00:03 INFO [AMQP Connection 10.10.20.13:5672] d.ltms.fleet.msg.LeadMailbox - AMQP lead mailbox connection recovered; cleared held messages for fresh redelivery LOG @@ -89,11 +94,10 @@ LOG } test_attributed_cross_connection_errors_stay_loud() { - # This fixture exercises the per-kind pending state should a future layout include a simple class - # name on the handler line. LeadMailbox recovery cannot heal AmqpReplyInbox errors. + # LeadMailbox recovery cannot heal AmqpReplyInbox errors. cat > "$TMP/cross-attributed.log" <<'LOG' -2026-09-05 12:00:00 ERROR AmqpReplyInbox ForgivingExceptionHandler - An unexpected connection driver error occurred -2026-09-05 12:00:01 ERROR AmqpReplyInbox ForgivingExceptionHandler - An unexpected connection driver error occurred +2026-09-05 12:00:00 ERROR AmqpReplyInbox - AMQP connection fleetd-reply-inbox: An unexpected connection driver error occurred +2026-09-05 12:00:01 ERROR AmqpReplyInbox - AMQP connection fleetd-reply-inbox: An unexpected connection driver error occurred 2026-09-05 12:00:02 INFO LeadMailbox - AMQP lead mailbox connection recovered; cleared held messages for fresh redelivery 2026-09-05 12:00:03 INFO LeadMailbox - AMQP lead mailbox connection recovered; cleared held messages for fresh redelivery LOG @@ -105,7 +109,7 @@ LOG test_attributed_unrecovered_connection_error() { cat > "$TMP/unrecovered.log" <<'LOG' -2026-09-05 12:00:00 ERROR AmqpReplyInbox ForgivingExceptionHandler - An unexpected connection driver error occurred +2026-09-05 12:00:00 ERROR AmqpReplyInbox - AMQP connection fleetd-reply-inbox: An unexpected connection driver error occurred LOG classify_fixture unrecovered.log assert_equals 1 "$REDEPLOY_ERROR_COUNT" "unrecovered total" @@ -134,7 +138,7 @@ test_recovery_requirement_mutation_is_caught() { *' ERROR '*|*' SEVERE '*) REDEPLOY_ERROR_COUNT=$((REDEPLOY_ERROR_COUNT + 1)) case "$line" in - *'ForgivingExceptionHandler'*'An unexpected connection driver error occurred'*) + *'AMQP connection fleetd-reply-inbox: An unexpected connection driver error occurred'*) REDEPLOY_RECOVERED_AMQP_ERRORS=$((REDEPLOY_RECOVERED_AMQP_ERRORS + 1)) ;; *) REDEPLOY_UNEXPLAINED_ERRORS=$((REDEPLOY_UNEXPLAINED_ERRORS + 1)) ;; @@ -163,9 +167,9 @@ test_shared_counter_mutation_is_caught() { *' ERROR '*|*' SEVERE '*) REDEPLOY_ERROR_COUNT=$((REDEPLOY_ERROR_COUNT + 1)) case "$line" in - *'ForgivingExceptionHandler'*'An unexpected connection driver error occurred'*|*'ForgivingExceptionHandler'*'Caught an exception during connection recovery!'*) + *'AMQP connection'*'An unexpected connection driver error occurred'*|*'AMQP connection'*'Caught an exception during connection recovery!'*) case "$line" in - *'AmqpReplyInbox'*|*'LeadMailbox'*) pending=$((pending + 1)) ;; + *'fleetd-reply-inbox'*|*'fleetd-lead-mailbox'*) pending=$((pending + 1)) ;; *) REDEPLOY_UNEXPLAINED_ERRORS=$((REDEPLOY_UNEXPLAINED_ERRORS + 1)) ;; esac ;; @@ -191,14 +195,44 @@ test_shared_counter_mutation_is_caught() { printf 'Shared-counter mutation: FAIL: cross-attributed recovered: expected 0, got 2\n' } +test_unattributable_quiet_mutation_is_caught() { + classify_amqp_connection_errors() { + local log_file="$1" line + REDEPLOY_ERROR_COUNT=0 + REDEPLOY_RECOVERED_AMQP_ERRORS=0 + REDEPLOY_UNEXPLAINED_ERRORS=0 + while IFS= read -r line || [ -n "$line" ]; do + case "$line" in + *' ERROR '*|*' SEVERE '*) + REDEPLOY_ERROR_COUNT=$((REDEPLOY_ERROR_COUNT + 1)) + case "$line" in + *'AMQP connection'*'An unexpected connection driver error occurred'*|*'AMQP connection'*'Caught an exception during connection recovery!'*) + REDEPLOY_RECOVERED_AMQP_ERRORS=$((REDEPLOY_RECOVERED_AMQP_ERRORS + 1)) + ;; + *) REDEPLOY_UNEXPLAINED_ERRORS=$((REDEPLOY_UNEXPLAINED_ERRORS + 1)) ;; + esac + ;; + esac + done < "$log_file" + } + + if test_cross_connection_unattributable_errors_stay_loud > "$TMP/unattributable-mutation-output" 2>&1; then + fail "unattributable mutation accepted an unknown connection" + fi + grep -F 'FAIL: cross-unattributable recovered: expected 0, got 2' "$TMP/unattributable-mutation-output" > /dev/null \ + || fail "unattributable mutation failed without the expected assertion" + printf 'Unattributable mutation: FAIL: cross-unattributable recovered: expected 0, got 2\n' +} + test_no_errors test_recovery_patterns_match_source test_attributed_recovered_connection_error -test_real_error_shape_is_loud_when_unattributable +test_source_derived_error_shapes_recover_by_connection test_cross_connection_unattributable_errors_stay_loud test_attributed_cross_connection_errors_stay_loud test_attributed_unrecovered_connection_error test_other_error_is_unexplained test_recovery_requirement_mutation_is_caught test_shared_counter_mutation_is_caught +test_unattributable_quiet_mutation_is_caught printf 'PASS: redeploy log classifier\n'