fix(codex-bridge): every log line names the process that wrote it - #795
Open
fujibee wants to merge 3 commits into
Open
fix(codex-bridge): every log line names the process that wrote it#795fujibee wants to merge 3 commits into
fujibee wants to merge 3 commits into
Conversation
The launcher appends the bridge's stderr to a per-identity log (`codex-bridge-launcher.sh`: `>>"$log" 2>&1`), and that file has more than one writer by construction: the bridge that is running, plus every launch attempt that finds it already there, says so, and exits. Lines were reported spliced mid-word, and other logs reported losing their line beginnings, on a self-hosted server run from Windows 11 / Git Bash. Refs #784. WHAT THIS DOES NOT DO. It does not claim to stop the interleaving, and nothing here is written as if it did. Whether two processes' appends can land inside each other is a property of the platform, and the lines involved are short — around 55 and 60 bytes — with each written by a single `console.error`, so "the line was too long to be atomic" is not available as an explanation. That leaves the platform's append as the open question, and it cannot be answered from a POSIX machine. Not reproduced here. WHAT IT DOES. One write per line: the newline is part of the same `write` as the text, so a line is never split into two writes by this side. The writer is named: `[<pid>] ` leads every diagnostic. A spliced line now carries two pids instead of reading as one line, and a line that lost its beginning no longer starts with the prefix. On the platform where these logs are the primary evidence for every other report, corruption that cannot be prevented can at least stop being invisible — a log that is quietly wrong is worse than one that is obviously wrong. Rebound once rather than applied at the forty-odd call sites: a helper that has to be remembered is one a later line will forget. STDOUT IS DELIBERATELY UNTOUCHED. `usage()`, the thread-id list and `--resolve-only` are read by people and asserted by tests in this suite; a prefix there would change an interface rather than a diagnostic. A test pins that, so the prefix cannot spread to stdout later. Measured, not asserted. Removing the rebinding turns the pid test red and leaves the stdout test green; prefixing `usage()` does the reverse. Both mutations were run against the tests in their final form and reverted. 39 pass in `test_codex_bridge.bats`, and the neighbouring suites that exercise the bridge stay green: `test_codex_bridge_launcher` 16, `test_close_fds` 4, `test_spawn_fd_guard` 4.
The first version of this change prefixed `console.error` and said every diagnostic line now names its writer. That was not true, and the part it missed was the more interesting one (raised in review). DERIVED, NOT LISTED. Grepping every write to stderr in this file returns three, not one: console.error forty-odd sites, whole lines, ours child.stderr chunk the app-server's own stderr, arbitrary chunks agent/message/delta partial BY NAME — there is no newline to wait for The second and third went straight to `process.stderr.write`, bypassing the prefix and any line framing. So a delta that ends mid-word followed by a diagnostic produced ONE physical line carrying both — the exact shape #784 reports, reachable inside a single process, with no second writer and no platform question. "The remaining question is Windows" was wrong, and this commit does not repeat it. Everything now goes through one funnel that remembers whether the last byte it wrote was a newline; a diagnostic opens a fresh line when it was not. Streamed content passes through byte-for-byte: a chunk is not a line, and buffering the child's output would delay someone's only view of a child that is hanging. Refs #784. WHAT IS STILL NOT ANSWERED. Whether two PROCESSES' appends can splice on Windows is untouched and unmeasured here — this is a POSIX machine, and the issue does not say which of the reporter's three environments the sample came from. The prefix makes that case visible if it happens; it does not prevent it. Measured. Four mutations, each turning exactly one test red and no other: drop the newline insertion -> "a diagnostic never continues …" delta straight to stderr again -> "only one place writes to stderr" remove the console.error rebind -> "every diagnostic line carries …" prefix usage() on stdout too -> "stdout is NOT prefixed" One-to-one, so no test is standing in for another. Note the second: the delta path is guarded by the writer COUNT, not by the funnel test, which drives the funnel directly — the two are only equivalent together, and that is why the count test exists. 41 pass in `test_codex_bridge.bats`; `test_codex_bridge_launcher` 16, `test_close_fds` 4, `test_spawn_fd_guard` 4. The new assertions use `grep -q` rather than `[[ ]]` in non-last positions, so the enforceable count stays at its baseline of 638 rather than being raised.
The previous commit said streamed content passes through byte-for-byte and then called `toString()` on every child-stderr Buffer. The comment was true and the code was not (raised in review). WHY IT MATTERS MORE THAN THE THING IT WAS FIXING. A multi-byte character split across two `data` events decodes to a replacement character in EACH half, so the app-server's own diagnostics arrive corrupted for anyone whose output is not ASCII. The direct `process.stderr.write(chunk)` that commit replaced did not do that, so the change made the log worse than leaving it alone — the opposite of what #784 is for. Buffers are now written as Buffers. `process.stderr.write` takes a string or a Buffer, so the funnel is a single call and nothing is decoded on the way through. The newline flag reads the last BYTE (`0x0a`) for a Buffer and the last CHARACTER for a string; those agree, because `\n` is never part of a multi-byte UTF-8 sequence. Folding the two branches into one write also restores something the test suite depends on: "nothing writes to stderr outside the funnel" is only checkable while there is one call to count. The control runs through the PRODUCTION WIRING rather than calling the funnel: a fake app-server writes a three-byte character with the split inside it, across two `data` events, and the bridge's own stderr is compared for the character and for the absence of any replacement character. Driving `writeErr` directly would not have shown that the real handler forwards undecoded — the same gap that let the first version of this claim through. The count test now strips comment lines before counting. This file explains the funnel by naming `process.stderr.write` in prose, and counting those made the check measure its own commentary: it read 3 and failed on a file with one call. Refs #784. Measured. Six mutations, each red in exactly one place: child chunk back to toString() -> the UTF-8 control String() inside the funnel -> the UTF-8 control (other route) drop the newline insertion -> "a diagnostic never continues ..." delta straight to stderr -> "only one place writes to stderr" remove the console.error rebind -> "every diagnostic line carries ..." prefix usage() on stdout -> "stdout is NOT prefixed" 42 pass in `test_codex_bridge.bats`; `test_codex_bridge_launcher` 16, `test_close_fds` 4, `test_spawn_fd_guard` 4. `check-enforced-assertions` reports 638, at the baseline. Not pushed with this commit: CI on this branch is frozen while a load problem is isolated, and the numbers above are local.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Declared reviewers: 1
Refs #784 — no closing keyword. This lands on
integration/remote, where GitHub does not act on one, and it does not finish the issue.The causal boundary, twice corrected
First claim, wrong: "the remaining question is Windows' append." Grepping every write to stderr returns three paths, not one:
console.error— forty-odd siteschild.stderrchunkagent/message/deltaThe last two went straight to
process.stderr.write, so a delta ending mid-word followed by a diagnostic produced one physical line carrying both — the shape the issue reports, reachable inside a single process, with no second writer and no platform involved.Second claim, also wrong: the fix for that said streamed content passes "byte-for-byte" while the code called
toString()on it. The comment was true and the implementation was not. That is the regression quoted at the top.What the change is, as it now stands locally
One funnel. Everything reaching stderr goes through
writeErr, which remembers whether the last byte it wrote was a newline; a diagnostic opens a fresh line when it was not.Buffers stay Buffers.
process.stderr.writetakes both, so the funnel is a single call and nothing is decoded on the way through. The newline flag reads the last byte (0x0a) for a Buffer and the last character for a string — those agree, because\nis never part of a multi-byte sequence.Diagnostics carry
[<pid>]. A line spliced by two processes shows two pids; a line that lost its beginning no longer starts with the prefix.stdout is untouched —
usage(), the thread-id list and--resolve-onlyare read by people and asserted by tests here.Still not answered
Whether two processes' appends can splice on Windows is unmeasured. This is a POSIX machine, and the issue does not say which of the reporter's three environments produced the sample. The prefix makes that case visible; it does not prevent it. Asking which environment it came from remains cheaper than any further change.
Mutations — six, each red in exactly one place
toString()againa multi-byte character split across child stderr chunks survives byte-for-byteString()the value inside the funnellogLinea diagnostic never continues the half-line streamed output left openprocess.stderr.writeonly one place writes to stderr, so the funnel cannot be bypassedconsole.error = logLineevery diagnostic line carries the pid that wrote itusage()on stdout toostdout is NOT prefixed — it is an interface, not a diagnosticNone is inert, and no test stands in for another. Two notes worth reading rather than skimming:
The UTF-8 control runs through the production wiring — a fake app-server writing a 3-byte character split inside itself, across two
dataevents — rather than by callingwriteErr, because what is being pinned is that the real handler forwards undecoded.Suites
This head:
test_codex_bridge42 pass, 0 fail locally.test_codex_bridge_launcher16,test_close_fds4,test_spawn_fd_guard4.New assertions use
grep -qrather than[[ ]]in non-last positions — on bash 3.2, which macOS CI runs, a false[[ ]]there reports ok — andrefuterather than!, which trips errexit on neither bash.check-enforced-assertionsreports 638, at the baseline: not raised.