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..8ec6dec09 --- /dev/null +++ b/docs/plans/2026-08-21-logger-separation-flake.md @@ -0,0 +1,301 @@ +# 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). + +- [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: + +```ts +import { existsSync, 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') + 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 + } + }) + }) +``` + +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', + // 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', + }) + }) + }, + ) +``` + +- [x] **Step 2: Run the tests and verify the intended failures** + +Run: +```bash +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). + +- [x] **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. 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`) +} +``` + +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. + +- [x] **Step 4: Run the focused tests** + +Run: +```bash +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 +``` + +Expected: PASS — both new tests and every pre-existing test in both files. + +- [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). +- 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. + +- [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. + +Run: +```bash +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' ' ' +``` + +Run any additional files the `rg` lists that actually execute the marker path (not docs). + +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.) + +- [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 +git commit -m "fix(server): write the debug-path startup receipt synchronously so short-lived imports never lose it" +``` + +--- 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..222eb4fca 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,20 +23,32 @@ 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 = [ '(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 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') 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 = [ @@ -210,6 +223,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') @@ -243,6 +262,19 @@ 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. + 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') expect(pathA).toContain('server-debug.development.concurrent-a.jsonl') expect(pathB).toContain('server-debug.development.concurrent-b.jsonl') @@ -276,6 +308,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') }) @@ -311,4 +347,53 @@ 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) + 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(() => '') + expect(content).toContain('Resolved debug log path') + + const startupPayload = parseStartupLogPayload(content) + expect(startupPayload).not.toBeNull() + expect(startupPayload).toMatchObject({ + 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) + }) + }, + ) }) diff --git a/test/unit/server/logger.test.ts b/test/unit/server/logger.test.ts index 496059fdc..f1d1b99e0 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,73 @@ 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') + // 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 }) + } + }) + + 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 + await fsp.rm(dir, { recursive: true, force: true }) + } + }) + }) })