Skip to content

fix(ci): Make the two halves comparable, and make a running shard readable - #2836

Merged
krlmlr merged 7 commits into
claude/preflight-shared-deps-8mj8p1from
claude/shard-always-both-8mj8p1
Aug 15, 2026
Merged

fix(ci): Make the two halves comparable, and make a running shard readable#2836
krlmlr merged 7 commits into
claude/preflight-shared-deps-8mj8p1from
claude/shard-always-both-8mj8p1

Conversation

@krlmlr

@krlmlr krlmlr commented Aug 15, 2026

Copy link
Copy Markdown
Contributor

Prepared with Claude Code. Stacked on #2834, as requested, so the run in flight there is not disturbed.

Why packages were "newly broken" with identical counts — confirmed

Shard 9 of run 31879790285 finished while I was working on this, so this is now data rather than a hypothesis. My first explanation in this PR — that the error text quoted a path — was wrong, and I have corrected it. compare_checks() hashes only the first line of each issue, with timings stripped, so a path further down could never have mattered.

The manifest is unambiguous:

package result old new baseline reused
rphylopic newly_broken 1E 0W 0N 1E 0W 0N yes
HospitalNetwork newly_broken 1E 0W 0N 1E 0W 0N yes
orthGS newly_broken 1E 0W 0N 1E 0W 0N yes
(8 others) ok no

Every false positive had a reused baseline standing in for the old half. Every package that ran a fresh old check was ok.

The cause is that the two halves were parsed by two different parsers. A baseline from an earlier run was produced by rcmdcheck::rcmdcheck(), which parses the stream as R CMD check writes it. This run's half is parse_check() on the finished 00check.log, where R has gone back and appended the status to the line it opened. The same failing test renders two ways:

old.rds (baseline, streamed)     new.rds (parse_check of the log)
checking tests ...               checking tests ... ERROR
  Running 'testthat.R'             Running 'testthat.R'
 ERROR                           Running the tests in ... failed.

Hash 81f6423… against 23e57fe…, so the new one matches nothing in the old, so change == 1, so newly_broken. And the clincher: their 00check.diff is eight lines, all of it the log directory. The logs agree; only the objects disagree.

Always running both halves is the fix, and it is the change this PR opened with. With the pair concurrent the old check costs no wall clock, so substituting a baseline bought nothing and cost comparability. The baseline is still read as a second opinion — when it disagrees with the old check just run, the shard says so and records baseline_agrees in the manifest.

Reading a shard while it runs

protti: ok (old 0E 0W 0N, new 0E 0W 0N, 1072s for the pair, 1/51, ~5.0 h left)

The count says where the shard is; the estimate answers the question actually being asked. The plan already priced every package — what it could not know is how this runner compares to its model, so the remaining packages are priced in the plan's own units and rescaled by how its estimates have held up in this shard so far. That absorbs both a slow runner and a systematically optimistic model without either having to be known in advance. On a 51-package shard planned at 10 min each that really takes 6, the opening 8.5 h becomes 5.0 h after the first pair and stays there. format_duration() grows an hours tier, because "217 min left" is a number you have to divide before it means anything.

The diff is printed into the job log

For every package that is not ok, the unified diff of the two logs goes into the job log under a foldable ::group:: heading, bounded by REVDEP2_DIFF_MAX_LINES (200); the whole diff stays in the artifact as 00check.diff.

And yes, the timings would have wrecked it. Measured on a pair run against the same igraph on both sides, whose logs differed in exactly two lines:

-* using log directory '.../work/old/rphylopic.Rcheck'
+* using log directory '.../work/new/rphylopic.Rcheck'
-* checking R code for possible problems ... [14s/12s] OK
+* checking R code for possible problems ... [13s/11s] OK

--as-cran sets _R_CHECK_TIMINGS_, so every stage over ten seconds prints its own [user/elapsed] pair, and two checks racing for the same four cores never agree on those. On a large package that is a dozen lines of noise, and it is exactly the lines you would be reading. neutral_log() now removes the timings along with the paths, and the same neutralised text is what gets parsed and what gets diffed — those two logs then diff in zero lines. Verified both ways:

::group::rphylopic: old vs new check log (0 line diff)
The two logs are identical apart from paths and stage timings.
::endgroup::

::group::rphylopic: old vs new check log (11 line diff)
--- old
+++ new
@@ -74,7 +74,7 @@
 * checking for unstated dependencies in 'tests' ... OK
-* checking tests ... OK
+* checking tests ... [] ERROR
   Running 'test-all.R'
::endgroup::

Why a package broke, without downloading anything

