From 7cd8e8963f37e2977e4fd395cf1fd76ab5963f9e Mon Sep 17 00:00:00 2001 From: Dan Shapiro <3732858+danshapiro@users.noreply.github.com> Date: Fri, 21 Aug 2026 01:35:12 -0700 Subject: [PATCH 1/9] docs: add implementation plan for logger-separation-flake --- .../2026-08-21-logger-separation-flake.md | 279 ++++++++++++++++++ 1 file changed, 279 insertions(+) create mode 100644 docs/plans/2026-08-21-logger-separation-flake.md diff --git a/docs/plans/2026-08-21-logger-separation-flake.md b/docs/plans/2026-08-21-logger-separation-flake.md new file mode 100644 index 000000000..fb4ded3e7 --- /dev/null +++ b/docs/plans/2026-08-21-logger-separation-flake.md @@ -0,0 +1,279 @@ +# Logger Separation Flake Fix Implementation Plan + +> **For agentic workers:** Execute this plan task by task with a fresh +> implementer and a specification-plus-quality review after every task. Track +> progress with the checkbox steps below. + +## User Request + +### Requested result +Fix the flaky integration test `test/integration/server/logger.separation.test.ts` (test "debug log separation > concurrent launches with the same mode keep separate files") so it passes reliably under the cloud test backend. + +### Explicit constraints +- Fix the flakiness (system over symptom); do not skip, weaken, or reduce coverage of the test. +- Work in a dedicated worktree on a branch from origin/main; do not merge the branch (PR happens separately). +- Cloud backends are configured for vitest and e2e (FRESHELL_VITEST_BACKEND/FRESHELL_E2E_BACKEND=cloud); broad/base gates against origin/main go through scripts/base-gate.sh. + +### Accepted tradeoffs and residuals +- A prior mitigation already on main (widening the file-content wait from 5s to 30s) did not eliminate the flake; the fix must address why the expected log line never appears under shard contention, not merely the wait duration. + +**Goal:** The debug-log startup receipt (`Resolved debug log path`) is written durably at logger construction, so a short-lived process that imports `server/logger.ts` and exits promptly never loses it, and the `logger.separation` integration tests pass deterministically on local and cloud backends. + +**Architecture:** `createLogger()` currently routes the one-time marker through the lazily-opened `rotating-file-stream`, so the line sits in an in-memory buffer that `process.exit()` can discard. Replace that one marker write with a synchronous `fs.appendFileSync` receipt of identical JSON shape, emitted inside the same `createLogger()` path and the same try/catch. Rotating-file-stream then handles only the ongoing verbose stream, unchanged. + +**Tech Stack:** Node.js/TypeScript (NodeNext/ESM), pino, rotating-file-stream, Vitest. + +## Global Constraints + +- Server code is NodeNext/ESM; relative imports must include `.js` extensions. The fix adds no new imports (`fs` and `path` are already imported in `server/logger.ts`). +- The marker line's JSON shape must stay byte-compatible with what the integration test parses: top-level `msg: "Resolved debug log path"`, `filePath`, `debugMode`, `debugInstance`, `app: "freshell"`, `env`, `version` (omitted when undefined), plus pino's `level: 30`, `severity: "info"`, `time` (ISO-8601). The current pino options replace `base` with `{app, env, version}`, so the marker line carries **no** `pid`/`hostname` — do not add them. +- Respect level semantics: the marker today is an `info` log, suppressed when the effective level is above `info` (e.g. `LOG_LEVEL=warn`). The synchronous write preserves that by gating on `isLevelEnabled('info')`. +- The marker goes only to the debug file, never to stdout/stderr (the console stream sits at `error` level and the first integration test asserts the marker never appears there). +- Never reduce coverage: do not skip or delete any existing test; the existing 30s content gates stay as-is. +- Run tests through repo-owned paths (`npm run test:vitest -- ...`), from the run worktree `/home/dan/code/freshell/.worktrees/logger-separation-flake`. +- `rotating-file-stream` tracks file size for rotation from its own writes; the out-of-band receipt is one short line per process launch — acceptable and noted, no guard needed. + +--- + +### Task 1: Durable synchronous startup marker in `createLogger()` + +**Files:** +- Modify: `server/logger.ts` (marker emission at ~line 344-347; new helper near `createDebugFileStream` at ~line 231) +- Test: `test/unit/server/logger.test.ts` (append a new `describe` at the end) +- Test: `test/integration/server/logger.separation.test.ts` (append one new test inside the existing `describe('debug log separation', ...)`) + +**Interfaces:** +- Consumes: `createLogger()` (`server/logger.ts`), `resolveDebugLogPath()` semantics (explicit `LOG_DEBUG_PATH` short-circuits the test-runtime null — that is what makes the unit test possible under vitest), the existing `logger.separation.test.ts` harness (`startSourceLoggerProcess`, `activeProcesses`). +- Produces: no new exported interface; `createLogger()` behavior change only (marker durability). + +- [ ] **Step 1: Write the failing behavioral tests** + +Part A — unit test (in `test/unit/server/logger.test.ts`): first merge any missing imports (`readFileSync` from `node:fs`, `fsp` from `node:fs/promises`, `os` from `node:os`, `path` from `node:path`) into the file's import block — skip any already present. Then append a new `describe` at the end of the file's existing top-level `describe`, reusing the file's existing `vi.resetModules()`-in-`beforeEach` + dynamic re-import convention: + +```ts +import { readFileSync } from 'node:fs' +import fsp from 'node:fs/promises' +import os from 'node:os' +import path from 'node:path' + +// ...inside the file's existing top-level describe, at the end: + + describe('startup debug marker durability', () => { + it('writes the resolved-path marker synchronously during logger construction', async () => { + const dir = await fsp.mkdtemp(path.join(os.tmpdir(), 'freshell-logger-marker-')) + const debugPath = path.join(dir, 'debug.jsonl') + process.env.LOG_DEBUG_PATH = debugPath + try { + await import("../../../server/logger") + // No waiting: the receipt must be durable before createLogger() returns. + // Pre-fix the marker only sat buffered in the lazily-opened rotating + // stream, so this file is missing or empty at this point. + const content = readFileSync(debugPath, 'utf8') + const line = content + .split(/\r?\n/) + .find((l) => l.includes('Resolved debug log path')) + expect(line).toBeDefined() + const parsed = JSON.parse(line as string) + expect(parsed).toMatchObject({ + msg: 'Resolved debug log path', + level: 30, + severity: 'info', + app: 'freshell', + filePath: debugPath, + }) + expect(typeof parsed.time).toBe('string') + expect(parsed.debugMode).toBeDefined() + expect(parsed.debugInstance).toBeDefined() + expect(parsed).not.toHaveProperty('pid') + expect(parsed).not.toHaveProperty('hostname') + } finally { + delete process.env.LOG_DEBUG_PATH + } + }) + + it('respects info-level suppression for the marker', async () => { + const dir = await fsp.mkdtemp(path.join(os.tmpdir(), 'freshell-logger-marker-suppressed-')) + const debugPath = path.join(dir, 'debug.jsonl') + process.env.LOG_DEBUG_PATH = debugPath + process.env.LOG_LEVEL = 'warn' + try { + await import("../../../server/logger") + const exists = readFileSync(debugPath, 'utf8') + expect(exists).not.toContain('Resolved debug log path') + } finally { + delete process.env.LOG_DEBUG_PATH + delete process.env.LOG_LEVEL + } + }) + }) +``` + +Note for the implementer: at `LOG_LEVEL=warn` pre-fix the empty-file state satisfies `not.toContain` vacuously (see Step 2). Post-fix the marker must exist in the durability test and remain absent in the suppression test — the pair pins both halves of the `isLevelEnabled('info')` gate. If the suppression test fails post-fix, that is a real production defect to fix, not a test to weaken. + +Part B — integration test (append inside `describe('debug log separation', ...)` in `test/integration/server/logger.separation.test.ts`; add `import { once } from 'node:events'` to the imports at top): + +```ts + it( + 'keeps the resolved-path receipt durable when the process exits immediately after import', + { timeout: DEFAULT_TEST_TIMEOUT_MS }, + async () => { + await withLogDir(async (logDir) => { + // The red lever: NO post-import timer at all — the child exits on the + // first macrotask after the import resolves, so rotating-file-stream's + // async open can never win. Pre-fix this is 100% red on any machine; + // post-fix the synchronous receipt makes it 100% green. + const IMMEDIATE_EXIT_PROBE = [ + '(async () => {', + " process.argv = ['node', 'server/index.ts']", + " await import('./server/logger.ts')", + ' process.exit(0)', + '})()', + ].join('\n') + const proc = await startServerProcess( + [process.execPath, getTSXCLI(), '-e', IMMEDIATE_EXIT_PROBE], + { + FRESHELL_LOG_DIR: logDir, + FRESHELL_LOG_INSTANCE_ID: 'immediate-exit', + NODE_ENV: 'development', + }, + REPO_ROOT, + ) + activeProcesses.push(proc) + await once(proc.process, 'exit') + + const markerPath = path.join(logDir, 'server-debug.development.immediate-exit.jsonl') + const content = await fsp.readFile(markerPath, 'utf8').catch(() => '') + expect(content).toContain('Resolved debug log path') + + const startupPayload = parseStartupLogPayload(content) + expect(startupPayload).not.toBeNull() + expect(startupPayload).toMatchObject({ + debugMode: 'development', + debugInstance: 'immediate-exit', + }) + }) + }, + ) +``` + +- [ ] **Step 2: Run the tests and verify the intended failures** + +Run: +```bash +npm run test:vitest -- run test/unit/server/logger.test.ts +npm run test:vitest -- run test/integration/server/logger.separation.test.ts --config config/vitest/vitest.server.config.ts +``` + +Expected: FAIL for exactly two new tests, for the durability reason: the unit durability test finds no `Resolved debug log path` line (file missing or empty at assertion time), and the integration test fails with `expect(content).toContain('Resolved debug log path')` receiving `''`. The second new unit test (`respects info-level suppression...`) may PASS pre-fix — pre-fix nothing reaches the file promptly at any level, so `not.toContain` is satisfied vacuously; it is a guard test whose real value is post-fix (marker written when allowed, still suppressed at `warn`). All pre-existing tests in both files still pass. + +If either new test unexpectedly PASSES pre-fix, stop: the repro is not load-bearing; re-investigate before implementing (do not weaken the test to manufacture a failure). + +- [ ] **Step 3: Add the minimal production implementation** + +In `server/logger.ts`, add the helper next to `createDebugFileStream` (~line 231): + +```ts +/** + * One-time startup receipt for the resolved debug log destination, appended + * SYNCHRONOUSLY at logger construction. rotating-file-stream opens lazily and + * buffers writes until its async open completes; a short-lived process that + * imports this module and exits promptly would otherwise lose the marker + * (observed as a hung-then-empty debug file in the logger.separation + * integration suite under CI shard contention). The direct append makes the + * receipt durable before createLogger() returns. Emitted before the stream's + * first write so rotating-file-stream's stat-based size bookkeeping already + * sees these bytes. Kept under createLogger()'s existing try/catch. + */ +function writeDebugLogPathMarkerSync(resolved: { + filePath: string + debugMode: LogMode + debugInstance: string +}): void { + const line = { + level: 30, + severity: 'info', + time: new Date().toISOString(), + app: 'freshell', + env, + version: appVersion, + ...resolved, + msg: 'Resolved debug log path', + } + fs.appendFileSync(resolved.filePath, `${JSON.stringify(line)}\n`) +} +``` + +Then, in `createLogger()`, replace: + +```ts + const nextLogger = pino(createPinoOptions(), pino.multistream(streams)) + if (resolvedDebugLog) { + nextLogger.info(resolvedDebugLog, 'Resolved debug log path') + } + return nextLogger +``` + +with: + +```ts + const nextLogger = pino(createPinoOptions(), pino.multistream(streams)) + if (resolvedDebugLog && nextLogger.isLevelEnabled('info')) { + writeDebugLogPathMarkerSync(resolvedDebugLog) + } + return nextLogger +``` + +Placement detail: the `writeDebugLogPathMarkerSync` call replaces — not duplicates — the stream-routed marker. The existing `try/catch` that builds `resolvedDebugLog` still covers stream construction and stays as-is. The level gate belongs on the constructed logger (`isLevelEnabled`), which requires `nextLogger` to exist; and the marker write gets its own narrow guard so a filesystem failure degrades to a diagnostic warning instead of crashing startup. The final shape of the section: + +```ts + const nextLogger = pino(createPinoOptions(), pino.multistream(streams)) + if (resolvedDebugLog && nextLogger.isLevelEnabled('info')) { + try { + writeDebugLogPathMarkerSync(resolvedDebugLog) + } catch (err) { + consoleDiagnosticLogger.warn({ err, filePath: resolvedDebugLog.filePath }, 'Debug log marker write failed') + } + } + return nextLogger +``` + +This is the intended final shape: one synchronous receipt, swallowed-with-warning on failure, console streams untouched. + +- [ ] **Step 4: Run the focused tests** + +Run: +```bash +npm run test:vitest -- run test/unit/server/logger.test.ts +npm run test:vitest -- run test/integration/server/logger.separation.test.ts --config config/vitest/vitest.server.config.ts +``` + +Expected: PASS — both new tests and every pre-existing test in both files. + +- [ ] **Step 5: Refactor while green** + +- Remove now-unneeded machinery only if the marker's old pino route left anything (it did not add any). +- Keep the 30s `FILE_CONTENT_TIMEOUT_MS` — it bounds content gates, not durability; the file's header comment about the 2026-08-18 observation stays accurate but should gain one sentence noting the durability fix (edit the comment, do not change the timeout value). + +- [ ] **Step 6: Run impacted-test verification** + +The change affects only `createLogger()` marker emission. Impacted set: every test that imports the real `server/logger.ts` marker path (the two files above) plus any test asserting on `createDebugFileStream`/debug streams. Unit runtime is gated away from the marker by `isTestRuntime`/env deletion except via explicit `LOG_DEBUG_PATH`, which only `logger.test.ts` uses. + +Run: +```bash +npm run test:vitest -- run test/unit/server/logger.test.ts +npm run test:vitest -- run test/integration/server/logger.separation.test.ts --config config/vitest/vitest.server.config.ts +rg -l "createDebugFileStream|Resolved debug log path" test/ | tr '\n' ' ' +``` + +Run any additional files the `rg` lists that actually execute the marker path (not docs). + +Expected: PASS for the full impacted set. + +- [ ] **Step 7: Commit the task** + +```bash +git add server/logger.ts test/unit/server/logger.test.ts test/integration/server/logger.separation.test.ts +git commit -m "fix(server): write the debug-path startup receipt synchronously so short-lived imports never lose it" +``` + +--- From 6c3ec268559782bf9f4fb4d14738a9f3400d1dd5 Mon Sep 17 00:00:00 2001 From: Dan Shapiro <3732858+danshapiro@users.noreply.github.com> Date: Fri, 21 Aug 2026 01:51:40 -0700 Subject: [PATCH 2/9] docs: plan corrections from load-bearing finder (suppression-test file absence, env hygiene, stat-comment precision, cloud verification step) --- .../2026-08-21-logger-separation-flake.md | 30 ++++++++++++++----- 1 file changed, 23 insertions(+), 7 deletions(-) diff --git a/docs/plans/2026-08-21-logger-separation-flake.md b/docs/plans/2026-08-21-logger-separation-flake.md index fb4ded3e7..0d7a66611 100644 --- a/docs/plans/2026-08-21-logger-separation-flake.md +++ b/docs/plans/2026-08-21-logger-separation-flake.md @@ -48,7 +48,7 @@ Fix the flaky integration test `test/integration/server/logger.separation.test.t - [ ] **Step 1: Write the failing behavioral tests** -Part A — unit test (in `test/unit/server/logger.test.ts`): first merge any missing imports (`readFileSync` from `node:fs`, `fsp` from `node:fs/promises`, `os` from `node:os`, `path` from `node:path`) into the file's import block — skip any already present. Then append a new `describe` at the end of the file's existing top-level `describe`, reusing the file's existing `vi.resetModules()`-in-`beforeEach` + dynamic re-import convention: +Part A — unit test (in `test/unit/server/logger.test.ts`): first merge any missing imports (`readFileSync` and `existsSync` from `node:fs`, `fsp` from `node:fs/promises`, `os` from `node:os`, `path` from `node:path`) into the file's import block — skip any already present. Then append a new `describe` at the end of the file's existing top-level `describe`, reusing the file's existing `vi.resetModules()`-in-`beforeEach` + dynamic re-import convention: ```ts import { readFileSync } from 'node:fs' @@ -62,6 +62,7 @@ import path from 'node:path' it('writes the resolved-path marker synchronously during logger construction', async () => { const dir = await fsp.mkdtemp(path.join(os.tmpdir(), 'freshell-logger-marker-')) const debugPath = path.join(dir, 'debug.jsonl') + delete process.env.LOG_LEVEL process.env.LOG_DEBUG_PATH = debugPath try { await import("../../../server/logger") @@ -98,8 +99,11 @@ import path from 'node:path' process.env.LOG_LEVEL = 'warn' try { await import("../../../server/logger") - const exists = readFileSync(debugPath, 'utf8') - expect(exists).not.toContain('Resolved debug log path') + // The file may not exist yet: at warn level nothing is written + // synchronously, and the lazily-opened stream may never have landed. + // Absence IS the suppressed outcome — only guard content if present. + const content = existsSync(debugPath) ? readFileSync(debugPath, 'utf8') : '' + expect(content).not.toContain('Resolved debug log path') } finally { delete process.env.LOG_DEBUG_PATH delete process.env.LOG_LEVEL @@ -180,9 +184,10 @@ In `server/logger.ts`, add the helper next to `createDebugFileStream` (~line 231 * imports this module and exits promptly would otherwise lose the marker * (observed as a hung-then-empty debug file in the logger.separation * integration suite under CI shard contention). The direct append makes the - * receipt durable before createLogger() returns. Emitted before the stream's - * first write so rotating-file-stream's stat-based size bookkeeping already - * sees these bytes. Kept under createLogger()'s existing try/catch. + * receipt durable before createLogger() returns. One out-of-band line per + * process launch: rotating-file-stream's open-time stat may or may not see + * these bytes yet (threadpool race), so rotation size accounting can be off + * by at most this one line at the 10M cap — negligible. */ function writeDebugLogPathMarkerSync(resolved: { filePath: string @@ -251,8 +256,11 @@ Expected: PASS — both new tests and every pre-existing test in both files. - [ ] **Step 5: Refactor while green** -- Remove now-unneeded machinery only if the marker's old pino route left anything (it did not add any). +- Remove now-unneeded machinery only if the marker's old pino route left anything (it did not add any). - Keep the 30s `FILE_CONTENT_TIMEOUT_MS` — it bounds content gates, not durability; the file's header comment about the 2026-08-18 observation stays accurate but should gain one sentence noting the durability fix (edit the comment, do not change the timeout value). +- Recorded behavior deltas, accepted deliberately: + - If the debug file is already at the 10MB rotation cap at process start, rotating-file-stream rotates at open time, which can move the freshly appended receipt into the rotated archive, leaving the active file without the marker. Diagnostic-only, never exercised by any test; no guard added. + - The first integration test's `LOG_LEVEL_PROBE` (50ms timer) keeps the theoretical exit-before-open loss window for its `error-level` content line; the reported flake concerned the marker receipt, which is now durable. No change in scope. - [ ] **Step 6: Run impacted-test verification** @@ -269,6 +277,14 @@ Run any additional files the `rg` lists that actually execute the marker path (n Expected: PASS for the full impacted set. +Then verify on the configured CLOUD backend — the venue where the flake lives (the local-focused commands above never reach it). The repo's cloud script takes `=`-joined flags: + +```bash +bash scripts/vitest-cloud.sh run --cloud --config=server test/integration/server/logger.separation.test.ts +``` + +Expected: all tests in the file pass on Cloud Run. (Local `npm run test:vitest -- run --config ` demonstrably selects the intended file and config — verified by observation earlier today; keep it for local loops only.) + - [ ] **Step 7: Commit the task** ```bash From bf1a821852325519b7a9707b6aae6f47462f1024 Mon Sep 17 00:00:00 2001 From: Dan Shapiro <3732858+danshapiro@users.noreply.github.com> Date: Fri, 21 Aug 2026 02:09:21 -0700 Subject: [PATCH 3/9] docs: align plan Part A import block with existsSync usage (fresh-eyes r1) --- docs/plans/2026-08-21-logger-separation-flake.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/plans/2026-08-21-logger-separation-flake.md b/docs/plans/2026-08-21-logger-separation-flake.md index 0d7a66611..1075bcca4 100644 --- a/docs/plans/2026-08-21-logger-separation-flake.md +++ b/docs/plans/2026-08-21-logger-separation-flake.md @@ -51,7 +51,7 @@ Fix the flaky integration test `test/integration/server/logger.separation.test.t Part A — unit test (in `test/unit/server/logger.test.ts`): first merge any missing imports (`readFileSync` and `existsSync` from `node:fs`, `fsp` from `node:fs/promises`, `os` from `node:os`, `path` from `node:path`) into the file's import block — skip any already present. Then append a new `describe` at the end of the file's existing top-level `describe`, reusing the file's existing `vi.resetModules()`-in-`beforeEach` + dynamic re-import convention: ```ts -import { readFileSync } from 'node:fs' +import { existsSync, readFileSync } from 'node:fs' import fsp from 'node:fs/promises' import os from 'node:os' import path from 'node:path' From f342b565d6d0ad1fc4c3259d234e82f03840a8ba Mon Sep 17 00:00:00 2001 From: Dan Shapiro <3732858+danshapiro@users.noreply.github.com> Date: Fri, 21 Aug 2026 02:22:38 -0700 Subject: [PATCH 4/9] docs: plan dispositions for fresh-eyes r2 minors (scoped vitest commands; pin LOG_LEVEL in immediate-exit probe env) --- docs/plans/2026-08-21-logger-separation-flake.md | 12 +++++++++--- 1 file changed, 9 insertions(+), 3 deletions(-) diff --git a/docs/plans/2026-08-21-logger-separation-flake.md b/docs/plans/2026-08-21-logger-separation-flake.md index 1075bcca4..fa6170ba1 100644 --- a/docs/plans/2026-08-21-logger-separation-flake.md +++ b/docs/plans/2026-08-21-logger-separation-flake.md @@ -139,6 +139,10 @@ Part B — integration test (append inside `describe('debug log separation', ... FRESHELL_LOG_DIR: logDir, FRESHELL_LOG_INSTANCE_ID: 'immediate-exit', NODE_ENV: 'development', + // The harness does not scrub ambient LOG_LEVEL; the marker is + // info-level, so an operator's LOG_LEVEL=warn would suppress it + // and keep this test red. Pin the supported default instead. + LOG_LEVEL: 'debug', }, REPO_ROOT, ) @@ -164,10 +168,12 @@ Part B — integration test (append inside `describe('debug log separation', ... Run: ```bash -npm run test:vitest -- run test/unit/server/logger.test.ts +npm run test:vitest -- run test/unit/server/logger.test.ts --config config/vitest/vitest.server.config.ts npm run test:vitest -- run test/integration/server/logger.separation.test.ts --config config/vitest/vitest.server.config.ts ``` +Command-form note (verified empirically this run): `test/unit/server/**` lives in the SERVER vitest config — the default config excludes it. The explicit `--config` keeps the coordinator's `test:vitest` passthrough verbatim; WITHOUT it the coordinator infers the server owner and prepends a second `run`, which vitest then treats as a filename filter — an unscoped `npm run test:vitest -- run test/unit/server/logger.test.ts` selected 11 files / 243 tests instead of 1 file / 36 tests. + Expected: FAIL for exactly two new tests, for the durability reason: the unit durability test finds no `Resolved debug log path` line (file missing or empty at assertion time), and the integration test fails with `expect(content).toContain('Resolved debug log path')` receiving `''`. The second new unit test (`respects info-level suppression...`) may PASS pre-fix — pre-fix nothing reaches the file promptly at any level, so `not.toContain` is satisfied vacuously; it is a guard test whose real value is post-fix (marker written when allowed, still suppressed at `warn`). All pre-existing tests in both files still pass. If either new test unexpectedly PASSES pre-fix, stop: the repro is not load-bearing; re-investigate before implementing (do not weaken the test to manufacture a failure). @@ -248,7 +254,7 @@ This is the intended final shape: one synchronous receipt, swallowed-with-warnin Run: ```bash -npm run test:vitest -- run test/unit/server/logger.test.ts +npm run test:vitest -- run test/unit/server/logger.test.ts --config config/vitest/vitest.server.config.ts npm run test:vitest -- run test/integration/server/logger.separation.test.ts --config config/vitest/vitest.server.config.ts ``` @@ -268,7 +274,7 @@ The change affects only `createLogger()` marker emission. Impacted set: every te Run: ```bash -npm run test:vitest -- run test/unit/server/logger.test.ts +npm run test:vitest -- run test/unit/server/logger.test.ts --config config/vitest/vitest.server.config.ts npm run test:vitest -- run test/integration/server/logger.separation.test.ts --config config/vitest/vitest.server.config.ts rg -l "createDebugFileStream|Resolved debug log path" test/ | tr '\n' ' ' ``` From e9be68c73f98ef16ecbc755e35676258a20b276b Mon Sep 17 00:00:00 2001 From: Dan Shapiro <3732858+danshapiro@users.noreply.github.com> Date: Fri, 21 Aug 2026 02:37:43 -0700 Subject: [PATCH 5/9] fix(server): write the debug-path startup receipt synchronously so short-lived imports never lose it --- server/logger.ts | 38 ++++++++++++- .../server/logger.separation.test.ts | 50 +++++++++++++++++ test/unit/server/logger.test.ts | 54 +++++++++++++++++++ 3 files changed, 140 insertions(+), 2 deletions(-) diff --git a/server/logger.ts b/server/logger.ts index b96ccae7b..2d7cde385 100644 --- a/server/logger.ts +++ b/server/logger.ts @@ -230,6 +230,36 @@ export function createDebugFileStream(filePath: string, options: DebugFileStream return createStream(path.basename(filePath), { path: dir, size, maxFiles }) } +/** + * One-time startup receipt for the resolved debug log destination, appended + * SYNCHRONOUSLY at logger construction. rotating-file-stream opens lazily and + * buffers writes until its async open completes; a short-lived process that + * imports this module and exits promptly would otherwise lose the marker + * (observed as a hung-then-empty debug file in the logger.separation + * integration suite under CI shard contention). The direct append makes the + * receipt durable before createLogger() returns. One out-of-band line per + * process launch: rotating-file-stream's open-time stat may or may not see + * these bytes yet (threadpool race), so rotation size accounting can be off + * by at most this one line at the 10M cap — negligible. + */ +function writeDebugLogPathMarkerSync(resolved: { + filePath: string + debugMode: LogMode + debugInstance: string +}): void { + const line = { + level: 30, + severity: 'info', + time: new Date().toISOString(), + app: 'freshell', + env, + version: appVersion, + ...resolved, + msg: 'Resolved debug log path', + } + fs.appendFileSync(resolved.filePath, `${JSON.stringify(line)}\n`) +} + type DedicatedFileLoggerOptions = { filePath: string level?: LevelWithSilent @@ -342,8 +372,12 @@ export function createLogger(destination?: DestinationStream) { } const nextLogger = pino(createPinoOptions(), pino.multistream(streams)) - if (resolvedDebugLog) { - nextLogger.info(resolvedDebugLog, 'Resolved debug log path') + if (resolvedDebugLog && nextLogger.isLevelEnabled('info')) { + try { + writeDebugLogPathMarkerSync(resolvedDebugLog) + } catch (err) { + consoleDiagnosticLogger.warn({ err, filePath: resolvedDebugLog.filePath }, 'Debug log marker write failed') + } } return nextLogger } diff --git a/test/integration/server/logger.separation.test.ts b/test/integration/server/logger.separation.test.ts index c916c8ba3..6ab71b0b8 100644 --- a/test/integration/server/logger.separation.test.ts +++ b/test/integration/server/logger.separation.test.ts @@ -1,4 +1,5 @@ // @vitest-environment node +import { once } from 'node:events' import { readFileSync } from 'node:fs' import fsp from 'node:fs/promises' import os from 'node:os' @@ -22,6 +23,9 @@ const DEFAULT_TEST_TIMEOUT_MS = 120_000 // which filename was chosen, never about how fast). A cold `tsx` start under // full-suite shard contention on a shared Cloud Run vCPU exceeded the old 5s // gate (observed 2026-08-18, execution freshell-vitest-l68jz); unify at 30s. +// Since 2026-08-21 the resolved-path receipt is appended synchronously by +// createLogger(), so marker durability no longer depends on this wait — it +// only covers the stream-routed content lines. const FILE_CONTENT_TIMEOUT_MS = 30_000 const ANSI_ESCAPE_PATTERN = /\u001b\[[0-9;]*m/g const SOURCE_LOGGER_PROBE = [ @@ -311,4 +315,50 @@ describe('debug log separation', () => { }) }, ) + + it( + 'keeps the resolved-path receipt durable when the process exits immediately after import', + { timeout: DEFAULT_TEST_TIMEOUT_MS }, + async () => { + await withLogDir(async (logDir) => { + // The red lever: NO post-import timer at all — the child exits on the + // first macrotask after the import resolves, so rotating-file-stream's + // async open can never win. Pre-fix this is 100% red on any machine; + // post-fix the synchronous receipt makes it 100% green. + const IMMEDIATE_EXIT_PROBE = [ + '(async () => {', + " process.argv = ['node', 'server/index.ts']", + " await import('./server/logger.ts')", + ' process.exit(0)', + '})()', + ].join('\n') + const proc = await startServerProcess( + [process.execPath, getTSXCLI(), '-e', IMMEDIATE_EXIT_PROBE], + { + FRESHELL_LOG_DIR: logDir, + FRESHELL_LOG_INSTANCE_ID: 'immediate-exit', + NODE_ENV: 'development', + // The harness does not scrub ambient LOG_LEVEL; the marker is + // info-level, so an operator's LOG_LEVEL=warn would suppress it + // and keep this test red. Pin the supported default instead. + LOG_LEVEL: 'debug', + }, + REPO_ROOT, + ) + activeProcesses.push(proc) + await once(proc.process, 'exit') + + const markerPath = path.join(logDir, 'server-debug.development.immediate-exit.jsonl') + const content = await fsp.readFile(markerPath, 'utf8').catch(() => '') + expect(content).toContain('Resolved debug log path') + + const startupPayload = parseStartupLogPayload(content) + expect(startupPayload).not.toBeNull() + expect(startupPayload).toMatchObject({ + debugMode: 'development', + debugInstance: 'immediate-exit', + }) + }) + }, + ) }) diff --git a/test/unit/server/logger.test.ts b/test/unit/server/logger.test.ts index 496059fdc..5b8022e70 100644 --- a/test/unit/server/logger.test.ts +++ b/test/unit/server/logger.test.ts @@ -1,4 +1,5 @@ import { describe, it, expect, beforeEach, afterEach, vi } from "vitest" +import { existsSync, readFileSync } from 'node:fs' import os from "os" import path from "path" import fsp from "fs/promises" @@ -581,4 +582,57 @@ describe("logger", () => { TEST_TIMEOUT_MS, ) }) + + describe('startup debug marker durability', () => { + it('writes the resolved-path marker synchronously during logger construction', async () => { + const dir = await fsp.mkdtemp(path.join(os.tmpdir(), 'freshell-logger-marker-')) + const debugPath = path.join(dir, 'debug.jsonl') + delete process.env.LOG_LEVEL + process.env.LOG_DEBUG_PATH = debugPath + try { + await import("../../../server/logger") + // No waiting: the receipt must be durable before createLogger() returns. + // Pre-fix the marker only sat buffered in the lazily-opened rotating + // stream, so this file is missing or empty at this point. + const content = readFileSync(debugPath, 'utf8') + const line = content + .split(/\r?\n/) + .find((l) => l.includes('Resolved debug log path')) + expect(line).toBeDefined() + const parsed = JSON.parse(line as string) + expect(parsed).toMatchObject({ + msg: 'Resolved debug log path', + level: 30, + severity: 'info', + app: 'freshell', + filePath: debugPath, + }) + expect(typeof parsed.time).toBe('string') + expect(parsed.debugMode).toBeDefined() + expect(parsed.debugInstance).toBeDefined() + expect(parsed).not.toHaveProperty('pid') + expect(parsed).not.toHaveProperty('hostname') + } finally { + delete process.env.LOG_DEBUG_PATH + } + }) + + it('respects info-level suppression for the marker', async () => { + const dir = await fsp.mkdtemp(path.join(os.tmpdir(), 'freshell-logger-marker-suppressed-')) + const debugPath = path.join(dir, 'debug.jsonl') + process.env.LOG_DEBUG_PATH = debugPath + process.env.LOG_LEVEL = 'warn' + try { + await import("../../../server/logger") + // The file may not exist yet: at warn level nothing is written + // synchronously, and the lazily-opened stream may never have landed. + // Absence IS the suppressed outcome — only guard content if present. + const content = existsSync(debugPath) ? readFileSync(debugPath, 'utf8') : '' + expect(content).not.toContain('Resolved debug log path') + } finally { + delete process.env.LOG_DEBUG_PATH + delete process.env.LOG_LEVEL + } + }) + }) }) From 3e344f54f4837d6446240ca6fd0632e2db59fabc Mon Sep 17 00:00:00 2001 From: Dan Shapiro <3732858+danshapiro@users.noreply.github.com> Date: Fri, 21 Aug 2026 13:29:15 -0700 Subject: [PATCH 6/9] test(server): pin debug-marker env/version shape and reap temp dirs in new logger marker tests --- test/unit/server/logger.test.ts | 16 ++++++++++++++++ 1 file changed, 16 insertions(+) diff --git a/test/unit/server/logger.test.ts b/test/unit/server/logger.test.ts index 5b8022e70..f1d1b99e0 100644 --- a/test/unit/server/logger.test.ts +++ b/test/unit/server/logger.test.ts @@ -612,8 +612,23 @@ describe("logger", () => { expect(parsed.debugInstance).toBeDefined() expect(parsed).not.toHaveProperty('pid') expect(parsed).not.toHaveProperty('hostname') + // env is captured at module import via `NODE_ENV || 'development'`; + // this test never touches NODE_ENV between import and assertion. + expect(parsed.env).toBe(process.env.NODE_ENV || 'development') + // version mirrors the appVersion rule: JSON.stringify drops an + // undefined version, so under 'test' env without explicit + // npm_package_version/APP_VERSION the key is absent, not null. + const explicitVersion = process.env.npm_package_version || process.env.APP_VERSION + if (explicitVersion) { + expect(parsed.version).toBe(explicitVersion) + } else if ((process.env.NODE_ENV || 'development') === 'test') { + expect(parsed).not.toHaveProperty('version') + } else { + expect(typeof parsed.version).toBe('string') + } } finally { delete process.env.LOG_DEBUG_PATH + await fsp.rm(dir, { recursive: true, force: true }) } }) @@ -632,6 +647,7 @@ describe("logger", () => { } finally { delete process.env.LOG_DEBUG_PATH delete process.env.LOG_LEVEL + await fsp.rm(dir, { recursive: true, force: true }) } }) }) From e529875ebe9781d456dc312845358f594bcb307e Mon Sep 17 00:00:00 2001 From: Dan Shapiro <3732858+danshapiro@users.noreply.github.com> Date: Fri, 21 Aug 2026 13:33:03 -0700 Subject: [PATCH 7/9] docs: mark logger-separation-flake plan task 1 steps complete --- docs/plans/2026-08-21-logger-separation-flake.md | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/docs/plans/2026-08-21-logger-separation-flake.md b/docs/plans/2026-08-21-logger-separation-flake.md index fa6170ba1..8ec6dec09 100644 --- a/docs/plans/2026-08-21-logger-separation-flake.md +++ b/docs/plans/2026-08-21-logger-separation-flake.md @@ -46,7 +46,7 @@ Fix the flaky integration test `test/integration/server/logger.separation.test.t - Consumes: `createLogger()` (`server/logger.ts`), `resolveDebugLogPath()` semantics (explicit `LOG_DEBUG_PATH` short-circuits the test-runtime null — that is what makes the unit test possible under vitest), the existing `logger.separation.test.ts` harness (`startSourceLoggerProcess`, `activeProcesses`). - Produces: no new exported interface; `createLogger()` behavior change only (marker durability). -- [ ] **Step 1: Write the failing behavioral tests** +- [x] **Step 1: Write the failing behavioral tests** Part A — unit test (in `test/unit/server/logger.test.ts`): first merge any missing imports (`readFileSync` and `existsSync` from `node:fs`, `fsp` from `node:fs/promises`, `os` from `node:os`, `path` from `node:path`) into the file's import block — skip any already present. Then append a new `describe` at the end of the file's existing top-level `describe`, reusing the file's existing `vi.resetModules()`-in-`beforeEach` + dynamic re-import convention: @@ -164,7 +164,7 @@ Part B — integration test (append inside `describe('debug log separation', ... ) ``` -- [ ] **Step 2: Run the tests and verify the intended failures** +- [x] **Step 2: Run the tests and verify the intended failures** Run: ```bash @@ -178,7 +178,7 @@ Expected: FAIL for exactly two new tests, for the durability reason: the unit du If either new test unexpectedly PASSES pre-fix, stop: the repro is not load-bearing; re-investigate before implementing (do not weaken the test to manufacture a failure). -- [ ] **Step 3: Add the minimal production implementation** +- [x] **Step 3: Add the minimal production implementation** In `server/logger.ts`, add the helper next to `createDebugFileStream` (~line 231): @@ -250,7 +250,7 @@ Placement detail: the `writeDebugLogPathMarkerSync` call replaces — not duplic This is the intended final shape: one synchronous receipt, swallowed-with-warning on failure, console streams untouched. -- [ ] **Step 4: Run the focused tests** +- [x] **Step 4: Run the focused tests** Run: ```bash @@ -260,7 +260,7 @@ npm run test:vitest -- run test/integration/server/logger.separation.test.ts --c Expected: PASS — both new tests and every pre-existing test in both files. -- [ ] **Step 5: Refactor while green** +- [x] **Step 5: Refactor while green** - Remove now-unneeded machinery only if the marker's old pino route left anything (it did not add any). - Keep the 30s `FILE_CONTENT_TIMEOUT_MS` — it bounds content gates, not durability; the file's header comment about the 2026-08-18 observation stays accurate but should gain one sentence noting the durability fix (edit the comment, do not change the timeout value). @@ -268,7 +268,7 @@ Expected: PASS — both new tests and every pre-existing test in both files. - If the debug file is already at the 10MB rotation cap at process start, rotating-file-stream rotates at open time, which can move the freshly appended receipt into the rotated archive, leaving the active file without the marker. Diagnostic-only, never exercised by any test; no guard added. - The first integration test's `LOG_LEVEL_PROBE` (50ms timer) keeps the theoretical exit-before-open loss window for its `error-level` content line; the reported flake concerned the marker receipt, which is now durable. No change in scope. -- [ ] **Step 6: Run impacted-test verification** +- [x] **Step 6: Run impacted-test verification** The change affects only `createLogger()` marker emission. Impacted set: every test that imports the real `server/logger.ts` marker path (the two files above) plus any test asserting on `createDebugFileStream`/debug streams. Unit runtime is gated away from the marker by `isTestRuntime`/env deletion except via explicit `LOG_DEBUG_PATH`, which only `logger.test.ts` uses. @@ -291,7 +291,7 @@ bash scripts/vitest-cloud.sh run --cloud --config=server test/integration/server Expected: all tests in the file pass on Cloud Run. (Local `npm run test:vitest -- run --config ` demonstrably selects the intended file and config — verified by observation earlier today; keep it for local loops only.) -- [ ] **Step 7: Commit the task** +- [x] **Step 7: Commit the task** ```bash git add server/logger.ts test/unit/server/logger.test.ts test/integration/server/logger.separation.test.ts From a70147d9ab9a94e4238ba875bc4a55a8a3158d15 Mon Sep 17 00:00:00 2001 From: Dan Shapiro <3732858+danshapiro@users.noreply.github.com> Date: Fri, 21 Aug 2026 14:13:02 -0700 Subject: [PATCH 8/9] test(server): assert stream-routed per-instance separation proof and immediate-exit code in debug-log separation tests --- .../server/logger.separation.test.ts | 36 ++++++++++++++++--- 1 file changed, 31 insertions(+), 5 deletions(-) diff --git a/test/integration/server/logger.separation.test.ts b/test/integration/server/logger.separation.test.ts index 6ab71b0b8..b79d44afb 100644 --- a/test/integration/server/logger.separation.test.ts +++ b/test/integration/server/logger.separation.test.ts @@ -31,15 +31,21 @@ const ANSI_ESCAPE_PATTERN = /\u001b\[[0-9;]*m/g const SOURCE_LOGGER_PROBE = [ '(async () => {', " process.argv = ['node', 'server/index.ts']", - " await import('./server/logger.ts')", - ' setTimeout(() => process.exit(0), 25)', + " const { logger } = await import('./server/logger.ts')", + // Stream-routed, process-specific proof line. Emitted at info level: the + // tests using this probe already require info enabled because the resolved- + // path marker is info-gated. No self-exit timer — the child idles until the + // harness's afterEach stopProcess kills it, so the rotating stream's async + // open always wins before the proof line must be durable (a timed exit + // here was the exact exit-before-stream-open race that flaked the marker). + " logger.info('stream-write-proof instance=' + (process.env.FRESHELL_LOG_INSTANCE_ID || process.env.FRESHELL_DEBUG_STREAM_INSTANCE || 'unknown'))", '})()', ].join('\n') const DIST_LOGGER_PROBE = [ '(async () => {', " process.argv = ['node', 'dist/server/index.js']", - " await import('./server/logger.ts')", - ' setTimeout(() => process.exit(0), 25)', + " const { logger } = await import('./server/logger.ts')", + " logger.info('stream-write-proof instance=' + (process.env.FRESHELL_LOG_INSTANCE_ID || process.env.FRESHELL_DEBUG_STREAM_INSTANCE || 'unknown'))", '})()', ].join('\n') const LOG_LEVEL_PROBE = [ @@ -214,6 +220,12 @@ describe('debug log separation', () => { const distPath = path.join(logDir, 'server-debug.production.dist-mode.jsonl') await waitForFileContent(devPath, /Resolved debug log path/) await waitForFileContent(distPath, /Resolved debug log path/) + // Stream-routed proof: the marker above lands via a synchronous + // out-of-band append, so it cannot prove the per-process rotating + // stream actually opened and wrote to this file. Require one record + // that went through pino's multistream in each destination instead. + await waitForFileContent(devPath, /stream-write-proof instance=source-mode/) + await waitForFileContent(distPath, /stream-write-proof instance=dist-mode/) expect(devPath).toContain('server-debug.development.source-mode.jsonl') expect(distPath).toContain('server-debug.production.dist-mode.jsonl') @@ -247,6 +259,13 @@ describe('debug log separation', () => { const pathB = path.join(logDir, 'server-debug.development.concurrent-b.jsonl') await waitForFileContent(pathA, /Resolved debug log path/) await waitForFileContent(pathB, /Resolved debug log path/) + // Stream-routed proof: each concurrent process must put a record + // through its own pino multistream, and neither file may contain the + // other process's record. + const contentA = await waitForFileContent(pathA, /stream-write-proof instance=concurrent-a/) + const contentB = await waitForFileContent(pathB, /stream-write-proof instance=concurrent-b/) + expect(contentA).not.toContain('instance=concurrent-b') + expect(contentB).not.toContain('instance=concurrent-a') expect(pathA).toContain('server-debug.development.concurrent-a.jsonl') expect(pathB).toContain('server-debug.development.concurrent-b.jsonl') @@ -280,6 +299,10 @@ describe('debug log separation', () => { const pathB = path.join(logDir, 'server-debug.production.ci-run-beta.jsonl') await waitForFileContent(pathA, /Resolved debug log path/) await waitForFileContent(pathB, /Resolved debug log path/) + // Stream-routed proof: one record through pino's multistream per process. + await waitForFileContent(pathA, /stream-write-proof instance=alpha/) + await waitForFileContent(pathB, /stream-write-proof instance=ci-run-beta/) + expect(pathA).toContain('server-debug.development.alpha.jsonl') expect(pathB).toContain('server-debug.production.ci-run-beta.jsonl') }) @@ -346,7 +369,7 @@ describe('debug log separation', () => { REPO_ROOT, ) activeProcesses.push(proc) - await once(proc.process, 'exit') + const [exitCode] = await once(proc.process, 'exit') const markerPath = path.join(logDir, 'server-debug.development.immediate-exit.jsonl') const content = await fsp.readFile(markerPath, 'utf8').catch(() => '') @@ -358,6 +381,9 @@ describe('debug log separation', () => { debugMode: 'development', debugInstance: 'immediate-exit', }) + // The child completed the import and reached its explicit exit — + // not a crash after the synchronous marker write. + expect(exitCode).toBe(0) }) }, ) From d58066ea907fc6b37b60bef7f13d19c30bdcf810 Mon Sep 17 00:00:00 2001 From: Dan Shapiro <3732858+danshapiro@users.noreply.github.com> Date: Fri, 21 Aug 2026 14:24:36 -0700 Subject: [PATCH 9/9] test(server): re-read concurrent debug files for cross-contamination assertions; correct probe lifecycle comment --- .../server/logger.separation.test.ts | 21 +++++++++++++------ 1 file changed, 15 insertions(+), 6 deletions(-) diff --git a/test/integration/server/logger.separation.test.ts b/test/integration/server/logger.separation.test.ts index b79d44afb..222eb4fca 100644 --- a/test/integration/server/logger.separation.test.ts +++ b/test/integration/server/logger.separation.test.ts @@ -34,10 +34,13 @@ const SOURCE_LOGGER_PROBE = [ " const { logger } = await import('./server/logger.ts')", // Stream-routed, process-specific proof line. Emitted at info level: the // tests using this probe already require info enabled because the resolved- - // path marker is info-gated. No self-exit timer — the child idles until the - // harness's afterEach stopProcess kills it, so the rotating stream's async - // open always wins before the proof line must be durable (a timed exit - // here was the exact exit-before-stream-open race that flaked the marker). + // path marker is info-gated. No self-exit timer: the proof line is written + // through the rotating stream before the event loop can drain (the pending + // stream open/write keeps Node alive until it lands), then the child exits + // naturally — an open file descriptor alone does not keep the loop alive, + // and the harness's afterEach stopProcess remains as a harmless backstop. + // A timed exit here was the exact exit-before-stream-open race that flaked + // the marker. " logger.info('stream-write-proof instance=' + (process.env.FRESHELL_LOG_INSTANCE_ID || process.env.FRESHELL_DEBUG_STREAM_INSTANCE || 'unknown'))", '})()', ].join('\n') @@ -262,8 +265,14 @@ describe('debug log separation', () => { // Stream-routed proof: each concurrent process must put a record // through its own pino multistream, and neither file may contain the // other process's record. - const contentA = await waitForFileContent(pathA, /stream-write-proof instance=concurrent-a/) - const contentB = await waitForFileContent(pathB, /stream-write-proof instance=concurrent-b/) + await waitForFileContent(pathA, /stream-write-proof instance=concurrent-a/) + await waitForFileContent(pathB, /stream-write-proof instance=concurrent-b/) + // Fresh re-reads AFTER both proof waits: the wait's returned content + // is a snapshot taken before the other process finished writing, so + // negative assertions on it would miss cross-contamination appended + // between the two snapshots. + const contentA = await fsp.readFile(pathA, 'utf8') + const contentB = await fsp.readFile(pathB, 'utf8') expect(contentA).not.toContain('instance=concurrent-b') expect(contentB).not.toContain('instance=concurrent-a')