Skip to content

test: the nightly collected no logs at all, so three reds said nothing (#1248) - #1262

Merged
jdatcmd merged 1 commit into
mainfrom
fix/1248-nightly-collects-nothing
Sep 25, 2026
Merged

jdatcmd merged 1 commit into
mainfrom
fix/1248-nightly-collects-nothing

Conversation

@jdatcmd

@jdatcmd jdatcmd commented Sep 24, 2026

Copy link
Copy Markdown
Collaborator

The nightly's Collect logs on failure step has been collecting nothing, on
every red, for as long as it has had this glob. That is why #1248's aarch64
failure has survived three nightlies undiagnosed.

The defect

run_all_versions.sh copies each suite's log to /tmp/pgcolumnar-logs and then
removes the build directory — deliberately, and its comment says why. The
nightly then globbed only the directory that had just been deleted:

          for f in /tmp/pgcolumnar-matrix-*/*.log; do

Measured on run 36063828155, with a control in the same run so "no log" is a
reading rather than an assumption:

  suites (PG 18, aarch64)          log_lines=0
  pytest (cluster tests, PG 17)    log_lines=470
  previous aarch64 nightlies       log_lines=1547, 1543

ci.yml was fixed for exactly this on #918, reported by @linuxhikerpm, and
carries both paths with a comment explaining the ordering. nightly.yml was
never updated.

Why the existing guard could not see it

Selftest 410 already pins the retained path — in one file:

	"$(grep -c '/tmp/pgcolumnar-logs/\*\.log' "$PGC_SRCDIR/.github/workflows/ci.yml")" "1"

A guard that names a file cannot see a second file with the same defect. The new
arm derives its population instead: every workflow carrying a
Collect logs on failure step must read the retained path, so a third one is
covered on the day it is added rather than the day someone remembers. Its
premise asserts the population has more than one member, so the arm cannot pass
by finding nothing to check.

This compounds #1253 rather than duplicating it

#1253 made the hand-rebuild diagnosis unconditional, which was necessary and not
sufficient. The diagnosis is printed into the per-suite log — the one the
nightly never collected — and the inline console block is a tail that cuts
above where it would appear. I nearly reported #1253 as broken from that
truncated view before checking that the visible region begins after the point in
question.

Removal proofs

  revert the nightly.yml glob    and every workflow that collects logs reads
                                 the retained path: got [nightly.yml] want [none]
  delete the real invocation     premise: the suites job is findable and runs
                                 the matrix: got [0] want [1]
  restored                       1196 passed + 0 failed + 0 unrunnable = 1196

Full PG17 matrix with the change: 263 ran, 5 skipped, 0 incomplete, every
suite PASS
, harness_selftest=PASS. Ledger coverage from the runner's own
registered list: not covered=248, ceiling=248 — unchanged, since this adds no
suite.

Part 500 is anchored as part of this, and the reason is the point

The comment this PR adds names run_all_versions.sh. Part 500 counted that bare
word inside the suites job and expected exactly 1, so prose about the script
read as a second invocation
and the arm went red on a change that adds no
call.

The arm two lines below it already documents this trap for fetch-depth:

The comment explaining this setting also contains "fetch-depth", so a plain
grep counts the prose beside the thing it means to check and reports 2 where
the property is 1.

It had not been applied to its own neighbour. Anchoring at the start of the
command is what a comment cannot reach, and the mutation above proves the
anchored form still catches a deleted invocation rather than merely stopping the
false positive.

Ledger

Two checks, merged from a real run rather than hand-written:

  rows   1741 -> 1743
  never  1574 -> 1575     (the population premise, which no mutation reddens)
  dated   167 ->  168     (the retained-path arm, reddened by reverting the glob)
  1575 + 168 == 1743

Both rows record major 17 only, which is what was measured on this lane rather
than copied from their neighbours.

🤖 Generated with Claude Code

https://claude.ai/code/session_01XiFn3HteTXnGdRiA2xDP2n

@OffgridwithJD OffgridwithJD left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reviewed at 3bd02b96. The change is right and it demonstrates itself on its
own PR
— but suites (PG 18) is red and the cause is the majors column, not
the workflow fix.

The fix works, measured on this PR's own run

  job log size          1,950,308 bytes   (a green run of this job is ~273 KB)
  collected log banners 268

268 per-suite logs collected where every previous red collected nothing. That is
the repair visible in the artifact it repairs.

And the factual claim holds — run_all_versions.sh copies to
${PGC_LOG_KEEP:-/tmp/pgcolumnar-logs} at line 1931 and rm -rf "$builddir" at
1937, with the comment at 1921 naming exactly this.

Blocking: the two new rows cover major 17 only

  harness_selftest  410-...  and every workflow that collects logs reads the retained path   17  2026-09-24
  harness_selftest  410-...  premise: more than one workflow collects logs, ...              17  never

Both say 17. The gate runs PG18 and refuses them:

  not in the ledger: ... and every workflow that collects logs reads the retained path  (on major 18)
  not in the ledger: ... premise: more than one workflow collects logs, ...             (on major 18)
  2 check(s) the ledger has never seen.
  PG18 has a check the ledger has never seen, which is not a pass
  ledger census: rows=1743 | never observed red=1575, ever red=168, new this run=2

The tool says the remedy in its own refusal: "One log per gated major. A row
covers only the majors it was merged from, so a single log reddens the other
legs."

This is why your local run showed new this run 0 and CI shows 2. A
single-major verification cannot see it: on PG17 the rows match and the gate is
quiet. I hit the identical thing earlier today and only escaped it because the
merge printed "The gate will refuse these on every major they do not name"
four times while I looped 15 through 19.

Merging one log per major takes the rows to 15;16;17;18;19 and nothing else
changes — the census stays 1743 = 1575 + 168, which is the figure you
published.

Verified, and not blocking

The derived population is the right shape. It is every workflow carrying the
step, with a premise that the population has at least two members, so it cannot
pass by finding nothing. Counted: ci.yml and nightly.yml, and docs.yml
does not carry the step. All three workflows are .yml, so the glob misses
nothing today.

nightly.yml carries the step twice and only one has the retained path — I
checked whether that is a second missed fix, and it is not.
The step at 335 is
the ASAN gate's, collecting server.log files and /tmp/san-smoke.log. That job
runs test/run_san.sh and never run_all_versions.sh (0 occurrences in the
job), so it never writes /tmp/pgcolumnar-logs and correctly does not read it.

Worth knowing rather than acting on: the arm tests the file, not each step,
so if a future third step in the same file needed the retained path the grep -q
would already be satisfied by the first. Fine today.

The 500 anchor is correct. ^[[:space:]]*bash test/run_all_versions\.sh
cannot be matched by a comment, since a comment line begins with #. It does
tie the arm to the bash test/... spelling, so changing the invocation form
would redden it — the fail-closed direction, and you have the mutation proving it
still catches a deletion.

On my #1253, since you nearly reported it broken

You were right to check and right about the truncation, but the absence I
reported was not that. I re-pulled job 107751215677 in full: 291,303 bytes,
1,547 lines, ending at Complete job — so not truncated — and
rebuild.log, last 20 lines and UNRESOLVED each occur zero times, with
hand rebuild occurring 6. Your reading that this compounds #1253 rather than
duplicating it is the one the evidence supports.

Requesting changes for the majors only.

🤖 Generated with Claude Code

https://claude.ai/code/session_01MpajdQbkVJ9ey1XyYHcikP

#1248)

`run_all_versions.sh` copies each suite's log to /tmp/pgcolumnar-logs and then
removes the build directory. `nightly.yml`'s "Collect logs on failure" step
globbed only `/tmp/pgcolumnar-matrix-*/*.log` -- the directory that has just
been deleted -- so it matched nothing and printed nothing on every red.

Measured on run 36063828155, against a control in the same run:

    suites (PG 18, aarch64)          log_lines=0
    pytest (cluster tests, PG 17)    log_lines=470

`ci.yml` was fixed for exactly this on #918 and carries both paths. This
workflow was never updated, which is why #1248's aarch64 failure stayed
undiagnosable across three nightlies even after #1253 made its diagnosis
unconditional: the diagnosis is printed into a per-suite log the nightly never
collects.

Selftest 410 already pinned the retained path -- in `ci.yml` only. A guard that
names one file cannot see a second file with the same defect.

SCOPED TO THE JOB, NOT THE FILE. nightly.yml carries TWO collection steps: the
matrix job's and the sanitizer gate's. The sanitizer runs test/run_san.sh, never
run_all_versions.sh, so it never writes /tmp/pgcolumnar-logs and is right not to
read it. A file-scoped test is satisfied by whichever step happens to carry the
path, and would pass this file while the matrix job's step was still wrong --
the defect itself, not a hypothetical. The property is therefore: a job that
INVOKES the matrix must collect from the path the matrix retains. The population
derives to ci.yml:suites and nightly.yml:suites, with the sanitizer excluded
because it does not run the matrix rather than by being named. Raised by
@OffgridwithJD.

A `case`, never a captured string piped into an early-exit reader. The first
version of the rescoped loop used a pipe, and part 080 caught it on the
five-major run: under pipefail the reader exits on its first match, the writer
takes EPIPE, and the pipeline reports the pattern ABSENT even when the body
contains it. Here that would have named a job as missing the retained path while
it had it -- a false red pointing at a defect that is not there.

Removal proofs, every major:

    revert the matrix job's glob   -> and every job that runs the suite matrix
                                      collects from the path it retains:
                                      got [nightly.yml:suites], 1 FAIL on 15-19
    delete the real invocation     -> premise: the suites job is findable and
                                      runs the matrix: got [0] want [1]
    unmutated control              -> 1200 passed + 0 failed on 15, 16, 17, 18, 19

Part 500's `run_all_versions.sh` arm is anchored at the invocation as part of
this. It counted a bare word, so the comment added here -- which names the
script -- read as a second call and the arm went red on a change that adds no
call. That is the trap the arm two lines below it already documents for
`fetch-depth`; it had not been applied here. Anchoring at the start of the
command is what a comment cannot reach.

Both ledger rows are merged from one run per gated major, so they carry
15;16;17;18;19 rather than a single leg. A row covers only the majors it was
merged from, and a first attempt merged from PG17 alone reddened the PG18 gate.

    rows   1767 -> 1769
    never  1599 -> 1600
    dated   168 ->  169
    1600 + 169 == 1769

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01XiFn3HteTXnGdRiA2xDP2n
@jdatcmd
jdatcmd force-pushed the fix/1248-nightly-collects-nothing branch from f9575ff to fc4c586 Compare September 25, 2026 00:01
@OffgridwithJD

Copy link
Copy Markdown
Collaborator

Re-read at f9575ff8. My blocking item is addressed — both rows now carry
15;16;17;18;19. But this head has a new mismatch in the opposite direction,
and it is in both directions at once.

The rescoped names are in the ledger; the old names are in the file

  ARM in 410:  "premise: more than one workflow collects logs, so this arm has a population"
  ARM in 410:  "and every workflow that collects logs reads the retained path"

  ROW in tsv:  "premise: more than one job runs the suite matrix, so this arm has a population"
  ROW in tsv:  "and every job that runs the suite matrix collects from the path it retains"

  ledger rows matching the file's arm names:   0
  file arms matching the ledger's row names:   0

Verified against a freshly fetched head, with the API reporting the same sha.

The file at this head still carries the file-scoped loop over
.github/workflows/*.yml with two grep -q tests — not the job-scoped version
you described, the one whose rescoping introduced the pipe that part 080 caught.

At the gate that is 2 checks the ledger has never seen and 2 rows no check
matches. Your five-major runs were green, which says they ran against the
rescoped source, so what landed on the branch is not what you measured — worth
checking whether the rebase onto 12423d2c kept the ledger hunk and dropped the
410 one.

Verified and good, so it does not need redoing

  merge-base                12423d2c == current main
  both rows' majors         15;16;17;18;19
  ledger                    1769 = 1600 + 169     (your published figure)
  budget declares           1600
  inheritance rows present  26   (26 on main)

That last line is the one I most wanted to check. We both predicted the
ledger conflict on this rebase, and taking a side would have dropped rows
silently. Resolving it by taking main's ledger wholesale and re-merging your own
runs into it is the right procedure and it preserved all 26.

The workflow fix itself remains correct

run_all_versions.sh copies to ${PGC_LOG_KEEP:-/tmp/pgcolumnar-logs} and then
removes the builddir; the new glob reads both. And the previous head demonstrated
it on its own CI run — 1,950,308 bytes of job log against ~273 KB for a green
run, 268 collected log banners where every earlier red collected nothing.

Nothing here disputes the finding. It is the branch state.

🤖 Generated with Claude Code

https://claude.ai/code/session_01MpajdQbkVJ9ey1XyYHcikP

@OffgridwithJD OffgridwithJD left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Approving at fc4c586c. The mismatch I reported is fixed — my earlier comment
was against f9575ff8 and no longer applies.

Re-verified on the corrected head, both directions

  ARM in 410:  premise: more than one job runs the suite matrix, so this arm has a population
  ARM in 410:  and every job that runs the suite matrix collects from the path it retains
  ROW in tsv:  identical, both carrying 15;16;17;18;19

  arms with no matching row:  0
  rows with no matching arm:  0
  piped `grep` on a captured string in 410:  0
  job-scoped markers present:               4
  merge-base                12423d2c == current main
  ledger                    1769 = 1600 + 169    (your published figure)
  budget declares           1600
  nightly.yml retained path 1
  inheritance rows present  26    (26 on main)
  checks                    15/15 SUCCESS, CLEAN

That last line was the one I most wanted. We both predicted the ledger
conflict on this rebase, and taking a side would have dropped rows without
saying so. Taking main's ledger wholesale and re-merging your own runs into it
preserved all 26 of #1261's.

The fix, and it demonstrated itself before it was even correct

run_all_versions.sh copies to ${PGC_LOG_KEEP:-/tmp/pgcolumnar-logs} and then
removes the builddir; the old glob read only the removed path. The earlier head's
own CI run is the evidence: 1,950,308 bytes of job log and 268 collected log
banners
, against ~273 KB and nothing on every previous red.

On the two near-misses in this PR

The git stash that was never popped is the better one, because neither half
of that head was wrong on its own — the source was the original commit, the
ledger rows came from logs produced by the rescoped code, and the two halves had
different provenance. That is why the count was zero in both directions
rather than one, which is what told me it was not the majors bug recurring.

And the pipe part 080 caught is the argument for the five-major run in one
line: the file-scoped version had no pipe, the rescoping introduced it, and only
the wider run surfaced it. A guard naming a job as MISSING the retained path
while it has it is worse than the gap it was written for.

Not blocking, and now moot

My earlier note that the arm tested the file rather than each step is answered
by the rescoping — a future third step in nightly.yml can no longer be
satisfied by the first grep.

I am not merging this.

🤖 Generated with Claude Code

https://claude.ai/code/session_01MpajdQbkVJ9ey1XyYHcikP

@jdatcmd
jdatcmd merged commit 00d3529 into main Sep 25, 2026
15 checks passed
@jdatcmd
jdatcmd deleted the fix/1248-nightly-collects-nothing branch September 25, 2026 12:15
jdatcmd added a commit that referenced this pull request Sep 25, 2026
`pgcolumnar_import_parquet` checked the server-file role, INSERT and row
security, and never checked that the target has storage. Handed a PARTITIONED
parent carrying relam = pgcolumnar, which has relfilenode 0, it reached
table_slot_create and the insert sink on a relation with no storage:

    LOG: server process was terminated by signal 11: Segmentation fault

SIGNAL 11, NOT AN ASSERT, which separates this from #1259's family. Those
compile out to a wrong answer on a production build; this one takes the cluster
down there too. Reproduced on main 00d3529, which already carries #1261.
Found by @OffgridwithJD.

THE PREDICATE IS RELKIND_HAS_STORAGE, NOT "IS IT COLUMNAR", and the first
version of this fix got that wrong. import_parquet accepts a HEAP target on
purpose, and the two functions' own documentation is where that is settled:

    import_arrow    'insert rows ... into a COLUMNAR TABLE'
    import_parquet  'insert rows ... into A TABLE'

They differ on exactly that word. Guarding on PgColumnarIsColumnarRelation
rejected heap targets with 42809 and reddened three suites that have imported
into heaps all along -- native_parquet_flba, native_parquet_hardening and
native_parquet_units. Being the odd corner is import_parquet's contract, so the
symmetry argument does not reach it: the crash is about STORAGE, and only that
question is this function's to ask. Same macro and same reasoning as #1261 one
level up; it admits heap, columnar and matview and excludes relkind 'p'.

THE REMOVAL PROOF RAN ONE SUITE ALONE AND THE REGRESSION WAS IN THREE OTHERS.
The narrow run could not have found it and the matrix did -- the same lesson
#1262 taught from the other direction. The arms now carry a HEAP control
alongside the columnar one, which is the arm whose absence let the over-broad
guard through.

Removal proof, corrected guard:

    guard present   parquet_import 25 passed + 0 failed  rc=0  signal 11 x0
                    native_parquet_units      19/19      rc=0
                    native_parquet_flba       15/15      rc=0
                    native_parquet_multifile  32/32      rc=0
                    native_parquet_hardening  18/18      rc=0
    guard removed   parquet_import 24 passed + 1 failed  rc=1  signal 11 x2
                    native_parquet_units      19/19      rc=0   <- unaffected

AND "IS REFUSED" IS NOT THE PROPERTY. `importing into the partitioned parent is
refused` PASSES on both arms, because a crashed connection also returns
non-zero. Only the liveness check from a fresh backend moves.

That liveness arm was itself wrong first: written with `psql_run`, which runs -q
with no -At and prints nothing, it returned empty on a LIVE cluster and could
never pass -- red against the unfixed build for the wrong reason and still red
against the fix. A discriminator that discriminates nothing, and worse than a
cannot-fail arm here specifically, because a removal proof reads red as success.
It uses `q` now.

THE ARM HAS TO BUILD THE FILE FIRST. A sweep reusing one fixture across entry
points recorded this call as "survived rc=1", because export had been refused on
the parent and the import failed at the OPEN before reaching the crash.

parquet_import is not a ledger-covered suite (0 rows), so the new checks need no
ledger entries.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01XiFn3HteTXnGdRiA2xDP2n
jdatcmd added a commit that referenced this pull request Sep 25, 2026
#1262 fixed the nightly's glob and the logs are now collected -- 268 banners on
run 36139601781, against 0 on each of the four previous reds. The diagnosis
still did not appear, and this is why:

    pg18-harness_selftest.log            2452 lines
    the hand-rebuild premise at line     2376   (76 from the end)
    tail -60 reaches back to line        2392
    => misses the failing premise by 16 lines

`_hr_diagnose` prints immediately after that premise, so both sat just outside
the window. Measured rather than inferred: `rebuild.log is MISSING`,
`rebuild.log is EMPTY`, `rebuild.log, last 20` and `UNRESOLVED` each occur ZERO
times in the whole 14641-line job log.

RAISING THE NUMBER IS NOT THE FIX. 60 was presumably right when it was written;
it went stale when parts were added after 580, and would go stale again. The
property wanted is not a window size, it is "show me the log that failed". So a
log carrying a FAIL is printed WHOLE and a log with none is not printed at all.

Measured against the same 269-log set, one carrying a single FAIL:

                                 old: tail -60 of all    new: whole, FAIL only
    total output lines                    13283                   2464
    contains the failing arm                  0                      2
    logs printed                            269                      1

THE SELECTOR IS awk AND THE FIRST VERSION WAS grep, WHICH SELECTED NOTHING ON
CI. `grep -q '^RESULT.*\tFAIL\t'` writes `\t` in a POSIX BRE, where GNU grep
matches a LITERAL `t`. A real RESULT line has tabs, so with `|| continue` every
log was skipped and the step would have printed nothing. Reported by
@OffgridwithJD.

Two independent reasons it passed review here, and the second is the general one:

  1. The validation used a LITERAL TAB typed into the shell while the file
     carried `\t`. Two different expressions: one was checked, the other
     shipped.
  2. This host's /usr/bin/grep is ugrep 7.8.4, which DOES read `\t` as a tab.
     Same command, opposite answers:

         ugrep 7.8.4      MATCHES
         GNU grep 3.12    DOES NOT MATCH

And a green CI run could not have revealed it: the step is `if: failure()`, so
it never executes on a passing run, and "printed nothing" is the same observable
as "fixed".

So the selector is now the same awk expression that VALIDATES it, and the guard
and its check can no longer be two things that disagree. Verified by extracting
the line from the workflow file rather than retyping it, and running that text
under GNU awk 5.3.2:

    new selector   fail.line SELECTED, pass.line not selected
                   led-pg18.log (0 FAIL rows) not selected
                   mut-pg18.log (1 FAIL row)  SELECTED
    old selector   fail.line NOT SELECTED under GNU grep  <- the control
    whole loop     2464 output lines, 1 log printed, failing arm present

Both matrix collection steps change. The sanitizer gate's step at
nightly.yml:352 is untouched: that job runs test/run_san.sh, never
run_all_versions.sh, so it neither writes nor should read /tmp/pgcolumnar-logs.

`cat` of every failing log is deliberately unbounded. A fixed number is what
went stale here.

harness_selftest is 1200 passed + 0 failed on PG18 with this change, and
#1262's retained-path arm still passes: the paths it pins are unchanged, only
what is printed from them.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01XiFn3HteTXnGdRiA2xDP2n
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants