fleetd #512 part 2: detect a died shutdown drain the ERROR count is blind to #534

Merged
ltms merged 1 commits from worker/512-part2-shutdown-detection-434701-9 into main 2026-09-12 08:04:15 +02:00
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'