Skip to content

test: a cluster that will not start reports why, and the verdict stops guessing (#537) #544

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
ChronicallyJD merged 4 commits into from
Aug 10, 2026
Merged

test: a cluster that will not start reports why, and the verdict stops guessing (#537) #544

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
f4f3131
test: a cluster that will not start reports why, and the verdict stop…
jdatcmd Aug 9, 2026
8539f47
test: name both routine FATAL classes, not just the one I happened to…
jdatcmd Aug 9, 2026
adca713
test: assert lib.sh ASKS these functions, and two smaller review defe…
jdatcmd Aug 9, 2026
b7b8f52
test: the immediate-stop measurement is now two runs, not one (#537)
jdatcmd Aug 9, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
114 changes: 114 additions & 0 deletions test/harness_selftest.sh
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
128 changes: 124 additions & 4 deletions test/lib.sh
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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"
Expand All @@ -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
}
Expand Down Expand Up @@ -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:-<unset>} ----" >&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() {
Expand Down Expand Up @@ -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"
Expand Down
Loading