Skip to content

Eleven timeout paths print a FAIL nothing records, and the accounting balances at the wrong number #965

Description

@OffgridwithJD

Ten registered suites emit no RESULT lines and no checks run: total. They print their own PASS <name>: <value> lines and their own verdict — AUDIT TEST PASSED, CONCURRENCY TEST PASSED — and exit 0. They pass, and nothing that reads machine-readable results can see them.

Found while measuring #432's coverage half, by running all 252 registered suites on PG18.

Measured

suite          PASS-style lines   RESULT lines   checks run:   own verdict line
audit                   31              0            absent          yes
concurrency              7              0            absent          yes
phase2                  42              0            absent          yes
phase3                  32              0            absent          yes
phase4                  38              0            absent          yes
phase5                  36              0            absent          yes
phase6                  43              0            absent          yes
smoke                    9              0            absent          yes
unique_conc             30              0            absent          yes
update_conc             25              0            absent          yes
                       ---
                       293

293 checks. For comparison the whole machine-readable corpus is 6,422 checks across 240 suites, so this is about 4.4% of the suite surface, concentrated in ten files.

Read first: 293 is a PG18 number, and one version gate is why

The count in these suites moves with the PostgreSQL major, so anyone chasing
the remainder must re-count on their own box rather than reconcile against 293.

Measured, not inferred — test/audit.sh run on both majors from the #969 tree at
66507a92, each in its own build tree:

PG18 (pg18a) PG16 (pg16a)
checks run: / RESULT records 26 23
human PASS lines 31 27
of those, from expect_error (unrecorded) 5 4
the server_version_num >= 170000 arm taken not taken
rc 0 0

The whole divergence is one gate, test/audit.sh:293. PG16 and earlier refuse
PARTITION BY ... USING pgcolumnar, so the partitioned-parent arm is gated out,
and it holds exactly 3 check calls and 1 expect_error — which is the 3-record
and 1-unrecorded difference, with nothing left over. linuxhikerpm measured all
ten suites on PG16 independently and audit is the only one of the ten that moves.

So the totals for both majors:

PG18 PG16
census of human PASS lines 293 289
recorded after #969 236 233
remainder still unrecorded 58 57

Each recorded figure includes one SKIP record for the citext case that has no
PASS line in the base census, which is why recorded + remainder exceeds the
census by one.

Correction to something I said earlier: I quoted the remainder as 57 on PG18.
That was linuxhikerpm's PG16 figure applied to my PG18 census. On PG18 it is 58 —
the audit row is 5 there, not 4.

The gate records nothing, which is how the denominator moves silently

The two version gates in these ten suites handle their skipped arm differently:

unique_conc.sh:546   else  check_skip "the NULLS NOT DISTINCT case" ...   -> a SKIP record
audit.sh:313         else  echo "-- PG16 refuses PARTITION BY ..."        -> nothing

On PG16 the ledger therefore receives 23 rows for audit with nothing saying an
arm was gated out
. The count simply differs, and a reader reconciling it against
a PG18 figure sees three checks that look lost.

audit.sh:313 should call check_skip, exactly as unique_conc.sh already does.
That is the same class #969 fixed for citext — an arm that is not run, not recorded,
and not reported — and it belongs in the remainder pass below rather than in #969.

This also argues against ever seeding these suites into the ledger from one major:
the ledger has no major dimension, so a census taken on PG18 states 26 rows for
audit that a PG16 run contradicts.

What cannot see them

Everything built on the RESULT vocabulary since #917:

  • the ledgerpgc_ledger.py merge reads RESULT lines, so none of these 293 checks can ever become a row. suites_not_covered therefore has a floor of 10 that no amount of seeding can lower.
  • checks_never_observed_red — a census of checks the ledger holds, so these are outside it.
  • the red-observation record — nothing can record that one of these was ever seen red, which is the gap Phase 4 of #858: nothing records whether a check has ever been red #918 and test: a ledger of which checks have ever been red (#918) #925 exist to close.
  • duplicate-check-name detectionpgc_ledger.py warns when one run emits the same check name twice; these suites are exempt by invisibility.
  • checks run: reconciliation — the merge guard refuses a log whose total does not reconcile with its records. A log with neither is not refused, it is simply empty.

What still does see them

Stated because the failure mode matters: their exit status. audit.sh runs set -euo pipefail with an EXIT trap that prints AUDIT TEST ABORTED (exit N) before reaching its verdict, so a failing command aborts the suite and the runner sees a non-zero exit. So these are not unguarded — a failure is caught. What is missing is per-check granularity and any record that survives the run.

That distinction is the reason this is not urgent: a regression in one of these suites still reddens the matrix. It just reddens it without saying which of 43 checks failed, and without any of the ledger machinery being able to say whether that check had ever passed before.

