From 190436c9cfce2fb3479f68a5497fc3a63b07e884 Mon Sep 17 00:00:00 2001 From: Dai Ha Date: Sat, 12 Sep 2026 12:55:54 +0700 Subject: [PATCH] fleetd #512 part 2: detect a died shutdown drain the ERROR count is blind to MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The previous daemon's dead shutdown drain (an uncaught exception in a shutdown thread) never passes through the logger, so it never carries an ERROR/SEVERE token, so redeploy-fleetd.sh's existing ERROR-count classifier is structurally blind to it and prints a confident "no ERROR lines since restart" while the drain actually died. Add scan_uncaught_exceptions (greps the shutdown window for the failure's real shape: `Exception in thread`, `NoClassDefFoundError`) and find_drain_complete_line (checks for #522's SessionManager.drainAll completion line). Compose both in report_shutdown_drain, a single decision+action function the main flow calls unconditionally (same shape as swap_if_built/refuse_drain_gate from #521/#528), which resolves to one of four outcomes: complete, died, unknown ("cannot tell" — the line is absent for either of two reasons that need opposite handling: the previous daemon predates #522, or its drain failed without throwing), or n/a (no previous daemon was actually stopped this run). Never fails the redeploy; warns loudly instead. Gate the "no ERROR lines since restart" summary line on the new outcome so it never reads as reassurance when the drain died or the outcome is "cannot tell" (item 4 of the ticket). Tests: 11 new test functions (60 defined/invoked, was 49), covering both pure classifiers, all four report_shutdown_drain outcomes, a source-grep proof of the main-flow call site (sourcing stops before the main flow runs), an ordering check, and the item-4 gating. Full suite green (exit 0, 0 anchored FAIL lines). Five mutations applied and killed by hand during review, each restored to a byte-identical file afterward. --- scripts/redeploy-fleetd.sh | 133 ++++++++++++++++++++++++- scripts/test-redeploy-fleetd.sh | 169 ++++++++++++++++++++++++++++++++ 2 files changed, 301 insertions(+), 1 deletion(-) diff --git a/scripts/redeploy-fleetd.sh b/scripts/redeploy-fleetd.sh index 5d46f28..c55def3 100755 --- a/scripts/redeploy-fleetd.sh +++ b/scripts/redeploy-fleetd.sh @@ -42,6 +42,14 @@ # 8. fleetd #492 — a post-restart check counts running fleetd processes and fails the whole run if # more than one is alive. That is the one thing none of the checks above (healthz 200, jar id, # the fresh "listening" line) can see: every one of them is satisfied by EITHER daemon. +# 9. fleetd #512 — the ERROR-line count above is blind by construction to the exact failure #493 +# is about: an uncaught exception in a shutdown thread never passes through the logger, so it +# never carries an ERROR (or SEVERE) token that any count could see. This script now also +# greps the previous daemon's shutdown window for that exception's real shape, and separately +# asserts that SessionManager's drain-complete line (fleetd #522) is present there — its +# absence is the real signal, because a drain that dies on its first session prints nothing +# else either. Warns loudly; never fails the redeploy, because by the time this is detectable +# the new daemon is already up and healthy. # # Usage: # scripts/redeploy-fleetd.sh # build, confirm, restart, verify @@ -490,6 +498,114 @@ classify_amqp_connection_errors() { REDEPLOY_UNEXPLAINED_ERRORS=$((REDEPLOY_UNEXPLAINED_ERRORS + pending_inbox + pending_lead_mailbox)) } +# fleetd #512 part 2 — the negative check. #493's failure (an uncaught exception in a shutdown +# thread) never passes through the logger: the JVM's default uncaught-exception handler prints +# straight to stderr, so the line never carries a level, so classify_amqp_connection_errors's +# ERROR/SEVERE token scan is structurally blind to it — measured on two hosts, including one where +# even a syslog PRIORITY filter is blind to it too (fd 1 and fd 2 collapse to one socket there, so +# every uncaught-exception line lands at priority 6/info). The fix is to grep the shape instead of +# the level: `Exception in thread` at the start of a line (the handler's own banner) or +# `NoClassDefFoundError` anywhere in it (the one real instance seen so far, but not the only shape +# this could take). Kept as its own function, never folded into classify_amqp_connection_errors — +# this is not an AMQP concern, and the two must stay independently readable and independently +# testable. +# +# Sets REDEPLOY_UNCAUGHT_EXCEPTION_COUNT (lines matched) and REDEPLOY_UNCAUGHT_EXCEPTION_SAMPLE +# (the first matching line, "" if none) so a caller can report both a count and a concrete quote +# without re-reading the file. Pure: reads $1, sets globals, no side effects. +scan_uncaught_exceptions() { + local log_file="$1" line + REDEPLOY_UNCAUGHT_EXCEPTION_COUNT=0 + REDEPLOY_UNCAUGHT_EXCEPTION_SAMPLE="" + while IFS= read -r line || [ -n "$line" ]; do + case "$line" in + 'Exception in thread'*|*NoClassDefFoundError*) + REDEPLOY_UNCAUGHT_EXCEPTION_COUNT=$((REDEPLOY_UNCAUGHT_EXCEPTION_COUNT + 1)) + [ -n "$REDEPLOY_UNCAUGHT_EXCEPTION_SAMPLE" ] || REDEPLOY_UNCAUGHT_EXCEPTION_SAMPLE="$line" + ;; + esac + done < "$log_file" +} + +# fleetd #512 part 2 — the positive check. fleetd #522 added a `log.info` at the very end of +# SessionManager.drainAll's normal path (never in a `finally` — see the ticket discussion for why +# that distinction matters): "drain complete: released=N abandoned=M (still BUSY at the shutdown +# deadline)", printed once, on every successful drain, including the all-zero case. A drain that +# dies partway through never reaches that statement, so the line's ABSENCE is a real signal — unlike +# the ERROR-count check above, this one does not depend on the failure happening to throw. +# +# Sets REDEPLOY_DRAIN_COMPLETE_LINE to the matching line (last one, though drainAll runs at most +# once per shutdown so there should never be more than one) or "" if absent. Pure, same shape as +# scan_uncaught_exceptions above. +find_drain_complete_line() { + local log_file="$1" + REDEPLOY_DRAIN_COMPLETE_LINE="$(grep -F 'drain complete: released=' "$log_file" | tail -1 || true)" +} + +# fleetd #512 part 2 — THE TRAP, and the reason this is one function instead of two independent +# checks the caller ORs together. Absence of the drain-complete line has TWO causes that need +# OPPOSITE handling, and a naive "line absent -> the drain died" reading collapses them exactly the +# way this whole ticket exists to stop: the line is emitted by the daemon being STOPPED, which is +# running the OLD jar. Until a redeploy has landed fleetd #522 once, every previous daemon predates +# the line and cannot emit it no matter how cleanly it drained — so on the very first redeploy after +# #522 merged, "absent" means "too old to know how", not "died". Only once BOTH signals — this +# line's absence AND scan_uncaught_exceptions' result — have been read together can the three real +# outcomes be told apart: +# +# complete -> the line is present: the drain finished. Name the counts it reported. +# died -> the line is absent AND an uncaught-exception shape was found: the drain died. Name +# what was found. +# unknown -> the line is absent AND no exception shape either: cannot tell. Say so, and say why +# (predates the line, or failed without throwing) — never worded as a pass or a +# failure, and never reassuring: "ok, no ERROR lines" one level up is the exact mistake +# this ticket exists to fix, and this outcome must not reproduce it. +# +# A fourth case, n/a, covers a cold start or a "loaded but wasn't running" restart: no previous +# daemon was actually stopped THIS run, so there is no shutdown window in $log_file to have an +# opinion about at all — scanning it anyway would read the NEW daemon's own startup lines and could +# misreport "cannot tell" on every clean cold start. had_previous_daemon carries that fact in from +# the caller (it already knows $OLD_PID) rather than this function re-deriving it from log content. +# +# Same shape as swap_if_built/refuse_drain_gate (fleetd #521/#528): the decision (which of the four +# outcomes applies) and the action (which ok/warn line to print, and setting REDEPLOY_DRAIN_STATE +# for the "result" section below to consult) live together in ONE function that the main flow calls +# unconditionally — there is no guard left in the main flow to remove, invert, or bypass +# independently of this function. Never calls die(): #512's own decision is to warn loudly and let +# the redeploy stand, because by the time this is detectable the new daemon is already up and +# healthy and failing here would give the operator nothing to do differently. +report_shutdown_drain() { + local log_file="$1" had_previous_daemon="$2" + REDEPLOY_UNCAUGHT_EXCEPTION_COUNT=0 + REDEPLOY_UNCAUGHT_EXCEPTION_SAMPLE="" + REDEPLOY_DRAIN_COMPLETE_LINE="" + + if [ "$had_previous_daemon" != 1 ]; then + REDEPLOY_DRAIN_STATE="n/a" + ok "no previous daemon was running before this restart — nothing to check for a died shutdown drain" + return 0 + fi + + find_drain_complete_line "$log_file" + scan_uncaught_exceptions "$log_file" + + if [ -n "$REDEPLOY_DRAIN_COMPLETE_LINE" ]; then + REDEPLOY_DRAIN_STATE="complete" + ok "previous daemon's shutdown drain finished: $REDEPLOY_DRAIN_COMPLETE_LINE" + elif [ "$REDEPLOY_UNCAUGHT_EXCEPTION_COUNT" -gt 0 ]; then + REDEPLOY_DRAIN_STATE="died" + warn "previous daemon's shutdown drain DIED — no drain-complete line, and an uncaught exception" + warn "was found in its shutdown window ($REDEPLOY_UNCAUGHT_EXCEPTION_COUNT line(s)):" + warn " $REDEPLOY_UNCAUGHT_EXCEPTION_SAMPLE" + warn "Some sessions from the PREVIOUS daemon may not have been released." + else + REDEPLOY_DRAIN_STATE="unknown" + warn "cannot tell whether the previous daemon's shutdown drain finished — no drain-complete line" + warn "and no uncaught-exception shape either. This is NOT a pass and NOT a failure: it means" + warn "either that daemon predates fleetd #522's drain-complete log line, or its drain failed" + warn "without throwing (hung, or returned early)." + fi +} + # fleetd #517: extracted so the suite can call this decision directly, the same way #510 extracted # wait_for_daemon_exit so its ordering became checkable. Before this, the only test of the drain-gate # abort message was a grep of this script's own source for the wording — so mutating the `if` below @@ -900,6 +1016,14 @@ trap 'rm -f "$FRESH_LOG"' EXIT tail -n "+$((RESTART_MARK + 1))" "$OUT" > "$FRESH_LOG" 2>/dev/null || true classify_amqp_connection_errors "$FRESH_LOG" +# fleetd #512 part 2: the previous daemon's shutdown drain, checked in the same fresh-log region — +# see report_shutdown_drain above for the full decision (four outcomes, one of them a deliberate +# "cannot tell"). HAD_OLD_PID crosses in whether a previous daemon was actually stopped this run; +# see the function's own comment for why that matters. +say "previous daemon's shutdown drain" +HAD_OLD_PID=0; [ -n "$OLD_PID" ] && HAD_OLD_PID=1 +report_shutdown_drain "$FRESH_LOG" "$HAD_OLD_PID" + # fleetd #492: checked here, after healthz and the fresh-log check have both had time to run, so a # supervisor that revives the OLD jar a few seconds late is caught too. Every check above (healthz # 200, jar id, the fresh 'listening' line) is satisfied by EITHER daemon if two are alive — this is @@ -909,7 +1033,14 @@ assert_single_daemon "$(running_pid)" say "result" ok "pid $NEW_PID, jar $(jar_id)" if [ "$REDEPLOY_ERROR_COUNT" -eq 0 ]; then - ok "no ERROR lines since restart" + # fleetd #512 item 4: this line must not print when the shutdown-drain check above found the + # previous daemon's drain died, or could not tell — either would make "no ERROR lines" read as a + # clean bill of health it is not (an uncaught exception never carries an ERROR token to begin + # with, so this count alone cannot see that failure). "complete" and "n/a" are the only two + # outcomes report_shutdown_drain sets that mean nothing is wrong there. + if [ "$REDEPLOY_DRAIN_STATE" = "complete" ] || [ "$REDEPLOY_DRAIN_STATE" = "n/a" ]; then + ok "no ERROR lines since restart" + fi elif [ "$REDEPLOY_UNEXPLAINED_ERRORS" -eq 0 ]; then ok "$REDEPLOY_RECOVERED_AMQP_ERRORS AMQP connection reset ERROR lines recovered since restart" else diff --git a/scripts/test-redeploy-fleetd.sh b/scripts/test-redeploy-fleetd.sh index ab72475..c720272 100755 --- a/scripts/test-redeploy-fleetd.sh +++ b/scripts/test-redeploy-fleetd.sh @@ -820,6 +820,164 @@ test_unattributable_quiet_mutation_is_caught() { printf 'Unattributable mutation: FAIL: cross-unattributable recovered: expected 0, got 2\n' } +# fleetd #512 part 2 — the negative check (scan_uncaught_exceptions). The heart of this half of the +# ticket: a fixture with the uncaught-exception shape and NO line carrying an ERROR token at all, +# proving the scan finds it without one. A fixture that also carried an ERROR line would pass for +# the wrong reason. +test_scan_uncaught_exceptions_finds_shape_without_error_token() { + cat > "$TMP/scan-died.log" <<'LOG' +2026-09-12 10:15:00 INFO fleetd listening on 127.0.0.1:8765 +Exception in thread "Thread-0" java.lang.NoClassDefFoundError: reactor/core/Exceptions + at dev.ltms.fleet.session.SessionManager.drainAll(SessionManager.java:1081) +LOG + local error_count + error_count="$(grep -c ' ERROR ' "$TMP/scan-died.log" || true)" + [ "$error_count" = "0" ] \ + || fail "test fixture error: scan-died.log unexpectedly carries an ERROR token" + scan_uncaught_exceptions "$TMP/scan-died.log" + assert_equals 1 "$REDEPLOY_UNCAUGHT_EXCEPTION_COUNT" "scan must find the exception without an ERROR token" + printf '%s' "$REDEPLOY_UNCAUGHT_EXCEPTION_SAMPLE" | grep -qF 'NoClassDefFoundError' \ + || fail "scan did not capture the matching line as the sample" +} + +test_scan_uncaught_exceptions_clean_control() { + cat > "$TMP/scan-clean.log" <<'LOG' +2026-09-12 10:15:00 INFO fleetd listening on 127.0.0.1:8765 +2026-09-12 10:15:05 INFO dev.ltms.fleet.session.SessionManager - drain complete: released=0 abandoned=0 (still BUSY at the shutdown deadline) +LOG + scan_uncaught_exceptions "$TMP/scan-clean.log" + assert_equals 0 "$REDEPLOY_UNCAUGHT_EXCEPTION_COUNT" "clean control must find no uncaught exception" + assert_equals "" "$REDEPLOY_UNCAUGHT_EXCEPTION_SAMPLE" "clean control sample must be empty" +} + +# fleetd #512 part 2 — the positive check (find_drain_complete_line). Both halves of #522's line: +# present, and absent. +test_find_drain_complete_line_present() { + cat > "$TMP/drain-line-present.log" <<'LOG' +2026-09-12 10:15:05 INFO dev.ltms.fleet.session.SessionManager - drain complete: released=2 abandoned=1 (still BUSY at the shutdown deadline) +LOG + find_drain_complete_line "$TMP/drain-line-present.log" + printf '%s' "$REDEPLOY_DRAIN_COMPLETE_LINE" | grep -qF 'released=2 abandoned=1' \ + || fail "find_drain_complete_line did not capture the present line" +} + +test_find_drain_complete_line_absent() { + cat > "$TMP/drain-line-absent.log" <<'LOG' +2026-09-12 10:15:00 INFO fleetd listening on 127.0.0.1:8765 +LOG + find_drain_complete_line "$TMP/drain-line-absent.log" + assert_equals "" "$REDEPLOY_DRAIN_COMPLETE_LINE" "find_drain_complete_line must report empty when absent" +} + +# fleetd #512 part 2 — report_shutdown_drain, the composite decision+action function the main flow +# calls unconditionally (same shape as swap_if_built/refuse_drain_gate, #521/#528). These four cover +# the four outcomes named in the ticket's "trap": complete, died, unknown ("cannot tell" — neither a +# pass nor a failure), and n/a (no previous daemon was actually stopped this run). +# +# Deliberately NOT run inside `$(...)`: report_shutdown_drain sets REDEPLOY_DRAIN_STATE as a global +# side effect that these tests need to read back afterward, and a command substitution forks a +# subshell that global assignment would not survive (the exact trap documented above +# detect_supervisor in redeploy-fleetd.sh, for the same reason). Plain output redirection to a file +# does not fork a subshell, so it is used to capture what was printed instead. +test_report_shutdown_drain_died_without_error_token() { + cat > "$TMP/drain-died.log" <<'LOG' +2026-09-12 10:15:00 INFO fleetd listening on 127.0.0.1:8765 +2026-09-12 10:15:05 INFO dev.ltms.fleet.Fleetd - shutting down +Exception in thread "Thread-0" java.lang.NoClassDefFoundError: reactor/core/Exceptions + at dev.ltms.fleet.session.SessionManager.drainAll(SessionManager.java:1081) +LOG + local error_count + error_count="$(grep -c ' ERROR ' "$TMP/drain-died.log" || true)" + [ "$error_count" = "0" ] \ + || fail "test fixture error: drain-died.log unexpectedly carries an ERROR token" + + report_shutdown_drain "$TMP/drain-died.log" 1 > "$TMP/drain-died-output" 2>&1 + assert_equals "died" "$REDEPLOY_DRAIN_STATE" "died fixture must set REDEPLOY_DRAIN_STATE=died" + assert_equals 1 "$REDEPLOY_UNCAUGHT_EXCEPTION_COUNT" "died fixture uncaught-exception count" + grep -qF 'NoClassDefFoundError' "$TMP/drain-died-output" \ + || fail "report_shutdown_drain did not report the uncaught-exception shape it found" + grep -qF 'DIED' "$TMP/drain-died-output" \ + || fail "report_shutdown_drain did not report the drain as DIED" +} + +test_report_shutdown_drain_complete_control() { + cat > "$TMP/drain-complete.log" <<'LOG' +2026-09-12 10:15:00 INFO fleetd listening on 127.0.0.1:8765 +2026-09-12 10:15:05 INFO dev.ltms.fleet.Fleetd - shutting down +2026-09-12 10:15:05 INFO dev.ltms.fleet.session.SessionManager - drain complete: released=3 abandoned=0 (still BUSY at the shutdown deadline) +LOG + report_shutdown_drain "$TMP/drain-complete.log" 1 > "$TMP/drain-complete-output" 2>&1 + assert_equals "complete" "$REDEPLOY_DRAIN_STATE" "complete-control fixture must set REDEPLOY_DRAIN_STATE=complete" + assert_equals 0 "$REDEPLOY_UNCAUGHT_EXCEPTION_COUNT" "complete-control fixture must find no uncaught exception" + grep -qF 'released=3 abandoned=0' "$TMP/drain-complete-output" \ + || fail "report_shutdown_drain did not report the drain-complete counts" +} + +test_report_shutdown_drain_unknown_cannot_tell() { + cat > "$TMP/drain-unknown.log" <<'LOG' +2026-09-12 10:15:00 INFO fleetd listening on 127.0.0.1:8765 +2026-09-12 10:15:05 INFO dev.ltms.fleet.Fleetd - shutting down +LOG + report_shutdown_drain "$TMP/drain-unknown.log" 1 > "$TMP/drain-unknown-output" 2>&1 + assert_equals "unknown" "$REDEPLOY_DRAIN_STATE" "cannot-tell fixture must set REDEPLOY_DRAIN_STATE=unknown" + grep -qF 'cannot tell' "$TMP/drain-unknown-output" \ + || fail "report_shutdown_drain did not say it could not tell" + if grep -qF ' ok' "$TMP/drain-unknown-output"; then + fail "cannot-tell outcome must not be printed via ok() — it is neither a pass nor a failure" + fi +} + +# A cold start (or a restart where nothing was actually stopped) has no previous-daemon shutdown +# window to have an opinion about at all. This fixture's log content looks exactly like a died drain +# — proving the had_previous_daemon=0 gate is actually consulted, not merely documented: without it, +# this would misreport "died" or "unknown" on every clean cold start. +test_report_shutdown_drain_no_previous_daemon_is_na() { + cat > "$TMP/drain-na.log" <<'LOG' +Exception in thread "Thread-0" java.lang.NoClassDefFoundError: reactor/core/Exceptions +LOG + report_shutdown_drain "$TMP/drain-na.log" 0 > "$TMP/drain-na-output" 2>&1 + assert_equals "n/a" "$REDEPLOY_DRAIN_STATE" "no-previous-daemon fixture must set REDEPLOY_DRAIN_STATE=n/a even though the log content looks like a died drain" + grep -qF 'nothing to check' "$TMP/drain-na-output" \ + || fail "report_shutdown_drain did not report that there was nothing to check" +} + +# fleetd #512 — closes the gap none of the seven tests above can: they call report_shutdown_drain +# directly, and sourcing stops before the main flow ever runs (the SOURCED guard), so none of them +# can prove the main flow still calls it at all. Same shape as test_refuse_drain_gate_call_site_present +# and test_swap_ordered_after_wait_and_before_start: a source-text grep for the real call site, plus +# an ordering check against its neighbours in the verify/result flow. +test_report_shutdown_drain_call_site_present() { + local src="$ROOT/scripts/redeploy-fleetd.sh" call_line + call_line="$(grep -Fn 'report_shutdown_drain "$FRESH_LOG" "$HAD_OLD_PID"' "$src" | head -1 | cut -d: -f1 || true)" + [ -n "$call_line" ] \ + || fail "could not find the main flow's report_shutdown_drain call site in redeploy-fleetd.sh" +} + +test_report_shutdown_drain_ordered_after_classify_and_before_result() { + local src="$ROOT/scripts/redeploy-fleetd.sh" classify_line drain_line result_line + classify_line="$(grep -Fn 'classify_amqp_connection_errors "$FRESH_LOG"' "$src" | tail -1 | cut -d: -f1 || true)" + drain_line="$(grep -Fn 'report_shutdown_drain "$FRESH_LOG" "$HAD_OLD_PID"' "$src" | head -1 | cut -d: -f1 || true)" + result_line="$(grep -Fn 'say "result"' "$src" | head -1 | cut -d: -f1 || true)" + [ -n "$classify_line" ] || fail "could not find the classify_amqp_connection_errors call site" + [ -n "$drain_line" ] || fail "could not find the report_shutdown_drain call site" + [ -n "$result_line" ] || fail "could not find the result section" + [ "$drain_line" -gt "$classify_line" ] \ + || fail "report_shutdown_drain (line $drain_line) is not after classify_amqp_connection_errors (line $classify_line)" + [ "$drain_line" -lt "$result_line" ] \ + || fail "report_shutdown_drain (line $drain_line) is not before the result section (line $result_line)" +} + +# fleetd #512 item 4 — the summary line must not read as reassurance when the shutdown-drain check +# found something wrong (or could not tell). Sourcing stops before the main flow runs, so this is a +# source-text check like test_drain_gate_abort_message_says_no_no_build above. +test_no_error_lines_message_gated_by_drain_state() { + local src="$ROOT/scripts/redeploy-fleetd.sh" block + block="$(grep -B2 -F 'ok "no ERROR lines since restart"' "$src")" + [ -n "$block" ] || fail "could not find the 'no ERROR lines since restart' line in redeploy-fleetd.sh" + printf '%s' "$block" | grep -qF 'REDEPLOY_DRAIN_STATE' \ + || fail "'no ERROR lines since restart' is not guarded by the shutdown-drain outcome (fleetd #512 item 4)" +} + test_detect_supervisor_launchd_only test_detect_supervisor_systemd_only test_detect_supervisor_none @@ -869,4 +1027,15 @@ test_other_error_is_unexplained test_recovery_requirement_mutation_is_caught test_shared_counter_mutation_is_caught test_unattributable_quiet_mutation_is_caught +test_scan_uncaught_exceptions_finds_shape_without_error_token +test_scan_uncaught_exceptions_clean_control +test_find_drain_complete_line_present +test_find_drain_complete_line_absent +test_report_shutdown_drain_died_without_error_token +test_report_shutdown_drain_complete_control +test_report_shutdown_drain_unknown_cannot_tell +test_report_shutdown_drain_no_previous_daemon_is_na +test_report_shutdown_drain_call_site_present +test_report_shutdown_drain_ordered_after_classify_and_before_result +test_no_error_lines_message_gated_by_drain_state printf 'PASS: redeploy log classifier\n'