Three blocks in the job summary now, each with its own budget rather than sharing one: the check log, 00install.out, and the .Rout.fail transcript. The check log only ever pointed at 00install.out, which meant fetching the artifact to read a compiler error. REVDEP2_DETAIL_MAX_LINES (300) bounds the two transcripts.

_R_CHECK_TESTS_NLINES_=0 also widens the check log's own copy of a failed test from R's default 13 lines to the complete output — confirmed locally, Last 13 lines of output: becomes Complete output:. Thirteen routinely cuts off the failure itself, which is both what a reader wants and the part the old/new diff has to see to be worth printing.

Spelling, and NOT_CRAN

R's own spelling stage lives inside check_CRAN_incoming(), which _R_CHECK_CRAN_INCOMING_: false already suppressed; _R_CHECK_CRAN_INCOMING_USE_ASPELL_: false now says so out loud so --as-cran cannot turn it back on. Spelling cannot say anything about igraph anyway — a misspelling in a revdep is the same misspelling in both halves, so it cancels out of every comparison this workflow makes.

A package's own tests/spelling.R is a different thing, and it runs only because r-lib/actions/setup-r sets NOT_CRAN=true. That is now a workflow input, defaulting to false: the shards behave like CRAN's own check machines, because this workflow exists to find what a released igraph would break, and a test CRAN never runs cannot break on CRAN. It does also skip every other skip_on_cran() test, which is a real reduction in what is exercised — hence an input rather than a constant. Dispatch with not-cran: true to widen the net again. It is written in a step rather than the job's env because setup-r writes its own value into $GITHUB_ENV, and a later write is what reliably overrides an earlier one.

\donttest examples are no longer run

--as-cran turns on --run-donttest. That is the most expensive thing a check does and the least useful thing here: \donttest{} is where packages put the examples too slow to run on CRAN, so it is where the runners spend their hours and where the timeouts land — varPro's old half was killed at 1200 s in checking examples with --run-donttest. _R_CHECK_DONTTEST_EXAMPLES_=false turns it back off. \dontrun{} was already off and stays off.

This also answers "is the timeout too conservative" from the other end: CRAN checks varPro in 104 s, so 1200 s was 11× the expected cost, never a marginal budget. The gap was work CRAN does not do, not a floor set too low.

Install packages is its own step

The refactor I deferred last time. The install is minutes to an hour and the checks are hours, and as one step Actions could only report their sum — so "shard 14 took five hours" said nothing about which half it spent them in, and the install times vary a lot between shards.

One driver, called twice with PHASE=install and PHASE=check. The install leaves the libraries and an install-state.json of what it cost behind; the check phase picks both up and repeats nothing. PHASE=all still runs the whole shard in one process, which is what a local invocation wants. The runner directories move to a $GITHUB_ENV step, because the runner context does not reach a job's env — setting them at job level would have silently emptied them.

Verified end to end locally against a real one-package plan: both phases run, install-state.json round-trips, and the install timings reach timing.json through the split. That run also turned up t_new being null for every package that compared — it was recorded only on the path where the comparison failed — which is fixed here too.

Per-line elapsed stamps

R CMD check reports a stage's own time only when it crosses a threshold, and never for the stage it was killed in — the one you actually want. Every line of driver.log now carries its elapsed seconds:

   11s  * checking foreign function calls ... OK
    8s  * checking for sufficient/correct file permissions ... OK
    4s  * checking tests ...

EPOCHSECONDS is a bash builtin, so this spawns nothing per line. PIPESTATUS[0] still carries timeout's exit 124 through the added pipe. Confirmed working in the real shard.

  • By submitting this pull request, I assign the copyright of my contribution to The igraph development team.

Generated by Claude Code

claude added 2 commits August 15, 2026 12:10
Three things, all from watching run 31879790285.

**Paths made shared failures look new.** `compare_checks()` matches issues
by their text, so text that differs for reasons that are not the package
turns a shared issue into a new one. The cascading libraries differ by
construction -- `.../lib-old/...` against `.../lib-new/...` -- and so do
the two check directories, so any error quoting a path differed between
the halves. That is why `dm`, `fsbrain` and `rphylopic` all reported "old
1E 0W 0N, new 1E 0W 0N" and were still called newly_broken: same count,
same error, different path. Both library paths and the phase directory are
now replaced by a constant before the log is parsed. Nothing else is
touched -- a difference anywhere but in those paths is what this workflow
exists to find.

