diff --git a/docs/memory/device-node/log-capture.md b/docs/memory/device-node/log-capture.md index 6055e49..d292229 100644 --- a/docs/memory/device-node/log-capture.md +++ b/docs/memory/device-node/log-capture.md @@ -81,6 +81,19 @@ whether the success path already did. Untracking and ending run in a `finally`, 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). +**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 +`DeviceNodeResponse { success: false }` with a message naming the error and leaves no tracked entry +behind — the caller-visible half of the contract. Registry-level tests cannot reach it: they call +`finalize` themselves, so replacing the success path's `finalize` with `finalizeQuietly` in +`AndroidLogcatProvider.stopLogCapture` and `IOSLogProvider.stopLogCapture` — which restores a +successful stop over a log file that was never written — leaves every one of them green. The two +platform-parameterized failing-stream tests in +`packages/device-node/src/device/test/logCaptureProviders.test.ts` are what fail on that swap, and +are mutation-verified against exactly it. They assert the response, not registry internals: a real +unopenable path (its parent directory absent), the stream's `error` event awaited deterministically +rather than slept on, and `liveStreamCount` back to zero. + #### Scenario: buffered output is still complete on disk after the stop - **GIVEN** a log capture whose child process has written data that is still buffered @@ -99,6 +112,14 @@ one case that skips the flush and still fails: it rejects with the recorded erro - **WHEN** finalization runs - **THEN** it resolves without throwing and without hanging +#### Scenario: the stop's write stream never opened + +- **GIVEN** a capture started against an output path whose parent directory does not exist, so the + stream's asynchronous `open(2)` fails with `ENOENT` after the start has already returned success +- **WHEN** `stopLogCapture` runs and its drain reaches EOF +- **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 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`, @@ -278,3 +299,61 @@ error is logged rather than thrown — that is `finalizeQuietly`, and collapsing 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 recorded error is consumed by the first finalization, and call ordering is documented rather than enforced + +**Decision**: A recorded error survives only until the first finalization consumes it — `finalize` +drops the entry in its `finally` — so a `finalizeQuietly` running *before* a `finalize` for the same +path swallows the error and leaves the later `finalize` to find an untracked path and resolve. The +required ordering (`finalize` before any `finalizeQuietly` for the same path) is stated on +`finalizeQuietly`'s doc comment; `logWriteStream.ts` enforces nothing. + +**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. + +**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- +stream success — cements an accident as a contract, which is worse than an accepted, documented +hazard. + +*Introduced by*: 260731-cjx8-provider-log-stop-test-coverage diff --git a/fab/changes/260731-cjx8-provider-log-stop-test-coverage/.history.jsonl b/fab/changes/260731-cjx8-provider-log-stop-test-coverage/.history.jsonl new file mode 100644 index 0000000..70feb0d --- /dev/null +++ b/fab/changes/260731-cjx8-provider-log-stop-test-coverage/.history.jsonl @@ -0,0 +1,15 @@ +{"action":"enter","driver":"fab-new","event":"stage-transition","stage":"intake","ts":"2026-07-31T10:35:17Z"} +{"args":"Close a mutation-proven test-coverage gap in packages/device-node: no provider-level test puts a failing write stream through stopLogCapture, so the finalize-vs-finalizeQuietly distinction PR #168 fixed is unpinned. Add provider tests against an unopenable path asserting stop reports success:false; verify the test kills the finalize-\u003efinalizeQuietly mutation. Also assess (judgement, not blind fix): finalize's unconditional entry.error rejection vs the writableFinished contract, and the once-consumed recorded error ordering hazard.","cmd":"fab-new","event":"command","ts":"2026-07-31T10:35:17Z"} +{"delta":"+4.7","event":"confidence","score":4.7,"trigger":"calc-score","ts":"2026-07-31T10:36:58Z"} +{"delta":"+0.0","event":"confidence","score":4.7,"trigger":"calc-score","ts":"2026-07-31T10:39:48Z"} +{"cmd":"fab-fff","event":"command","ts":"2026-07-31T10:40:20Z"} +{"action":"enter","driver":"fab-fff","event":"stage-transition","stage":"apply","ts":"2026-07-31T10:40:26Z"} +{"cmd":"fab-continue","event":"command","ts":"2026-07-31T10:41:26Z"} +{"action":"enter","driver":"fab-fff","event":"stage-transition","stage":"review","ts":"2026-07-31T10:47:41Z"} +{"action":"enter","driver":"fab-fff","event":"stage-transition","stage":"hydrate","ts":"2026-07-31T10:59:04Z"} +{"event":"review","result":"passed","ts":"2026-07-31T10:59:04Z"} +{"cmd":"fab-continue","event":"command","ts":"2026-07-31T10:59:50Z"} +{"action":"enter","driver":"fab-fff","event":"stage-transition","stage":"ship","ts":"2026-07-31T11:03:52Z"} +{"action":"enter","driver":"git-pr","event":"stage-transition","stage":"review-pr","ts":"2026-07-31T11:07:02Z"} +{"cmd":"git-pr-review","event":"command","ts":"2026-07-31T11:08:40Z"} +{"event":"review","result":"passed","ts":"2026-07-31T11:27:17Z"} diff --git a/fab/changes/260731-cjx8-provider-log-stop-test-coverage/.status.yaml b/fab/changes/260731-cjx8-provider-log-stop-test-coverage/.status.yaml new file mode 100644 index 0000000..1751b11 --- /dev/null +++ b/fab/changes/260731-cjx8-provider-log-stop-test-coverage/.status.yaml @@ -0,0 +1,53 @@ +id: cjx8 +name: 260731-cjx8-provider-log-stop-test-coverage +created: 2026-07-31T10:35:17Z +created_by: droid-ash +change_type: test +issues: [] +progress: + intake: done + apply: done + review: done + hydrate: done + ship: done + review-pr: done +plan: + generated: true + task_count: 5 + acceptance_count: 11 + acceptance_completed: 11 +confidence: + certain: 3 + confident: 3 + tentative: 0 + unresolved: 0 + score: 4.7 + fuzzy: true + dimensions: + signal: 85.0 + reversibility: 80.0 + competence: 88.3 + disambiguation: 79.2 +stage_metrics: + intake: {started_at: "2026-07-31T10:35:17Z", driver: fab-new, iterations: 1, completed_at: "2026-07-31T10:40:26Z"} + apply: {started_at: "2026-07-31T10:40:26Z", driver: fab-fff, iterations: 1, completed_at: "2026-07-31T10:47:41Z"} + review: {started_at: "2026-07-31T10:47:41Z", driver: fab-fff, iterations: 1, completed_at: "2026-07-31T10:59:04Z"} + hydrate: {started_at: "2026-07-31T10:59:04Z", driver: fab-fff, iterations: 1, completed_at: "2026-07-31T11:03:52Z"} + ship: {started_at: "2026-07-31T11:03:52Z", driver: fab-fff, iterations: 1, completed_at: "2026-07-31T11:07:02Z"} + review-pr: {started_at: "2026-07-31T11:07:02Z", driver: git-pr, iterations: 1, completed_at: "2026-07-31T11:27:17Z"} +prs: + - https://github.com/droid-ash/finalrun-agent/pull/173 +change_type_source: explicit +true_impact: + added: 456 + deleted: 1 + net: 455 + tests: + added: 66 + deleted: 0 + net: 66 + computed_at: "2026-07-31T11:07:02Z" + computed_at_stage: ship +summary: Pinned the caller-visible finalize-vs-finalizeQuietly stop contract with two mutation-verified provider-level failing-stream tests, and documented the keep-unconditional-rejection and once-consumed-recorded-error decisions +# true_impact: lazily created on first stage-finish that computes it (no placeholder here). +last_updated: 2026-07-31T11:27:17Z diff --git a/fab/changes/260731-cjx8-provider-log-stop-test-coverage/intake.md b/fab/changes/260731-cjx8-provider-log-stop-test-coverage/intake.md new file mode 100644 index 0000000..43a6337 --- /dev/null +++ b/fab/changes/260731-cjx8-provider-log-stop-test-coverage/intake.md @@ -0,0 +1,101 @@ +# Intake: Provider-Level Log-Stop Failure Test Coverage + +**Change**: 260731-cjx8-provider-log-stop-test-coverage +**Created**: 2026-07-31 + +## Origin + +One-shot `/fab-new` invocation carrying an independent adversarial review finding against PRs #168–#172. The user's raw input (condensed; full text in `.history.jsonl`): + +> Close a test-coverage gap that was proven by mutation, in packages/device-node. PR #168 fixed a real defect where stopping log capture reported success over a log file that was never written. All 7 tests it added drive LogWriteStreamRegistry directly, and all 8 pre-existing provider tests use a good writable path. So no test ever puts a FAILING write stream through stopLogCapture, and the caller-visible outcome of the fix is completely unpinned. Proof: replacing `finalize` with `finalizeQuietly` at AndroidLogcatProvider.ts:157 and IOSLogProvider.ts:135 — which restores exactly the defect #168 fixed — leaves all 120 device-node tests green. REQUIRED: add provider-level coverage so that mutation would fail. Verify the new test actually kills the mutation (apply it, confirm the test fails, revert with git checkout, confirm clean status). Per the constitution Test Integrity rule, append only — do not modify or weaken any existing test. ALSO ASSESS with judgement: (a) logWriteStream.ts:172–174 never clears `entry.error`, so `finalize` rejects unconditionally once an error is recorded even when the flush succeeded and `writableFinished` is true, contradicting the contract at lines 133–136 — an existing test (logCaptureProviders.test.ts:304–320) pins the inconsistent behaviour; (b) the recorded error is consumed once (finalize deletes the entry in its `finally`), so a `finalizeQuietly` before `finalize` silently discards it — safe only by accident of call ordering and untested. Fix or document each, and state which and why. Do NOT commit or `git add fab/backlog.md` under any circumstance — it is intentionally untracked scratch; the git-pr expected-area guard would otherwise stage untracked files under fab/. + +Key decisions from intake analysis (verified against the working tree, see Assumptions): the mutation-proof claim checks out structurally; `createUnopenableFilePath()` already exists in the target test file (line 115) and MUST be reused; both assessment items resolve to "keep behaviour, document" rather than code changes to `logWriteStream.ts`. + +## Why + +1. **The pain point**: PR #168 (`260730-zga4` / `260730-eyvt`) fixed a defect where `stopLogCapture` reported success over a log file that was never written — `finalize` now re-throws the error `open()`'s listener recorded, and the providers' success path converts that rejection into `DeviceNodeResponse { success: false }`. But the fix's *caller-visible outcome* — a stop over a failed stream reports `success: false` — is pinned by no test. The 7 registry tests added by #168 (logCaptureProviders.test.ts:226–407) drive `LogWriteStreamRegistry` directly, and all 8 provider tests (the `for (const platform of ['Android', 'iOS'])` loop, lines 120–224) use `createOutputFilePath()`, a good writable path. No test ever puts a failing write stream through a provider's `stopLogCapture`. + +2. **The consequence**: the load-bearing distinction between `finalize` (throws — the success path's call at `AndroidLogcatProvider.ts:157` and `IOSLogProvider.ts:135`) and `finalizeQuietly` (swallows — the already-failing paths' call) is mutation-invisible. Replacing `finalize` with `finalizeQuietly` at those two call sites — which restores exactly the defect #168 fixed — leaves all 120 device-node tests green (mutation run by the adversarial reviewer). Any future refactor of the providers can silently reintroduce the defect, and nothing in CI would notice. A truncated/unwritten device log raises no error anywhere downstream — a short log reads as a quiet device — so the test suite is the *only* place this defect can ever be caught. + +3. **Why this approach**: a provider-level test that opens a capture against an unopenable path and asserts the stop response reports `success: false` pins the caller-visible contract (the `DeviceNodeResponse`), not the registry internals — which is precisely the layer the mutation shows is uncovered. Killing the mutation is the acceptance proof: apply the two-line mutation, the new test must fail; revert, it must pass. + +## What Changes + +### 1. New provider-level failing-stream stop tests (REQUIRED) + +**File**: `packages/device-node/src/device/test/logCaptureProviders.test.ts` — append-only; no existing test is modified or weakened (constitution Test Integrity rule, reinforced by the user). + +Add one parameterized test per platform (Android + iOS — a new `for (const platform of ['Android', 'iOS'] as const)` block mirroring the existing one, reusing its `createProvider`-style construction with `execFileStub`/`spawnStub`/`FakeChildProcess`): + +- **GIVEN** a provider started against `await createUnopenableFilePath()` — the existing helper at line 115 (a path whose parent directory does not exist, so `fs.createWriteStream` fails its async `open(2)` with ENOENT). `startLogCapture` succeeds: the ENOENT arrives as an `error` event after `open()` returns. **Reuse this helper — do not write a new one** (user checked; it exists). +- **WHEN** `stopLogCapture` runs with the default `'exits'` fake-child behaviour (SIGINT lands, child exits, `stdout` ended so the drain reaches EOF). +- **THEN** the stop response asserts `success === false` (the recorded ENOENT makes `finalize` reject; the provider's outer catch converts it to a failure response), the message reflects the stop error (e.g. matches `/ENOENT/`), and `liveStreamCount(providerRegistry(provider)) === 0` (the entry is untracked on every path). + +Mechanics the test must respect (from reading the code): + +- The write stream's `error` event must have fired before the stop asserts on the recorded error. Await it deterministically (e.g. `await once(stream-bearing event source)` is not available at provider level — instead await the registry-visible effect or a `setImmediate`/`once`-based settle; the registry tests use `once(stream, 'error')` but the provider owns the stream privately). The concrete synchronization technique is an apply-time decision; what is REQUIRED is that the test is deterministic, not sleep-based flakiness. +- Piping `LOG_PAYLOAD` into a destroyed stream is unnecessary; the test needs no payload — the defect is about the *error*, not the bytes. +- **Placement**: the existing test at lines 373–407 is *deliberately LAST in the file* (its header comment explains a throwing-sink failure mode that must not cascade into later tests). New tests MUST be inserted **before** it — right after the existing platform loop (after line 224) is the natural spot. Inserting between existing tests does not modify any existing test. + +### 2. Mutation-kill verification (REQUIRED, procedural — no committed artifact) + +After the new tests pass: + +1. Apply the mutation: change `finalize` → `finalizeQuietly` at `AndroidLogcatProvider.ts:157` and `IOSLogProvider.ts:135` (the success-path finalize calls only). +2. Run the device-node tests (`npm test` in `packages/device-node`, which runs `node ../../scripts/run-node-tests.mjs`). The two new tests MUST fail; if they stay green the test does not pin the contract and must be reworked. +3. Revert the mutation with `git checkout -- packages/device-node/src/device/AndroidLogcatProvider.ts packages/device-node/src/device/IOSLogProvider.ts` and confirm `git status` is clean (modulo this change's own `fab/changes/` artifacts and intentionally-untracked files) before proceeding. +4. Re-run the tests to confirm all green post-revert. + +### 3. Assessment item A — `finalize`'s unconditional recorded-error rejection: KEEP, document (no code change) + +`logWriteStream.ts:172–174` re-throws `entry.error` unconditionally — even if `_endAndFlush` completed and `stream.writableFinished` is true. The user flags this as contradicting the contract prose ("a log that could not be flushed is a failed stop") and notes a `writableFinished` guard would align code with contract, while the existing test at logCaptureProviders.test.ts:304–320 pins the unconditional behaviour (it `emit`s errors directly, leaving the stream undestroyed, so the flush succeeds and only the recorded error can reject). + +**Decision: keep the unconditional rejection; document the reasoning. Do not add a `writableFinished` guard.** Reasoning: + +- **The contradicting state is unreachable in production.** `fs.WriteStream` has `autoDestroy: true`: every *real* `error` (ENOENT on open, ENOSPC on write) destroys the stream, so `writableFinished` can never become true after a genuine error. The flush-succeeded-with-recorded-error state exists only via a bare `stream.emit('error', …)` — which is exactly how the pinning test constructs it, because two real failures cannot be ordered deterministically (its own comment, lines 309–314). +- **Conservative failure is the safer contract.** An `error` event on the stream means the file is *not known to be complete* — the actual invariant the callers need (the CLI copies the file immediately after the stop). 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 original #168 defect. +- **Test Integrity.** The guard would flip the outcome of the existing test at 304–320 (`assert.rejects(...)` would resolve), forcing a modification of an existing test — prohibited for this change (append-only), and rightly so: that test pins first-error-wins *and* the rejection. +- The "contradiction" is between code and one reading of the docstring prose, not between code and any reachable behaviour. The cheap alignment is one clarifying sentence in the `finalize` doc comment (a rationale claim passing the deletion test): a recorded error rejects even when the flush later succeeded, because an errored stream's contents are not trustworthy and the only reachable errored states are auto-destroyed anyway. Whether to add that sentence or leave the existing prose (which already says "That holds for an error open's listener recorded long before this call") is an apply-time judgement — the existing sentence arguably already covers it, and adding redundant prose has its own cost. + +### 4. Assessment item B — recorded error consumed once (quiet-then-loud ordering): DOCUMENT, do not fix + +`finalize` deletes the registry entry in its `finally` (`logWriteStream.ts:161`), so the recorded error is consumed by whichever caller finalizes first. A `finalizeQuietly` call *before* a `finalize` for the same path would log-and-swallow the error, leaving the later `finalize` to find an untracked path and resolve — success over a possibly-unwritten file. Today this cannot happen, but only by call ordering: + +- In both providers' `stopLogCapture`, `finalize` (success path) always runs before the catch-path `finalizeQuietly`; the quiet-first paths (start failure, signal-undelivered early return) all return `success: false` themselves, so no success is ever reported over a swallowed error. +- The one sequence that *could* reach quiet-then-loud — a failing stop followed by a second stop for the same file — reports `success: true` on the second stop (untracked path resolves). This is reachable at provider level but guarded upstream: `LogCaptureManager`'s `_stoppedTestCases` set prevents double-stop per test case, and the existing "tolerates a second stop" test (lines 159–178) pins second-stop-success for the *good-path* case only. + +**Decision: document the ordering invariant; no code change.** Reasoning: any "fix" is a redesign with real costs — keeping errored entries as tombstones leaks them (the registry's whole design GCs entries with their owner; see the memory Design Decision rejecting a module-level registry for exactly this), and making `finalizeQuietly` preserve the entry breaks its "end the stream and drop its entry" contract that the leak-prevention paths rely on. The hazard is real but currently unreachable through the manager, and the cost of the fix exceeds the risk. Documentation lands in two places: + +1. A short rationale comment on `finalize`'s `finally` (or `finalizeQuietly`'s doc comment) stating the invariant: *the recorded error is consumed by the first finalization; callers that need the error surfaced must call `finalize` before any `finalizeQuietly` for the same path — the providers' call ordering and `LogCaptureManager`'s stopped-set are what currently guarantee this.* This passes the deletion test (a cross-file coupling not recoverable from the code in front of the reader). +2. The `device-node/log-capture` memory file (hydrate stage) records the same invariant under the finalization requirement. + +No new test pins the accidental behaviour — a test asserting "second stop over a failed stream reports success" would cement the accident as a contract, which is worse than leaving it documented as an accepted hazard. + +## Affected Memory + +- `device-node/log-capture`: (modify) add the provider-level failing-stream coverage to the finalization contract's test surface; record the once-consumed recorded-error ordering invariant (item B) and the keep-unconditional-rejection decision (item A) as Design Decisions. + +## Impact + +- `packages/device-node/src/device/test/logCaptureProviders.test.ts` — append two parameterized tests (Android/iOS) before the deliberately-last test; no existing test modified. +- `packages/device-node/src/device/logWriteStream.ts` — at most comment-only edits (item B's ordering-invariant rationale comment; possibly one clarifying sentence for item A). **No behavioural change to any source file.** +- `AndroidLogcatProvider.ts` / `IOSLogProvider.ts` — touched only transiently during mutation verification; reverted via `git checkout`; zero net diff. +- Test count goes 120 → 122; all existing tests must stay green throughout. +- **Ship-stage constraint**: `fab/backlog.md` MUST NOT be committed or `git add`ed under any circumstance — it is intentionally untracked scratch. The `/git-pr` expected-area guard would otherwise stage untracked files under `fab/`; the ship step must stage explicitly around it. + +## Open Questions + +- None. The input is fully specified; the two judgement calls (items A and B) are resolved above with reasoning, as requested. + +## Assumptions + +| # | Grade | Decision | Rationale | Scores | +|---|-------|----------|-----------|--------| +| 1 | Certain | Reuse the existing `createUnopenableFilePath()` helper (logCaptureProviders.test.ts:115) for the new provider tests | User instructed to check for it; verified present in the working tree — writing a duplicate would violate the project's own anti-pattern list | S:95 R:90 A:100 D:95 | +| 2 | Certain | New tests are appended as a second platform-parameterized loop placed before the deliberately-last test (lines 373–407), not after it | That test's header comment mandates last-in-file placement to contain a throwing-sink failure mode; inserting before it modifies no existing test | S:85 R:90 A:95 D:90 | +| 3 | Confident | Item A: keep `finalize`'s unconditional recorded-error rejection; no `writableFinished` guard; at most a clarifying doc sentence | `autoDestroy` makes the contradicting state unreachable with real errors; a guard flips the existing pinning test (304–320), which is append-only-prohibited; conservative failure matches the "not known to be complete" invariant the CLI copy depends on | S:80 R:60 A:85 D:70 | +| 4 | Confident | Item B: document the once-consumed recorded-error ordering invariant (code comment + memory); no redesign, no test pinning the accident | Hazard is unreachable through `LogCaptureManager`'s stopped-set today; tombstone/preserve-entry fixes reintroduce the leak the per-instance registry design exists to prevent; user explicitly allowed "fix or document, your call" | S:80 R:65 A:80 D:65 | +| 5 | Confident | The new test asserts `success === false`, a message matching the stop error (ENOENT), and `liveStreamCount === 0`; the exact async-settle technique for the stream's `error` event is left to apply | The response fields are the caller-visible contract the mutation proof targets; the synchronization detail is a test-mechanics choice with several deterministic options, all reversible | S:75 R:80 A:75 D:60 | +| 6 | Certain | Mutation-kill verification is procedural: apply the two-line mutation, confirm the new tests fail, revert via `git checkout`, confirm clean status, re-run green | Explicit user requirement restated verbatim; no interpretation needed | S:95 R:95 A:95 D:95 | + +6 assumptions (3 certain, 3 confident, 0 tentative, 0 unresolved). diff --git a/fab/changes/260731-cjx8-provider-log-stop-test-coverage/plan.md b/fab/changes/260731-cjx8-provider-log-stop-test-coverage/plan.md new file mode 100644 index 0000000..aa68f29 --- /dev/null +++ b/fab/changes/260731-cjx8-provider-log-stop-test-coverage/plan.md @@ -0,0 +1,130 @@ +# Plan: Provider-Level Log-Stop Failure Test Coverage + +**Change**: 260731-cjx8-provider-log-stop-test-coverage +**Intake**: `intake.md` + +## Requirements + +### device-node: Provider-level failing-stream stop coverage + +#### R1: A stop over a failed write stream is pinned at the provider level + +`packages/device-node/src/device/test/logCaptureProviders.test.ts` MUST gain one parameterized test per platform (Android + iOS — a new `for (const platform of ['Android', 'iOS'] as const)` block mirroring the existing one, reusing its `createProvider`-style construction with `execFileStub`/`spawnStub`/`FakeChildProcess`) that pins the caller-visible outcome of PR #168's fix: a `stopLogCapture` over a write stream whose asynchronous `open(2)` failed reports `success: false`. + +The test MUST reuse the existing `createUnopenableFilePath()` helper (line 115) — no duplicate helper. It MUST await the stream's `error` event deterministically (no sleep-based settling) before stopping. The changes MUST be append-only with respect to existing tests: no existing test is modified or weakened (constitution Test Integrity rule), and the new block MUST be inserted **before** the deliberately-last test (its header comment mandates last-in-file placement) — right after the existing platform loop is the natural spot. + +- **GIVEN** a provider started against `await createUnopenableFilePath()` (start succeeds — the ENOENT arrives as an `error` event after `open()` returns) +- **WHEN** the stream's recorded `error` has been awaited deterministically and `stopLogCapture` runs with the default `'exits'` fake-child behaviour (`stdout` ended so the drain reaches EOF) +- **THEN** the stop response asserts `success === false`, its message matches `/ENOENT/`, and `liveStreamCount(providerRegistry(provider)) === 0` + +#### R2: The new tests kill the finalize→finalizeQuietly mutation + +The new provider-level tests MUST fail when the success-path `finalize` call is mutated to `finalizeQuietly` at `AndroidLogcatProvider.ts` (~line 157) and `IOSLogProvider.ts` (~line 135) — the mutation that restores exactly the defect #168 fixed. Verification is procedural (no committed artifact): apply the mutation, run the device-node tests, confirm the new tests fail; revert with `git checkout -- packages/device-node/src/device/AndroidLogcatProvider.ts packages/device-node/src/device/IOSLogProvider.ts`, confirm `git status` shows the providers clean, re-run and confirm all green. + +- **GIVEN** the new tests pass against the unmutated providers +- **WHEN** `finalize` → `finalizeQuietly` is applied at both success-path call sites and the suite re-runs +- **THEN** the two new tests fail (and only source-mutation-caused failures appear); after `git checkout` revert, the working tree providers are clean and the full suite is green again + +#### R3: Item A — `finalize`'s unconditional recorded-error rejection is kept and documented + +`logWriteStream.ts` MUST keep the unconditional `entry.error` re-throw (no `writableFinished` guard — a guard would flip the existing pinning test at logCaptureProviders.test.ts:304–320, prohibited by append-only Test Integrity, and would err toward false success over a possibly-corrupt file, the exact shape of the #168 defect). The only permitted edit is comment-only: at most one clarifying sentence in `finalize`'s doc comment stating that a recorded error rejects even when the flush later succeeded, because an errored stream's contents are not trustworthy and the only errored states reachable with real errors are auto-destroyed anyway (`fs.WriteStream` has `autoDestroy: true`). + +- **GIVEN** the change is complete +- **WHEN** `logWriteStream.ts` is diffed against its pre-change state +- **THEN** no behavioural change exists — the diff is comment-only — and the unconditional rejection remains + +#### R4: Item B — the once-consumed recorded-error ordering invariant is documented, not fixed + +`logWriteStream.ts` MUST gain a short rationale comment (on `finalizeQuietly`'s doc comment or `finalize`'s `finally`) stating the invariant: the recorded error is consumed by the first finalization (`finalize` deletes the entry in its `finally`), so a `finalizeQuietly` before a `finalize` for the same path silently discards it; callers that need the error surfaced must call `finalize` before any `finalizeQuietly` for the same path — the providers' call ordering and `LogCaptureManager`'s stopped-set are what currently guarantee this. No redesign (tombstones/preserved entries reintroduce the leak the per-instance registry design prevents), and no new test pins the accidental second-stop-over-failed-stream behaviour. + +- **GIVEN** the change is complete +- **WHEN** a reader encounters `finalizeQuietly`/`finalize` +- **THEN** the cross-file ordering invariant is stated in a comment that passes the deletion test, and no code path in `logWriteStream.ts` behaves differently + +### Non-Goals + +- No behavioural change to `logWriteStream.ts`, `AndroidLogcatProvider.ts`, or `IOSLogProvider.ts` (providers touched only transiently during mutation verification; zero net diff) +- No test pinning the quiet-then-loud second-stop accident — that would cement an accident as a contract +- No modification of any existing test (append-only) +- Never `git add`/commit anything in this stage; `fab/backlog.md` is never touched + +## Tasks + +### Phase 2: Core Implementation + +- [x] T001 Add the provider-level failing-stream stop tests to `packages/device-node/src/device/test/logCaptureProviders.test.ts`: a small structural helper to reach the tracked stream (mirroring `providerRegistry`/`liveStreamCount`) plus a new `for (const platform of ['Android', 'iOS'] as const)` block, inserted after the existing platform loop and before the first registry test (so the deliberately-last test stays last). Each test: start against `createUnopenableFilePath()`, `await once(trackedStream, 'error')`, end `stdout`, stop, assert `success === false`, message matches `/ENOENT/`, `liveStreamCount === 0`. Append-only — no existing test touched. +- [x] T002 [P] Add one clarifying sentence to `finalize`'s doc comment in `packages/device-node/src/device/logWriteStream.ts` (item A rationale: recorded error rejects even when the flush succeeded; comment-only). +- [x] T003 [P] Add the once-consumed ordering-invariant rationale comment to `finalizeQuietly`'s doc comment in `packages/device-node/src/device/logWriteStream.ts` (item B; comment-only). + +### Phase 3: Integration & Edge Cases + +- [x] T004 Rebuild and run `npm test` in `packages/device-node`; confirm 122 tests, all green, and that the pre-existing 120 are unchanged. +- [x] T005 Mutation-kill verification: apply `finalize` → `finalizeQuietly` at `AndroidLogcatProvider.ts` success-path call (~line 157) and `IOSLogProvider.ts` (~line 135), rebuild, run tests, confirm the two new tests FAIL; revert with `git checkout -- packages/device-node/src/device/AndroidLogcatProvider.ts packages/device-node/src/device/IOSLogProvider.ts`, confirm `git status` shows the providers clean, rebuild, re-run tests, confirm all 122 green. Capture the failing output as evidence. + +## Execution Order + +- T001 blocks T004; T004 blocks T005 +- T002/T003 are comment-only and can run alongside T001 + +## Acceptance + +### Functional Completeness + +- [x] A-001 R1: Two new parameterized provider tests (Android + iOS) exist in `logCaptureProviders.test.ts`, reuse `createUnopenableFilePath()`, and pass against the unmutated providers +- [x] A-002 R3: `finalize`'s unconditional recorded-error rejection is unchanged; item A is addressed by at most one clarifying doc sentence +- [x] A-003 R4: The once-consumed ordering invariant is documented in `logWriteStream.ts` as a rationale comment passing the deletion test + +### Behavioral Correctness + +- [x] A-004 R1: The new tests assert the caller-visible contract — `success === false`, message matching `/ENOENT/`, `liveStreamCount === 0` — not registry internals beyond the established structural-access pattern +- [x] A-005 R2: With the two-site `finalize` → `finalizeQuietly` mutation applied, the new tests fail; after `git checkout` revert the providers are clean and the full suite is green (procedural evidence reported) + +### Scenario Coverage + +- [x] A-006 R1: The tests await the stream's `error` event deterministically (no sleeps/arbitrary timeouts) before stopping, and use the default `'exits'` fake-child behaviour with `stdout` ended + +### Edge Cases & Error Handling + +- [x] A-007 R1: Test changes are append-only — no existing test modified or weakened; the deliberately-last test (throwing-sink) remains last in the file + +### Removal Verification + +- [x] A-008 R3: No `writableFinished` guard was added and no behavioural diff exists in `logWriteStream.ts` (comment-only edits) + +### Code Quality + +- [x] A-009 Pattern consistency: New tests follow the file's existing conventions (structural private-state access helpers, `once`-based awaits, platform-parameterized loop shape) +- [x] A-010 No unnecessary duplication: `createUnopenableFilePath()` and the existing stub helpers are reused; no duplicate helpers written +- [x] A-011 Comment content: New comments carry rationale/coupling information that passes the deletion test (no restatement comments) + +### Review Verification (2026-07-31) + +Evidence recorded by the review stage: + +- Clean rebuild (`npm run build`) + `npm test` in `packages/device-node`: **122 tests, 122 pass, 0 fail** — both new tests named in the output (A-001, A-004). +- `git diff --numstat`: `logCaptureProviders.test.ts` **66 added / 0 deleted** (strictly insertion-only, A-007); `logWriteStream.ts` **17 added / 1 deleted**, the single deletion being one JSDoc line replaced by an extended version of the same prose — comment-only, no behavioural diff (A-002, A-008). The deliberately-last throwing-sink test remains last in the file. +- Mutation kill re-run independently: `finalize` → `finalizeQuietly` at `AndroidLogcatProvider.ts:157` and `IOSLogProvider.ts:135` → **120 pass / 2 fail**, and the two failures are exactly the two new tests. Reverted with `git checkout --`; `git status` shows both providers clean; rebuild + re-run → **122/122 green** (A-005). +- Determinism (A-006): `open()` is the last statement before `startLogCapture` returns on the test's path, and the `fs.open` completion is a macrotask, so no `error` event can precede the `once(trackedStream(...), 'error')` attach. No sleeps or timeouts. +- `npx eslint` on both changed files: clean. (`prettier --check` flags `logCaptureProviders.test.ts`, but the sole violation is the pre-existing `spawnStub` cast at lines 93–98 — present on `HEAD` and untouched by this change; no CI job runs prettier.) +- A-010 checked on the item's own terms: `createUnopenableFilePath()` and every module-level stub helper are reused, and no duplicate *helper* was written. The per-loop `createProvider` arrow function is duplicated verbatim (lines 242–251 vs 121–130), which `plan.md` R1 explicitly prescribed ("reusing its `createProvider`-**style** construction"); it is reported as a should-fix rather than an acceptance failure. + +## Notes + +- Check items as you review: `- [x]` +- All acceptance items must pass before `/fab-continue` (hydrate) +- If an item is not applicable, mark checked and prefix with **N/A**: `- [x] A-NNN **N/A**: {reason}` + +## Deletion Candidates + +- None — this change adds test coverage and rationale comments without making existing code redundant. Specifically checked: the seven registry-level tests added by PR #168 (`logCaptureProviders.test.ts:292–473`) are **not** superseded by the new provider-level tests — they pin registry contracts the provider tests cannot reach (listener attachment at `open()` return, first-error-wins, `finalizeQuietly`'s resolve-and-log, the throwing-`Logger`-sink escape paths), while the new tests pin only the caller-visible `DeviceNodeResponse`. No source symbol, branch, or config became unused. + +## Assumptions + +| # | Grade | Decision | Rationale | Scores | +|---|-------|----------|-----------|--------| +| 1 | Certain | Await the failed open deterministically via structural access to the registry's tracked entry (`_streams.get(path).stream`) + `await once(stream, 'error')` | Intake left the settle technique to apply but required determinism; the file already reads private state structurally (`providerRegistry`, `liveStreamCount`) and its registry tests already use `once(stream, 'error')` — this composes both established patterns with zero new machinery | S:80 R:90 A:90 D:85 | +| 2 | Confident | Item A: add the single clarifying sentence to `finalize`'s doc comment rather than leaving the existing prose | Intake explicitly weighed both and called it an apply-time judgement; the existing sentence covers errors recorded "long before this call" but not the flush-succeeded case the pinning test constructs, so one sentence carries non-recoverable rationale (autoDestroy reachability) and passes the deletion test | S:70 R:85 A:80 D:65 | +| 3 | Certain | Item B's invariant comment lands on `finalizeQuietly`'s doc comment (with a pointer from the consumption site) rather than inside `finalize`'s `finally` | Intake offered either location; `finalizeQuietly` is the call whose early placement triggers the hazard, so its doc is where the reader who could misorder the calls looks first | S:75 R:90 A:85 D:75 | +| 4 | Confident | The new tests do not write `LOG_PAYLOAD` into the failed stream | Intake states the payload is unnecessary — the defect is about the error, not the bytes; the errored stream auto-unpiped, so bytes would go nowhere and only add noise | S:85 R:90 A:85 D:80 | + +4 assumptions (2 certain, 2 confident, 0 tentative). diff --git a/packages/device-node/src/device/logWriteStream.ts b/packages/device-node/src/device/logWriteStream.ts index dd43ee7..22c0dda 100644 --- a/packages/device-node/src/device/logWriteStream.ts +++ b/packages/device-node/src/device/logWriteStream.ts @@ -133,7 +133,14 @@ export class LogWriteStreamRegistry { * 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. + * 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. */ async finalize(outputFilePath: string, source?: Readable | null): Promise { const entry = this._streams.get(outputFilePath); @@ -184,6 +191,22 @@ export class LogWriteStreamRegistry { * Shared here rather than repeated in each provider for the same reason the * rest of this bookkeeping is: the two versions would differ only by a log * prefix, and the output file path already identifies the capture. + * + * Ordering matters across the two entry points: a recorded error is consumed + * by whichever finalization runs first ({@link finalize} drops the entry in + * its `finally`), so a quiet call before a loud one for the same path + * swallows the error here and leaves the later {@link finalize} to find an + * untracked path and resolve — success over a possibly-unwritten file. A + * caller that needs the error surfaced must therefore call {@link finalize} + * before any `finalizeQuietly` for the same path. What guarantees that today + * lives outside this file: both providers' `stopLogCapture` run the loud call + * on the success path before any quiet catch-path call, and + * `LogCaptureManager`'s `_stoppedTestCases` set prevents a *sequential* + * second stop from reaching quiet-then-loud. Overlapping calls it does not + * cover: the set's `has()` check and its `add()` straddle the awaited + * `stopLogCapture`, so a concurrent stop/abort pair for the same capture is a + * check-then-act race — an accepted hazard, recorded in + * `docs/memory/device-node/log-capture.md`. */ async finalizeQuietly(outputFilePath: string, source?: Readable | null): Promise { try { diff --git a/packages/device-node/src/device/test/logCaptureProviders.test.ts b/packages/device-node/src/device/test/logCaptureProviders.test.ts index 1385176..bebce18 100644 --- a/packages/device-node/src/device/test/logCaptureProviders.test.ts +++ b/packages/device-node/src/device/test/logCaptureProviders.test.ts @@ -223,6 +223,72 @@ for (const platform of ['Android', 'iOS'] as const) { }); } +/** + * The write stream the registry tracks for `outputFilePath`, read structurally + * for the same reason as `providerRegistry` above. The provider owns the stream + * privately, and the failing-stop tests below must await its asynchronous + * `error` event deterministically before stopping — anything sleep-based races + * the fd open on a slow box. + */ +function trackedStream(registry: LogWriteStreamRegistry, outputFilePath: string): EventEmitter { + const entry = ( + registry as unknown as { _streams: Map } + )._streams.get(outputFilePath); + assert.ok(entry, `no tracked write stream for ${outputFilePath}`); + return entry.stream; +} + +for (const platform of ['Android', 'iOS'] as const) { + const createProvider = (childProcess: FakeChildProcess): LogCaptureProvider => + platform === 'Android' + ? new AndroidLogcatProvider({ + execFileFn: execFileStub, + spawnFn: spawnStub(childProcess), + }) + : new IOSLogProvider({ + execFileFn: execFileStub, + spawnFn: spawnStub(childProcess), + }); + + test(`${platform} log capture stop reports failure over a write stream that never opened`, async () => { + const outputFilePath = await createUnopenableFilePath(); + const childProcess = new FakeChildProcess(); + const provider = createProvider(childProcess); + + // The start still succeeds: `fs.createWriteStream` opens its fd + // asynchronously, so the ENOENT arrives as an `error` event only after + // `startLogCapture` has returned. + await startCapture(provider, childProcess, outputFilePath); + + const [openError] = await once( + trackedStream(providerRegistry(provider), outputFilePath), + 'error', + ); + assert.match(String(openError), /ENOENT/); + + // No payload: the defect this pins is about the error, not the bytes — the + // errored stream auto-destroyed and the pipe detached itself, so nothing + // written here could reach the file anyway. Ending stdout lets the stop's + // drain reach EOF instead of its 5 s timeout. + childProcess.stdout.end(); + + const stopped = await provider.stopLogCapture({ + process: childProcess as unknown as ChildProcess, + outputFilePath, + }); + + // The caller-visible half of the fix the registry tests above cannot see: + // the success path calls `finalize` — not `finalizeQuietly` — so the + // recorded open error reaches the stop response as a failure. Mutating + // that one call to the quiet variant restores the original defect (a + // successful stop over a log file that was never written) while every + // registry-level test stays green; these assertions are what kill it. + assert.equal(stopped.success, false); + assert.match(stopped.message ?? '', /ENOENT/); + assert.equal(liveStreamCount(providerRegistry(provider)), 0); + }); +} + test('LogWriteStreamRegistry ends and untracks the stream when the source errors', async () => { const outputFilePath = await createOutputFilePath(); const registry = new LogWriteStreamRegistry();