From f4f3131a12d7989674f5b54e9cf9ca49d4a3c534 Mon Sep 17 00:00:00 2001 From: "Joshua D. Drake" Date: Sun, 9 Aug 2026 14:42:21 -0600 Subject: [PATCH 1/4] test: a cluster that will not start reports why, and the verdict stops guessing (#537) Three defects on one path. A failed start 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 since attempt one. pgc_teardown then removed the workdir, so the evidence was deleted moments after the only message anyone saw. The fix is three functions in lib.sh, so the decisions are testable without standing a cluster up, which is what #465 set that precedent for: pgc_fatal_pattern one definition of "not a failed assertion", shared by the start path and the summary path, which had drifted to having a pattern and no pattern respectively pgc_start_log_report the first FATALs with line numbers, then a tail, and an explicit line when it found neither -- silence here reads as "nothing to say", which was the complaint pgc_start_failure_message the verdict, which now takes whether a foreign data directory was actually seen The verdict no longer asserts a cause it has not established. "(refusing to run against a cluster this suite does not own)" was printed unconditionally and was false in the reported case: nothing was squatting, our own postmaster died on eight different ports, and the parenthetical sent the reader hunting a port collision that did not exist. The loop already knew which case it saw. ONE DEPARTURE FROM THE ISSUE AS FILED, and one correction to my own first attempt at it. The issue proposed broadening the pattern to include bare "FATAL:". It does not, and the justification for that is measured because the first justification I wrote was wrong. Wrong, and refuted by @ChronicallyJD rather than by me: I claimed an immediate stop logs a routine FATAL per live backend. Measured with four backends held open on pg_sleep, an immediate stop SIGQUITs them and logs none. Zero. Right, and measured: a PASSING run of native_backend_crash.sh leaves two FATAL lines in its log, both "the database system is in recovery mode", consequences of the crash that suite deliberately causes. Matching bare FATAL would print them as "first fatal events" on any later failure of that suite -- a consequence presented as a cause, which is the defect this issue exists to fix. The START path does grep bare FATAL, because a cluster that never started has produced no routine FATALs to confuse it. Proved end to end, not only by unit check. Built a .so with a genuine undefined symbol, which reproduces the reported failure exactly because lib.sh puts pgcolumnar in shared_preload_libraries, and ran the same broken build against both versions of lib.sh: before: eight retry lines, then "(refusing to run against a cluster this suite does not own)", no cause anywhere after: FATAL: could not load library ... undefined symbol, a log tail, then "(nothing was squatting: our own postmaster failed to start ...)" harness_selftest goes 54 checks to 70. Gate: PG17 assert 132 ran PASS, PG19 assert 137 ran with only temporal, which is btree_gist absent from this container and fails identically on unmodified main. lib.sh is in the path of every suite, which is why this was gated on the full set and not on units. Closes #537 --- test/harness_selftest.sh | 71 +++++++++++++++++++++++++++++ test/lib.sh | 98 ++++++++++++++++++++++++++++++++++++++-- 2 files changed, 165 insertions(+), 4 deletions(-) diff --git a/test/harness_selftest.sh b/test/harness_selftest.sh index 12ea1b51..b5b497bc 100755 --- a/test/harness_selftest.sh +++ b/test/harness_selftest.sh @@ -667,4 +667,75 @@ 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 another cluster really was found" \ + "$(pgc_start_failure_message 8 15208 1 | grep -c 'does not own')" "1" +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" + pgc_summary diff --git a/test/lib.sh b/test/lib.sh index 7a862c49..c4f5737d 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 _sawforeign _started=0 + _sawforeign=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 + _sawforeign=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" "$_sawforeign" >&2 exit 1 fi } @@ -331,6 +337,90 @@ 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". +# +# One definition, used by both the start-failure path and the summary path, +# because they were drifting: the summary path had a pattern and the start path +# had none at all, so a library that would not load produced eight identical +# retry lines and a verdict naming no cause, while the reason sat in server.log +# from the first attempt. +# +# "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 PASSING run of native_backend_crash.sh leaves two FATAL lines +# in its server log, both of them +# +# FATAL: the database system is in recovery mode +# +# which are consequences of the crash that suite deliberately causes, not causes +# of anything. Matching bare FATAL would print them under "first fatal events" on +# any later failure of that suite: a consequence presented as 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 with +# four backends held open on pg_sleep, an immediate stop SIGQUITs them and they +# log no FATAL at all. Zero. Do not restore that reasoning. +# +# 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' +} + +# 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 'FATAL:|PANIC:' "$_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 whether any attempt actually found ANOTHER cluster's data +# directory on the port. Only then is "a cluster this suite does not own" a +# statement about what happened. In #537 nothing was squatting: our own +# postmaster died on eight different ports, and the parenthetical sent the reader +# hunting a port collision that was not there. +pgc_start_failure_message() { + local _attempts="$1" _port="$2" _sawforeign="$3" + + printf '%s\n' "FATAL: no cluster of our own on port $_port after $_attempts attempts" + if [ "$_sawforeign" = "1" ]; then + printf '%s\n' " (a cluster this suite does not own was on the port; refusing to use it)" + else + 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)" + fi +} + # ---- SQL helpers (run as root over TCP, trust auth) ------------------------ PGC_PSQL_BASE() { @@ -741,7 +831,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" From 8539f472b4af43f71d051c97d3254bfb583c1ff2 Mon Sep 17 00:00:00 2001 From: "Joshua D. Drake" Date: Sun, 9 Aug 2026 14:46:20 -0600 Subject: [PATCH 2/4] test: name both routine FATAL classes, not just the one I happened to see (#537) Review point from @ChronicallyJD, verified here rather than taken on trust. The comment justified excluding bare FATAL with one routine class, "the database system is in recovery mode", measured at two lines on a passing native_backend_crash run. There is a second class, and it is the one that decides the argument. Forcing a crash restart and attempting twelve connections during the recovery window, measured here: 5 FATAL: the database system is not yet accepting connections 3 FATAL: the database system is in recovery mode The second class outnumbered the first in my run, and its count scales with how many connections arrive during recovery rather than with anything about the failure. So the noise bare FATAL would print is NOT bounded at the two lines the crash suite happens to show, and a reader who saw only the first class could reason from a bound that does not exist. The decision is unchanged; the reason for it is now the whole reason. Third time today a stated bound turned out to be one sample. Worth the extra grep every time. Refs #537 --- test/lib.sh | 25 +++++++++++++++---------- 1 file changed, 15 insertions(+), 10 deletions(-) diff --git a/test/lib.sh b/test/lib.sh index c4f5737d..68480345 100755 --- a/test/lib.sh +++ b/test/lib.sh @@ -351,16 +351,21 @@ pgc_pg() { # 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 PASSING run of native_backend_crash.sh leaves two FATAL lines -# in its server log, both of them -# -# FATAL: the database system is in recovery mode -# -# which are consequences of the crash that suite deliberately causes, not causes -# of anything. Matching bare FATAL would print them under "first fatal events" on -# any later failure of that suite: a consequence presented as a cause, which is -# the exact defect #537 exists to fix. PANIC stays in the pattern because a PANIC -# is a cause. +# 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 with From adca71359e3e96795d90cf9b6889fc8acb478fcd Mon Sep 17 00:00:00 2001 From: "Joshua D. Drake" Date: Sun, 9 Aug 2026 15:19:18 -0600 Subject: [PATCH 3/4] test: assert lib.sh ASKS these functions, and two smaller review defects (#537) Adversarial review by @ChronicallyJD, all three findings reproduced here before being fixed. The first should have blocked the merge and did. 1. THE FIX WAS REMOVABLE WITHOUT A RED. Measured, not reasoned: delete the pgc_start_log_report call from pgc_setup -> 70 checks, PASSED revert the summary path to a hardcoded pattern -> 70 checks, PASSED assert a squatter unconditionally -> FAILED, 2 checks The 16 checks fed the three functions fixtures and proved their arithmetic. Nothing asserted the failure path calls any of them, so the entire contribution of this branch could be deleted and the suite still reported green. That is the same gap #538 found in #532's bench guards -- the same mistake, twice, the second time inside a fix for an issue about a message asserting something the code has not established. Six call-site checks now, over source text, which is the weaker kind and is labelled as such. The failure path needs a cluster that will not start, which this suite cannot stand up; a weak check on the call site beats none. Both greps are premised on the path still existing, or they approve nothing. Rows 1 and 2 above are now red. Row 3 already was. 2. pgc_fatal_pattern's docstring claimed "one definition, used by both the start-failure path and the summary path". pgc_start_log_report never called it; it hardcoded FATAL:|PANIC:. So the comment asserting the drift had been fixed was itself untrue, committed in the fix for #537. The divergence is right and argued below it. There are now two NAMED patterns, pgc_fatal_pattern and pgc_start_fatal_pattern, so the difference is greppable rather than two literals in two places, and a check asserts each path asks its own. 3. _sawforeign was sticky: set on any attempt, never cleared. One squatter on attempt 1 followed by seven genuine start failures printed the squatter verdict for all eight -- #537's own defect narrowed rather than removed, and reachable, since escaping a port collision is what the retry loop is for. It is a count now, with three cases: none, all, and the mixed one that a flag cannot express. The mixed case has its own check and fails when the old any-nonzero behaviour is restored. One check of my own was wrong rather than the code: a grep for the inline verdict matched two unrelated lines about the previously installed .so (#513). Tightened to the start-failure text, with the reason recorded, since that is the same prefix-matching trap this suite already guards for suite names. harness_selftest 70 checks to 78. End-to-end re-verified with a genuinely broken .so after the pattern change. Gate: PG17 assert 132 ran PASS, PG19 assert 137 ran with only temporal, btree_gist absent from this container, identical on main. Refs #537 --- test/harness_selftest.sh | 47 ++++++++++++++++++++++++++++++-- test/lib.sh | 58 ++++++++++++++++++++++++++-------------- 2 files changed, 83 insertions(+), 22 deletions(-) diff --git a/test/harness_selftest.sh b/test/harness_selftest.sh index b5b497bc..1fa6dfcb 100755 --- a/test/harness_selftest.sh +++ b/test/harness_selftest.sh @@ -705,8 +705,14 @@ check "nor an ordinary log line" \ 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 another cluster really was found" \ - "$(pgc_start_failure_message 8 15208 1 | grep -c 'does not own')" "1" +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" \ @@ -738,4 +744,41 @@ check "and a log with no fatal line still reports rather than staying silent" \ "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 68480345..cfa70003 100755 --- a/test/lib.sh +++ b/test/lib.sh @@ -233,10 +233,10 @@ pgc_setup() { # suite proceeds, and if it never does, the suite fails rather than guessing. echo "-- start" { - local _a _i _dd _started _sawforeign + local _a _i _dd _started _nforeign _started=0 - _sawforeign=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 @@ -247,7 +247,7 @@ pgc_setup() { _dd="$(pgc_cluster_datadir)" fi if [ -n "$_dd" ]; then - _sawforeign=1 + _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" @@ -277,7 +277,7 @@ pgc_setup() { # 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" "$_sawforeign" >&2 + pgc_start_failure_message "$_a" "$PGC_PORT" "$_nforeign" >&2 exit 1 fi } @@ -339,13 +339,15 @@ pgc_pg() { # ---- reporting a failure that happened before any check ran (#537) ---------- -# The events in a server log that mean "this was not a failed assertion". +# The events in a server log that mean "this was not a failed assertion", for the +# SUMMARY path. # -# One definition, used by both the start-failure path and the summary path, -# because they were drifting: the summary path had a pattern and the start path -# had none at all, so a library that would not load produced eight identical -# retry lines and a verdict naming no cause, while the reason sat in server.log -# from the first attempt. +# 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 @@ -378,6 +380,14 @@ 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 @@ -392,7 +402,7 @@ pgc_start_log_report() { return 0 fi - _fatal="$(grep -nE 'FATAL:|PANIC:' "$_log" 2>/dev/null | head -5 || true)" + _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 @@ -409,20 +419,28 @@ pgc_start_log_report() { # The verdict, which must not assert a cause the code has not established. # -# The third argument is whether any attempt actually found ANOTHER cluster's data -# directory on the port. Only then is "a cluster this suite does not own" a -# statement about what happened. In #537 nothing was squatting: our own -# postmaster died on eight different ports, and the parenthetical sent the reader -# hunting a port collision that was not there. +# 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" _sawforeign="$3" + local _attempts="$1" _port="$2" _nforeign="$3" printf '%s\n' "FATAL: no cluster of our own on port $_port after $_attempts attempts" - if [ "$_sawforeign" = "1" ]; then - printf '%s\n' " (a cluster this suite does not own was on the port; refusing to use it)" - else + 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 } From b7b8f5258331d21de8f0bd99ce685b98e865834d Mon Sep 17 00:00:00 2001 From: "Joshua D. Drake" Date: Sun, 9 Aug 2026 15:25:10 -0600 Subject: [PATCH 4/4] test: the immediate-stop measurement is now two runs, not one (#537) The comment cited a single measurement, made by @ChronicallyJD on their pg18a prefix. They then disclosed that the same prefix had carried a contaminated .so for a four-hour window overlapping some of their work, and that they got lucky rather than careful. The measurement is almost certainly unaffected -- a contaminated library fails to load, so a cluster that ran the experiment had a working one -- but a claim in a committed comment resting on one run on one machine is not something to reason about. Reproduced here on PG17, in a different container: four backends held open on pg_sleep, pg_ctl stop -m immediate, zero FATAL lines before and after. Two majors, two machines, same answer. The comment now says so, and says why the refuted reasoning is recorded at all: it is the intuitive answer, and it was written into this file once already as though it were a finding. Refs #537 --- test/lib.sh | 13 ++++++++++--- 1 file changed, 10 insertions(+), 3 deletions(-) diff --git a/test/lib.sh b/test/lib.sh index cfa70003..f644c76a 100755 --- a/test/lib.sh +++ b/test/lib.sh @@ -370,9 +370,16 @@ pgc_pg() { # 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 with -# four backends held open on pg_sleep, an immediate stop SIGQUITs them and they -# log no FATAL at all. Zero. Do not restore that reasoning. +# 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.