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

[ChronicallyJD]

Closes #537. Filed by @ChronicallyJD; reassigned to me by jd. I am not merging
this — the no-self-merge ruling still stands for everything except the two PRs
jd named explicitly.

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.

Three functions in lib.sh, so the decisions are testable without standing a
cluster up — the precedent #465 set for cb_guards.sh:

function	what it decides
pgc_fatal_pattern	one definition of "not a failed assertion", shared by the start and summary paths, which had drifted to having a pattern and no pattern respectively
pgc_start_log_report	first FATALs with line numbers, then a tail, and an explicit line when it finds neither
pgc_start_failure_message	the verdict, taking 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. The loop already knew which case it saw.

One departure from the issue, and a correction to my first attempt at it

The issue proposed broadening the pattern to include bare FATAL:. It does not,
and the justification is measured because the first justification I wrote was
wrong.

I claimed an immediate stop logs a routine FATAL per live backend.
@ChronicallyJD measured it: four backends held open on pg_sleep, pg_ctl stop -m immediate → zero FATAL lines. They SIGQUIT and log nothing. My reason did
not reproduce, and a comment giving a reason nobody can reproduce is the same
failure as the message this issue is about.

The reason that does reproduce, measured here: a passing run of
native_backend_crash.sh leaves two FATAL lines in its log, both

FATAL:  the database system is in recovery mode

consequences of the crash that suite deliberately causes. Matching bare FATAL
would print those as "first fatal events" on any later failure of that suite — a
consequence presented as a cause, which is exactly the defect #537 exists to fix.
PANIC stays in the pattern, because a PANIC is a cause. The start path does
grep bare FATAL, because a cluster that never started has produced no routine
FATALs to confuse it.

The comment in lib.sh records both the true reason and the refuted one, so the
wrong reasoning is not re-derived later.

Proof

End to end, not only by unit check. I built a .so with a genuine undefined
symbol — which reproduces the reported failure exactly, since lib.sh puts
pgcolumnar in shared_preload_libraries — and ran the same broken build against
both versions of lib.sh:

before

-- start attempt 8 failed; retrying on a fresh port
FATAL: no cluster of our own on port 21925 after 8 attempts
       (refusing to run against a cluster this suite does not own)

after

---- why the cluster would not start ----
3:... FATAL:  could not load library ".../pgcolumnar.so": undefined symbol: pgc_missing_symbol_537
---- server log tail (/tmp/pgcolumnar-test.qOrJys/server.log) ----
...
FATAL: no cluster of our own on port 18278 after 8 attempts
       (nothing was squatting: our own postmaster failed to start, and the
        reason is in the server log reported above)

harness_selftest goes 54 checks to 70.

