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'