**Both halves always run.** A reusable baseline used to stand in for the
old check and skip it. With the pair running concurrently the old check
costs no wall clock, and a baseline is a result from another run -- another
machine, another CRAN snapshot, another dependency tree, and another set of
paths, which is how `rphylopic` managed to be newly_broken off a reused
baseline. The baseline is still read, but as a second opinion: when it
disagrees with the old check just run, the shard says so and records
`baseline_agrees`, which makes drift over time visible instead of
authoritative.

**Every line of check output is stamped with its elapsed seconds.** R CMD
check reports a stage's own time only when it exceeds a threshold, and
never for the stage it was killed in -- which is the one worth knowing
about. `varPro: old check timed out (1200s) at * checking examples with
--run-donttest` says where it stopped but not what it spent getting there;
now the log says both. `EPOCHSECONDS` is a bash builtin, so this spawns
nothing per line.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01D1xpHRV7yVfgtJg4vp9P7z
Three things a reader of a run asked for and could not get.

Install and check are separate steps.
The install is minutes to an hour and the checks are hours,
and as one step the run page could only report their sum,
so "shard 14 took five hours" said nothing about which half it spent
them in -- and the install times vary a lot between shards.
One driver, called twice with `PHASE=install` and `PHASE=check`;
the install leaves the libraries and an `install-state.json`
of what it cost behind, and the check phase picks both up.
`PHASE=all` still runs the whole shard in one process.
The paths move from the step to a `$GITHUB_ENV` step,
because `runner.temp` does not reach a job's `env`.

The diff between the two halves goes into the job log,
under a foldable heading, bounded by `REVDEP2_DIFF_MAX_LINES`.
Downloading an artifact to find out that a NOTE gained a line
is a poor trade for the one thing a reader wants.

For that to be worth printing, two identical results have to produce
an empty diff, and two concurrent checks do not naturally do that:
`--as-cran` sets `_R_CHECK_TIMINGS_`, so every stage slower than ten
seconds prints its own `[user/elapsed]` pair, and two checks racing
each other for the same four cores never agree on those.
Measured rather than assumed -- rphylopic checked against the *same*
igraph on both sides differed in exactly two lines, the log directory
and `[14s/12s]` against `[13s/11s]`, and in none once neutralised.
So `neutral_log()` now takes the timings out as well as the paths,
and the same neutralised text is what gets parsed and what gets
diffed. An empty diff says so in as many words: a package called
`newly_broken` whose two logs are identical is this harness getting
it wrong, and the run page will now say that rather than imply it.

`\donttest{}` examples are no longer run.
`--as-cran` turns on `--run-donttest`, which is the most expensive
thing a check does and the least useful thing here: it is where
packages put the examples too slow for CRAN, so it is where the
runners spend their hours and where the timeouts land -- varPro's old
half was killed at 1200s in "checking examples with --run-donttest".
`\dontrun{}` was already off and stays off.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01D1xpHRV7yVfgtJg4vp9P7z
@krlmlr krlmlr changed the title fix(ci): Always check both halves, and stop paths faking a new failure fix(ci): Make the two halves comparable, split install from check, print the diff Aug 15, 2026
claude added 4 commits August 15, 2026 12:38
`t_new` was set only where the comparison failed, so it was null for
every package that compared -- that is, for all of them. The pair's
wall clock is charged to both halves, because they ran side by side
and neither one's own time is separable from the other's.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01D1xpHRV7yVfgtJg4vp9P7z
Shard 9 of run 31879790285 finished and settled it with data rather
than with my guess about paths.

All three `newly_broken` packages there had a reused baseline standing
in for the old half; all eight that ran a fresh old check were `ok`.
The two halves had been parsed by two different parsers -- a baseline
by `rcmdcheck()` from the stream, this run's half by `parse_check()`
from the finished log, where R has appended the status to the line it
opened -- so the same failing test rendered as `checking tests ...` on
one side and `checking tests ... ERROR` on the other. `compare_checks()`
hashes the first line, so those are two different issues. Their
`00check.diff` is eight lines, all of it the log directory: the logs
agree and only the objects disagree.

Always running both halves is the fix, and it is already in. The path
and timing normalisation is hygiene for the diff, not a fix for this --
`compare_checks()` never looked past the first line to begin with.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01D1xpHRV7yVfgtJg4vp9P7z
Three things a reader of a running shard could not get from its log.

Position in the shard, on every line that reports a package:

  protti: ok (old 0E 0W 0N, new 0E 0W 0N, 1072s for the pair, 1/51)

A shard runs for hours and its log is read while it runs, so "is this
nearly done?" should not need counting lines.

The two transcripts that say *why* something broke, each as its own
block in the job summary with its own budget rather than sharing the
check log's. `00install.out` is where a package that could not be
installed explains itself -- the check log only points at the file,
which meant downloading the artifact to read a compiler error. A
`.Rout.fail` is the whole test run. `REVDEP2_DETAIL_MAX_LINES` (300)
bounds both.

