diff --git a/test/harness_selftest.sh b/test/harness_selftest.sh index 12ea1b51..1fa6dfcb 100755 --- a/test/harness_selftest.sh +++ b/test/harness_selftest.sh @@ -667,4 +667,118 @@ check "premise: at least one suite drives the C-level encoding selftest" \ check "the sanitizer subset runs every suite that drives the encoding selftest" \ "$(printf '%s' "$_san_missing" | sed 's/^ //')" "" +# ---- a cluster that will not start must report WHY (#537) ------------------- +# +# The failure path printed eight identical retry lines and a verdict naming none +# of the eight causes, while pg_ctl -l had been writing the reason to server.log +# the whole time. The workdir is removed on exit, so the evidence was gone by the +# time anyone read the verdict. +# +# These are text decisions, so they are tested without standing anything up, for +# the same reason bench_guards exists (#465). + +check "premise: the harness exposes its fatal pattern to be judged" \ + "$(type -t pgc_fatal_pattern)" "function" + +_m() { grep -cE "$(pgc_fatal_pattern)" <<<"$1"; } + +check "the fatal pattern matches a library that will not load" \ + "$(_m 'FATAL: could not load library "/usr/local/pg19/lib/pgcolumnar.so": undefined symbol: get_relation_info_hook')" \ + "1" +check "and still matches an AddressSanitizer report" \ + "$(_m '==1==ERROR: AddressSanitizer: heap-buffer-overflow on address 0x1')" "1" +check "and still matches a PANIC" \ + "$(_m 'PANIC: could not write to file')" "1" +check "and still matches a signal death" \ + "$(_m 'server process was terminated by signal 11: Segmentation fault')" "1" +check "but not a routine statement error" \ + "$(_m 'ERROR: division by zero')" "0" +check "nor an ordinary log line" \ + "$(_m 'LOG: database system is ready to accept connections')" "0" + +# ---- the verdict must not assert a cause it has not established ------------- +# +# "(refusing to run against a cluster this suite does not own)" is ONE reason a +# start can fail, and it was not the reason in #537: nothing was squatting, our +# own postmaster died on eight different ports. The loop already knows which case +# it saw; the message collapsed them. +check "premise: the verdict is composed somewhere it can be judged" \ + "$(type -t pgc_start_failure_message)" "function" + +check "the ownership claim is made when a squatter held the port every time" \ + "$([ "$(pgc_start_failure_message 8 15208 8 | grep -c 'does not own')" -ge 1 ] && echo yes || echo no)" "yes" +# The mixed case is the one a sticky flag got wrong: one squatter then seven +# genuine start failures used to print the squatter verdict for all eight. +check "a mixed run reports both causes and neither as the whole story" \ + "$([ "$(pgc_start_failure_message 8 15208 1 | grep -c '1 of 8')" -ge 1 ] && \ + [ "$(pgc_start_failure_message 8 15208 1 | grep -c 'other 7 failed to start')" -ge 1 ] && echo yes || echo no)" \ + "yes" +check "and is NOT made when our own postmaster died, which is the #537 case" \ + "$(pgc_start_failure_message 8 15208 0 | grep -c 'does not own')" "0" +check "the port is named either way" \ + "$(pgc_start_failure_message 8 15208 0 | grep -c '15208')" "1" +check "and so is the attempt count" \ + "$(pgc_start_failure_message 8 15208 0 | grep -c '8 attempts')" "1" +check "and the no-squatter verdict points at the server log" \ + "$([ "$(pgc_start_failure_message 8 15208 0 | grep -ci 'log')" -ge 1 ] && echo yes || echo no)" "yes" + +# ---- and the log report must show the cause, not just that there was one ---- +check "premise: the log report is a function that can be fed a fixture" \ + "$(type -t pgc_start_log_report)" "function" + +_lf="$(mktemp /tmp/pgc-537.XXXXXX)"; chmod 644 "$_lf" +{ + echo 'LOG: starting PostgreSQL 19beta2' + echo 'FATAL: could not load library "/usr/local/pg19/lib/pgcolumnar.so": undefined symbol: get_relation_info_hook' + echo 'LOG: database system is shut down' +} > "$_lf" +_rep="$(pgc_start_log_report "$_lf" 2>&1)" +# At least once, not exactly once: the line legitimately appears twice, in the +# first-fatal block and again in the tail, and pinning it to one would fail on +# correct output. +check "the report names the symbol that was actually missing" \ + "$([ "$(grep -c 'undefined symbol: get_relation_info_hook' <<<"$_rep")" -ge 1 ] && echo yes || echo no)" \ + "yes" +check "and a log with no fatal line still reports rather than staying silent" \ + "$([ -n "$(printf 'LOG: all fine\n' > "$_lf"; pgc_start_log_report "$_lf" 2>&1)" ] && echo yes || echo no)" \ + "yes" +rm -f "$_lf" + +# ---- and lib.sh must ASK these functions, not merely contain them ----------- +# +# The checks above feed the three functions fixtures and prove their arithmetic. +# None of them proves the failure path calls any of them. Measured, not reasoned: +# with the pgc_start_log_report call deleted from pgc_setup, every check above +# still PASSED, 70 of 70. That is the same gap #538 found in #532's bench guards, +# found again in the fix for #537 by an adversarial review. +# +# These are checks over source text, which is the weaker kind. They are here +# because the failure path needs a cluster that will not start, which this suite +# cannot stand up, and a weak check on the call site beats none. + +_LIB="$(dirname "${BASH_SOURCE[0]}")/lib.sh" +check "premise: lib.sh is readable, or every grep below approves nothing" \ + "$([ -r "$_LIB" ] && echo yes || echo no)" "yes" +# Without this the three greps could pass against a file that no longer HAS a +# start-failure path, which is the vacuous form of all of them. +check "premise: the start-failure path still exists to be judged" \ + "$([ "$(grep -c 'no cluster of our own' "$_LIB")" -ge 1 ] && echo yes || echo no)" "yes" + +check "the failure path asks pgc_start_log_report for the reason" \ + "$([ "$(grep -c 'pgc_start_log_report "' "$_LIB")" -ge 1 ] && echo yes || echo no)" "yes" +check "and asks pgc_start_failure_message for the verdict" \ + "$([ "$(grep -c 'pgc_start_failure_message "' "$_LIB")" -ge 1 ] && echo yes || echo no)" "yes" +# The verdict text must live in ONE place. An inline echo beside the call is how +# the old hardcoded parenthetical would come back wearing the same words. +# Matched on the START-FAILURE verdict specifically. A looser grep for +# `echo " (refusing` finds two unrelated lines about the previously +# installed .so (#513) and reports a defect that is not there -- which is the +# same prefix-matching trap this suite already guards for suite names. +check "and the old start-failure verdict is not echoed inline anywhere" \ + "$(grep -c 'refusing to run against a cluster' "$_LIB")" "0" +check "the summary path asks pgc_fatal_pattern rather than hardcoding it" \ + "$([ "$(grep -c 'grep -nE .\$(pgc_fatal_pattern)' "$_LIB")" -ge 1 ] && echo yes || echo no)" "yes" +check "and the start path asks pgc_start_fatal_pattern, its deliberately wider one" \ + "$([ "$(grep -c 'pgc_start_fatal_pattern)' "$_LIB")" -ge 1 ] && echo yes || echo no)" "yes" + pgc_summary diff --git a/test/lib.sh b/test/lib.sh index 7a862c49..f644c76a 100755 --- a/test/lib.sh +++ b/test/lib.sh @@ -233,9 +233,10 @@ pgc_setup() { # suite proceeds, and if it never does, the suite fails rather than guessing. echo "-- start" { - local _a _i _dd _started + local _a _i _dd _started _nforeign _started=0 + _nforeign=0 for _a in 1 2 3 4 5 6 7 8; do _dd="" if pgc_pg "pg_ctl -D '$PGC_PGDATA' -l '$PGC_LOGFILE' start -w" >/dev/null 2>&1; then @@ -246,6 +247,7 @@ pgc_setup() { _dd="$(pgc_cluster_datadir)" fi if [ -n "$_dd" ]; then + _nforeign=$(( _nforeign + 1 )) echo "-- port $PGC_PORT serves $_dd, not ours; retrying on a fresh port" else echo "-- start attempt $_a failed; retrying on a fresh port" @@ -270,8 +272,12 @@ pgc_setup() { done if [ "$_started" != "1" ]; then - echo "FATAL: no cluster of our own on port $PGC_PORT after $_a attempts" >&2 - echo " (refusing to run against a cluster this suite does not own)" >&2 + # The reason FIRST, then the verdict. pg_ctl -l has been writing it + # to this file since attempt one, and pgc_teardown removes the + # workdir on exit, so a verdict without it is the last thing anyone + # sees before the evidence is deleted (#537). + pgc_start_log_report "${PGC_LOGFILE:-}" + pgc_start_failure_message "$_a" "$PGC_PORT" "$_nforeign" >&2 exit 1 fi } @@ -331,6 +337,120 @@ pgc_pg() { "${PGC_RUNPG[@]}" env PATH="$PGC_BINDIR:$PATH" bash -lc "$1" } +# ---- reporting a failure that happened before any check ran (#537) ---------- + +# The events in a server log that mean "this was not a failed assertion", for the +# SUMMARY path. +# +# There are deliberately TWO patterns, not one, and an earlier version of this +# comment claimed they were one shared definition while the code had already +# diverged -- the exact defect #537 is about, committed in the fix for it. They +# are named functions so the divergence is visible and greppable rather than two +# literals in two places: pgc_fatal_pattern here, pgc_start_fatal_pattern below. +# Their reasons for differing are given at each. +# +# "could not load library" is the addition. Bare "FATAL:" deliberately is NOT in +# here, and the reason is measured rather than reasoned, because the first reason +# written here was wrong and did not survive being checked. +# +# What is true: a crash restart produces routine FATALs in TWO classes, and +# neither is a cause of anything. A PASSING run of native_backend_crash.sh leaves +# two lines of the first class; forcing a crash and then attempting twelve +# connections during the recovery window produces both: +# +# 5 FATAL: the database system is not yet accepting connections +# 3 FATAL: the database system is in recovery mode +# +# The second class is the one that matters for this decision, because its count +# scales with how many connections arrive during recovery rather than with +# anything about the failure. So the wallpaper bare FATAL would print is not +# bounded at the two lines the crash suite happens to show; a busier run prints +# as many as it raced. Matching them would put a consequence under "first fatal +# events" as though it were a cause, which is the exact defect #537 exists to +# fix. PANIC stays in the pattern because a PANIC is a cause. +# +# What is NOT true, and was the original justification here: that a cluster +# stopped with -m immediate logs a routine FATAL per live backend. Measured twice, +# independently, on two majors and two machines -- four backends held open on +# pg_sleep, then pg_ctl stop -m immediate: +# +# PG18: 0 FATAL lines PG17: 0 FATAL lines, before and after +# +# An immediate stop SIGQUITs them and they log nothing. Do not restore that +# reasoning. It is recorded here BECAUSE it is the intuitive answer and will +# otherwise be re-derived by whoever reads this next; it was written into this +# file once already as though it were a finding. +# +# The START path can afford a bare FATAL grep, and does one, because a cluster +# that never started has produced no routine FATALs to confuse it. +pgc_fatal_pattern() { + printf '%s\n' 'AddressSanitizer|UndefinedBehaviorSanitizer|runtime error:|terminated by signal|PANIC:|could not load library' +} + +# The same question for the START path, which can afford a bare FATAL where the +# summary path cannot. A cluster that never started has produced no routine +# FATALs -- the two routine classes both come from crash RECOVERY, which requires +# having started -- so here every FATAL is a candidate cause. +pgc_start_fatal_pattern() { + printf '%s\n' 'FATAL:|PANIC:' +} + +# What the server log says about a cluster that would not start. +# +# Takes the log path so it can be tested against a fixture without standing a +# cluster up. Prints the first FATAL lines with their line numbers, then a tail, +# and says so explicitly when it found neither -- silence here reads as "there +# was nothing to say", which was the whole complaint in #537. +pgc_start_log_report() { + local _log="$1" _fatal _tail + + if [ -z "$_log" ] || [ ! -s "$_log" ]; then + echo "---- server log: absent or empty at ${_log:-} ----" >&2 + return 0 + fi + + _fatal="$(grep -nE "$(pgc_start_fatal_pattern)" "$_log" 2>/dev/null | head -5 || true)" + if [ -n "$_fatal" ]; then + echo "---- why the cluster would not start ----" >&2 + printf '%s\n' "$_fatal" >&2 + else + echo "---- no FATAL in the server log; its tail follows ----" >&2 + fi + _tail="$(tail -20 "$_log" 2>/dev/null || true)" + if [ -n "$_tail" ]; then + echo "---- server log tail ($_log) ----" >&2 + printf '%s\n' "$_tail" >&2 + fi + return 0 +} + +# The verdict, which must not assert a cause the code has not established. +# +# The third argument is HOW MANY attempts actually found another cluster's data +# directory on the port. A count rather than a flag, because a flag was sticky: +# set on any attempt and never cleared, so one squatter on attempt 1 followed by +# seven genuine start failures printed the squatter verdict for all eight. That +# is #537's own defect narrowed rather than removed, and it is reachable, since +# escaping a port collision is what the retry loop exists for. +# +# Three cases, and the mixed one is why this is not a branch on zero. +pgc_start_failure_message() { + local _attempts="$1" _port="$2" _nforeign="$3" + + printf '%s\n' "FATAL: no cluster of our own on port $_port after $_attempts attempts" + if [ "$_nforeign" = "0" ]; then + printf '%s\n' " (nothing was squatting: our own postmaster failed to start, and the" + printf '%s\n' " reason is in the server log reported above)" + elif [ "$_nforeign" = "$_attempts" ]; then + printf '%s\n' " (a cluster this suite does not own held the port on every attempt;" + printf '%s\n' " refusing to use it)" + else + printf '%s\n' " ($_nforeign of $_attempts attempts found a cluster this suite does not" + printf '%s\n' " own; the other $(( _attempts - _nforeign )) failed to start, and that" + printf '%s\n' " reason is in the server log reported above)" + fi +} + # ---- SQL helpers (run as root over TCP, trust auth) ------------------------ PGC_PSQL_BASE() { @@ -741,7 +861,7 @@ pgc_summary() { # # grep the whole file for the events that mean "this was not a failed # assertion", and print the first few with line numbers. - _pgc_fatal="$(pgc_pg "grep -nE 'AddressSanitizer|UndefinedBehaviorSanitizer|runtime error:|terminated by signal|PANIC:' '$PGC_LOGFILE' | head -5" 2>/dev/null || true)" + _pgc_fatal="$(pgc_pg "grep -nE '$(pgc_fatal_pattern)' '$PGC_LOGFILE' | head -5" 2>/dev/null || true)" if [ -n "$_pgc_fatal" ]; then echo "---- first fatal events in the server log ----" printf '%s\n' "$_pgc_fatal"