fleetd #512 part 2: detect a died shutdown drain the ERROR count is blind to
CI / contract (pull_request) Successful in 1m15s
CI / build (pull_request) Successful in 2m4s

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.
This commit is contained in:
Dai Ha
2026-09-12 12:55:54 +07:00
parent 8335b12562
commit 190436c9cf
2 changed files with 301 additions and 1 deletions
+132 -1
View File
@@ -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
+169
View File
@@ -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'