`_R_CHECK_TESTS_NLINES_=0` widens the check log's own copy of a failed
test from R's default 13 lines to the complete output. Thirteen
routinely cuts off the failure itself, which is both what a reader
wants and the part the old/new diff has to see to be worth printing.

No spell checking. It cannot say anything about igraph -- a
misspelling in a revdep is the same misspelling in both halves, so it
cancels out of every comparison this workflow makes. R's spelling
stage lives inside `check_CRAN_incoming()`, which
`_R_CHECK_CRAN_INCOMING_: false` already suppressed;
`_R_CHECK_CRAN_INCOMING_USE_ASPELL_: false` says so out loud so that
`--as-cran` cannot turn it back on.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01D1xpHRV7yVfgtJg4vp9P7z
  protti: ok (old 0E 0W 0N, new 0E 0W 0N, 1072s for the pair, 1/51, ~5.0 h left)

The count says where the shard is; the estimate answers the question
actually being asked, which is when. The plan already priced every
package -- what it could not know is how this runner compares to its
model, so the remaining packages are priced in the plan's own units and
rescaled by how its estimates have held up in this shard so far. That
absorbs both a slow runner and a systematically optimistic model
without either having to be known in advance. On a 51-package shard
planned at 10 min each that really takes 6, the opening 8.5 h becomes
5.0 h after the first pair and stays there.

`format_duration()` grows an hours tier, because "217 min left" is a
number the reader has to divide before it means anything.

`NOT_CRAN` becomes a workflow input, defaulting to false. It is what
makes `skip_on_cran()` skip, and `r-lib/actions/setup-r` sets it to
true -- which is why packages' own `tests/spelling.R` runs here at all.
CRAN-like is the right default: this workflow exists to find what a
released igraph would break, and a test CRAN never runs cannot break on
CRAN. It also skips every other `skip_on_cran()` test, which is a real
reduction in what is exercised, so it is an input rather than a
constant -- dispatch with `not-cran: true` to widen the net again.

It is written in a step rather than the job's `env` because `setup-r`
writes its own value into `$GITHUB_ENV`, and a later write is what
reliably overrides an earlier one.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01D1xpHRV7yVfgtJg4vp9P7z
@krlmlr krlmlr changed the title fix(ci): Make the two halves comparable, split install from check, print the diff fix(ci): Make the two halves comparable, and make a running shard readable Aug 15, 2026
Run 31879790285 finished: 1011 packages, 909 ok, 78 newly broken, 19
timed out, 3 failed, 1 error, 1 depfail, nothing deferred, 3h22m.

Two things it settles.

Baseline reuse was the defect, at scale. Of the 909 packages whose old
half came from a reused baseline, 76 were called `newly_broken` --
8.4%. Of the 78 that ran a fresh old check, 2 were -- 2.6%, and both
are real (`cranly` on `eigen_centrality(scale = FALSE)` now being a
`deprecate_stop()`, and `vkR`). 29 of the 76 have identical counts in
both halves, which is the parser artefact exactly; the other 47 differ,
which is a baseline being a result from another machine and another
CRAN snapshot. Both halves already always run; what was left is that
the *plan* still priced a reusable package at one check instead of two.
That condition is now wrong, and wrong in the direction that under-fills
whichever shards hold the most of them -- which after this change is
almost all of them: 909 of 1011 here. Every package weighs double now.
The factor is nominal either way, since `check_scale` is fitted from
measurements, but every package has to be priced the same way.

And `-Ex.Rout` is kept. R writes the complete transcript of a failed
test file to `<file>.Rout.fail` and of the examples to `<pkg>-Ex.Rout`;
only the first matched the `.fail` pattern, so an examples failure --
13 of this run's 19 timeouts, and both of its genuine regressions --
left nothing to read but the check log's own excerpt. Both are copied
now and both get a summary block.

That is what makes bounding the check log free, so
`_R_CHECK_TESTS_NLINES_` goes to 300 rather than unlimited: the excerpt
is carried three times over (check log, diff, summary) and one chatty
test would bury the shard in all three, while the complete transcript
sits beside it either way -- measured at 521 lines with the setting at
13, at 300 and at 0 alike.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01D1xpHRV7yVfgtJg4vp9P7z
@krlmlr
krlmlr merged commit 350ab0a into claude/preflight-shared-deps-8mj8p1 Aug 15, 2026
1 check passed
@krlmlr
krlmlr deleted the claude/shard-always-both-8mj8p1 branch August 15, 2026 14:56
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