Skip to content

test: drop the relay child-watcher race from stdio stderr checks - #475

Closed
hellices wants to merge 2 commits into
mainfrom
fix/472-relay-watcher-stderr
Closed

hellices wants to merge 2 commits into
mainfrom
fix/472-relay-watcher-stderr

Conversation

@hellices

@hellices hellices commented Oct 23, 2026 •

Copy link
Copy Markdown
Owner

Closes #472

Summary

test_stdout_noise_is_diverted_and_wire_is_restored[True] failed on test (3.12) in #469's CI because the stdio server's stderr carried one extra line: child process pid 3098 exit status already read: will report returncode 255.

That line is asyncio's child watcher inside the server, racing Popen:

  1. relay=True forces the Windows-only relays onto POSIX.
  2. When the test closes stdin, the stdin relay exits on its own.
  3. If _relay_stdin's cleanup runs before the event loop has processed that exit, process.returncode is still None and the cleanup calls process.kill().
  4. Popen.send_signal polls the child first (bpo-38630), and on POSIX that waitpid reaps the relay.
  5. The loop's watcher then finds the child gone, reports exit status 255, and logs the warning.

On Windows, where the relays run in production, nothing reaps, so production never writes this line.

  • The fix: the three forced-relay tests that compare the server's stderr exactly now read it through _server_stderr. It drops whole lines matching either watcher's warning and keeps everything else. The pidfd watcher writes "exit status already read"; the threaded watcher writes "Unknown child process pid". The product code is unchanged, because the race only exists where the tests run the relays on POSIX.
  • Unrelated to ci: run the test suite on four xdist workers #469: the race is inside the server process. ci: run the test suite on four xdist workers #469's first CI run passed on every interpreter, and the failed job has been re-run.

Update after #471's CI. Under four xdist workers on korvid-runners, the race hit a fourth exact check on 3.12, twice: test_stdio_delivers_large_utf8_output_without_truncation[True] expected an empty stderr log. Rather than wait for the next one, the forced-relay entrypoint now logs asyncio's exact warning at startup. Every relay=True test that reads the server's stderr therefore has to filter it on every run, not just on a lucky one. With the line emitted, exactly that test failed. It now reads its log through _server_stderr, which accepts text as well as bytes, and tests/mcp/test_stdio.py passes in full (57 passed, twice). The branch is rebased onto main at 9ab38db, and the full suite passes there: pytest -n 8 -q, 13,752 passed, 25 skipped. The CI table below is from the first push.

Verification

  • The filter: test_server_stderr_drops_the_relay_child_watcher_race (both watcher forms) failed first against a helper that only decoded, and passes now. test_server_stderr_keeps_every_other_line pins the other direction: a line that only contains one of the warnings, or a shortened form, is kept.
  • The stdio tests: tests/mcp/test_stdio.py passes in full (57 passed).

Run locally on macOS with Python 3.13 and the frozen lock. Each step ran directly with the project's environment rather than through make, because this machine cannot sync from PyPI:

