Skip to content

🐛 Fix worker results dropped by a teardown race, and Windows spec discovery paths - #56

Merged
pboling merged 2 commits into
mainfrom
bug/worker-output-drain-race
Oct 6, 2026
Merged

pboling merged 2 commits into
mainfrom
bug/worker-output-drain-race

Conversation

@pboling

@pboling pboling commented Oct 5, 2026 •

Copy link
Copy Markdown
Member

Two independent CI bugs, one per commit. Both are race/spelling issues that only manifest under specific environments, so each section records what was measured rather than what was assumed.

  • 386bf40 — teardown race dropping a worker's results (intermittent, CI contention)
  • 22eddd2 — spec discovery returning absolute paths on Windows (deterministic, windows-latest)

Bug 1: worker results dropped by a teardown race

Problem

ruby-3.0.yml failed intermittently in spec/integration/multi_process_spec.rb. The nested turbo_tests2 run reported 1 example, 0 failures instead of 4 examples, 0 failures, 3 pending, one worker's block was truncated to just Run options:, and which worker vanished flipped between runs — one run failed at :46 ("passes"), the next at :52-54 (the pending worker). A whole worker's JSON rows were dropped.

Not a bad assertion and not order/seed dependent: the failing run was a style-only release-prep commit, and 17 local Ruby 3.0.7 parallel runs across 5 seeds all passed. It is a teardown timing race that only bites under CI contention.

@messages is a FIFO queue. Each stdout reader thread queues that worker's rows as it reads the pipe, then pushes its own {type: "exit"} at EOF. Separately, the exit-watcher thread did:

status = wait_thr.value
@messages << {type: "exit", process_id: process_id}   # <- signaled FIRST
ensure
  stop_reader_thread(stdout_thread, stdout)            # <- drained AFTER

So the watcher could push exit while the reader was still draining. handle_messages breaks once it has seen process_count exits, so that worker's rows — queued behind the exit signal — were never read. stop_reader_thread then allowed only 0.1s before close_io discarded the still-kernel-buffered pipe contents and thread.killed the reader.

An earlier read of the CI log suggested leaked state from RSPEC_FORMATTER_OUTPUT_ID=fixed-test-output-id, but that is a red herring: it is warn output from runner_spec's own "logs the command when @verbose is true" test, captured on CI stderr. The integration subprocess runs a fresh Ruby process where rspec-mocks stubs do not apply, so SecureRandom.uuid is real there.

Fix

  • Drain before signaling. Both readers are joined to EOF before the watcher pushes exit. Because the queue is FIFO and each reader queues its rows before its own EOF-exit, the last process's exit can no longer be dequeued before every row from every process has been. The watcher's exit/error remain a deduped fallback for a reader force-stopped before EOF.
  • Bounded, not hung. Drain uses one shared monotonic deadline across both streams (READER_DRAIN_TIMEOUT) rather than per-stream joins, so a wedged pipe whose write end is held open by a grandchild cannot double teardown time or hang. Force-stop still closes the pipe and kills the reader, preserving the existing wedged-pipe behavior and its spec.
  • Latent hang fixed. exit now always comes from ensure, so the watcher can no longer fail to signal exit if wait_thr.value raises.
  • Extracted drain_worker_readers so the refactor adds no new reek smells.

Note on the two readers: only the stdout reader parses the pipe into @messages rows and pushes its own exit; start_copy_thread for stderr merely buffers text into @worker_output and queues nothing. stderr is drained so no buffered warning output is lost, but it does not participate in the exit/rows ordering invariant. (Copilot caught an earlier comment that wrongly claimed both readers enqueue rows and their own exit.)


Bug 2: absolute paths from spec discovery on Windows

Problem

current.yml failed on windows-latest in two .rspec_configured_files_to_run specs:

expected: ["gems/example/spec/example_spec.rb"]
     got: ["C:/Users/runneradmin/AppData/Local/Temp/turbo-tests2-.../gems/example/spec/example_spec.rb"]

The absolute temp path leaked through unstripped, which crashes parallel_tests' File.stat during group sizing.

Root cause: a path string is a name, not an identity. One directory can have several valid names, reaching this method from different APIs within one process. Measured on the runner:

Dir.pwd         => "C:/Users/RUNNER~1/AppData/Local/Temp/turbo-tests2-...-ujisy2"
ENV["TEMP"]     => "C:\Users\RUNNER~1\AppData\Local\Temp"
Dir.glob result => "C:/Users/runneradmin/AppData/Local/Temp/turbo-tests2-...-ujisy2/gems/example/spec/example_spec.rb"

RUNNER~1 is the 8.3 short name, runneradmin the long name of the same directory. Dir.pwd/ENV report short while Dir.glob — which RSpec uses to expand --pattern — reports long. The old start_with?(root_prefix) check never matched.

The same class of mismatch arises from a symlinked ancestor on any platform, e.g. this workspace's Fedora /home/pboling → /var/home/pboling. That is what makes the bug reproducible in specs without a Windows runner.

Approaches that do not work

Four were tried on this branch and all failed. Recorded so nobody repeats the sequence — the full detail is in the TurboTests::Utils::Paths doc comment:

  1. String prefix (the original) — never matches across spellings. Also wrongly reports sibling project-other as inside project.
  2. File.realpath canonicalization — wrong premise: File.realpath does NOT expand 8.3 short names. Measured on the runner, root_realpath stayed RUNNER~1, so canonicalization cannot reconcile the spellings at all. (kettle-dev's Kettle::Dev::Paths.canonical documents realpath as expanding 8.3 names — that comment is inaccurate, and is what sent the first two attempts down this path. Worth fixing independently.)
  3. Component-wise comparison of canonical parts — built on the same false premise, so RUNNER~1 never equals runneradmin under any case folding. Also relied on File::ALT_SEPARATOR, which measured as "" (empty string, not nil) on that runner, making the separator-normalizing tr a silent no-op.
  4. Pathname#relative_path_from — Ruby's own stdlib helper is purely lexical. With differing spellings it walks up and back down, returning "../../../../../runneradmin/...". It does not raise, so a rescue ArgumentError guard cannot catch it; the plausible-looking wrong relative path is worse than the leak in feat: add rake hooks to allow setup and cleanup before parallel runs #1 because it silently selects the wrong files.

Fix

File.identical? compares by filesystem identity (inode on Unix, file index on Windows) and is spelling-agnostic. The fix ascends from the file asking "is this the root?" and re-joins basenames on the way back down, so the relative path is built from the file's spelling — which is what the caller needs, since parallel_tests stats these paths and spawns workers from this cwd.

Extracted as TurboTests::Utils::Paths.relative_from / .within?. Recursion self-terminates because File.dirname of the filesystem root returns itself, so no depth constant is needed.

How it was finally diagnosed

The failure only reproduced on the Windows CI runner and its output was swallowed: the discovery specs run a subprocess via Open3.capture3 whose stderr surfaces only on a status-check failure, while the assertion that failed was the JSON comparison. Four blind fixes failed in a row.

What resolved it was a temporary, Windows-guarded spec (if: Gem.win_platform?) that deliberately failed with diagnostic JSON embedded in the expectation message, so the runner's real path forms printed into the CI log while the other 22 checks stayed green. It measured the File.identical? walk-up producing the correct gems/example/spec/example_spec.rb while both the string-prefix and Pathname baselines failed in the same run. That spec is removed; its findings live in the module doc comment.

Lesson: when a bug is environment-specific and the environment is not available locally, spend the iteration instrumenting the real environment rather than shipping another hypothesized fix.


Tests

  • Bug 1 regression spec forces the exact interleaving with Queue barriers rather than sleeps: the reader blocks mid-drain after queueing row-1 but before row-2, wait_thr.value only returns once the reader is provably blocked, and stop_reader_thread is replaced by a deterministic drain so exit-vs-rows ordering is the only variable. An earlier sleep-based version could pass by luck against the broken ordering — Copilot caught that; this one fails 5/5 against it.
  • Bug 2 regression spec (spec/utils/paths_spec.rb) reproduces the bug portably via a symlinked ancestor, so it guards the fix on every platform and not only in the Windows job. Fails 3/3 against the old Pathname implementation, passes with the fix. Also covers a sibling directory sharing a string prefix, which a prefix check would wrongly report as inside the root.
  • Existing exits from the waiter thread and closes worker pipes when output remains open still passes — teardown stays within its join budget. A per-stream 5s join initially broke it before the shared deadline fixed it.
  • Nested begin/ensure rather than block-level ensure (Ruby 2.6+); this gem's floor is 2.4. Both files confirmed to parse under ruby-parse --24.
  • Full suite: 254 examples, 0 failures (Ruby 4.0.7 serial, coverage 96.93% line / 85.91% branch, seed 28920).
  • 6/6 parallel runs on Ruby 3.0.7 (CI-like contention): 254/254 each.
  • rubocop-gradual clean on changed files; reek at 184, below the 185 baseline.
  • CI on 22eddd2: 23 pass, 0 fail, including Specs windows-latest ruby@current: success after three consecutive failures. 16 skipping is expected — PRs run MRI only; JRuby/TruffleRuby need jruby/* / truffleruby/* branch names.

Two Keep A Changelog entries added under Unreleased → Fixed.

Signed-off-by per CONTRIBUTING.md (DCO).

Copilot AI balanced review requested due to automatic review settings October 5, 2026 14:13
@coveralls

coveralls commented Oct 5, 2026 •

Copy link
Copy Markdown

Coverage Report for CI Build 37471402742

Coverage increased (+0.3%) to 94.353%

Details

  • Coverage increased (+0.3%) from the base build.
  • Patch coverage: 2 uncovered changes across 2 files (47 of 49 lines covered, 95.92%).
  • No coverage regressions found.

Uncovered Changes

File Changed Covered %
lib/turbo_tests/runner.rb 16 15 93.75%
lib/turbo_tests/utils/paths.rb 33 32 96.97%

Coverage Regressions

No coverage regressions found.


Coverage Stats

Coverage Status
Relevant Lines: 977
Covered Lines: 947
Line Coverage: 96.93%
Relevant Branches: 298
Covered Branches: 256
Branch Coverage: 85.91%
Branches in Coverage %: Yes
Coverage Strength: 15.87 hits per line

💛 - Coveralls

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Copilot review overview

🟡 Changes recommended

The regression test relies on nondeterministic sleeps and may pass against the broken implementation.

Review effort: Balanced
Findings: 1 Medium severity · 1 Low severity

Open (2)
What changed in this PR

Fixes a worker teardown race that could drop queued test results.

Changes:

  • Drains stdout/stderr readers before signaling worker exit.
  • Adds bounded reader shutdown handling and regression coverage.
  • Documents the fix in the changelog.
File Description
lib/​turbo_tests/​runner.rb Reorders reader draining and exit signaling.
spec/​turbo_tests/​runner_spec.rb Adds regression coverage for queued output ordering.
CHANGELOG.md Records the teardown race fix.

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

Comment thread spec/turbo_tests/runner_spec.rb
Comment thread lib/turbo_tests/runner.rb Outdated
Fixes an intermittent example undercount and missing streamed output under CI
contention. Symptom: a nested run reported "1 example, 0 failures" instead of
"4 examples, 0 failures, 3 pending", and which worker vanished flipped between
runs (spec/integration/multi_process_spec.rb failed at :46 on one run and
:52-54 on the next).

@messages is FIFO. Each stdout reader queues that worker's rows as it reads the
pipe, then pushes its own {type: "exit"} at EOF. The exit-watcher also pushed an
exit as soon as it reaped the child — before the reader had drained. So a worker
that was still mid-drain had its rows queued behind its own exit signal, and
handle_messages could reach process_count exits and break, never reporting them.
The subsequent 0.1s force-stop then closed the pipe while the child's output was
still kernel-buffered, discarding it.

Fix: drain both readers to EOF before the watcher signals exit. FIFO ordering
then guarantees the last process's exit cannot be dequeued before every row from
every process. The watcher's exit/error remain a deduped fallback for a reader
force-stopped before EOF, and being in ensure also prevents a hang if
wait_thr.value raises.

Drain uses one shared monotonic deadline (READER_DRAIN_TIMEOUT) across both
streams, so a wedged pipe whose write end stays open — e.g. held by a
grandchild — cannot double teardown time or hang. Force-stop behavior is
unchanged: close the pipe, brief join (FORCE_STOP_JOIN), then kill.

The stdout reader parses the pipe into @messages rows and pushes its own exit;
start_copy_thread for stderr only buffers text into @worker_output and queues
nothing. stderr is drained too so no buffered warning output is lost, but it
does not participate in the exit/rows ordering invariant.

Spec coverage:

- Regression spec forces the exact interleaving with Queue barriers: the reader
  blocks mid-drain after row-1 but before row-2, wait_thr.value only returns
  once the reader is provably blocked, and stop_reader_thread is replaced by a
  deterministic drain so exit-vs-rows ordering is the only variable. An earlier
  sleep-based version could pass by luck against the broken ordering; this one
  fails 5/5 against it.
- The bounded force-stop itself remains covered by the existing wedged-pipe spec
  (exits from the waiter thread and closes worker pipes when output remains
  open), which a per-stream 5s join initially broke before the shared deadline
  fixed it.

Full suite 244 examples, 0 failures; 6/6 parallel runs on Ruby 3.0.7.
rubocop-gradual clean; reek at the 185 baseline.

Signed-off-by: Peter H. Boling <peter.boling@gmail.com>
@pboling
pboling force-pushed the bug/worker-output-drain-race branch from 3ebf786 to 22eddd2 Compare October 6, 2026 12:49
@pboling
pboling requested a balanced review from Copilot October 6, 2026 12:59

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Copilot review overview

🟡 Changes recommended

The path rewrite is outside the described scope, and its symlink test is not isolated across concurrent runs.

Review effort: Balanced
Findings: 1 Medium severity · 2 Low severity

Open (3)
Resolved since last review (2)

Comment thread spec/utils/paths_spec.rb Outdated
file = File.join(real_root, "gems", "example", "spec", "example_spec.rb")
FileUtils.touch(file)

link = File.join(File.dirname(real_root), "turbo-tests2-paths-symlink")

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

Fixed in cf86971. The symlink now lives in its own uniquely-named Dir.mktmpdir("turbo-tests2-paths-link"), so both the link name and its parent directory are unique per run — no fixed name in the shared system temp dir.

Verified the race empirically before the fix (a second run creating the same fixed name raised Errno::EEXIST) and after (20 concurrent runs, 0 collisions). This also removes the manual File.unlink in ensure you flagged: mktmpdir removes the symlink via lstat without following it into real_root, confirmed by checking that real_root's contents survive the inner cleanup.

The obsolete note about nested begin/ensure for Ruby 2.4 is also gone, since cleanup no longer uses ensure at all. The spec still fails 3/3 against the pre-fix Pathname implementation and passes with the fix.

Comment thread lib/turbo_tests/runner.rb
configuration.files_to_run.map do |path|
expanded_path = File.expand_path(path.to_s, root).tr("\\", "/")
expanded_path.start_with?(root_prefix) ? expanded_path[root_prefix.length..-1] : expanded_path
TurboTests::Utils::Paths.relative_from(File.expand_path(path.to_s, root), root)

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

Resolved — you reviewed at 13:02Z; the title and body were updated at 13:05Z, just after your snapshot. The PR title now reads "Fix worker results dropped by a teardown race, and Windows spec discovery paths" and the body has a Problem / Approaches that do not work / Fix / Tests section for each bug.

Kept both fixes in one PR rather than splitting: they share a branch, a changelog release (the unreleased 3.2.14), and the Windows discovery fix was found while debugging this same CI failure. Each is its own commit (386bf40 drain-race, cf86971 paths), so they stay independently reviewable and bisectable.

Comment thread spec/utils/paths_spec.rb Outdated
@pboling pboling changed the title 🐛 Drain worker output before signaling exit to stop dropping results 🐛 Fix worker results dropped by a teardown race, and Windows spec discovery paths Oct 6, 2026
Fixes two discovery specs failing on windows-latest. Symptom:
rspec_configured_files_to_run returned absolute temp paths
("C:/Users/runneradmin/AppData/Local/Temp/turbo-tests2-.../gems/example/spec/example_spec.rb")
instead of "gems/example/spec/example_spec.rb", crashing parallel_tests'
File.stat during group sizing.

Root cause: a path string is a name, not an identity, and one directory can have
several valid names reaching this module from different APIs in one process. On
the Windows runner Dir.pwd / ENV["TEMP"] / Dir.tmpdir report the 8.3 short name
(RUNNER~1) while Dir.glob — which RSpec uses to expand --pattern — reports the
long name (runneradmin). The old string prefix check never matched, so the
absolute path leaked through.

The same class of mismatch arises from a symlinked ancestor on any platform,
e.g. this workspace's Fedora /home/pboling -> /var/home/pboling, which is what
makes the bug reproducible in specs without a Windows runner.

Four approaches were tried and all failed. The measurements that disproved each
are recorded in the module's doc comment so nobody repeats the sequence:

1. String prefix (the original) — never matches across spellings; also wrongly
   reports a sibling "project-other" as inside "project".
2. File.realpath canonicalization — WRONG PREMISE: realpath does NOT expand 8.3
   short names (root_realpath stayed RUNNER~1 on the runner). Canonicalization
   cannot reconcile the two spellings. kettle-dev's Kettle::Dev::Paths.canonical
   documents realpath as expanding 8.3 names; that comment is inaccurate and is
   worth correcting if this module is ever extracted to a shared gem.
3. Component-wise comparison of canonical parts — same false premise, so
   RUNNER~1 never equals runneradmin under any case folding. Also depended on
   File::ALT_SEPARATOR, which measured as "" (empty, not nil) on the runner,
   making the separator-normalizing tr a silent no-op.
4. Pathname#relative_path_from — purely lexical; with differing spellings it
   returns "../../../../../runneradmin/..." WITHOUT raising, so a
   rescue ArgumentError guard cannot catch it. Worse than the leak in #1
   because it silently selects the wrong files.

The fix: File.identical? compares by filesystem identity (inode on Unix, file
index on Windows) and is spelling-agnostic. Ascend from the file asking "is this
the root?", re-joining basenames on the way back down. Recursion terminates on
its own because File.dirname of the filesystem root returns itself, so no depth
constant is needed. Extracted as TurboTests::Utils::Paths.relative_from/.within?.

How it was finally diagnosed: the failure only reproduced on the Windows CI
runner and its output was swallowed (the discovery specs run a subprocess whose
stderr only surfaces on a status-check failure, while the assertion that failed
was the JSON comparison). Four blind fixes failed in a row. What resolved it was
a temporary, Windows-guarded spec (if: Gem.win_platform?) that deliberately
failed with diagnostic JSON embedded in the expectation message, so the runner's
real path forms printed into the CI log while the other 22 checks stayed green.
It measured the File.identical? walk-up producing the correct relative path
while both the string-prefix and Pathname baselines failed in the same run. That
spec is removed here; its findings live in the module doc comment.

Spec coverage (spec/utils/paths_spec.rb):

- Reproduces the bug portably via a symlinked ancestor, so it guards the fix on
  every platform, not only in the Windows job. Fails 3/3 against the old
  Pathname implementation, passes with the fix.
- The symlink lives in its own uniquely-named Dir.mktmpdir, so both the link
  name and its parent are unique per run. A fixed name in the shared system
  temp dir raced under the parallel runner (Errno::EEXIST on setup, and one
  run's ensure unlinking another's symlink); proven 0 collisions across 20
  concurrent runs after the fix. mktmpdir removes the symlink via lstat without
  following it into real_root, so there is no manual unlink to race.
- Covers a sibling directory sharing a string prefix, which a prefix check would
  wrongly report as inside the root.
- Neither spec/utils/*_spec.rb requires "spec_helper": .rspec loads it via
  --require, and the project guide says spec files must not add it. Removed
  from both paths_spec.rb and hash_extension_spec.rb so the pattern stops being
  copied forward.
- paths.rb confirmed to parse under ruby-parse --24 (this gem's floor).

Full suite 254 examples, 0 failures; 6/6 parallel runs on Ruby 3.0.7.
rubocop-gradual clean; reek 184 (below the 185 baseline).

Signed-off-by: Peter H. Boling <peter.boling@gmail.com>
@pboling
pboling force-pushed the bug/worker-output-drain-race branch from 22eddd2 to cf86971 Compare October 6, 2026 13:30
@github-actions

github-actions Bot commented Oct 6, 2026

Copy link
Copy Markdown

Code Coverage

Package Line Rate Branch Rate Health
turbo_tests2 97% 86% ➖
Summary 97% (947 / 977) 86% (256 / 298) ➖

Minimum allowed line rate is 92%

@pboling
pboling merged commit f2e759d into main Oct 6, 2026
39 checks passed
@pboling
pboling deleted the bug/worker-output-drain-race branch October 6, 2026 14:22
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.

3 participants