Skip to content

The refused-first-dial red measured: a child's copy of a dropped listener, fixed on main by #566; two issues filed - #591

Merged
Japabu merged 2 commits into
mainfrom
wt/toyos-dialflake
Sep 28, 2026
Merged

Japabu merged 2 commits into
mainfrom
wt/toyos-dialflake

Conversation

@Japabu

@Japabu Japabu commented Sep 28, 2026 •

Copy link
Copy Markdown
Collaborator

Two issue files. No code changes: the flake this branch was sent to fix was already fixed on main before the work began.

The red, and why no test changes

metaltalk::tests::a_refused_first_dial_is_asked_again_up_to_its_ceiling failed once in 200 loaded full --lib runs at 9aa473d0, panicking at src/metaltalk.rs:1326:37 ("the dial gave up within 5 s of its 60 and said why"). At 9aa473d0 the test bound 127.0.0.1:0, dropped the listener, and dialled its port. 9aa473d0 does not contain #566. #566 (e47d1f06) replaced that premise with a Refusing stage through Reach, so on main no socket reaches the test and there is nothing for a thread or a child to steal. The panic line and column are the same in both versions, which is why the red still looked open.

The mechanism, measured

A standalone Rust probe binds 127.0.0.1:0, drops the listener, and runs connect_timeout(5 s) on that port, for 15 s per arm:

arm dials refused taken timed out
quiet 72572 72572 0 0
4 threads binding and dropping 127.0.0.1:0 87686 87686 0 (none on a binder's port) 0
8 threads spawning children 94095 94086 9 0
  • Children stealing the dial: measured. In the spawner arm nothing else in the process holds the port, so each of the 9 taken dials went to a copy of the listener held by a child.
  • Another listener in the process binding the freed port: not seen. Binders did get ports the probe had used, 16307 times over the run, but never inside the window between the drop and the dial.
  • An unanswered SYN costing the whole 5 s CONNECT_WAIT: not seen. No dial timed out, and the slowest refusal took 92 ms.

The review's two candidate mechanisms therefore give way to the one 8cc19ef1 measured first. #566's commit already carries that finding.

Negative control

Each arm is a checked patch on this tree, built, run with --exact, and reverted. The tree was clean before and after.

  • main: build EXIT=0, test EXIT=0.
  • nc1, the old premise reinstated (bind, drop, Stream::connect through Net): build EXIT=0, test EXIT=0 when run alone.
  • nc2, nc1 plus a try_clone of the listener made before the drop (the child's copy), which accepts the dial and closes it before a line: build EXIT=0, test EXIT=101, panicked at src/metaltalk.rs:1332:37: the dial gave up within 5 s of its 60 and said why after 5.02 s. That is the filed red's own message.

Loop

The main binary at e3a1cdc8 ran as 200 full --lib runs beside a cargo test --workspace --exclude toyos-build loop (load EXIT=0 for each finished run; 1-minute load average 40 to 80). The refused-first-dial test was ok in 200 of 200. The binary exited 0 in 199: run 182 was red in another test, filed here.

What this files

  • issues/diagnostics/a-first-dial-turned-away-before-a-line-is-waited-on-to-its-callers-bound.md covers the production path nc2 ran through. serve records no unopened for a first dial closed before a line, so wait_for_connection waits out its whole bound, although its doc says it returns once the dial has ended with none.
  • issues/build/a-compiler-fixtures-git-commit-could-not-create-a-temporary-file.md covers the red in run 182. a_missing_primary_record_is_refused_and_builds_nothing failed because its fixture's git commit got "unable to create temporary file: Invalid argument".

Gates, at this head

  • cargo test -p toyos-build --lib: EXIT=0 (412 passed, 3 ignored)
  • cargo run -- --clippy: EXIT=0

Unsure

  • Why a child holds a copy of the listener is not settled. It could be the fork-to-exec window, or the window between std's socket() and its FIOCLEX on macOS. Either way the dial is stolen.
  • The cause of the EINVAL in run 182 was not investigated.

🤖 Generated with Claude Code

Japabu and others added 2 commits September 28, 2026 23:57
…er's bound

This came out of measuring the red of
`metaltalk::tests::a_refused_first_dial_is_asked_again_up_to_its_ceiling`: one
in 200 full `--lib` runs under load at 9aa473d, panicking at
`src/metaltalk.rs:1326:37`. The test is not changed here. At 9aa473d it dialled
a listener it had bound and dropped. #566 (e47d1f0) replaced that with a
`Refusing` stage before this was measured, so no socket reaches it on main.

A standalone probe (bind 127.0.0.1:0, drop, connect_timeout 5 s, 15 s per arm)
named the mechanism:
- quiet: 72572 dials, all refused.
- four threads binding and dropping 127.0.0.1:0 listeners: 87686 dials, all
  refused, none taken on a binder's port.
- eight threads spawning children: 94095 dials, 9 taken. Nothing else in the
  process held the port, so a child's copy of the listener took them.
- no dial timed out in any arm; the slowest refusal was 92 ms.

A mutation reinstating the old premise, with a copy of the dropped listener
that takes the dial and closes it before a line, fails the test the way the
filed red did (build EXIT=0, test EXIT=101, "the dial gave up within 5 s of
its 60 and said why", after 5.02 s). The old premise without that copy passes
alone (EXIT=0).

The wait running out its whole bound is a production path, filed here: `serve`
neither redials a first dial closed before a line nor records `unopened`, so
`wait_for_connection` waits to its bound, where its doc says it returns once
the dial has ended with none.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
The 200-run loop that proved the refused-first-dial test green under load
went red once elsewhere. In run 182 of 200 at e3a1cdc, with the 1-minute load
average at 62.82, `compiler::tests::a_missing_primary_record_is_refused_and_builds_nothing`
failed because its fixture's `git commit` hit "unable to create temporary
file: Invalid argument". It is off this branch's path, so it is filed and not
investigated.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
@Japabu Japabu changed the title The refused-first-dial red: mechanism measured, fixed on main by #566; the wait it exposed filed The refused-first-dial red measured: a child's copy of a dropped listener, fixed on main by #566; two issues filed Sep 28, 2026
@Japabu
Japabu marked this pull request as ready for review September 28, 2026 22:19
@Japabu

Japabu commented Sep 28, 2026

Copy link
Copy Markdown
Collaborator Author

Review, round 1, at f4a30b0

CI: host check SUCCESS (the other host entry is SKIPPED, a duplicate check-run name, not a second suite). Branch adds no code and no tests, so "tests the branch adds are green" is vacuously satisfied; no hardware claim is made.

Diff: git diff --shortstat origin/main...HEAD — 2 files changed, 63 insertions(+), 0 deletions, both under issues/. No production code, no test code.

Verified against main's code (this worktree, unchanged from main here):

  • issues/diagnostics/a-first-dial-turned-away-before-a-line-is-waited-on-to-its-callers-bound.md: true. serve (src/metaltalk.rs:325-368) only re-enters the redial branch on a post-connect close when again is true (line 345: read(conn, ...).filter(|_| again)); on the first dial again is false (line 329), so a connection that closes before a line is silently dropped — the thread parks at the state.redial.take() loop (355-367) and never calls state.unopened = Some(...). open() (402-465) is the only path that sets unopened, and it is reached only for connect-level failures, never for a post-accept close. wait_for_connection's dialing (line 297: state.redial.is_some() || state.current.is_some() || state.unopened.is_none()) is therefore still true — unopened stays None — so it waits its whole by instead of returning early per its own doc comment (286-288, "once the dial asked for it ended with none"). The three named callers check out: src/metalswap.rs:142, tests/common/logstream.rs:115, and converse at src/metaltalk.rs:928 waiting FOREVER.
  • issues/build/a-compiler-fixtures-git-commit-could-not-create-a-temporary-file.md: the cited panic site matches — src/compiler.rs:373 is the assert!(out.status.success(), ...) in the test's git() helper. This is a different mechanism from A swap's redial dials until logd admits one, bounded by the swap's window alone #566/Host tests assert a lock free only after another process held it: the keyed-lock flake fixed #581: those fixed a listener socket surviving into a spawned child across fork/exec and stealing a connect; this is git commit failing to create its own temp file in the object database (EINVAL), with no fork/exec or socket involved anywhere in the fixture. The issue file does not claim the two are the same class — it says the EINVAL's cause "was not investigated" — so there is no misattribution to flag.

Format, per issues/README.md: both files carry status: open, a valid kind (tooling for both — a harness flake and a test flake are both "the development machine"), a valid area (diagnostics, build are both in the closed area list), and a checkable exit condition. No slug collides with an existing file (git grep for both slugs outside issues/ finds nothing), and neither duplicates an existing entry (checked issues/diagnostics/a-swaps-redial-asks-again-with-no-event-to-wait-on.md and issues/build/wait-until-for-inits-word-never-wakes-once-the-stream-is-dead.md, both adjacent but about different mechanisms).

PR body: no scratchpad path or private-tmp citation (grep for scratchpad|/private/tmp|/tmp/ in the body: no match) — the quoted panic lines and EXIT codes are the evidence, matching the rule. The nc2 negative control's construction (try_clone before drop, accept-then-close-before-line, test EXIT=101 at src/metaltalk.rs:1332:37) matches the mechanism and message the issue file cites, and the line-number shift (1326 on the base test vs. 1332 in the mutated one) is consistent with the mutation adding lines above it.

BLOCKER: none.

NOTE: the "Negative control" and probe-table paragraphs describe methodology ("run with --exact", "a standalone Rust probe") without literally quoting the invocation; the exit codes and panic text given are enough to check the load-bearing claim (nc2 reproduces the filed red), so this isn't sent back, but a future evidentiary PR body should paste the command line, not just narrate it.

REMOVE: none — both issue files are invariant + exit condition, no narration, no dates beyond opened, no story.

LAND

@Japabu
Japabu added this pull request to the merge queue Sep 28, 2026
Merged via the queue into main with commit 0692082 Sep 28, 2026
2 checks passed
@Japabu
Japabu deleted the wt/toyos-dialflake branch September 28, 2026 22:57
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.

1 participant