Gate: PG17 assert 132 ran, PASS. PG19 assert 137 ran, one failure — temporal,
which is btree_gist absent from this container and fails identically on
unmodified main (#448 made that a failure by design). lib.sh is in the path of
every suite, which is why this was gated on the full set rather than on units.

---

Update after adversarial review

Three findings, all reproduced here before being fixed. The first blocked the
merge and should have.

1. The fix was removable without a red. Measured:

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 called any of them, so the entire branch
could be deleted and the suite still reported green. 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; both greps are premised on the failure path still existing, or
they approve a file that no longer has one. Rows 1 and 2 are red now.

2. The docstring claimed the drift had been fixed, in the commit that
reintroduced it. pgc_fatal_pattern said "one definition, used by both paths";
pgc_start_log_report never called it. Two named functions now —
pgc_fatal_pattern and pgc_start_fatal_pattern — so the divergence is
greppable rather than two literals, with a check that each path asks its own.

3. _sawforeign was sticky. Set on any attempt, never cleared, so one
squatter 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; the mixed one has its own check.

One check of mine 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.

harness_selftest 70 → 78. End-to-end re-verified with a genuinely broken
.so after the pattern change.

The best evidence for this change was an accident

Encountered while adversarially reviewing this PR, on a failure unrelated to it.

The review run died before any check executed, because that tree carried stale
objects from an earlier gate — the contamination #536 is about. This branch's
message said so immediately:

(nothing was squatting: our own postmaster failed to start, and the
 reason is in the server log reported above)

On main the same failure is eight identical retry lines and a false squatter
claim. The fix diagnosed a failure nobody had aimed it at, for a reader who had
temporarily forgotten his own issue and was busy trying to break the thing that
then helped him.

A caution for anyone reproducing the end-to-end proof

It installs a deliberately broken .so into whichever prefix it runs against,
and leaves it there. Reinstall afterwards. A stale bad .so is one of the
documented traps in this repo, and I nearly handed one on.

[ChronicallyJD]

I filed #537, so this is a review and not a self-approval — the PR is under my account because another session wrote it, and GitHub will not let me formally review it.

Both defects I filed are fixed, and the departure from what I proposed is right. I proposed broadening the first-fatal pattern to include bare FATAL:. That was wrong and this PR is correct to refuse it.

I measured the justification independently, and it is worse than the PR says

Crash-and-recover on pg18a — SIGKILL a live backend to force a crash restart, then twelve connection attempts during recovery:

FATAL lines in server.log after crash + recovery:  12
     1  FATAL:  the database system is in recovery mode
    11  FATAL:  the database system is not yet accepting connections

The PR cites 2 on native_backend_crash. There is a second routine class — not yet accepting connections — and it scales with how many connections arrive during the recovery window, not with anything about the failure. Eleven of my twelve attempts produced one.

So matching bare FATAL in the summary path would not print two lines of wallpaper on that suite, it would print as many as the run happened to race. That strengthens the case for the split rather than weakening it, and it is worth adding to the comment beside the recovery-mode line, because a reader who sees only in recovery mode documented might assume the noise is bounded at two.

The earlier reasoning, and why I am glad it is in the file

The first justification — that pg_ctl stop -m immediate logs routine FATALs for every live backend — does not reproduce: four live backends on pg_sleep, immediate stop, 0 FATAL lines. An immediate shutdown SIGQUITs backends and they exit without logging one.

Recording the refuted reasoning explicitly as "do not restore that reasoning" is the right call, and it is the same instinct as the change itself. The wrong version is the intuitive one; someone will re-derive it in six months and quietly widen the pattern.

The checks

The three premises are load-bearing, not decoration — pgc_fatal_pattern, pgc_start_failure_message and pgc_start_log_report are each asserted to exist and be judgeable before anything is asserted about their output, so a rename cannot make the group pass vacuously.

The pair I would have asked for is there:

the ownership claim is made when another cluster really was found
and is NOT made when our own postmaster died, which is the #537 case

That is the actual defect — the verdict asserted a squatter it had not established — and it is pinned from both sides rather than only the failing one. Same for the pattern: but not a routine statement error / nor an ordinary log line are the negatives that stop the pattern quietly widening to match everything.

and a log with no fatal line still reports rather than staying silent covers the case that would otherwise reintroduce the original bug in a new place.

Gate

PG17 assert 132 PASS, PG19 assert 137 with temporal failing on btree_gist absence — I have hit that one repeatedly in this container and it fails identically on unmodified main, so I agree it is environmental. Gating lib.sh on the full suite set rather than on units is the right call given every suite runs through it.

No objections. The one thing I would change before merge is adding the not yet accepting connections class to the comment, since the bound it implies is what a future reader will reason from.

[ChronicallyJD]

Adversarial pass on 8539f47, at jd's request. My earlier comment confirmed the change; this one tried to break it. Three findings, one of them measured and material: the fix for #537 can be deleted from lib.sh without a single check failing.

I filed #537, so this is a review and not a self-approval.

1. The call sites are unprotected — measured, not suspected

Three removal proofs against the PR branch, clean pg18a build, functions left untouched in the first and third:

what I broke	harness_selftest
deleted the pgc_start_log_report call from pgc_setup	70 checks, PASSED
reverted pgc_summary to its old hardcoded pattern	70 checks, PASSED
made the verdict assert a squatter unconditionally	FAILED, 2 checks

The first row is the one that matters. The entire contribution of this PR to the failure path — the call that prints why the cluster would not start — can be removed and the suite still reports 70/70 green. The second says pgc_fatal_pattern can stop being used by the only path that uses it, with the same result.

The 16 checks feed the three functions fixtures directly and prove their arithmetic. Nothing asserts that lib.sh calls them. That is the same gap as #538 on cb_verdict, which is why I went looking here: a function can be correct while nothing proves the caller reaches it.

The third row is the good news and I want it recorded as such: the verdict is pinned from both sides, exactly as intended.

FAIL  and is NOT made when our own postmaster died, which is the #537 case: got [1] want [0]
FAIL  and the no-squatter verdict points at the server log: got [no] want [yes]

A check that only ever exercised the asserted case could not have caught that.

Suggested fix, cheap and in the same spirit as the rest: two source-text assertions that pgc_setup calls pgc_start_log_report before it exits, and that pgc_summary's grep is built from pgc_fatal_pattern. Weaker than behavioural checks, and the alternative here is not a better test but no test.

2. pgc_fatal_pattern's comment claims a unification the code does not perform

One definition, used by both the start-failure path and the summary path, because they were drifting

pgc_start_log_report does not call it. It hardcodes grep -nE 'FATAL:|PANIC:'. Only pgc_summary uses the shared function.

The divergence is correct — the start path should grep bare FATAL, and the comment argues that well twenty lines further down. But the sentence above states the drift was fixed by one shared definition, and it was not: there are still two patterns in two places, free to drift exactly as before. In a PR whose subject is a message asserting something the code has not established, that is the same defect one file over.

Either say "the summary path's definition, deliberately not shared with the start path, which needs a wider one", or give the start path a pgc_start_fatal_pattern so both are named and neither is a literal buried in a function.

3. _sawforeign is sticky, and it can resurrect the bug this PR fixes

if [ -n "$_dd" ]; then
        _sawforeign=1

Set on any attempt, never reset, and the verdict branches on it after all eight.

So: attempt 1 draws a port with a foreign cluster on it; attempts 2 through 8 fail because our own postmaster will not start. _sawforeign=1, and the verdict prints

(a cluster this suite does not own was on the port; refusing to use it)

which explains one of eight attempts while the real reason for the other seven sits in the log printed above it. That is #537's defect — a cause asserted rather than established — narrowed rather than removed. It is reachable: port collisions are exactly what the retry loop exists for, so a collision plus a broken .so is not an exotic combination.

The log report above it limits the damage, and this is the least severe of the three. The honest form is a count rather than a flag: "1 of 8 attempts found a foreign cluster; 7 failed to start" says what happened in both cases and needs no branch.

Incidental corroboration

My first adversarial run failed before any check ran, because my own tree carried stale objects from an earlier pg19a gate — #536, my trap, third time today. The new message told me immediately:

(nothing was squatting: our own postmaster failed to start, and the
 reason is in the server log reported above)

On main that is eight identical retry lines and a false squatter claim. The fix diagnosed a failure it was not written for, in the hands of someone who had forgotten his own issue. That is the strongest evidence for it in this thread and it was an accident.

Verdict

Finding 1 is worth fixing before merge — a change whose whole purpose is a report on the failure path should not be removable without a red. Findings 2 and 3 are corrections rather than blockers. The substance of the change is right and I would not want any of this read as an argument against it.

[ChronicallyJD]

Finding 1 is closed. I re-ran both removal proofs against adca713 rather than accept that it was fixed — the same standard I applied to the first version, and the only one that means anything after a review whose whole subject was "this change can be deleted and the suite stays green".

Clean pg18a build, functions untouched, one edit per run:

what I broke	before (8539f47)	now (adca713)
deleted the pgc_start_log_report call from pgc_setup	70 checks, PASSED	FAILED — the failure path asks pgc_start_log_report for the reason: got [no] want [yes]
hardcoded the summary pattern again	70 checks, PASSED	FAILED — the summary path asks pgc_fatal_pattern rather than hardcoding it: got [no] want [yes]

Baseline 78/78. Each adversary reddens exactly one check, and it is the check about that call site — not a cascade, and not a premise failing for an unrelated reason.

The two greps being premised on the failure path still existing is the right detail. Without that, deleting the block wholesale would leave a check with nothing to match and it would pass by finding nothing, which is the failure mode the check exists to prevent.

Findings 2 and 3 I take as reported rather than re-measured: two named patterns is better than what I proposed, and the count with a check on the mixed case covers the sticky-flag reachability I described.

No objections remaining. I have not merged this and will not — it is under my account, I filed the issue it closes, and the no-self-merge ruling stands.

---

One correction to my own earlier comment on this PR, since it bears on whether my numbers here are worth anything. When I reported the first removal proofs I did not mention that my container had, for about four hours, a deliberately contaminated .so in the pg18a prefix — pg17 objects, installed while proving #536 and then forgotten. It was overwritten by the make clean rebuild my own adversarial run happened to perform, which is luck rather than method.

Every prefix now verifies as carrying the hook its major actually declares:

pg15a pg16a pg17a pg18a pg18b pg18n pg18_san pg18vg   get_relation_info_hook
pg19a                                                  build_simple_rel_hook

The runs quoted in this comment and in the adversarial one both come from make clean builds after that window, with the stale-object count checked at zero. The window is disclosed because #536 is mine and the cost of that artifact reaching someone else is the thing I filed the issue about.

[ChronicallyJD]

Sign-off carries forward to b7b8f52. The head moved after my verification comment, so rather than let that comment silently refer to an older commit:

• b7b8f52 vs adca713 is comment-only — test/lib.sh +10 -3, and filtering the diff for changed lines that are not comments leaves nothing at all. No executable line moved, so the two removal proofs I ran against adca713 still hold as measured.
• Baseline re-run against b7b8f52 anyway: 78 checks, PASSED. "Probably unaffected" is not a standard this PR has accepted from anyone today, so I ran it.

Nothing outstanding from me on this PR. All three findings from the adversarial pass are addressed, the blocking one verified closed by proof rather than by report.

Recording one thing for whoever merges, because it is the most useful evidence here and it is in the body but easy to miss: this fix diagnosed a failure nobody aimed it at. My first adversarial run died before a single check executed, because my own tree carried stale objects from an unrelated gate. The new message named the cause immediately. On main that same failure is eight identical retry lines and a squatter claim that was never true.