Why it matters for #432 specifically

suites_not_covered cannot go below 10 while these exist in this form, so the coverage burn-down has a floor that is not about effort. And the 293 checks are exactly the population where "a check that cannot fail" would be undetectable, because the mechanism that detects that (#918's ledger, #925's census) cannot see them.

Proposed

Convert them to check / check_num / check_text from lib.sh. That is mechanical per call site but 293 of them, and each conversion has to preserve what the existing line asserts rather than approximate it — several print a value alongside the name (PASS B both first deletes survived (ids 1,2 gone): 3,4,5,6), which maps onto check_text with the value as the comparison rather than onto check with a message.

Worth doing in batches by file, with each file's own verdict line removed only once its checks are individually counted, so the suite never reports less than it did before.

Not proposed

Deleting the suites or excluding them from the registry. They test real behaviour — audit alone holds 31 checks on add-column and transaction interaction — and the problem is their vocabulary, not their content.

Remaining after #969: 58 checks on PG18, 57 on PG16

#969 converted each suite's own check helper and recorded 236 of the 293. The
rest go through additional helpers with their own display formats, so they need
a second pass rather than the same substitution:

suite helper PG18 PG16
phase6 eq_on_off 39 39
phase4 assert_plan, assert_plan_seq, expect_fail 9 9
audit expect_error 5 4
phase5 assert_plan 5 5
58 57

phase6's 39 come from 40 call sites, one of which is shared. Each helper prints a
different line — expect_error emits PASS <name> (rejected), so the conversion
must keep (rejected) in the display or the human log says less than it did.

Also in that pass: audit.sh:313, so the gated-out arm records a SKIP.

Eleven timeout paths remain after #970, and a green run cannot see them

Found by sweeping the ten for verdict-printing lines after the conversion, not by
counting — no count could have found them, because on a green run not one executes.

concurrency.sh   4   timeout waiting for $name/$label, ...sentinel, ...to block, ...idle-in-transaction
unique_conc.sh   4   the same four
update_conc.sh   3   three of the four
                --
                11

Each prints FAIL timeout waiting for ..., sets the suite-local fail, and touches
neither PGC_CHECKS nor the record stream.

Measured by inducing one, rather than argued. send_wait's iteration bound was
lowered from 1200 (60 s) to 1 in a scratch tree, so the first wait reports a timeout
though its sentinel would have arrived. That changes when the path fires, not what it
does — the three lines under test are untouched, and a real 60-second hang runs the same
three. All four bounds in the file were rewritten and the count asserted before the run.

rc                              1
suite verdict                   CONCURRENCY TEST FAILED
FAIL lines printed              1   (FAIL  timeout waiting for s1/a_del)
RESULT records with FAIL        0
RESULT records total            7
checks run:                     7
human verdict lines             8
human - records                 1   <- the timeout, counted nowhere

So, precisely:

  • it is not a false green today. All three suites derive their verdict from the local
    fail (concurrency.sh:394, unique_conc.sh:588, update_conc.sh:478), and the run
    above exits 1 and says CONCURRENCY TEST FAILED;
  • but the reconciliation is self-consistent and still wrong. Records 7 and
    checks run: 7 agree with each other, so nothing refuses the log — on a run that
    printed a FAIL and exited 1. Once these suites emit an accounting: line it will read
    7 passed + 0 failed + 0 unrunnable + 0 skipped = 7, which is a reconciling statement
    asserting zero failures on a failing run. That is worse than invisibility: an
    aggregate that is merely missing data can be noticed, and one that balances cannot;
  • and it becomes an outright false green the day any of the three derives its verdict
    from PGC_FAILED instead, which is the natural next step after this conversion.

Two things have to be decided before converting them, and neither is mechanical.

The name is dynamic. "timeout waiting for $name/$label" interpolates a session name
and a sentinel label, so a direct conversion puts unbounded names into a ledger keyed on
(suite, part, name) — rows nobody can enumerate and therefore nobody can seed. The
likely right shape is a fixed name per helper with the dynamic part in pgc_record's
REASON field, which exists for that, but that is a decision about the key space and
belongs with the seeding design.

It cannot be proven by running the suite. These lines do not execute on a green run,
so every count stays identical whether the conversion is right, wrong, or absent. It needs
an induced timeout — a fixture that makes a wait actually exhaust its 60 seconds — and
that arm is the work, not the substitution.

Provenance

Measured on PG18 at main 9cfa32d8, one run of every registered suite. Eight unrelated suites in that run were refused by the #960 stamp check because I had overwritten the prefix mid-run; those were re-run after restoring it and are green, and are not part of the ten above.

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions