diff --git a/scripts/redeploy-fleetd.sh b/scripts/redeploy-fleetd.sh index a5df9fb..872e233 100755 --- a/scripts/redeploy-fleetd.sh +++ b/scripts/redeploy-fleetd.sh @@ -549,14 +549,51 @@ check_log_path_matches_plist() { ok "log path check: script and plist agree ($resolved_out)" } +# fleetd #552: the post-restart fresh-log capture, pulled out of the main flow so it is testable by +# sourcing (the same reason systemd_installed/systemd_loaded above guard their OWN mktemp inline +# instead of leaving it bare) even though its only caller sits below the SOURCED guard. By the time +# the caller reaches this, the daemon has already been stopped, the jar swapped, and the new daemon +# started — fleetd #552's whole point is that a `mktemp` failure here must never undo that success +# by aborting the script, the way the old unguarded `FRESH_LOG="$(mktemp ...)"` assignment did. +# +# So this function never dies, and — like detect_supervisor above — never reports failure through a +# global either: it is meant to be called as `VAR="$(capture_fresh_log_region ...)"`, which runs it +# in a subshell, and any global it set there would die with that subshell. Failure crosses back the +# only way that survives: a non-zero exit and empty stdout. The caller decides what a failure means +# (warn, and leave FRESH_LOG at its already-declared "" sentinel) and owns the EXIT trap, because +# that trap has to outlive this function's own return — the file must survive until every reader +# below (classify_amqp_connection_errors, report_shutdown_drain, the result section) has looked. +capture_fresh_log_region() { + local out_file="$1" restart_mark="$2" log_file + if ! log_file="$(mktemp -t fleetd-fresh-log.XXXXXX)"; then + return 1 + fi + tail -n "+$((restart_mark + 1))" "$out_file" > "$log_file" 2>/dev/null || true + printf '%s' "$log_file" +} + # 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. +# +# fleetd #552: log_file can now arrive as "" — capture_fresh_log_region's own sentinel for "the +# post-restart region could never be captured". That is a DIFFERENT fact from "captured a region +# with nothing in it", which is exactly what every count below staying at its initialized 0 already +# means; conflating the two would make "no errors found" and "could not look for errors" print +# identically; the exact defect class this ticket exists to fix. REDEPLOY_AMQP_CHECK_SKIPPED carries +# the distinction to the result section below, and this reader says so in its own output too. classify_amqp_connection_errors() { 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 + REDEPLOY_AMQP_CHECK_SKIPPED=0 + + if [ -z "$log_file" ]; then + REDEPLOY_AMQP_CHECK_SKIPPED=1 + warn "cannot check for AMQP/ERROR lines since restart — the post-restart log region could not be captured" + return 0 + fi while IFS= read -r line || [ -n "$line" ]; do case "$line" in @@ -680,6 +717,19 @@ report_shutdown_drain() { return 0 fi + # fleetd #552: checked AFTER the n/a case above, not before it — a cold start has nothing to check + # regardless of whether the log region could be captured, and that fact must not be overridden by + # an unrelated mktemp failure. "skipped" is a fifth state on REDEPLOY_DRAIN_STATE, distinct from + # "unknown" (the log WAS read, and neither a drain-complete line nor an exception shape was found + # in it): here there was no log to read at all, and that is a different fact that must say so in + # its own output, never silently reported as "unknown" or, worse, as "complete"/"n/a". + if [ -z "$log_file" ]; then + REDEPLOY_DRAIN_STATE="skipped" + warn "cannot tell whether the previous daemon's shutdown drain finished — the post-restart log" + warn "region could not be captured" + return 0 + fi + find_drain_complete_line "$log_file" scan_uncaught_exceptions "$log_file" @@ -1110,9 +1160,24 @@ tail -n "+$((RESTART_MARK + 1))" "$OUT" 2>/dev/null \ # 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.XXXXXX)" +# +# fleetd #552: by this point the daemon has already been stopped, the jar swapped, and the new +# daemon started. The old unguarded `FRESH_LOG="$(mktemp ...)"` here aborted the whole script on any +# mktemp failure — AFTER all of that had already succeeded — so a caller read the resulting non-zero +# exit as "the redeploy failed" and the likely next action was to restart an already-correctly- +# restarted daemon. The mktemp itself now lives in capture_fresh_log_region (guarded the same way +# :293/:317/:344/:359 guard their own), and a failure there only warns: there is nothing left to +# protect by refusing after a successful restart. FRESH_LOG="" is declared and the trap installed +# BEFORE the call that may fail to fill it in, not after — an empty FRESH_LOG makes `rm -f ""` a +# harmless no-op, so there is no ordering hazard left between "the file might already exist" and +# "the trap that cleans it up". +FRESH_LOG="" trap 'rm -f "$FRESH_LOG"' EXIT -tail -n "+$((RESTART_MARK + 1))" "$OUT" > "$FRESH_LOG" 2>/dev/null || true +if ! FRESH_LOG="$(capture_fresh_log_region "$OUT" "$RESTART_MARK")"; then + warn "could not create a temp file for the post-restart log region — the restart itself already" + warn "succeeded (pid $NEW_PID); only the post-restart ERROR/drain checks below are skipped." + warn "Check $OUT yourself for anything since the restart." +fi classify_amqp_connection_errors "$FRESH_LOG" # fleetd #512 part 2: the previous daemon's shutdown drain, checked in the same fresh-log region — @@ -1131,7 +1196,14 @@ assert_single_daemon "$(running_pid)" say "result" ok "pid $NEW_PID, jar $(jar_id)" -if [ "$REDEPLOY_ERROR_COUNT" -eq 0 ]; then +if [ "$REDEPLOY_AMQP_CHECK_SKIPPED" -eq 1 ]; then + # fleetd #552: the fourth reader of the fresh-log region. Without this branch REDEPLOY_ERROR_COUNT + # stays at its untouched 0 (classify_amqp_connection_errors never got a file to read) and + # REDEPLOY_DRAIN_STATE is "skipped" (never "complete"/"n/a"), so the branches below would print + # NOTHING about ERROR lines at all — a silence that reads exactly like the clean bill of health + # this ticket exists to prevent. Say the unknown result out loud instead. + warn "ERROR-line count since restart is UNKNOWN — the post-restart log region could not be captured (see above)" +elif [ "$REDEPLOY_ERROR_COUNT" -eq 0 ]; then # 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 diff --git a/scripts/test-redeploy-fleetd.sh b/scripts/test-redeploy-fleetd.sh index 384e9a2..9fcdd3d 100755 --- a/scripts/test-redeploy-fleetd.sh +++ b/scripts/test-redeploy-fleetd.sh @@ -236,6 +236,129 @@ test_no_unguarded_macos_only_hasher_calls() { || fail "script(s) invoke the macOS-only hasher with no portable-hasher-first fallback guard in the same file: $bad" } +# fleetd #552 — the shape, not the one line just fixed: a `mktemp` failure AFTER the daemon has +# already been restarted must never be a bare, unguarded assignment again, anywhere in the script, +# so the next one added is caught too — not just line 1113 as it stood at 26f380a. Anchored on the +# real "start" section (the restart call itself), the same anchor test_swap_ordered_after_wait_and_ +# before_start above already uses for "before the start section". Needle built from two concatenated +# pieces, the same trick test_no_unguarded_macos_only_hasher_calls uses above, so this check's own +# description of the pattern it looks for can never become a match for itself. +test_no_unguarded_mktemp_assignments_after_restart() { + local src="$ROOT/scripts/redeploy-fleetd.sh" start_line needle bad + start_line="$(grep -Fn 'say "start"' "$src" | head -1 | cut -d: -f1 || true)" + [ -n "$start_line" ] || fail "could not find the restart call's start section in redeploy-fleetd.sh" + needle='^[[:space:]]*[A-Za-z_][A-Za-z0-9_]*="' + needle="$needle"'\$\(mktemp' + bad="$(grep -nE "$needle" "$src" | awk -F: -v start="$start_line" '$1+0>start')" + [ -z "$bad" ] \ + || fail "unguarded 'VAR=\"\$(mktemp ...)\"' assignment(s) after the restart call (fleetd #552): $bad" +} + +# fleetd #552 — capture_fresh_log_region itself. Sourcing stops before the main flow can be driven +# directly (the SOURCED guard below), so this exercises the extracted function the real call site +# now uses, the same stub-mktemp-on-PATH technique +# test_detect_supervisor_systemd_probe_setup_failure_is_unclear uses above. +test_capture_fresh_log_region_control() { + printf 'line one\nline two\nline three\n' > "$TMP/fresh-log-src.out" + local result + result="$(capture_fresh_log_region "$TMP/fresh-log-src.out" 0)" + [ -n "$result" ] || fail "capture_fresh_log_region returned nothing on a working mktemp" + [ -f "$result" ] || fail "capture_fresh_log_region did not create the file it named" + assert_equals "$(printf 'line one\nline two\nline three')" "$(cat "$result")" \ + "captured region did not carry the whole source file (restart_mark=0)" + rm -f "$result" +} + +test_capture_fresh_log_region_mktemp_failure_returns_nonzero_and_prints_nothing() { + local bin_dir rc=0 out + bin_dir="$TMP/stub-bin-fresh-log-mktemp-fails"; mkdir -p "$bin_dir" + cat > "$bin_dir/mktemp" <<'STUB' +#!/usr/bin/env bash +echo "mktemp: cannot create temp file" >&2 +exit 1 +STUB + chmod +x "$bin_dir/mktemp" + printf 'line one\n' > "$TMP/fresh-log-src2.out" + + out="$(PATH="$bin_dir:$PATH" capture_fresh_log_region "$TMP/fresh-log-src2.out" 0)" && rc=0 || rc=$? + [ "$rc" -ne 0 ] \ + || fail "capture_fresh_log_region must return non-zero when its own mktemp fails" + [ -z "$out" ] \ + || fail "capture_fresh_log_region printed a path even though mktemp failed: $out" +} + +# fleetd #552 acceptance: "the exit status after a stubbed mktemp failure must still report the +# restart's own outcome". Sourcing stops before the main flow runs, so this drives the REAL +# call-site shape (the `if ! FRESH_LOG="$(capture_fresh_log_region ...)"; then warn; fi` guard that +# now stands where the old unguarded assignment did) in a subshell, under the SAME `set -euo +# pipefail` the real script runs under, with `mktemp` stubbed to fail on PATH. A regression back to +# the old unguarded `FRESH_LOG="$(mktemp ...)"` shape would abort this subshell before it reaches +# SUBSHELL_REACHED_END, and this test would go red with a non-zero rc. +test_fresh_log_capture_failure_does_not_abort_under_sete() { + local bin_dir rc=0 out + bin_dir="$TMP/stub-bin-call-site-mktemp-fails"; mkdir -p "$bin_dir" + cat > "$bin_dir/mktemp" <<'STUB' +#!/usr/bin/env bash +echo "mktemp: cannot create temp file" >&2 +exit 1 +STUB + chmod +x "$bin_dir/mktemp" + printf 'line one\n' > "$TMP/fresh-log-callsite.out" + + out="$( + PATH="$bin_dir:$PATH" + set -euo pipefail + FRESH_LOG="" + trap 'rm -f "$FRESH_LOG"' EXIT + if ! FRESH_LOG="$(capture_fresh_log_region "$TMP/fresh-log-callsite.out" 0)"; then + echo "WARN skipped" + fi + echo "SUBSHELL_REACHED_END" + )" && rc=0 || rc=$? + + [ "$rc" -eq 0 ] \ + || fail "the guarded call-site shape aborted under set -e when mktemp failed (rc=$rc) — a successful restart must not be reported as a failure" + printf '%s' "$out" | grep -qF 'SUBSHELL_REACHED_END' \ + || fail "the subshell aborted before reaching the end — a post-restart mktemp failure must not abort the script" + printf '%s' "$out" | grep -qF 'WARN skipped' \ + || fail "the guarded call site did not report the post-restart check as skipped when mktemp failed" +} + +# fleetd #552 item 4 (the fourth reader): the result section must check REDEPLOY_AMQP_CHECK_SKIPPED +# and say so BEFORE it ever consults REDEPLOY_ERROR_COUNT — otherwise a skipped capture (which +# leaves REDEPLOY_ERROR_COUNT at its untouched 0) falls through the same "no ERROR lines" gate a +# genuinely clean restart uses, and (because REDEPLOY_DRAIN_STATE is "skipped", not "complete"/"n/a") +# prints nothing at all: a silence indistinguishable from the clean bill of health this ticket exists +# to prevent. Sourcing stops before the main flow runs, so this is a source-text ordering check, the +# same shape as test_report_shutdown_drain_ordered_after_classify_and_before_result above. +# fleetd #552 — closes the gap test_no_unguarded_mktemp_assignments_after_restart cannot: after +# extracting the mktemp into capture_fresh_log_region, the SAME class of hazard (an unguarded +# command-substitution assignment that can abort the script under set -e, because capture_fresh_ +# log_region still returns non-zero on its own mktemp failure) would reappear if the main flow's +# call to it ever lost its own "if !" guard — and that line no longer contains the literal text +# "mktemp", so the sweep above cannot see it. Pin the real call site directly instead, the same +# shape test_swap_ordered_after_wait_and_before_start above uses for its own call site. +test_capture_fresh_log_region_call_site_is_guarded() { + local src="$ROOT/scripts/redeploy-fleetd.sh" call_line + call_line="$(grep -Fn 'if ! FRESH_LOG="$(capture_fresh_log_region "$OUT" "$RESTART_MARK")"; then' "$src" | head -1 | cut -d: -f1 || true)" + [ -n "$call_line" ] \ + || fail "could not find the main flow's guarded capture_fresh_log_region call site in redeploy-fleetd.sh" +} + +test_result_section_checks_amqp_skip_before_no_error_lines() { + local src="$ROOT/scripts/redeploy-fleetd.sh" result_line skip_line ok_line + result_line="$(grep -Fn 'say "result"' "$src" | head -1 | cut -d: -f1 || true)" + skip_line="$(grep -Fn '"$REDEPLOY_AMQP_CHECK_SKIPPED" -eq 1' "$src" | tail -1 | cut -d: -f1 || true)" + ok_line="$(grep -Fn 'ok "no ERROR lines since restart"' "$src" | head -1 | cut -d: -f1 || true)" + [ -n "$result_line" ] || fail "could not find the result section in redeploy-fleetd.sh" + [ -n "$skip_line" ] || fail "could not find a REDEPLOY_AMQP_CHECK_SKIPPED check in redeploy-fleetd.sh" + [ -n "$ok_line" ] || fail "could not find the 'no ERROR lines since restart' line in redeploy-fleetd.sh" + [ "$skip_line" -gt "$result_line" ] \ + || fail "the REDEPLOY_AMQP_CHECK_SKIPPED check (line $skip_line) is not inside the result section (starts line $result_line)" + [ "$skip_line" -lt "$ok_line" ] \ + || fail "the REDEPLOY_AMQP_CHECK_SKIPPED check (line $skip_line) is not checked before 'no ERROR lines since restart' (line $ok_line)" +} + # fleetd #492 follow-up (Item 1): this must go through the REAL call-site shape at :437-440, not a # hand-constructed "unclear" value — a test that builds "unclear" directly proves the switch, not # the handoff, and that is exactly the gap that let SUPERVISOR_UNCLEAR_DETAIL never reach the real @@ -890,6 +1013,20 @@ LOG classify_fixture no-errors.log assert_equals 0 "$REDEPLOY_ERROR_COUNT" "no-errors total" assert_equals 0 "$REDEPLOY_UNEXPLAINED_ERRORS" "no-errors unexplained" + # fleetd #552 control: a REAL, readable log region with nothing in it must never look like a + # region that could not be captured at all. + assert_equals 0 "$REDEPLOY_AMQP_CHECK_SKIPPED" "no-errors must not report the check as skipped" +} + +# fleetd #552 — the third state: "" (capture_fresh_log_region's own sentinel for "the post-restart +# region could never be captured") must never look like "read a file with nothing in it", which is +# exactly what REDEPLOY_ERROR_COUNT staying at 0 already means on its own (see test_no_errors above). +test_classify_amqp_connection_errors_reports_skipped_when_log_missing() { + classify_amqp_connection_errors "" > "$TMP/classify-skipped-output" 2>&1 + assert_equals 1 "$REDEPLOY_AMQP_CHECK_SKIPPED" "an empty log_file must set REDEPLOY_AMQP_CHECK_SKIPPED=1" + assert_equals 0 "$REDEPLOY_ERROR_COUNT" "a skipped check must still leave REDEPLOY_ERROR_COUNT at its initialized 0 (the flag, not the count, carries the distinction)" + grep -qF 'could not be captured' "$TMP/classify-skipped-output" \ + || fail "classify_amqp_connection_errors did not say the post-restart log region could not be captured" } test_recovery_patterns_match_source() { @@ -1203,6 +1340,27 @@ LOG || fail "report_shutdown_drain did not report that there was nothing to check" } +# fleetd #552 — a fifth outcome: log_file="" (capture_fresh_log_region's own sentinel) with a +# previous daemon that WAS stopped this run. Distinct from "unknown" (a log was read and neither +# signal was found in it) — here there was no log to read at all. +test_report_shutdown_drain_skipped_when_log_missing() { + report_shutdown_drain "" 1 > "$TMP/drain-skipped-output" 2>&1 + assert_equals "skipped" "$REDEPLOY_DRAIN_STATE" "an empty log_file with a previous daemon must set REDEPLOY_DRAIN_STATE=skipped" + grep -qF 'could not be captured' "$TMP/drain-skipped-output" \ + || fail "report_shutdown_drain did not say the post-restart log region could not be captured" + if grep -qF ' ok' "$TMP/drain-skipped-output"; then + fail "the skipped outcome must not be printed via ok() — it is neither a pass nor a failure" + fi +} + +# fleetd #552 — proves the had_previous_daemon=0 check really does run BEFORE the missing-log check: +# with BOTH conditions true at once, n/a must win, because a cold start has nothing to check +# regardless of whether the log region could be captured. +test_report_shutdown_drain_na_wins_over_missing_log() { + report_shutdown_drain "" 0 > "$TMP/drain-na-and-missing-output" 2>&1 + assert_equals "n/a" "$REDEPLOY_DRAIN_STATE" "no-previous-daemon must win over a missing log region" +} + # 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 @@ -1249,6 +1407,12 @@ test_detect_supervisor_systemd_probe_error_is_unclear test_detect_supervisor_systemd_probe_setup_failure_is_unclear test_mktemp_dash_t_templates_have_x_placeholders test_no_unguarded_macos_only_hasher_calls +test_no_unguarded_mktemp_assignments_after_restart +test_capture_fresh_log_region_control +test_capture_fresh_log_region_mktemp_failure_returns_nonzero_and_prints_nothing +test_fresh_log_capture_failure_does_not_abort_under_sete +test_capture_fresh_log_region_call_site_is_guarded +test_result_section_checks_amqp_skip_before_no_error_lines test_require_drivable_supervisor_refuses_ambiguous test_require_drivable_supervisor_refuses_unclear test_require_drivable_supervisor_accepts_known_kinds @@ -1289,6 +1453,7 @@ test_stop_systemd_if_loaded_dies_on_real_failure test_stop_systemd_if_loaded_tolerates_clean_negative test_stop_branches_call_tolerant_helpers_not_bare_or_true test_no_errors +test_classify_amqp_connection_errors_reports_skipped_when_log_missing test_recovery_patterns_match_source test_attributed_recovered_connection_error test_source_derived_error_shapes_recover_by_connection @@ -1307,6 +1472,8 @@ 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_skipped_when_log_missing +test_report_shutdown_drain_na_wins_over_missing_log 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