diff --git a/docs/memory/device-node/index.md b/docs/memory/device-node/index.md index bf018fc..81e09b3 100644 --- a/docs/memory/device-node/index.md +++ b/docs/memory/device-node/index.md @@ -8,4 +8,4 @@ description: "Device interaction via gRPC: lifecycle, recording, log capture, an | File | Description | |------|-------------| | [android-ios-mirror](android-ios-mirror.md) | The Android/iOS mirror in device-node — platform clients, gRPC setups, recording/log providers, discovery probes: sharing is settled per pair by a measured diff, not parallel shape (`infra/commandFailure.ts`, `device/logWriteStream.ts`, `MAX_DIAGNOSTIC_OUTPUT_CHUNKS`), diagnostic buffers are bounded rings with a consumer, `simctl` plist fields degrade per field, driver recovery replays only an explicit allow-list, and `closeDriverChannel` closes a channel rather than killing a process. | -| [log-capture](log-capture.md) | Per-test device log capture (manager, providers, Device integration) and the write-stream finalization contract: every exit from start/stop ends and flushes the log file's write stream through one shared `LogWriteStreamRegistry`, held per provider instance and keyed on the capture's output file path, so the file the CLI copies next is complete. `open()` attaches a persistent `error` listener that records the first error and never throws, and `finalize` fails the stop on it. | +| [log-capture](log-capture.md) | Per-test device log capture (manager, providers, Device integration) and the write-stream finalization contract: every exit from start/stop ends and flushes the log file's write stream through one shared `LogWriteStreamRegistry`, held per provider instance and keyed on the capture's output file path, so the file the CLI copies next is complete. `open()` records the first stream `error` and never throws; `finalize` decides the stop from the stream's terminal `'close'` state. | diff --git a/docs/memory/device-node/log-capture.md b/docs/memory/device-node/log-capture.md index 7d9ab04..5a455d4 100644 --- a/docs/memory/device-node/log-capture.md +++ b/docs/memory/device-node/log-capture.md @@ -1,6 +1,6 @@ --- type: memory -description: "Per-test device log capture (manager, providers, Device integration) and the write-stream finalization contract: every exit from start/stop ends and flushes the log file's write stream through one shared `LogWriteStreamRegistry`, held per provider instance and keyed on the capture's output file path, so the file the CLI copies next is complete. `open()` attaches a persistent `error` listener that records the first error and never throws, and `finalize` fails the stop on it." +description: "Per-test device log capture (manager, providers, Device integration) and the write-stream finalization contract: every exit from start/stop ends and flushes the log file's write stream through one shared `LogWriteStreamRegistry`, held per provider instance and keyed on the capture's output file path, so the file the CLI copies next is complete. `open()` records the first stream `error` and never throws; `finalize` decides the stop from the stream's terminal `'close'` state." --- # Log Capture (device-node) @@ -26,7 +26,7 @@ The log capture system mirrors RecordingManager/RecordingProvider exactly: - **Three maps**: `_logProcessMap` (ChildProcess), `_logInfoMap` (LogInfo), `_deviceToLogKeysMap` (deviceId to keys). - **Stopped set**: `_stoppedTestCases` Set prevents double-stop. - **Output path**: `/finalrun-logs/{sanitizedRunId}_{sanitizedTestId}.log`. Never writes directly to the report directory — the CLI copies the finished file in and redacts it there ([/cli/report-writer.md](/cli/report-writer.md)). -- **Process stop**: SIGINT + `_waitForExit` (listens for `exit` event via `once`), then `LogWriteStreamRegistry.finalize(outputFilePath, stdout)` — drain `stdout` to EOF, end the write stream, await its flush. Both providers use this pattern, and both finalize on every other exit too (see the finalization requirement below). +- **Process stop**: SIGINT + `_waitForExit` (listens for `exit` event via `once`), then `LogWriteStreamRegistry.finalize(outputFilePath, stdout)` — drain `stdout` to EOF, end the write stream, await its terminal `'close'`. Both providers use this pattern, and both finalize on every other exit too (see the finalization requirement below). - **Write-stream registry**: `LogWriteStreamRegistry` (`src/device/logWriteStream.ts`) is a **per-provider-instance** field (`private readonly _logStreams`), not a module-level singleton, and is keyed on `outputFilePath` — which `LogCaptureManager` derives from the same `(runId, testId)` pair as its own `mapKey`, so the key is that capture's identity. It is not re-exported from the package barrel. - **Provider selection**: Constructor accepts optional providers map; defaults to `PLATFORM_ANDROID -> AndroidLogcatProvider`, `PLATFORM_IOS -> IOSLogProvider`. - **Default instance**: `defaultLogCaptureManager` exported as a singleton. @@ -47,8 +47,8 @@ The log capture system mirrors RecordingManager/RecordingProvider exactly: - Stop failures still finalize state (delete from maps, add to stopped set) to prevent leaks. - File deletion on `keepOutput: false` uses `force: true` and logs warnings on failure. - A write stream's own `error` is handled by the listener `open()` attaches, recorded on the registry - entry, and surfaced by `finalize` — never left to Node's unhandled-`error` throw (see the listener - requirement below). + entry, and reported by `finalize`'s terminal-state decision — never left to Node's + unhandled-`error` throw (see the listener requirement below). ## Requirements @@ -59,15 +59,15 @@ A provider MUST end and flush the log file's write stream on **every** path out pipe **without** ending the destination: anything still buffered is dropped, `finish` never fires, and the file is silently truncated — so detaching alone is never a stop. Finalization happens through `LogWriteStreamRegistry`, which drains the child's `stdout` to EOF (the pipe writes -everything the child produced), ends the write stream, and awaits its flush. +everything the child produced), ends the write stream, and waits for its terminal `'close'`. Two entry points express the difference in how a failure is reported: - **`finalize(outputFilePath, source?)`** throws. It is the success path's call (`AndroidLogcatProvider.stopLogCapture`, `IOSLogProvider.stopLogCapture`): a log that could not be - flushed is a failed stop, because the file is not known to be complete. That holds for an error the - stream emitted long before the stop as much as for one raised by the flush here (see the listener - requirement below). + flushed is a failed stop, because the file is not known to be complete. Which streams that covers + is settled by the stream's terminal state — whether it finished and closed un-errored — not by + whether an `error` event was ever seen (see the terminal-state requirement below). - **`finalizeQuietly(outputFilePath, source?)`** logs and swallows. It is the call on every path that is already returning a failure — a start that threw, a stop whose SIGINT was never delivered (an early return), and each provider's outer `catch` when `_waitForExit` throws. Those paths still @@ -75,11 +75,14 @@ Two entry points express the difference in how a failure is reported: failure being reported. `finalize` is idempotent and cheap on repeat: an untracked path (a capture that never opened a -stream, or one an earlier stop already finalized) returns at once, and an already-finished or -already-destroyed stream skips the flush, which is what lets an error path call it without knowing -whether the success path already did. Untracking and ending run in a `finally`, so a rejecting drain -cannot strand a stream that nothing else holds a handle on. A stream destroyed *by an error* is the -one case that skips the flush and still fails: it rejects with the recorded error (below). +stream, or one an earlier stop already finalized) returns at once, a stream that has already ended +or been destroyed is not ended again, and the terminal-state wait is skipped once `stream.closed` +is true — which is what lets an error path call it without knowing whether the success path already +did. +Untracking and ending run in a `finally`, so a rejecting drain cannot strand a stream that nothing +else holds a handle on, and that rejection keeps precedence over the terminal-state decision after +it. A stream destroyed *by an error* still reaches `'close'`, so it is untracked and ended like any +other and then fails on the decision (below). **Which of the two entry points the success path calls is only observable from outside a provider, so it is pinned there.** A stop over a write stream whose asynchronous `open(2)` failed returns @@ -120,6 +123,58 @@ rather than slept on, and `liveStreamCount` back to zero. - **THEN** the provider's response is `success: false` with a message naming the `ENOENT`, and the registry tracks no stream for that path +### Requirement: The stop's outcome is decided from the stream's terminal state + +`finalize` MUST NOT decide success or failure until the tracked stream has reached its terminal +`'close'` state, and MUST then resolve iff `stream.writableFinished && stream.errored === null`. +`fs.WriteStream` always emits `'close'` (`emitClose` defaults true) — after `end()` → `finish` → +auto-destroy on the clean path, after `destroy(err)` on the failing one — so the wait terminates on +every tracked path, including a stream that already finished or was already destroyed; only an +already-`closed` stream skips it. The wait itself MUST NOT throw: the failure already lives in the +recorded entry error and `stream.errored`, and the decision is what reports it. + +The wait is load-bearing because auto-destroy runs `close(2)` **after** `finish`: a stream can flush +completely and still fail on close (`EIO`), an error that arrives with `writableFinished` already +true. Deciding before it lands makes the outcome depend on which tick won — and the losing side is a +*successful* stop over a file whose durability the OS just refused to confirm, which the CLI then +copies. Waiting for `'close'` first is what makes the outcome a property of the stream's state rather +than of event timing. + +On a stream that finished and closed cleanly, a recorded `entry.error` is stale: that state is +reachable only through a bare non-destroying `stream.emit('error', …)`, since every real fs error +either destroys the stream (`autoDestroy: true`) or arrives at close time and sets `errored`. Such a +stop succeeds, with a guarded warning naming the output file and the stale error — the contract keys +failure to the file not being known complete, and this file *is* complete. Every other terminal state +rejects with `entry.error ?? stream.errored`: the first recorded error ahead of whatever destroyed +the stream, with a synthesized error only for the in-principle-unreachable state where both are null. + +#### Scenario: a close-time error arrives after a clean finish + +- **GIVEN** a stream that emitted `finish` cleanly and then fails its close teardown with an `EIO` +- **WHEN** `finalize` — entered before that error landed — decides +- **THEN** it rejects with the close-time error deterministically, even though `writableFinished` is + true and the flush itself completed + +#### Scenario: a flushed log carries a stale non-destroying error + +- **GIVEN** a stream that recorded a bare `error` event and then wrote, ended and closed cleanly +- **WHEN** `finalize` decides +- **THEN** the stop succeeds, the file on disk holds every byte written, and a warning names the + output file and the stale error + +#### Scenario: the stream was already destroyed and closed + +- **GIVEN** a stream a failed asynchronous `open(2)` already destroyed and closed +- **WHEN** `finalize` runs +- **THEN** the terminal-state wait is skipped and the decision rejects at once with the recorded error + +#### Scenario: the drain rejects before the decision runs + +- **GIVEN** a stop whose drain rejects because the child's `stdout` emitted `error` +- **WHEN** `finalize` runs +- **THEN** the stream is still ended, closed and untracked, and the rejection carries the drain error + rather than a redundant one + ### Requirement: The drain wait is bounded, and its timeout degrades to a truncated log Waiting for a stopped capture's `stdout` to reach EOF MUST be bounded — `LOG_DRAIN_TIMEOUT_MS`, @@ -152,15 +207,16 @@ itself. **The first error is recorded, not merely logged, and a later one MUST NOT overwrite it** — a second event is fallout on an already-destroyed stream, while the first is what explains the failure. -Recording is what makes the failure outlive the event: `_endAndFlush` early-returns on a -`writableFinished`/`destroyed` stream and an errored stream auto-destroys, so without the record -`finalize` would skip the flush, find nothing to report, and resolve — **a successful stop over a log -file that was never written**. `finalize` MUST fail the stop on a recorded error, and MUST do so -**after** its existing `try`/`finally`: a drain rejection or a flush error is already the failure -being reported and keeps precedence, so nothing is masked by a redundant one. +Recording is what makes that first error outlive the event carrying it: `stream.errored` holds only +the error that *destroyed* the stream, so on a stream that failed twice it names the fallout rather +than the cause. The record is therefore what `finalize`'s rejection prefers ahead of +`stream.errored`, and on the one flushed-cleanly state a stale record survives into, it is what the +warning names. That decision MUST run **after** `finalize`'s `try`/`finally` and after the terminal +`'close'` (see the terminal-state requirement above): a drain rejection or a flush error is already +the failure being reported and keeps precedence, so nothing is masked by a redundant one. **The listener MUST NOT throw.** It is the listener of last resort, so its `Logger.e` call is guarded, -and `finalizeQuietly`'s own `Logger.e` is guarded for the same reason: `finalize`'s re-throw of a +and `finalizeQuietly`'s own `Logger.e` is guarded for the same reason: `finalize`'s rejection with a recorded error is what makes that `catch` reachable on the very failure the guard exists for, and `finalizeQuietly` MUST resolve for callers that are already returning a failure. The reason is `Logger.e`'s **independent** fallibility: `Logger._emit`'s sink @@ -187,13 +243,15 @@ stake. - **GIVEN** an output path inside a directory that does not exist - **WHEN** the stream emits `error` - **THEN** the error is recorded on the entry and logged, no uncaught exception is raised, and the - subsequent `finalize` rejects with it even though the flush was skipped + subsequent `finalize` rejects with it — the stream never finished, so the file is not known to be + complete -#### Scenario: a stream errors twice +#### Scenario: a stream errors twice on its way to being destroyed -- **GIVEN** a stream that emits `error` and then emits a second, different `error` +- **GIVEN** a stream that emits `error`, then a second different `error`, and is then destroyed by a + third - **WHEN** `finalize` runs -- **THEN** it rejects with the **first** error +- **THEN** it rejects with the **first** error, ahead of the one `stream.errored` carries #### Scenario: the logger sink fails alongside the stream @@ -249,28 +307,28 @@ reader re-derives "detaching is enough" from a pipe that visibly works. *Introduced by*: 260730-zga4-drivers-ci-gate-audit-defects -### A recorded error fails the stop after `finalize`'s `try`/`finally`, never inside it +### The stop's outcome is decided after `finalize`'s `try`/`finally`, never inside it **Decision**: The `error` listener records the first error on the registry entry, and `finalize` -re-throws it only once its existing `try`/`finally` has completed without throwing. Recording is +decides the stop only once its `try`/`finally` has completed without throwing. Recording is required; logging alone is not. **Why**: A drain rejection and a recorded write error both mean "the log is not known to be -complete", so either satisfies the "a write error rejects" contract — but re-throwing *after* the +complete", so either satisfies the "a write error fails the stop" contract — but deciding *after* the `finally` gets precedence right for free and cannot replace an in-flight failure with a redundant -one. The recording half is what closes the second face of the same defect: an errored stream -auto-destroys, `_endAndFlush` early-returns on a destroyed stream, and a log-only listener would -leave `finalize` with nothing to observe, resolving over an unwritten file. Both faces — a crash -before finalization and a silently successful stop after it — come from the same missing listener, -so both are closed at `open()`. +one. The recording half is what makes the rejection name the *cause*: `stream.errored` carries only +whatever destroyed the stream, which on a stream that failed twice is the fallout. It also closes the +half nothing in a run's output would reveal — an `error` event with no listener at all crashes the +CLI, and one that is logged and forgotten leaves the stop with no first error to prefer. **Rejected**: (a) throwing inside the `finally` — masks a drain rejection with a redundant error; -(b) logging the error without recording it — leaves the silently successful stop in place, which is -the half nothing in a run's output would reveal; (c) attaching the listener in each provider — the +(b) logging the error without recording it — the rejection then carries whichever error destroyed the +stream instead of the one that explains the failure; (c) attaching the listener in each provider — the two versions would diff empty modulo a log prefix (the case the mirror rule says to share), and the registry already owns this bookkeeping; (d) observing the error only through `await finished(stream)` -inside `_endAndFlush` — that listener does not exist until the stop runs and is skipped on exactly -the destroyed stream an error produces. +inside the finalization path — that listener does not exist until the stop runs, so an error emitted +earlier is still unhandled, and a rejecting wait would throw from the very path whose job is to end, +untrack and then *report* the failure. *Introduced by*: 260730-eyvt-ci-cost-guards-carried-defects @@ -284,8 +342,9 @@ the same way. Nothing else in the listener can throw. `uncaughtException` cannot itself be a source of one. `Logger.e` is fallible on its own schedule — an unguarded sink loop reaching an unguarded `fs.appendFileSync` — so an unguarded log call there converts the failure being handled into the failure being prevented, on a tick Node runs with no -enclosing `try`. Recording before logging is what makes swallowing the log line free: the stop still -fails, and only a diagnostic line is lost. This is **not** the shape rejected in +enclosing `try`. Recording before logging is what makes swallowing the log line free: the record is +already in place for `finalize`'s decision to report, so only a diagnostic line is lost. This is +**not** the shape rejected in [/cli/session-runner.md](/cli/session-runner.md): that rejection is scoped to the acquisition-ordering problem, where two statements can be reordered and a local catch would patch one call site while the next inserted statement stays lethal. Here there is nothing to reorder. @@ -300,33 +359,58 @@ distinction between a stop that failed and a path already reporting a failure. *Introduced by*: 260730-eyvt-ci-cost-guards-carried-defects -### The recorded-error rejection is unconditional, with no `writableFinished` guard - -**Decision**: `finalize` re-throws `entry.error` whenever one was recorded, without consulting -`stream.writableFinished`. A stop whose flush completed cleanly still fails if the stream ever -emitted `error`, and nothing clears the record once `_endAndFlush` resolves. - -**Why**: An `error` event means the file is **not known to be complete** — the invariant the callers -actually depend on, since the CLI copies the file immediately after the stop resolves. Rejecting on -any recorded error errs toward a false failure of a diagnostic artifact; a guard errs toward a false -success over a possibly-corrupt file, which is the exact shape of the defect the `open()` listener -exists to close. The reachability argument only runs one way, and it cuts the same direction: in the -**error-then-flush** order a guard would change nothing observable with real errors, because -`fs.WriteStream` has `autoDestroy: true` — every genuine failure (`ENOENT` on open, `ENOSPC` on -write) destroys the stream, so `writableFinished` cannot go true afterwards, and only a bare -`stream.emit('error', …)` reaches that state (which is how the existing pinning test constructs it, -two real failures not being deterministically orderable). The **flush-then-error** order *is* -reachable: a close-time error — an `EIO` from the `close(2)` auto-destroy performs after `finish` — -can be recorded while `writableFinished` is already true, and a guard would silently drop precisely -that error. So the guard is either inert or harmful. - -**Rejected**: (a) guarding the re-throw on `writableFinished` — drops close-time errors, and flips -the outcome of the existing test that pins first-error-wins *and* the rejection together; (b) -clearing `entry.error` once the flush resolves — the same silent drop by another route; (c) relying on -the surrounding doc prose alone — it covers an error recorded "long before this call" but not the -flush-succeeded case, which is the one a reader would otherwise take for a bug. - -*Introduced by*: 260731-cjx8-provider-log-stop-test-coverage +### The stop succeeds iff the stream finished and closed un-errored, decided after the terminal `'close'` + +**Decision**: `finalize` awaits the tracked stream's terminal `'close'` on every path — a plain, +never-rejecting listener, skipped only when `stream.closed` is already true — and then resolves iff +`stream.writableFinished && stream.errored === null`. A stale recorded error in that state is warned +about and the stop still succeeds; every other terminal state rejects with +`entry.error ?? stream.errored`. + +**Why**: Deciding from error *history* — whether an error was ever recorded, read at whatever moment +the `finally` completes — is wrong in two directions from one root cause. It fails a log that was +flushed completely whenever a stale non-destroying record survives, contradicting this file's own +contract: that contract keys failure to the file not being known complete, and a stream that finished +and closed cleanly IS known complete. And it sees a close-time `EIO` (from the `close(2)` auto-destroy +performs after `finish`) only when that error happens to land before the read — a timing dependence +whose losing side reports success over a file whose durability the OS just refused to confirm, which +the CLI then copies. That is the data-integrity face, and it is why the wait comes first: with the +terminal state settled, the predicate can key on what the contract cares about. The wait runs even on +an already-finished or already-destroyed stream, because skipping it there is exactly where the +close-time window opens. Two independent reviewers converged on this reading: an operator-side +adversarial review rated it should-fix, and CodeRabbit rated the same `finalize` check MAJOR under +data integrity on PR #173, asking for the terminal-state wait and a regression test by name. + +**Rejected**: (a) a bare `writableFinished` guard on the rejection — fixes only the stale-record face +and makes the other unconditional, since a close-time error is recorded *with* `writableFinished` +true, so the guard drops precisely the error that matters most; (b) unconditional rejection on any +recorded error — contradicts the flushed-log contract and leaves close-time observation racy, because +nothing waits for the error to arrive; (c) clearing `entry.error` once the flush resolves — the same +silent drop of close-time errors by another route; (d) `finished(stream)` or +`events.once(stream, 'close')` as the wait primitive — both reject when the stream errors while +waiting, and the wait must never throw: the failure already lives in the record and `stream.errored`, +and the decision is what reports it. + +*Introduced by*: 260731-vojm-log-finalize-terminal-state + +### The close-time failure is forced through the write stream's `_destroy` teardown seam + +**Decision**: The test pinning deterministic close-time rejection overrides the tracked stream's +`_destroy` to run the real teardown and then hand its callback an `EIO`-shaped error, writes, `end()`s +and awaits `finish`, and only then calls `finalize`. + +**Why**: A real `close(2)` failure cannot be provoked on a healthy fd, and the shape being pinned is +specific — `finish` first, error at close, `stream.errored` set while `writableFinished` is true. +`_destroy` is the documented `Writable` customization seam for exactly that teardown step, so the +test reproduces the production sequence instead of approximating it, and the fd is still really +closed. + +**Rejected**: (a) `stream.destroy(err)` after `finish` — races auto-destroy's own `destroy()` call, so +it pins the window nondeterministically or not at all; (b) timing the error with a sleep — flaky by +construction, the shape this suite avoids everywhere else (its stream errors are awaited as events, +never slept on). + +*Introduced by*: 260731-vojm-log-finalize-terminal-state ### The recorded error is consumed by the first finalization, and call ordering is documented rather than enforced @@ -339,21 +423,26 @@ required ordering (`finalize` before any `finalizeQuietly` for the same path) is **Why**: What upholds the ordering lives outside the registry, which is exactly why a comment is the right carrier — a reader of `finalizeQuietly` cannot recover it from the code in front of them. Both providers' `stopLogCapture` run the loud call on the success path before any quiet catch-path call, -and every quiet-first path (a start that threw, a stop whose SIGINT was never delivered) returns a -failure on its own, so no success is ever reported over a swallowed error. The one remaining sequence -that could reach quiet-then-loud is a second stop for the same capture, which -`LogCaptureManager`'s `_stoppedTestCases` set covers **sequentially only**: the `has()` early-return -and the `add()` inside `_finalizeStoppedLogCapture` straddle the awaited -`provider.stopLogCapture(…)`, so overlapping stop/abort calls for one `(runId, testId)` are a -check-then-act race the set does not close. Enforcing the invariant inside the registry costs more -than the hazard: an errored entry kept as a tombstone is a leak, and the registry is a per-provider -instance precisely so entries are collected with their owner. +and every quiet-first path (a start that threw, a stop whose SIGINT was never delivered, a provider's +outer `catch` when `_waitForExit` throws) returns a failure response on its own, so no success is ever +reported over a swallowed error. **That invariant — not the swallow — is what makes the hazard safe, +and it is pinned on both platforms**: a capture over an unopenable path (recorded `ENOENT`) whose +stop's SIGINT is never delivered answers `success: false` naming the SIGINT failure, with +`liveStreamCount` back to zero. The one remaining sequence that could reach quiet-then-loud is a +second stop for the same capture, which `LogCaptureManager`'s `_stoppedTestCases` set covers +**sequentially only**: the `has()` early-return and the `add()` inside +`_finalizeStoppedLogCapture` straddle the awaited `provider.stopLogCapture(…)`, so overlapping +stop/abort calls for one `(runId, testId)` are a check-then-act race the set does not close — an +accepted, documented hazard. Enforcing the invariant inside the registry costs more than the hazard: +an errored entry kept as a tombstone is a leak, and the registry is a per-provider instance precisely +so entries are collected with their owner. **Rejected**: (a) tombstoning errored entries so a later `finalize` still observes the error — reintroduces the unbounded growth the per-instance registry design rejects; (b) making `finalizeQuietly` preserve the entry — breaks its "end the stream and drop its entry" contract, which -is what every already-failing path calls it for; (c) a test pinning today's second-stop-over-a-failed- +is what every already-failing path calls it for; (c) a test pinning the second-stop-over-a-failed- stream success — cements an accident as a contract, which is worse than an accepted, documented -hazard. +hazard, so the quiet-first tests stop at the failure response and assert nothing about a later +`finalize` for the same path. *Introduced by*: 260731-cjx8-provider-log-stop-test-coverage diff --git a/fab/changes/260731-vojm-log-finalize-terminal-state/.history.jsonl b/fab/changes/260731-vojm-log-finalize-terminal-state/.history.jsonl new file mode 100644 index 0000000..d16c0fb --- /dev/null +++ b/fab/changes/260731-vojm-log-finalize-terminal-state/.history.jsonl @@ -0,0 +1,12 @@ +{"action":"enter","driver":"fab-new","event":"stage-transition","stage":"intake","ts":"2026-07-31T17:56:32Z"} +{"args":"Fix stream-error reporting defect: finalize rejects unconditionally on recorded entry.error even when the log was fully flushed (writableFinished true); await terminal close/error state, update pinning test per Test Integrity, decide finalizeQuietly-before-finalize consumption behavior","cmd":"fab-new","event":"command","ts":"2026-07-31T17:56:32Z"} +{"delta":"+4.6","event":"confidence","score":4.6,"trigger":"calc-score","ts":"2026-07-31T17:58:43Z"} +{"delta":"+0.0","event":"confidence","score":4.6,"trigger":"calc-score","ts":"2026-07-31T18:00:32Z"} +{"cmd":"fab-fff","event":"command","ts":"2026-07-31T18:01:08Z"} +{"action":"enter","driver":"fab-fff","event":"stage-transition","stage":"apply","ts":"2026-07-31T18:01:13Z"} +{"action":"enter","driver":"fab-fff","event":"stage-transition","stage":"review","ts":"2026-07-31T18:14:48Z"} +{"action":"enter","driver":"fab-fff","event":"stage-transition","stage":"hydrate","ts":"2026-07-31T18:36:00Z"} +{"event":"review","result":"passed","ts":"2026-07-31T18:36:00Z"} +{"action":"enter","driver":"fab-fff","event":"stage-transition","stage":"ship","ts":"2026-07-31T18:44:54Z"} +{"action":"enter","driver":"git-pr","event":"stage-transition","stage":"review-pr","ts":"2026-07-31T18:48:51Z"} +{"event":"review","result":"passed","ts":"2026-07-31T19:06:49Z"} diff --git a/fab/changes/260731-vojm-log-finalize-terminal-state/.status.yaml b/fab/changes/260731-vojm-log-finalize-terminal-state/.status.yaml new file mode 100644 index 0000000..efbd99b --- /dev/null +++ b/fab/changes/260731-vojm-log-finalize-terminal-state/.status.yaml @@ -0,0 +1,53 @@ +id: vojm +name: 260731-vojm-log-finalize-terminal-state +created: 2026-07-31T17:56:32Z +created_by: ashish-noon +change_type: fix +issues: [] +progress: + intake: done + apply: done + review: done + hydrate: done + ship: done + review-pr: done +plan: + generated: true + task_count: 9 + acceptance_count: 14 + acceptance_completed: 14 +confidence: + certain: 2 + confident: 3 + tentative: 0 + unresolved: 0 + score: 4.6 + fuzzy: true + dimensions: + signal: 80.0 + reversibility: 68.0 + competence: 83.0 + disambiguation: 77.0 +stage_metrics: + intake: {started_at: "2026-07-31T17:56:32Z", driver: fab-new, iterations: 1, completed_at: "2026-07-31T18:01:13Z"} + apply: {started_at: "2026-07-31T18:01:13Z", driver: fab-fff, iterations: 1, completed_at: "2026-07-31T18:14:48Z"} + review: {started_at: "2026-07-31T18:14:48Z", driver: fab-fff, iterations: 1, completed_at: "2026-07-31T18:36:00Z"} + hydrate: {started_at: "2026-07-31T18:36:00Z", driver: fab-fff, iterations: 1, completed_at: "2026-07-31T18:44:54Z"} + ship: {started_at: "2026-07-31T18:44:54Z", driver: fab-fff, iterations: 1, completed_at: "2026-07-31T18:48:51Z"} + review-pr: {started_at: "2026-07-31T18:48:51Z", driver: git-pr, iterations: 1, completed_at: "2026-07-31T19:06:49Z"} +prs: + - https://github.com/droid-ash/finalrun-agent/pull/177 +change_type_source: explicit +true_impact: + added: 749 + deleted: 142 + net: 607 + tests: + added: 116 + deleted: 8 + net: 108 + computed_at: "2026-07-31T18:48:51Z" + computed_at_stage: ship +summary: Log-stop finalization now decides from the write stream's terminal 'close' state — success iff writableFinished with no stream.errored, warn-and-resolve over a stale non-destroying record, deterministic rejection on a close-time error — superseding the unconditional recorded-error rejection, with registry and both-platform provider tests pinning the new outcomes and the quiet-first failure-response invariant. +# true_impact: lazily created on first stage-finish that computes it (no placeholder here). +last_updated: 2026-07-31T19:06:49Z diff --git a/fab/changes/260731-vojm-log-finalize-terminal-state/intake.md b/fab/changes/260731-vojm-log-finalize-terminal-state/intake.md new file mode 100644 index 0000000..646a40a --- /dev/null +++ b/fab/changes/260731-vojm-log-finalize-terminal-state/intake.md @@ -0,0 +1,118 @@ +# Intake: Log Finalize Awaits Terminal Stream State + +**Change**: 260731-vojm-log-finalize-terminal-state +**Created**: 2026-07-31 + +## Origin + +One-shot `/fab-new` invocation. The user's raw input, abridged to its operative content — this quote is the fullest surviving record; `.history.jsonl` retains only a condensed one-line summary of the command arguments (via `--log-args`): + +> Fix a stream-error reporting defect that two independent reviewers flagged and PR #173 deliberately only documented. In `packages/device-node/src/device/logWriteStream.ts`, `entry.error` is never cleared once set, so `finalize` rejects UNCONDITIONALLY — including when the log was flushed completely and `stream.writableFinished` is true. That contradicts the contract written in the same file, which says a log that could not be flushed is a failed stop; here it WAS flushed. Why this is being reopened: an operator-side adversarial review raised it as should-fix; PR #173 chose to document the behaviour and add provider-level failure coverage instead of changing it; CodeRabbit then reviewed #173 and independently rated the same issue at lines 140 and 202 as MAJOR severity under data integrity. Two independent reviewers converging is why it is now being fixed. COMPLICATION: an existing test in `logCaptureProviders.test.ts` currently PINS the inconsistent behaviour — it emits a non-destroying error directly then expects finalize to reject even though the flush succeeds. Per the constitution Test Integrity rule, tests conform to the spec rather than the reverse — updating that test is legitimate if a fully-flushed log is a successful stop; weakening a test merely to make the change pass is not. State plainly which you are doing and why. Read CodeRabbit's reasoning on PR #173 first: it notes the unconditional check rejects a close-time error when the listener records it before finalize completes, and that waiting for the terminal stream state is the alternative — so decide whether a `writableFinished` guard suffices or whether you must await the terminal state properly. ALSO decide with reasons, do not fix blindly: the recorded error is consumed once because finalize deletes the entry in its finally, so `finalizeQuietly` before `finalize` silently discards it — currently safe only by accident of provider call ordering, and untested. Add tests pinning whatever behaviour you land on and verify device-node plus the repo-wide suite stay green. Do NOT commit `fab/backlog.md`. + +Key intake-time findings (CodeRabbit's PR #173 review was read in full before this intake was written): + +- **CodeRabbit finding 1** (MAJOR, Data Integrity, anchored at `logWriteStream.ts:136-140`): "`fs.WriteStream` sets `writableFinished` and then starts asynchronous auto-destroy. A close callback can report `EIO` after `finalize` skips `_endAndFlush`; the final `entry.error` check can therefore resolve successfully before the listener records the error. Wait for the terminal close/error state on the `writableFinished` path, add a regression test, and update the decision in `docs/memory/device-node/log-capture.md`." So the defect is **two-faced and timing-dependent**: a close-time error recorded *before* the check rejects a fully-flushed log (the contract contradiction the user quotes), and one recorded *after* the check is silently missed (success over a non-durable file). A bare `writableFinished` guard fixes only the first face and makes the second face unconditional — it is not sufficient. +- **CodeRabbit finding 2** (concurrent-stop serialization at `LogCaptureManager`) was **withdrawn by CodeRabbit itself** after verification: "The memory document explicitly accepts the overlapping-stop check-then-act race... I also verified both providers. Each current quiet-first path returns `success: false`. A swallowed recorded error does not produce a successful stop response in these paths." +- The pinning test the user cites now sits at `logCaptureProviders.test.ts:370-386` (`'LogWriteStreamRegistry records only the first error a stream emits'`) — line numbers drifted since the user's reading. It emits two bare non-destroying `stream.emit('error', …)` calls, lets the flush succeed, and asserts `finalize` rejects with the first error — pinning first-error-wins *and* the unconditional rejection in one test. +- The memory DD "The recorded-error rejection is unconditional, with no `writableFinished` guard" (`docs/memory/device-node/log-capture.md`, introduced by PR #173 / change `cjx8`) itself concedes both halves of the argument this change relies on: real errors auto-destroy the stream (so flushed-but-errored is reachable in production only via a close-time error), and a close-time error is recorded with `writableFinished` already true (so a guard drops it). What that DD did not resolve is the race CodeRabbit identified: today the close-time error is observed only if it lands before `finalize`'s check. + +## Why + +1. **The pain point**: `LogWriteStreamRegistry.finalize` decides success/failure by reading `entry.error` at whatever moment its `finally` completes, instead of after the stream's terminal state. That produces two wrong outcomes from one root cause: (a) a log that flushed completely (`writableFinished === true`) with a stale non-destroying error recorded is reported as a *failed* stop, contradicting the file's own contract ("a log that could not be flushed is a failed stop" — this one *was* flushed); (b) a close-time error (`EIO` from the `close(2)` that auto-destroy performs after `finish`) arriving *after* the check is silently missed — a *successful* stop over a file whose durability the OS just refused to confirm. Face (b) is the data-integrity defect: the CLI copies the log file immediately after the stop resolves. +2. **If not fixed**: stop success/failure for close-time errors stays a race, and the pinned contradiction stays cemented in a test, misleading the next reader into treating either behaviour as designed. Two independent reviewers (operator-side adversarial review: should-fix; CodeRabbit: MAJOR / data integrity) converged on this after PR #173 explicitly deferred it — the deferral decision has been overtaken. +3. **Why this approach**: awaiting the stream's terminal close/error state before deciding removes the race entirely, at which point the success predicate can be made state-based (did the stream finish and close cleanly?) rather than history-based (was an error ever recorded?). A bare `writableFinished` guard was considered and rejected — see Assumptions #1. + +## What Changes + +### 1. `finalize` awaits the terminal stream state before deciding (`packages/device-node/src/device/logWriteStream.ts`) + +`_endAndFlush` currently early-returns on `stream.writableFinished || stream.destroyed`, which is exactly where the close-time window opens (auto-destroy's `close(2)` runs after `finish`). The fix: after the existing drain/end sequence in `finalize`'s `try`/`finally`, wait until the stream has emitted `'close'` (fs.WriteStream always emits it — `emitClose` defaults true — after either `end()` → `finish` → auto-destroy, or `destroy(err)`), so every error the stream will ever deliver has been recorded before the decision runs. + +Implementation guidance (apply may refine mechanics, not semantics): + +- A state-based wait is the cleaner primitive: `if (!stream.closed) await once(stream, 'close')` (or equivalent). `finished(stream)` from `node:stream/promises` is awkward here — it *rejects* on an errored stream and has premature-close edge cases on already-destroyed streams; the recorded `entry.error` / `stream.errored` already carry the failure, so the wait itself should never throw. +- The wait belongs on every finalize path that reaches a tracked stream (not only the `writableFinished` one) — after `'close'`, terminal state is fully settled for all cases. +- Precedence is preserved: a drain rejection thrown from the `try` still wins (the `finally` still untracks, ends, and now awaits close); the recorded-error decision still runs only when nothing above threw. +- The drain-timeout degradation is untouched: unpipe → end → await close → (no recorded error) → resolve with a possibly-truncated log. Bounding is unchanged; awaiting `'close'` on an ended stream cannot hang. + +### 2. New success/failure semantics — state-based, not history-based + +After terminal state, `finalize`: + +- **Resolves** iff `stream.writableFinished && stream.errored === null` — the stream finished (all data handed to the fd) *and* was not destroyed by any error, including a close-time one. If `entry.error` is set in this state (reachable only via a bare non-destroying `emit('error')` — every real fs error either destroys the stream or is a close-time error, which sets `stream.errored`), log a warning naming the file and the stale error, and resolve: the flush and close both completed cleanly, so the file *is* known to be complete — this is the contract ("a log that could not be flushed is a failed stop") applied literally. +- **Rejects** otherwise, with `entry.error ?? stream.errored` (first-recorded error wins, exactly as today; `stream.errored` is the fallback for a defensive premature-destroy with nothing recorded — apply may synthesize a generic error if both are somehow null in that unreachable state). + +Outcome matrix (all after the terminal-state wait, so all deterministic): + +| Scenario | `writableFinished` | `stream.errored` | `entry.error` | Outcome | +|---|---|---|---|---| +| Clean flush, clean close | true | null | unset | resolve (today: resolve) | +| Open fails (ENOENT) / write fails (ENOSPC) | false | set | set | reject with first error (today: reject) | +| Close-time error (EIO after finish) | true | set | set | **reject — now deterministic** (today: race — reject or silent success by timing) | +| Bare non-destroying `emit('error')`, clean flush+close | true | null | set | **resolve + warning log** (today: reject — the contract contradiction) | +| Drain timeout, stream ends clean | true | null | unset | resolve, possibly-truncated log (today: same) | + +The large doc comments on `finalize` and `_endAndFlush` that currently *argue for* the unconditional rejection (the "a guard on `writableFinished` here would silently drop exactly that error" paragraph and the `_endAndFlush` "destroyed early return" paragraph) must be rewritten to state the new guarantee: the decision runs after the terminal close/error state, so close-time errors are always observed and a cleanly-finished-and-closed stream is a successful stop. + +### 3. Test updates (Test Integrity rule — stated plainly) + +**This change updates the pinning test to match the spec; it does not weaken a test to make the change pass.** The spec (the contract in `logWriteStream.ts` itself, and the memory Requirement "a log that could not be flushed is a failed stop... because the file is not known to be complete") keys failure to *the file not being known complete*. After the terminal-state wait, a stream that finished and closed cleanly is known complete — rejecting it contradicts the spec, and the constitution's Test Integrity rule directs updating the test to the spec. The rejection previously pinned there is not lost as coverage: it is *re-pinned deterministically* on the close-time-error scenario, which is the only production-reachable flushed-then-errored shape. + +Concretely, in `packages/device-node/src/device/test/logCaptureProviders.test.ts`: + +- **Rework** `'LogWriteStreamRegistry records only the first error a stream emits'` (currently ~line 370): first-error-wins must stay pinned, but on a *genuinely failing* stream — e.g. emit two errors and destroy the stream (or use two bare emits followed by `stream.destroy(firstError)`), then assert `finalize` rejects with the **first**. Its current secondary assertion (rejection despite a clean flush) moves to the two new tests below. +- **New test — flushed-cleanly resolves over a stale non-destroying error**: bare `emit('error')`, clean write, `finalize` resolves, file content intact, stream untracked. This pins face (a) of the fix. +- **New test — close-time error rejects deterministically** (CodeRabbit's requested regression test): drive a stream to `finish` cleanly, then deliver a destroying error at close time (e.g. force the auto-destroy `close(2)` to fail by stubbing/subclassing, or `stream.destroy(err)` after `finish` — apply picks the most faithful deterministic construction), and assert `finalize` — started *before* the error lands — rejects with it. This pins face (b) and the race closure. +- **Provider-level quiet-first pinning tests** (both platforms, parameterized like the existing block): see §4. +- All existing registry-level and provider-level tests are re-run; any other test asserting the old unconditional rejection is updated on the same spec-conformance ground (state which in the PR). + +### 4. `finalizeQuietly`-before-`finalize` consumption — decided: keep once-consumed semantics, pin the safety invariant with tests + +Decision (with reasons, per the user's instruction not to fix blindly): **keep** the registry's once-consumed error (entry deleted in `finalize`'s `finally`) and the documented-not-enforced ordering. Rationale: + +- CodeRabbit raised serialization and then **withdrew it** after verifying every quiet-first provider path (`startLogCapture` catch, kill-returns-false early return, `_waitForExit` outer catch) already returns `success: false` on its own — no success is ever reported over a swallowed error in sequential flows. +- The memory DD's rejections stand unchanged: tombstoning errored entries reintroduces unbounded growth the per-instance registry exists to avoid; making `finalizeQuietly` preserve entries breaks its "end the stream and drop its entry" contract for every already-failing caller. +- The overlapping stop/abort check-then-act race in `LogCaptureManager` remains an accepted, documented hazard — out of scope here, as it was for #173 and for CodeRabbit's withdrawal. + +What changes is the **"untested" half**: add provider-level tests (both platforms) pinning the invariant that makes the hazard safe — a quiet-first path over a stream with a recorded error returns a *failure* response by itself (e.g. `kill()` returning false → early failure return, over an errored stream: assert `success: false` and zero live streams). This pins the safety invariant, **not** the accident — the memory DD's rejection of "a test pinning today's second-stop-over-a-failed-stream success" is about cementing the swallow-then-resolve sequence as a contract, which these tests deliberately do not touch. + +### 5. Memory + comment updates (hydrate stage) + +- `docs/memory/device-node/log-capture.md`: the DD "The recorded-error rejection is unconditional, with no `writableFinished` guard" is **superseded** — rewritten to record the terminal-state-wait decision, the state-based success predicate, why the bare guard was rejected (drops close-time errors), and why unconditional rejection was rejected (contradicts the flushed-log contract *and* leaves close-time observation racy). The "consumed by the first finalization" DD gets its "untested" clause corrected (now pinned by provider-level tests). The Requirements section's listener/finalize scenarios are updated to the new outcomes (notably the "stream errors twice" scenario and the description-frontmatter's "finalize fails the stop on it" phrasing). +- `logWriteStream.ts` doc comments per §2. +- `LogWriteStreamRegistry.open`'s listener comment ("the record — the thing `finalize` reads to fail the stop") stays accurate but is adjusted to the new decision rule. + +### Non-goals + +- No change to the `finalize`/`finalizeQuietly` split or to any provider call site ordering. +- No serialization/single-flight guard in `LogCaptureManager` (withdrawn finding; accepted hazard stands). +- No change to drain-timeout bounding or its truncated-log degradation. +- `fab/backlog.md` MUST NOT be committed (explicit user instruction). + +## Affected Memory + +- `device-node/log-capture`: (modify) supersede the "unconditional recorded-error rejection" Design Decision with the terminal-state-wait decision and state-based success predicate; correct the "consumed by the first finalization" DD's untested-hazard clause (invariant now test-pinned); update the affected Requirement scenarios and the frontmatter description's finalize phrasing. + +## Impact + +- **Source**: `packages/device-node/src/device/logWriteStream.ts` (only source file with behavior change — `finalize`/`_endAndFlush` and their doc comments). +- **Tests**: `packages/device-node/src/device/test/logCaptureProviders.test.ts` (one reworked test, ~4 new tests across registry + both-platform provider blocks). Existing provider stop tests must stay green — their scenarios (ENOENT open error → `success: false`) are destroying errors, unaffected by the new predicate. +- **Docs**: `docs/memory/device-node/log-capture.md`. +- **Verification**: device-node package suite, then the repo-wide suite (build/typecheck/test per the CI gate), both green. +- **External context**: CodeRabbit holds a learning on PR #173 stating the unconditional re-throw is deliberate; the PR for this change should state explicitly that it supersedes that decision (two-reviewer convergence), so future bot reviews don't flag the fix as contradicting the learning. + +## Open Questions + +None — the input is highly directive, delegates the two open design decisions explicitly ("decide with reasons"), and both are resolved above with rationale (Assumptions #1–#4). + +## Assumptions + +| # | Grade | Decision | Rationale | Scores | +|---|-------|----------|-----------|--------| +| 1 | Confident | Await the terminal close/error state, not a bare `writableFinished` guard | User poses exactly this fork; CodeRabbit recommends the wait; the #173 memory DD itself proves the bare guard drops close-time errors, and the guard leaves the close-time race unfixed — the guard is strictly worse on both faces | S:85 R:55 A:90 D:85 | +| 2 | Confident | Success predicate: resolve iff `writableFinished && stream.errored === null`; stale non-destroying recorded error → warn + resolve; otherwise reject with `entry.error ?? stream.errored` | Applies the file's own contract literally (flushed+closed = known complete); keeps close-time errors failing deterministically; first-error-wins preserved; only reachable resolve-over-recorded-error path is a test-artifact bare emit | S:80 R:50 A:80 D:75 | +| 3 | Certain | Rework the pinning test to the spec (first-error-wins re-pinned on a genuinely failing stream; rejection re-pinned on close-time error) — spec-conformance under the constitution's Test Integrity rule, not test-weakening | Constitution explicitly permits updating tests to match spec; coverage is moved, not dropped — the rejection assertion survives in a deterministic, production-reachable form | S:90 R:70 A:85 D:80 | +| 4 | Confident | Keep once-consumed `finalizeQuietly` semantics and the documented ordering hazard; add provider-level tests pinning that quiet-first paths return failure responses | CodeRabbit withdrew its serialization finding after verifying the invariant; memory DD rejections (tombstone, preserve-entry) stand; the user's "untested" complaint is answered by pinning the safety invariant, not the accident | S:70 R:75 A:70 D:60 | +| 5 | Certain | The user-cited test "lines 304–320" is the first-error-wins test now at lines 370–386 | Only test matching the description (bare non-destroying emit + reject despite successful flush); line drift explained by #173 having appended tests | S:75 R:90 A:90 D:85 | + +5 assumptions (2 certain, 3 confident, 0 tentative, 0 unresolved). diff --git a/fab/changes/260731-vojm-log-finalize-terminal-state/plan.md b/fab/changes/260731-vojm-log-finalize-terminal-state/plan.md new file mode 100644 index 0000000..52c0fa7 --- /dev/null +++ b/fab/changes/260731-vojm-log-finalize-terminal-state/plan.md @@ -0,0 +1,193 @@ +# Plan: Log Finalize Awaits Terminal Stream State + +**Change**: 260731-vojm-log-finalize-terminal-state +**Intake**: `intake.md` + +## Requirements + +### device-node: Write-stream finalization decides from terminal state + +#### R1: `finalize` awaits the stream's terminal `'close'` state before deciding +`LogWriteStreamRegistry.finalize` MUST NOT decide success or failure until the tracked stream has reached its terminal `'close'` state, on **every** finalize path that reaches a tracked stream (`fs.WriteStream` always emits `'close'` — `emitClose` defaults true — after `end()` → `finish` → auto-destroy, and after `destroy(err)`). The wait MUST be state-based and MUST NOT itself throw (e.g. skip when `stream.closed`, else await a plain `'close'` listener): the failure already lives in `entry.error` / `stream.errored`, and the decision is what reports it. Untracked paths keep their immediate return. + +- **GIVEN** a tracked stream that has emitted `finish` but whose auto-destroy `close(2)` has not yet completed +- **WHEN** `finalize` runs +- **THEN** it waits for `'close'` before reading any error state, so a close-time error is always observed — never missed by timing + +- **GIVEN** a tracked stream already destroyed and closed (e.g. a failed asynchronous `open(2)`) +- **WHEN** `finalize` runs +- **THEN** the wait is skipped (`stream.closed` already true) and the decision runs immediately + +#### R2: Success is state-based — resolve iff finished and un-errored, else reject with the first error +After terminal state, `finalize` MUST resolve iff `stream.writableFinished && stream.errored === null`. In that state, if a stale `entry.error` is recorded (reachable only via a bare non-destroying `emit('error')` — every real fs error either destroys the stream or is a close-time error, which sets `stream.errored`), `finalize` MUST log a warning naming the file and the stale error and still resolve. Otherwise it MUST reject with `entry.error ?? stream.errored` (first-recorded error wins; `stream.errored` is the fallback for a destroy with nothing recorded), synthesizing a generic error only in the in-principle-unreachable state where both are null. The normative outcome matrix is the intake's §2 table. + +- **GIVEN** a stream that flushed and closed cleanly with a stale non-destroying recorded error +- **WHEN** `finalize` decides +- **THEN** it resolves, and a warning names the output file and the stale error + +- **GIVEN** a stream that emitted `finish` and then errored at close time (EIO from auto-destroy's `close(2)`) +- **WHEN** `finalize` — started before the error landed — decides +- **THEN** it rejects with that error, deterministically + +- **GIVEN** a stream that recorded a first error, then emitted a second, then was destroyed +- **WHEN** `finalize` decides +- **THEN** it rejects with the **first** recorded error + +#### R3: Drain-rejection precedence and the drain-timeout degradation are preserved +A drain rejection thrown from `finalize`'s `try` MUST still win (the `finally` still untracks, ends, and now awaits `'close'`); the terminal-state decision MUST run only when nothing above threw. The drain-timeout degradation is untouched: unpipe → end → await close → (clean state) → resolve with a possibly-truncated log; awaiting `'close'` on an ended stream cannot hang, so bounding is unchanged. + +- **GIVEN** a source whose `finished(source)` rejects mid-drain +- **WHEN** `finalize` runs +- **THEN** the stream is still untracked, ended, and closed, and `finalize` rejects with the drain error — not a redundant one + +- **GIVEN** a drain that times out on a stream that then ends cleanly +- **WHEN** `finalize` completes +- **THEN** it resolves after the timeout warning, exactly as today + +#### R4: Doc comments state the new guarantee, not the superseded one +The doc comments in `logWriteStream.ts` that argue for the unconditional rejection MUST be rewritten to state the terminal-state guarantee: the `finalize` contract paragraph (the "a guard on `writableFinished` here would silently drop exactly that error" argument), `_endAndFlush`'s "destroyed early return" paragraph (that early return is removed), the `LogStreamEntry` rationale, and `open()`'s listener comment (the record's remaining role: first-error-wins precedence ahead of `stream.errored`, plus the stale-error warning). `finalizeQuietly`'s quiet-before-loud ordering hazard paragraph stays — that decision is unchanged. + +- **GIVEN** the updated `logWriteStream.ts` +- **WHEN** a reader consults the `finalize`/`_endAndFlush`/`open` doc comments +- **THEN** every claim matches the implemented behavior (decision after terminal state; close-time errors always observed; cleanly-finished-and-closed stream is a successful stop), and no comment argues for the removed unconditional rejection + +### device-node: Test conformance to the spec (Test Integrity) + +#### R5: Registry tests are updated to the spec — coverage moved, not dropped +Per the constitution's Test Integrity rule, the test pinning the superseded behavior MUST be updated to the spec — this is spec-conformance test updating, not test-weakening; the plan and PR MUST state this plainly. Concretely, in `packages/device-node/src/device/test/logCaptureProviders.test.ts`: (a) the first-error-wins test (`'LogWriteStreamRegistry records only the first error a stream emits'`, ~line 370) MUST keep pinning first-error-wins but on a *genuinely failing* stream (its old secondary assertion — rejection despite a clean flush — moves to the new tests); (b) a new test MUST pin flushed-cleanly-resolves over a stale non-destroying error (file content intact, stream untracked, warning logged); (c) a new deterministic regression test MUST pin close-time-error-rejects (drive the stream to `finish` cleanly, force the auto-destroy close to fail, assert `finalize` — started before the error lands — rejects with it). Any other test asserting the old unconditional rejection is updated on the same ground. + +- **GIVEN** the reworked first-error-wins test +- **WHEN** it runs against the new implementation +- **THEN** it emits two errors on a stream that is then genuinely destroyed and asserts `finalize` rejects with the first + +- **GIVEN** the new flushed-cleanly test +- **WHEN** it runs +- **THEN** a bare `emit('error')` followed by a clean write/flush yields a resolving `finalize`, an intact file, zero live streams, and a warning naming the file + +- **GIVEN** the new close-time-error test +- **WHEN** it runs +- **THEN** the stream finishes cleanly, the forced close failure is delivered, and `finalize` rejects with it — with no timing dependence + +#### R6: Provider-level quiet-first failure-response invariant is pinned on both platforms +New provider-level tests (parameterized over Android and iOS like the existing blocks) MUST pin the invariant that makes the documented quiet-before-loud ordering hazard safe: a quiet-first path over a stream with a recorded error returns a **failure** response by itself (e.g. `kill()` returning `false` → early failure return over an errored stream: assert `success: false` and zero live streams). These tests pin the safety invariant, NOT the swallow-then-resolve accident — they do not assert a later `finalize` outcome for the same path. + +- **GIVEN** a capture over an unopenable path (recorded `ENOENT`) whose stop's SIGINT is not delivered +- **WHEN** `stopLogCapture` takes the quiet-first early-return path +- **THEN** the response is `success: false` naming the SIGINT failure, and the registry tracks no stream + +### Verification + +#### R7: Package and repo-wide suites stay green +The device-node package suite MUST pass, then the repo-wide gate (build, typecheck, test) MUST pass. Nothing is committed by this stage, and `fab/backlog.md` is not touched. + +- **GIVEN** the completed implementation and test updates +- **WHEN** the device-node suite and then the repo-wide build/typecheck/test run +- **THEN** all pass with no skipped or newly-failing tests + +### Non-Goals + +- No change to the `finalize`/`finalizeQuietly` split or any provider call-site ordering +- No serialization/single-flight guard in `LogCaptureManager` (withdrawn finding; accepted, documented hazard stands) +- No change to drain-timeout bounding or its truncated-log degradation +- Memory (`docs/memory/device-node/log-capture.md`) updates happen at hydrate, not this stage +- `fab/backlog.md` MUST NOT be committed + +### Design Decisions + +#### Await the terminal `'close'` state, not a bare `writableFinished` guard +**Decision**: `finalize` waits for the stream's `'close'` event (state-checked, never-throwing) before deciding, on every tracked path. +**Why**: The defect is two-faced and timing-dependent — a close-time error recorded before the check rejects a flushed log; one recorded after is silently missed. Awaiting `'close'` removes the race entirely; a bare `writableFinished` guard fixes only the first face and makes the second unconditional. +**Rejected**: `writableFinished` guard on the re-throw — drops close-time errors (the #173 memory DD itself proves this); `finished(stream)`/`events.once(stream, 'close')` as the wait primitive — both reject on an errored stream, but the recorded error already carries the failure, so the wait must never throw. +*Introduced by*: 260731-vojm-log-finalize-terminal-state + +#### State-based success predicate with warn-and-resolve for a stale non-destroying error +**Decision**: Resolve iff `writableFinished && stream.errored === null`; in that state a recorded `entry.error` is logged as a guarded warning and the stop succeeds; otherwise reject with `entry.error ?? stream.errored` (synthesized generic error if both null). +**Why**: Applies the file's own contract literally — a stream that finished and closed cleanly IS known complete; the only reachable resolve-over-recorded-error path is a test-artifact bare emit. First-error-wins is preserved because `entry.error` takes precedence over `stream.errored` (which only holds whatever destroyed the stream). The warning is guarded so a throwing logger sink cannot flip a successful stop into a rejection. +**Rejected**: Unconditional rejection on any recorded error — contradicts the flushed-log contract and leaves close-time observation racy; clearing `entry.error` once the flush resolves — silently drops close-time errors by another route. +*Introduced by*: 260731-vojm-log-finalize-terminal-state + +#### Keep once-consumed `finalizeQuietly` semantics; pin the safety invariant with provider tests +**Decision**: The registry's once-consumed error (entry deleted in `finalize`'s `finally`) and documented-not-enforced quiet-before-loud ordering are kept; the "untested" half is answered with provider-level tests pinning that quiet-first paths return failure responses by themselves. +**Why**: CodeRabbit withdrew its serialization finding after verifying every quiet-first provider path already returns `success: false`; tombstoning errored entries reintroduces the unbounded growth the per-instance registry avoids; making `finalizeQuietly` preserve entries breaks its contract for every already-failing caller. +**Rejected**: Tombstoning errored entries; entry-preserving `finalizeQuietly`; a test pinning the second-stop-over-a-failed-stream success (cements an accident as a contract). +*Introduced by*: 260731-vojm-log-finalize-terminal-state + +#### Force the close-time failure via a `_destroy` override in the regression test +**Decision**: The close-time-error test overrides the tracked stream's documented `_destroy` hook to invoke the real teardown and then deliver the callback an `EIO`-shaped error, then ends the stream and awaits `finish` before calling `finalize`. +**Why**: A real `close(2)` failure cannot be provoked deterministically on a healthy fd, and `stream.destroy(err)` after `finish` races auto-destroy's own `destroy()` call. The `_destroy` override is the documented customization seam for exactly this teardown step, and it reproduces the precise production shape: `finish` first, error at close, `stream.errored` set with `writableFinished` true. +**Rejected**: `stream.destroy(err)` after `finish` — non-deterministic against auto-destroy; sleeping on timing — flaky by construction, the shape this suite explicitly avoids. +*Introduced by*: 260731-vojm-log-finalize-terminal-state + +## Tasks + +### Phase 2: Core Implementation + +- [x] T001 Rework `_endAndFlush` in `packages/device-node/src/device/logWriteStream.ts`: remove the `writableFinished || destroyed` early return; `end()` the stream only when `!writableEnded && !destroyed`; then, unless `stream.closed`, await a plain never-rejecting `'close'` listener (no `finished()`, no `events.once`) +- [x] T002 Replace `finalize`'s history-based decision in `packages/device-node/src/device/logWriteStream.ts` with the state-based predicate: resolve iff `writableFinished && stream.errored === null` (guarded `Logger.w` warning naming the file and error when a stale `entry.error` is set), else `throw entry.error ?? stream.errored ?? new Error(...)`; keep the drain/unpipe `try` and untrack-in-`finally` structure unchanged +- [x] T003 Rewrite the affected doc comments in `packages/device-node/src/device/logWriteStream.ts`: the `finalize` contract paragraph, the post-`finally` decision comment, `_endAndFlush`'s doc (the "destroyed early return" paragraph is gone — state the close-wait guarantee and why the wait never throws), the `LogStreamEntry` rationale, `open()`'s listener rationale (record = first-error-wins ahead of `stream.errored` + the stale-error warning), and `finalizeQuietly`'s catch comment (drop the stale "used to be reached only by" narration); keep the quiet-before-loud ordering hazard paragraph + +### Phase 3: Tests + +- [x] T004 Rework `'LogWriteStreamRegistry records only the first error a stream emits'` (~line 370 of `packages/device-node/src/device/test/logCaptureProviders.test.ts`) to pin first-error-wins on a genuinely failing stream: two bare emits, then `stream.destroy(...)`, assert `finalize` rejects with the first error and zero live streams +- [x] T005 Add registry test: flushed-cleanly resolves over a stale non-destroying error — bare `emit('error')`, clean write, `finalize` resolves, file content intact, stream untracked, and a captured-sink warning names the output file +- [x] T006 Add registry regression test: close-time error rejects deterministically — override the tracked stream's `_destroy` to fail the close, write + `end()` + await `finish`, then assert `finalize` rejects with the close-time error while `writableFinished` is true +- [x] T007 Add provider-level quiet-first failure-response tests (both platforms, in the existing parameterized block of `logCaptureProviders.test.ts`): unopenable path (recorded `ENOENT`) + `signal-undelivered` child → assert `success: false` matching the SIGINT message and zero live streams + +### Phase 4: Verification + +- [x] T008 Run the device-node package suite (`npm run build && npm test` scoped to `packages/device-node`); sweep for any other test asserting the old unconditional rejection and update it on the same spec-conformance ground (record which in the PR notes) +- [x] T009 Run the repo-wide gate: `npm run build`, `npm run typecheck`, `npm test` — all green; do not commit anything and do not touch `fab/backlog.md` + +## Acceptance + +### Functional Completeness + +- [x] A-001 R1: `finalize` reaches its success/failure decision only after the tracked stream's `'close'` state on every tracked path, via a never-throwing state-based wait +- [x] A-002 R2: The decision resolves iff `writableFinished && stream.errored === null`, warns-and-resolves on a stale non-destroying recorded error, and otherwise rejects with `entry.error ?? stream.errored` (generic synthesis only when both are null) +- [x] A-003 R4: No doc comment in `logWriteStream.ts` still argues for the unconditional rejection or the `_endAndFlush` destroyed early-return; the new comments state the terminal-state guarantee and pass the deletion test +- [x] A-004 R5: The reworked and new registry tests exist and pass: first-error-wins on a failing stream, flushed-cleanly-resolves with warning, deterministic close-time-error rejection +- [x] A-005 R6: Both platforms have a passing quiet-first failure-response test asserting `success: false` and zero live streams over an errored stream + +### Behavioral Correctness + +- [x] A-006 R2: Every row of the intake's outcome matrix holds: clean flush resolves; destroying open/write errors reject with the first error; close-time error rejects deterministically; bare-emit-then-clean-flush resolves with a warning; drain-timeout-then-clean-end resolves *(review: first four rows are test-covered; the drain-timeout row holds by inspection — no test exercises the 5 s bound, unchanged from before this change)* +- [x] A-007 R3: A drain rejection still wins over the terminal-state decision (the existing `'stdout exploded'` test passes unchanged), and the drain-timeout truncated-log degradation is unchanged *(review: `_endAndFlush` can no longer throw at all, so the drain rejection's precedence is now structural rather than incidental)* + +### Scenario Coverage + +- [x] A-008 R5: The close-time-error regression test is deterministic — no sleeps, no timing races; it awaits `finish` before finalizing and the forced close failure is delivered via the `_destroy` seam *(review: 30 consecutive runs of the file, 0 failures)* +- [x] A-009 R6: The quiet-first tests pin the safety invariant (failure response, zero live streams) without asserting a later `finalize` outcome for the same path (the accident stays unpinned) + +### Edge Cases & Error Handling + +- [x] A-010 R1: An already-closed stream (failed async open) skips the wait and decides immediately; an ended-but-not-yet-closed stream cannot hang the wait +- [x] A-011 R2: The stale-error warning is guarded so a throwing logger sink cannot flip a successful stop into a rejection; existing logger-sink-failure tests stay green *(review: guard verified by inspection; no test drives a throwing sink through the warn path)* + +### Code Quality + +- [x] A-012 Pattern consistency: New code follows the file's existing structure (guarded log calls, state-checked early returns, rationale-bearing comments) and the test file's existing deterministic-event conventions +- [x] A-013 No unnecessary duplication: The close-wait lives in one place (`_endAndFlush`), reused by every finalize path; no new helper duplicates existing utilities +- [x] A-014 No restatement comments introduced; every rewritten comment carries rationale the code cannot show (deletion test per `fab/project/code-quality.md`), and no rationale comment is deleted without replacement *(review: the rejected-alternative knowledge dropped from `finalize`'s contract paragraph is preserved in `_endAndFlush`'s new close-time-window paragraph, so nothing is unrecoverable)* + +## Notes + +- Test Integrity (constitution): the rework of the ~line-370 pinning test is spec-conformance test updating — the spec keys failure to "the file is not known to be complete", and after the terminal-state wait a finished-and-closed stream IS known complete. The old rejection assertion is not dropped: it is re-pinned deterministically on the close-time-error scenario, the only production-reachable flushed-then-errored shape. +- The PR should state it supersedes CodeRabbit's PR #173 learning ("the unconditional re-throw is deliberate") on two-reviewer convergence. + +## Deletion Candidates + +- `packages/device-node/src/device/test/logCaptureProviders.test.ts:383-385` — the comment block above the `finalize rejects with the error a failed open recorded` assertion describes a `_endAndFlush` early return that no longer exists and a resolve-without-the-record outcome that `stream.errored` now prevents; both claims are dead and misleading, so the block should be replaced (not merely trimmed) with the record's remaining role — first-error precedence ahead of `stream.errored` +- `packages/device-node/src/device/test/logCaptureProviders.test.ts:528-531` — the "`finalize` now re-throws a recorded error where it used to resolve, which is what first makes `finalizeQuietly`'s own `Logger.e` reachable" narration is the same stale-history shape T003 deliberately deleted from `finalizeQuietly`'s own catch comment in the source; the surviving mirror in this test is a deletion candidate on the same ground +- `docs/memory/device-node/log-capture.md` Design Decision "The recorded-error rejection is unconditional, with no `writableFinished` guard" (lines ~303-325) — superseded wholesale by this change; also the falsified `_endAndFlush` early-return claims at lines ~78, ~155-158, ~262, ~272 and the frontmatter description's "`finalize` fails the stop on it". Hydrate owns this (plan Non-Goals), listed here so the hydrate agent has the line inventory rather than re-deriving it +- No source symbol, branch, or config became unused: `finished` from `node:stream/promises` is still consumed by `_drain`, and nothing else in the repo references `_endAndFlush` or the removed early return + +## Assumptions + +| # | Grade | Decision | Rationale | Scores | +|---|-------|----------|-----------|--------| +| 1 | Certain | The close wait is a plain `'close'` listener wrapped in a bare Promise, skipped when `stream.closed` — not `events.once(stream, 'close')` and not `finished(stream)` | Both library primitives reject when the stream errors while waiting, violating the intake's explicit "the wait itself should never throw"; a bare listener is the only never-rejecting form and `'close'` is guaranteed by `emitClose: true` (fs default) | S:85 R:90 A:90 D:85 | +| 2 | Confident | The stale-error warning on the warn-and-resolve path is wrapped in the same guarded `try`/`catch` shape as the file's other log calls | The intake mandates warn + resolve; an unguarded `Logger.w` could reject a successful stop through a throwing sink, changing semantics the intake fixed — guarding preserves them and matches the file's established discipline | S:70 R:85 A:85 D:80 | +| 3 | Confident | Flush errors now surface through the terminal-state decision (recorded/`stream.errored`) instead of a `finished(stream)` rejection propagating from the `finally` | `_endAndFlush` must never throw for the close wait to run on every path; a flush error destroys the stream, so the decision rejects with the same error — caller-visible behavior is unchanged, only the throw site moves | S:65 R:80 A:85 D:75 | +| 4 | Confident | The close-time-error test forces the failure via a `_destroy` override (real teardown first, then an errored callback) rather than `stream.destroy(err)` after `finish` | `destroy(err)` after `finish` races auto-destroy's own `destroy()` call and is non-deterministic; `_destroy` is the documented Writable customization seam and reproduces the exact production shape (finish, then close-time error) | S:75 R:90 A:80 D:70 | + +4 assumptions (1 certain, 3 confident, 0 tentative). diff --git a/packages/device-node/src/device/logWriteStream.ts b/packages/device-node/src/device/logWriteStream.ts index 051c428..35853b5 100644 --- a/packages/device-node/src/device/logWriteStream.ts +++ b/packages/device-node/src/device/logWriteStream.ts @@ -17,13 +17,14 @@ const LOG_DRAIN_TIMEOUT_MS = 5000; /** * A tracked write stream plus the first `error` it emitted, if any. * - * The registry tracks this rather than the bare stream because an error has to - * outlive the event that carried it: the only place the old code could observe - * one was `await finished(stream)` inside `_endAndFlush`, which does not exist - * as a listener until `finalize` runs — and which `_endAndFlush` then skips - * anyway, because an errored stream auto-destroys and hits its early return. So - * the error is remembered here at the moment it happens, and {@link - * LogWriteStreamRegistry.finalize} reads it back. + * The registry tracks this rather than the bare stream because the first error + * has to outlive the event that carried it: `stream.errored` holds only the + * error that *destroyed* the stream, which on a stream that failed more than + * once is fallout rather than cause. The first error — the one that explains + * the failure — is remembered here at the moment it happens. When {@link + * LogWriteStreamRegistry.finalize} rejects, it rejects with this ahead of + * `stream.errored`; on a stream that nonetheless finished and closed cleanly + * the record is only warned about, because the file is known complete. * * Deliberately not exported: the registry itself is kept out of the package * barrel as an internal detail of the two log-capture providers, so its map @@ -74,14 +75,16 @@ export class LogWriteStreamRegistry { // does not forward a destination's errors to the source, so with no listener // the first one is an unhandled 'error' — which Node throws, taking the CLI // down in the middle of a run. The error is RECORDED and not merely logged - // because `_endAndFlush` early-returns on an errored (hence auto-destroyed) - // stream: without the record, `finalize` would resolve and report a - // successful stop over a log file that was never written. + // because the record is what `finalize`'s decision prefers over + // `stream.errored`: `stream.errored` carries only the error that destroyed + // the stream — on a stream that failed twice, the fallout, not the cause — + // and on the one flushed-cleanly path a stale record survives into, the + // record is what the warning names. stream.on('error', (error) => { // First error wins: it is the one that explains the failure, and anything // after it is fallout on an already-destroyed stream. Recorded FIRST, so - // the record — the thing `finalize` reads to fail the stop — is in place - // before anything fallible runs. + // the record — what `finalize`'s decision rejects with, ahead of + // `stream.errored` — is in place before anything fallible runs. entry.error ??= error; // The log call is guarded because THIS listener must not throw. `Logger.e` @@ -123,24 +126,21 @@ export class LogWriteStreamRegistry { * at `outputFilePath` is complete when this resolves. * * Untracked paths (a capture that never opened a stream, a path an earlier - * stop already finalized) return at once, and an already-finished or - * already-destroyed stream skips the flush: there is nothing left to flush in - * either case. That also makes this idempotent and cheap on repeat, so a - * provider's error path may call it without knowing whether its success path - * already did. A stream destroyed *by an error* is the one exception to - * "returns quietly" — it skips the flush and then rejects with that error. + * stop already finalized) return at once. That makes this idempotent and + * cheap on repeat, so a provider's error path may call it without knowing + * whether its success path already did. * - * A write error rejects, because a log that could not be flushed is a failed - * stop, not a successful one — but the stream is ended and untracked first, on - * every path. That holds for an error {@link open}'s listener recorded long - * before this call as much as for one raised by the flush here. It holds even - * when the flush itself later succeeded (`writableFinished` true): an errored - * stream's contents are not trustworthy. `autoDestroy: true` makes that state - * unreachable in the error-then-flush direction (a real error destroys the - * stream before it can finish), but not in the other: auto-destroy runs - * `close(2)` after `finish`, and a close-time failure (EIO) is recorded with - * `writableFinished` already true — a guard on `writableFinished` here would - * silently drop exactly that error. + * Success or failure is decided from the stream's TERMINAL state, not from + * whether an error was ever recorded: the `finally` waits until the stream + * has emitted `'close'`, so every error the stream will ever deliver — + * including a close-time EIO from the `close(2)` auto-destroy runs *after* + * `finish` — has been observed before the decision runs, never missed by + * timing. The stop succeeds iff the stream finished and closed cleanly + * (`writableFinished` with no `errored`): a log that could not be flushed is + * a failed stop, and one that was flushed and closed IS known to be complete. + * Anything else rejects with the first recorded error — one {@link open}'s + * listener recorded long before this call as much as one raised by the flush + * here — but the stream is ended and untracked first, on every path. */ async finalize(outputFilePath: string, source?: Readable | null): Promise { const entry = this._streams.get(outputFilePath); @@ -169,16 +169,45 @@ export class LogWriteStreamRegistry { await this._endAndFlush(stream); } - // Reached only when nothing above threw: a drain rejection or a flush error - // is already the failure being reported, and re-throwing here would replace - // it with a redundant one. A recorded write error still fails the stop, per - // the contract above — a log that could not be flushed is not a stop. This - // is also the only way such an error can surface at all: `_endAndFlush` - // early-returns on the auto-destroyed stream an error leaves behind, so - // without this the stop would resolve over an unwritten file. - if (entry.error) { - throw entry.error; + // Reached only when nothing above threw: a drain rejection is already the + // failure being reported, and re-throwing here would replace it with a + // redundant one. `_endAndFlush` has awaited the terminal 'close' by now, so + // this reads settled state rather than racing the stream's own teardown — + // the pre-terminal-state version of this check could resolve before a + // close-time error's listener ran, a successful stop over a file whose + // durability the OS just refused to confirm. + if (stream.writableFinished && stream.errored === null) { + if (entry.error) { + // Only a bare non-destroying `emit('error', …)` can leave a recorded + // error on a stream that still finished and closed cleanly: every real + // fs error either destroys the stream (`autoDestroy: true`) or arrives + // at close time, setting `errored`. The file is known to be complete, + // so the stop succeeds — the contract keys failure to the file, not to + // the stream's event history — and the stale record is worth a warning, + // not a failure. Guarded like every log call on a path whose outcome + // must not change: a throwing logger sink must not flip a successful + // stop into a rejection. + try { + Logger.w( + `LogWriteStreamRegistry: stream finished and closed cleanly despite a recorded error (${entry.error.message}); treating the stop as successful: ${outputFilePath}`, + ); + } catch { + // Deliberately empty: the stop's outcome is already decided, and a + // logger that just failed is not where a failing logger gets reported. + } + } + return; } + + // The stream did not finish, or an error destroyed it — possibly at close + // time, after a clean `finish`. First-recorded error wins; `stream.errored` + // is the fallback for a destroy that recorded nothing, and the synthesized + // error covers the in-principle-unreachable state where both are null. + throw ( + entry.error ?? + stream.errored ?? + new Error(`log write stream did not finish cleanly: ${outputFilePath}`) + ); } /** @@ -215,10 +244,9 @@ export class LogWriteStreamRegistry { // Guarded for the same reason {@link open}'s listener guards its own log // call: `Logger.e` is fallible on its own schedule, so an unguarded call // here would make this method reject and break the "logged rather than - // thrown" contract above. `finalize`'s new re-throw of a recorded error is - // what makes that reachable — this catch used to be reached only by a drain - // or flush rejection, and on ENOSPC it now runs with the logger sink just as - // likely to fail. + // thrown" contract above. The failures that land here — a drain rejection, + // a stream an fs error destroyed — include ENOSPC, exactly the condition + // under which the logger sink is just as likely to fail. try { Logger.e( `LogWriteStreamRegistry: Failed to finalize log write stream: ${outputFilePath}`, @@ -258,25 +286,36 @@ export class LogWriteStreamRegistry { } /** - * Ends the write stream and waits for its flush. The pipe ends the destination - * itself once `source` reaches EOF, so this usually finds the stream already - * ended and only awaits the flush; the explicit `end()` covers the paths with - * no source at all — a start that threw before spawning, or a stop whose - * child never delivered its signal. + * Ends the write stream (unless something already ended or destroyed it) and + * waits for its terminal `'close'`, which `fs.WriteStream` always emits + * (`emitClose` defaults true): after `end()` → `finish` → auto-destroy on the + * clean path, after `destroy(err)` on the failing one. The pipe ends the + * destination itself once `source` reaches EOF, so the explicit `end()` + * covers the paths with no source at all — a start that threw before + * spawning, or a stop whose child never delivered its signal. + * + * Waiting for `'close'` rather than `finish` — and not skipping the wait on + * an already-finished or already-destroyed stream — is what closes the + * close-time window: auto-destroy runs `close(2)` *after* `finish`, so a + * stream can finish cleanly and still error on close (EIO), and deciding + * before that error has been delivered turns it into a race. After `'close'`, + * every error the stream will ever emit has been recorded, so {@link + * finalize}'s decision reads settled state. * - * The `destroyed` early return is why a failed stream cannot report itself from - * here: an `error` auto-destroys the stream, so by the time {@link finalize} - * reaches this it returns without ever awaiting `finished`. {@link finalize} - * therefore re-throws the error {@link open}'s listener recorded, after its - * `finally`. + * The wait itself never rejects — a plain `'close'` listener, deliberately + * not `finished()` (rejects on an errored stream) and not `events.once` + * (rejects when `'error'` is emitted while waiting): the failure already + * lives in the recorded entry error and `stream.errored`, and {@link + * finalize}'s decision is what reports it. */ private async _endAndFlush(stream: fs.WriteStream): Promise { - if (stream.writableFinished || stream.destroyed) { - return; - } - if (!stream.writableEnded) { + if (!stream.writableEnded && !stream.destroyed) { stream.end(); } - await finished(stream); + if (!stream.closed) { + await new Promise((resolve) => { + stream.once('close', resolve); + }); + } } } diff --git a/packages/device-node/src/device/test/logCaptureProviders.test.ts b/packages/device-node/src/device/test/logCaptureProviders.test.ts index bebce18..0252335 100644 --- a/packages/device-node/src/device/test/logCaptureProviders.test.ts +++ b/packages/device-node/src/device/test/logCaptureProviders.test.ts @@ -287,6 +287,40 @@ for (const platform of ['Android', 'iOS'] as const) { assert.match(stopped.message ?? '', /ENOENT/); assert.equal(liveStreamCount(providerRegistry(provider)), 0); }); + + test(`${platform} log capture quiet-first stop path reports failure over an errored stream`, async () => { + const outputFilePath = await createUnopenableFilePath(); + const childProcess = new FakeChildProcess('signal-undelivered'); + const provider = createProvider(childProcess); + + await startCapture(provider, childProcess, outputFilePath); + + const [openError] = await once( + trackedStream(providerRegistry(provider), outputFilePath), + 'error', + ); + assert.match(String(openError), /ENOENT/); + + childProcess.stdout.end(); + + const stopped = await provider.stopLogCapture({ + process: childProcess as unknown as ChildProcess, + outputFilePath, + }); + + // The undelivered SIGINT makes this a quiet-first path: `finalizeQuietly` + // consumes the recorded ENOENT silently (it drops the registry entry), so a + // later `finalize` for the same path would find nothing — safe only because + // the path is already reporting a failure of its own. That invariant, every + // quiet-first path returning `success: false` by itself, is what makes the + // documented quiet-before-loud ordering hazard in `logWriteStream.ts` safe. + // Pinned deliberately WITHOUT asserting what a later stop over the swallowed + // error returns: the swallow-then-resolve sequence is an accepted, documented + // accident, not a contract. + assert.equal(stopped.success, false); + assert.match(stopped.message ?? '', /Failed to send SIGINT/); + assert.equal(liveStreamCount(providerRegistry(provider)), 0); + }); } test('LogWriteStreamRegistry ends and untracks the stream when the source errors', async () => { @@ -346,9 +380,10 @@ test('LogWriteStreamRegistry finalize rejects with the error a failed open recor const [openError] = await once(stream, 'error'); assert.match(String(openError), /ENOENT/); - // The error auto-destroyed the stream, so `_endAndFlush` early-returns and the - // flush never observes it: without the recorded error, the stop would resolve - // and report success over a log file that was never written. + // The ENOENT destroyed the stream, so the terminal-state decision would reject + // via `stream.errored` even with no record. What the record adds — and what + // this pins — is precedence: the rejection carries the FIRST error the stream + // emitted, not whichever one happened to destroy it. await assert.rejects(registry.finalize(outputFilePath), /ENOENT/); assert.equal(liveStreamCount(registry), 0); }); @@ -373,13 +408,16 @@ test('LogWriteStreamRegistry records only the first error a stream emits', async const stream = registry.open(outputFilePath); // `??=` is what makes this hold: the first error is the one that explains the - // failure and everything after it is fallout on an already-destroyed stream. - // Emitted directly rather than provoked, because two real failures on one stream - // cannot be ordered deterministically — and a direct `emit` leaves the stream - // undestroyed, so the flush below still runs and the recorded error is the only - // thing that can reject. + // failure and everything after it is fallout on an already-doomed stream. + // Emitted directly rather than provoked, because two real failures on one + // stream cannot be ordered deterministically. The destroy is what makes the + // stream genuinely failing — `finish` can no longer fire, so `finalize` must + // reject — and it carries a THIRD error so the assertion also pins precedence: + // the recorded first error outranks `stream.errored` (the destroy reason, + // which is fallout) in the rejection. stream.emit('error', new Error('first failure')); stream.emit('error', new Error('second failure')); + stream.destroy(new Error('destroy fallout')); await assert.rejects(registry.finalize(outputFilePath), /first failure/); assert.equal(liveStreamCount(registry), 0); @@ -400,6 +438,76 @@ test('LogWriteStreamRegistry finalize resolves and untracks a stream that wrote assert.equal(liveStreamCount(registry), 0); }); +test('LogWriteStreamRegistry finalize resolves a stream that flushed cleanly despite a stale non-destroying error', async () => { + const outputFilePath = await createOutputFilePath(); + const registry = new LogWriteStreamRegistry(); + const stream = registry.open(outputFilePath); + stream.write('one logcat line\n'); + + // A bare emit is the only construction that reaches this state: every real fs + // error either destroys the stream (`autoDestroy: true`) or arrives at close + // time, setting `stream.errored`. The stream itself is untouched, so the + // flush below completes and the file on disk is genuinely whole — the state + // in which the old unconditional rejection contradicted the file's own + // contract (a log that could not be flushed is a failed stop; this one was + // flushed). + stream.emit('error', new Error('stale failure')); + + const warnings: string[] = []; + const capturingSink: LoggerSink = (entry) => { + warnings.push(entry.message); + }; + Logger.addSink(capturingSink); + try { + await registry.finalize(outputFilePath); + } finally { + Logger.removeSink(capturingSink); + } + + assert.equal(stream.writableFinished, true); + assert.equal(await readFile(outputFilePath, 'utf8'), 'one logcat line\n'); + assert.equal(liveStreamCount(registry), 0); + // The stale record is not silently swallowed: the warning names the file and + // the error it is overriding. + assert.ok( + warnings.some((m) => m.includes(outputFilePath) && m.includes('stale failure')), + `expected a warning naming ${outputFilePath} and the stale error, got: ${JSON.stringify(warnings)}`, + ); +}); + +test('LogWriteStreamRegistry finalize rejects deterministically on a close-time error after a clean finish', async () => { + const outputFilePath = await createOutputFilePath(); + const registry = new LogWriteStreamRegistry(); + const stream = registry.open(outputFilePath); + + // Forces the failure auto-destroy's `close(2)` would report. `_destroy` is + // the documented Writable teardown seam: the real teardown still runs (the fd + // is actually closed) and the callback is then handed the EIO the OS would + // have returned, which Node surfaces as `error` → `errored` → `close`. + // `stream.destroy(err)` after `finish` cannot pin this — it races + // auto-destroy's own `destroy()` call and loses nondeterministically. + const realDestroy = stream._destroy.bind(stream); + stream._destroy = (error, callback) => { + realDestroy(error, () => { + callback(error ?? new Error('EIO: i/o error, close')); + }); + }; + + stream.write('one logcat line\n'); + stream.end(); + await once(stream, 'finish'); + + // `finalize` starts with `writableFinished` already true and the close-time + // error not yet delivered — exactly the window the pre-fix code raced: its + // `_endAndFlush` early-returned on a finished stream and the recorded-error + // check then resolved or rejected by whether the close callback had run yet. + // Awaiting the terminal 'close' makes this rejection deterministic. + await assert.rejects(registry.finalize(outputFilePath), /EIO/); + + assert.equal(stream.writableFinished, true, 'the flush itself completed cleanly'); + assert.equal(liveStreamCount(registry), 0); +}); + test('LogWriteStreamRegistry finalizeQuietly resolves when the logger sink throws too', async () => { const outputFilePath = await createUnopenableFilePath(); const registry = new LogWriteStreamRegistry();