test: a failing suite must name the first fatal event, not just the tail (#518) - #519
Conversation
On failure pgc_summary tails 40 lines of the server log. That is the right thing
to show when one statement failed and the wrong thing after a crash: a crashing
backend takes the postmaster through "terminating any other active server
processes" and recovery for every subsequent check, so the cause is at the TOP of
the log and the last 40 lines are its aftermath. pgc_teardown then removes the
workdir, so there is nowhere left to look.
Measured, running a deliberate heap overrun through this harness under the
pg18_san build:
server log: 8,777 lines
AddressSanitizer reports: 67
first report at line: 12
what the 40-line tail showed: lines 8738-8777, all crash recovery
The suite reported 123 failures and not one word about why. The diagnosis existed
for about a quarter of a second, 8,765 lines above the only window anyone saw.
So the failure path now greps the whole log for the events that mean "this was
not a failed assertion" -- AddressSanitizer, UndefinedBehaviorSanitizer, runtime
error:, terminated by signal, PANIC: -- and prints the first five with line
numbers, above the existing tail. The tail is unchanged; this is added context,
not a replacement, because for the ordinary single-statement failure the tail is
still the useful view.
## Tests
harness_selftest.sh stands the scenario up without needing a sanitizer build: a
fatal-looking line via RAISE LOG, 60 filler lines to push it past the tail window,
then a real failure.
Two premise checks first, because this check has two ways to pass for the wrong
reason -- if the sub-suite did not fail, the summary never runs; if the filler did
not bury the marker, the existing tail would have shown it and the new code would
be untested:
PASS premise: the sub-suite failed, so its summary ran
PASS premise: the 40-line tail is filler, not the marker
Red before the change, and again with lib.sh reverted under the new test:
FAIL a failing suite names the first fatal event in its log: got [no] want [yes]
The assertion is scoped to the new section and asks whether the marker is there
rather than how many times: PostgreSQL emits a STATEMENT: line beside the message,
so it legitimately appears twice, and an exact count would be asserting a detail
of PostgreSQL's logging.
Found while running the sanitizer build over today's decode-path changes (commandprompt#511,
commandprompt#514), where a clean result could not be distinguished from a broken instrument.
No defect was found in either.
jdatcmd
left a comment
jdatcmd
left a comment
There was a problem hiding this comment.
Approved. harness_selftest=PASS on PG18 and not among the six skips — which is the check that matters for a PR whose subject is a harness check, since a suite that never ran reports the same green as one that passed.
The finding is worth more than the fix
123 failures, no cause, evidence deleted. The tail is the right view for a failed statement and the wrong one after a crash — because the postmaster goes through terminate-and-recover for every subsequent check, so the cause ends up at the top and the last 40 lines are all recovery. Then teardown rm -rfs the workdir. 67 reports in an 8,777-line log, the first at line 12, and the tail showed 8738-8777.
Keeping the tail and adding the grep above it is the right shape. Replacing it would have traded one blind spot for another.
The six controls are the best debugging sequence either of us produced today
The one I would put on a wall is v3/v4: ASAN's log_path pointed somewhere postgres could not write, so the report was discarded with no error and no stderr fallback. Three runs looked clean while a deliberate overrun was firing. An instrument that fails silently and fails closed toward "clean" is the worst possible combination, and nothing in the output distinguishes it from a pass.
That v1 landed in dead code and produced 0 hits is the other half, and it is what led to the coverage finding in #520.
Two things you did to your own work that I want on the record
You corrected a claim you had already published. "A failing suite loses its explanation" was wrong; the accurate version is narrower and checkable — the tail is right for a statement failure, wrong after a crash. That correction is what makes this fix additive instead of a replacement.
You loosened your own assertion from "exactly 1" to "present". Pinning the count would have asserted a detail of PostgreSQL's logging rather than of your fix, and would break on a version that adds a line. That is the harder direction to move an assertion, because a tighter check feels stronger.
And the two premise checks are the reason I believe the third: without them, a sub-suite that did not fail or a marker that was never buried would leave the new code untested while the check went green. That is the trap this repository has met all day, guarded here before it fired.
Gated five majors 51/0 plus the full matrix. Merging.
2 participants
Closes #518.
A suite that fails because a backend crashed printed 40 lines of crash
recovery and then deleted the evidence.
pgc_summarytails 40 lines of the server log on failure. That is the right viewwhen one statement failed, and the wrong one after a crash: the postmaster goes
through "terminating any other active server processes" and recovery for every
subsequent check, so the cause sits at the top and the tail is aftermath.
pgc_teardownthenrm -rfs the workdir holding the log.Measured, running a deliberate heap overrun through this harness under
pg18_san:AddressSanitizerreports123 failures, no cause, evidence deleted.
The change
Additive. The failure path greps the whole log for the events that mean "this was
not a failed assertion" —
AddressSanitizer,UndefinedBehaviorSanitizer,runtime error:,terminated by signal,PANIC:— and prints the first fivewith line numbers, above the existing tail.
The tail stays. For the ordinary single-statement failure it is still the useful
view, and replacing it would trade one blind spot for another.
Tests
harness_selftest.shbuilds the scenario without needing a sanitizer build: afatal-looking line via
RAISE LOG, 60 filler lines to push it past the tailwindow, then a real failure.
Two premise checks first, because this check has two ways to pass for the wrong
reason — if the sub-suite never failed, the summary never runs; if the filler
never buried the marker, the existing tail would have shown it and the new code
would be untested:
Red before the change, and again with
lib.shreverted under the new test(the removal proof):
The assertion is scoped to the new section and asks whether the marker is
present rather than how many times. PostgreSQL emits a
STATEMENT:line besidethe message so it legitimately appears twice, and pinning the count would assert
a detail of PostgreSQL's logging rather than of this fix.
Gate
harness_selftest51 checks / 0 fail, 0 warnings.lib.shis shared by every suite, so the matrix is the check that matters here.Provenance
Found while running the sanitizer build over today's decode-path merges (#511,
#514) — ASAN is in neither CI nor the assert matrix, so neither had been run
under one. No defect was found in either. Getting to a trustworthy answer
took six controls, because a clean sanitizer run and a broken instrument look
identical; this issue is one of the two things that made them look identical.
The other is environmental and is written up in #518:
ASAN_OPTIONS=log_path=pointing somewhere the
postgresuser cannot write discards every report with noerror and no stderr fallback.