Command Result
pytest -p no:tach tests/mcp/test_stdio.py 57 passed
python scripts/check_source_size.py passed
ruff check src/ tests/ and ruff format --check src/ tests/ passed; 659 files already formatted
SKIP=mypy,source-size pre-commit run --files tests/mcp/test_stdio.py passed
mypy no issues in 659 source files
tach check all modules validated
pytest -n 8 -q 13,699 passed, 25 skipped (one earlier attempt hit the gzip collection mismatch that #469 fixes)

This PR's CI (run 39938500526, hosted runners) passed every required check. That includes the forced-relay stdio tests on Linux with 3.11, 3.12 and 3.13, and windows-test, where the relays run natively:

Job Result
test (3.11) passed, 39m0s
test (3.12) passed, 36m1s
test (3.13) passed, 38m4s
windows-test passed, 32m18s

Checklist

  • This closes an accepted issue in this repository that is assigned to me.
  • Tests cover the change, written to fail first where behavior changed.
  • make check passes locally.
  • User-facing docs and the README match the change, or nothing user-facing changed.
  • No security invariant is weakened: writes still need a keystroke approval
    and a fail-closed audit entry, and sensitive reads are still masked.

Copilot AI balanced review requested due to automatic review settings October 23, 2026 10:21

Copilot AI left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

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

🔵 Needs a closer look

No blocking code issues were identified, but completion of the required Linux and Windows CI checks remains unverified.

No open issues 🎉

What changed in this PR

Addresses #472 by stabilizing exact stderr assertions in MCP stdio tests that force Windows relays onto POSIX. Production code is unchanged.

Changes:

  • Adds a helper that removes whole lines matching either known asyncio child-watcher race warning.
  • Tests that both warning forms are removed while unrelated diagnostics remain intact.
  • Applies the helper to three exact stderr checks.
File Description
tests/​mcp/​test_stdio.py Adds targeted warning filtering, regression coverage, and updated stderr assertions.

Review effort: Balanced

@my-reviewer-agent my-reviewer-agent Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

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

검토 범위에서 보고할 이슈가 없습니다.

Copilot AI left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

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

🟢 Approval recommended

The narrow test-only change satisfies the linked issue’s requirements, preserves unrelated stderr output, and has no identified blocking issues.

No open issues 🎉

Review effort: Balanced

hellices and others added 2 commits October 24, 2026 02:15
test_stdout_noise_is_diverted_and_wire_is_restored[True] failed on 3.12
because the stdio server's stderr carried "child process pid 3098 exit
status already read:  will report returncode 255" (#472). relay=True
forces the Windows-only relays onto POSIX. When the stdin relay exits on
its own as the test closes stdin, and _relay_stdin's cleanup runs before
the event loop has processed that exit, process.kill() goes through
Popen.send_signal, which polls first (bpo-38630). That waitpid reaps the
relay, and asyncio's child watcher then finds it gone, reports 255 and
logs the warning. On Windows, where the relays run in production, nothing
reaps.

The three forced-relay tests that compare the server's stderr exactly now
read it through _server_stderr, which drops whole lines matching either
watcher's warning (pidfd: "exit status already read", threaded: "Unknown
child process pid") and keeps everything else. Two tests pin both
directions: both warnings are dropped with the surrounding lines intact,
and a line that only contains one is kept.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
The race is rare on its own, so the first fix only covered the three
exact stderr checks it was seen against. Under four xdist workers on
korvid-runners it hit a fourth on 3.12, twice:
test_stdio_delivers_large_utf8_output_without_truncation[True] expected
an empty stderr log and got "child process pid ... exit status already
read:  will report returncode 255".

The forced-relay entrypoint now logs that exact asyncio warning at
startup, so every relay=True test that reads the server's stderr has to
filter it on every run instead of passing on a lucky one. With the line
emitted, exactly that test failed; it now reads its stderr log through
_server_stderr, which accepts text as well as bytes, and test_stdio.py
passes in full.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
@hellices
hellices force-pushed the fix/472-relay-watcher-stderr branch from c8c7e52 to 0d5d2b5 Compare October 23, 2026 17:24

@my-reviewer-agent my-reviewer-agent Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

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

검토 범위에서 보고할 이슈가 없습니다.

Copilot AI left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

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

🟢 Approval recommended

The test-only changes narrowly filter known race warnings, preserve other diagnostics, and have no identified blocking issues.

No open issues 🎉

Review effort: Balanced

@hellices

Copy link
Copy Markdown
Owner Author

Superseded by #482, which carries this pull request's commits unchanged (0b1a74f and 96a56bd) together with the other open fixes and the dependency security bumps, so all of them need one CI run and one merge instead of a rebase after each merge. Closing in favour of #482; the branch stays, so this can be reopened if needed.

@hellices hellices closed this Oct 25, 2026
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.

Forced POSIX relay: asyncio's child watcher can warn into the stdio server's stderr

2 participants