diff --git a/AGENTS.md b/AGENTS.md index b09f7e4a..715b1bbb 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -163,7 +163,7 @@ src/ ## Quality Standards -- Target **100% test coverage** — but only with meaningful tests, no padding +- **100% test coverage** on statements, branches, functions and lines — enforced by `coverage.thresholds` in `vitest.config.ts` (`npm run coverage`, CI's Node 20 job, fails below it) — but only with meaningful tests, no padding. Vitest 4 counts the implicit `else` of every `if` as a branch and binds `/* v8 ignore next */` to a single AST node (`next N` counts are ignored; use `/* v8 ignore else */` before an `if` for a truly unreachable else path) - Every new feature **must** have corresponding tests - Every new feature **must** be reflected in the docs (`docs/`) - Don't write tests just to hit coverage numbers; each test should verify real behavior diff --git a/CHANGELOG.md b/CHANGELOG.md index ab061126..0c872f42 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,6 +8,10 @@ All notable changes to this project are documented here. This project adheres to - **Logged errors are cloned** — with `mask` configured, an `Error` argument is replaced by a masked clone like every other argument, and that clone is what transports receive as `nativeError`. It is a real `Error` with the source's prototype (no subclass constructor runs), so `instanceof`, JSON error detection and Sentry-style transports keep working, and the caller's instance is never modified. Without `mask`, errors pass through untouched as before. ### Fixed +- **Frozen or getter-based default LogObj** — a default log object passed as the second `Logger` argument (or via `getSubLogger`) that is frozen / has read-only properties, or exposes a value through a getter, made every log call throw (`Cannot assign to read only property`). The per-call clone now carries the evaluated value inside the copied descriptor; getters are read once per log and stored as plain values, like function fields. +- **Hostile source maps never throw** — a `.map` file that is valid JSON but structurally wrong (`"sections": [null]`, a non-string `mappings`, ...) made source-map resolution throw a `TypeError` out of the log call in development. Such maps now count as "no map" (cached like any other miss) and the transpiled position is kept. +- **Worker transport `flush()` after a failed spawn** — when `new Worker()` threw, every write already went inline, yet each later `flush()` rejected with the spawn error (and `logger.flush()` reported a transport error every time). It now resolves like the off-Node inline path. +- **`restoreConsole()` on a partial console** — a method the console did not have before `wrapConsole()` is put back to `undefined` instead of leaving tslog's forwarder installed. - **Masking inside errors** — a secret in an error's message, in a property assigned to the error or down the `cause` chain no longer reaches the JSON line, the pretty error block or `nativeError` in plaintext. `mask.regex` covers the message and the `: ` header of a V8 stack (frames are left alone, so a broad pattern cannot corrupt positions), `mask.keys`/`regex`/`paths` cover every other own property and the whole `cause` chain. `name`, `message` and `stack` are exempt from `mask.keys`, so `keys: ["name"]` does not blank every error, while `mask.paths` can still target them. (#214, #361) ## [5.1.0] - 2026-07-17 diff --git a/src/core/logObj.ts b/src/core/logObj.ts index 9f422213..adff54ce 100644 --- a/src/core/logObj.ts +++ b/src/core/logObj.ts @@ -54,7 +54,8 @@ export function cloneError(error: T): T { /** * Deeply clones a value while executing any zero-purpose field that is a function (e.g. a `requestId` * generator on the default LogObj), so every log gets a freshly evaluated value. Arrays and Dates are - * cloned; objects are rebuilt preserving prototype and property descriptors; primitives pass through. + * cloned; objects are rebuilt with the source's prototype and per-property enumerability as plain writable + * data properties (frozen sources stay loggable, accessors are read once); primitives pass through. * Circular references are short-circuited with a shallow copy via a `seen` list. */ export function recursiveCloneAndExecuteFunctions(source: T, seen: (object | Array)[] = []): T { @@ -74,10 +75,14 @@ export function recursiveCloneAndExecuteFunctions(source: T, seen: (object | return Object.getOwnPropertyNames(source).reduce( (o, prop) => { const descriptor = Object.getOwnPropertyDescriptor(source, prop); + /* v8 ignore else -- typing-only: getOwnPropertyDescriptor is typed `| undefined`, but for a key getOwnPropertyNames just reported on the same object it is only undefined when a Proxy ownKeys trap invents a ghost key — no supported default LogObj shape does that */ if (descriptor) { - Object.defineProperty(o, prop, descriptor); const value = (source as Record)[prop]; - o[prop] = typeof value === "function" ? value() : recursiveCloneAndExecuteFunctions(value, seen); + const cloned = typeof value === "function" ? value() : recursiveCloneAndExecuteFunctions(value, seen); + // Define a plain data property holding the evaluated value; only enumerability is carried over (it + // decides whether the field is spread into the record). Copying the source descriptor and assigning + // afterwards threw in strict mode on a frozen/read-only source or a getter-only accessor. + Object.defineProperty(o, prop, { value: cloned, writable: true, enumerable: descriptor.enumerable, configurable: true }); } return o; }, @@ -94,9 +99,7 @@ export function recursiveCloneAndExecuteFunctions(source: T, seen: (object | * `seen` set prevents infinite loops on self-referential cause chains. */ export function toErrorObject(error: Error, deps: LogObjDeps, depth = 0, seen: Set = new Set()): IErrorObject { - if (!seen.has(error)) { - seen.add(error); - } + seen.add(error); const errorObject: IErrorObject = { nativeError: error, diff --git a/src/env/sourceMap.node.ts b/src/env/sourceMap.node.ts index 6ee3cf1f..fd8f9f56 100644 --- a/src/env/sourceMap.node.ts +++ b/src/env/sourceMap.node.ts @@ -38,7 +38,8 @@ interface RawSourceMap { } interface SourceMapSection { - offset: { line: number; column: number }; + /** Required by the spec; optional here because the raw JSON is untrusted (see parseRawMap). */ + offset?: { line: number; column: number }; map?: RawSourceMap; url?: string; // external sub-map url (relative to outer map) } @@ -158,6 +159,7 @@ function requireNodeModule(name: string): T | undefined { if (typeof getBuiltin === "function") { try { const resolved = getBuiltin(name) as T | undefined; + /* v8 ignore else -- defensive: the sole caller asks for "node:fs", which every runtime implementing getBuiltinModule resolves; the fall-through only guards the generic signature */ if (resolved != null) { return resolved; } @@ -177,13 +179,16 @@ function requireNodeModule(name: string): T | undefined { type FsLike = { readFileSync: (path: string, encoding: "utf8") => string; existsSync: (path: string) => boolean }; -let cachedFs: FsLike | null | undefined; +// `node:fs`, probed exactly once on first use. A failed probe (undefined) is cached too and never +// retried — the flag, not a sentinel value, records that the probe ran. +let cachedFs: FsLike | undefined; +let fsProbed = false; function getFs(): FsLike | undefined { - if (cachedFs === undefined) { - /* v8 ignore next 3 -- defensive: node:fs is always resolvable on Node/Bun/Deno, the only runtimes this resolver is wired into */ - cachedFs = requireNodeModule("node:fs") ?? null; + if (!fsProbed) { + fsProbed = true; + cachedFs = requireNodeModule("node:fs"); } - return cachedFs ?? undefined; + return cachedFs; } function dirnameOf(filePath: string): string { @@ -275,10 +280,9 @@ function getParsedSourceMap(filePath: string): ParsedSourceMap | undefined { // Defensive cap: a pathological process could load thousands of modules with source maps. Evict // the oldest entry (FIFO — the cost of re-reading one file is negligible) to bound memory. if (parsedMapCache.size >= PARSED_MAP_CACHE_LIMIT) { - const firstKey = parsedMapCache.keys().next().value; - if (firstKey !== undefined) { - parsedMapCache.delete(firstKey); - } + // The cache is non-empty here, so its first key always exists. + const [firstKey] = parsedMapCache.keys(); + parsedMapCache.delete(firstKey); } const fs = getFs(); @@ -288,8 +292,15 @@ function getParsedSourceMap(filePath: string): ParsedSourceMap | undefined { return undefined; } - const loaded = loadRawSourceMap(filePath, fs); - const parsed = loaded != null ? parseRawMap(loaded.raw, loaded.mapDir, fs) : undefined; + // A map that is valid JSON but structurally hostile (`"sections": [null]`, `"mappings": 123`, ...) must + // degrade to "no map" — cached like any other miss — rather than throw a TypeError into the log call. + let parsed: ParsedSourceMap | undefined; + try { + const loaded = loadRawSourceMap(filePath, fs); + parsed = loaded != null ? parseRawMap(loaded.raw, loaded.mapDir, fs) : undefined; + } catch { + parsed = undefined; + } parsedMapCache.set(filePath, parsed ?? null); return parsed; } @@ -310,7 +321,8 @@ function parseRawMap(raw: RawSourceMap, mapDir: string, fs: FsLike, depth = 0): if (depth >= MAX_SECTION_DEPTH) return undefined; const sections: ParsedSection[] = []; for (const section of raw.sections) { - /* v8 ignore next 2 -- `offset` is required by the spec; the ?? 0 guards malformed maps only */ + // `offset` is required by the spec; a malformed section without one is anchored at 0:0 rather + // than throwing — this parse runs outside any try/catch, so a TypeError here would reach the log call. const offsetLine = section.offset?.line ?? 0; const offsetColumn = section.offset?.column ?? 0; let subRaw = section.map; diff --git a/src/env/stackTrace.ts b/src/env/stackTrace.ts index f94503bd..e9b2a8b3 100644 --- a/src/env/stackTrace.ts +++ b/src/env/stackTrace.ts @@ -31,10 +31,14 @@ const OWN_DIR_MARKER: string | undefined = (() => { } })(); -/** A frame whose path begins with tslog's actual own directory is internal (location-based, name-independent). */ -/* v8 ignore next 2 -- unreachable under the Node ESM runner where OWN_DIR_MARKER always resolves; live in the browser IIFE and user bundles where it is undefined */ -const OWN_DIR_PATTERN: RegExp | undefined = - OWN_DIR_MARKER != null ? new RegExp(`^(?:file://)?${OWN_DIR_MARKER.replace(/[.*+?^${}()|[\]\\]/g, "\\$&")}[\\\\/]`, "i") : undefined; +/** + * A frame whose path begins with tslog's actual own directory is internal (location-based, + * name-independent). Kept as a spreadable list so {@link DEFAULT_IGNORE_PATTERNS} needs no + * conditional: empty in the browser IIFE and user bundles, where no marker resolves. + */ +/* v8 ignore next -- the empty arm is unreachable under the Node ESM runner where OWN_DIR_MARKER always resolves; live in the browser IIFE and user bundles where it is undefined */ +const OWN_DIR_PATTERNS: RegExp[] = + OWN_DIR_MARKER != null ? [new RegExp(`^(?:file://)?${OWN_DIR_MARKER.replace(/[.*+?^${}()|[\]\\]/g, "\\$&")}[\\\\/]`, "i")] : []; const DEFAULT_IGNORE_PATTERNS: RegExp[] = [ /(?:^|[\\/])node_modules[\\/].*tslog/i, @@ -48,8 +52,7 @@ const DEFAULT_IGNORE_PATTERNS: RegExp[] = [ // The published bundle layout, so a frame in dist/esm or dist/cjs of *the tslog package* is internal. // Anchored to `tslog/dist/...` rather than any bare `tslog/` substring. /(?:^|[\\/])tslog[\\/]dist[\\/](?:esm|cjs)[\\/]/i, - /* v8 ignore next -- unreachable under the Node ESM runner where OWN_DIR_PATTERN is non-null; live in the browser IIFE and user bundles where it is undefined */ - ...(OWN_DIR_PATTERN != null ? [OWN_DIR_PATTERN] : []), + ...OWN_DIR_PATTERNS, // Runtime-chunk names from modern bundlers (Turbopack/Next.js dev). These are *generated* names — // successful source-map remapping has already turned user frames into real `src/...` paths before // this check runs, so only unremapped bundler-runtime frames still match. diff --git a/src/render/inspect.polyfill.ts b/src/render/inspect.polyfill.ts index f72c9b53..91877911 100644 --- a/src/render/inspect.polyfill.ts +++ b/src/render/inspect.polyfill.ts @@ -29,10 +29,8 @@ export function inspect(obj: unknown, opts?: InspectOptions) { stylize: stylizeNoColor, }; - if (opts != null) { - // got an "options" object - _extend(ctx, opts); - } + // Merge the caller's options (a missing or non-object value is a no-op inside _extend). + _extend(ctx, opts); // set default options if (isUndefined(ctx.showHidden)) ctx.showHidden = false; if (isUndefined(ctx.depth)) ctx.depth = 2; @@ -426,9 +424,9 @@ function reduceToSingleString(output: string[], base: string, braces: string[]): return `${braces[0] + (base === "" ? "" : `${base}\n`)} ${output.join(",\n ")} ${braces[1]}`; } -function _extend(origin: object, add: object): object { +function _extend(origin: object, add: unknown): object { const typedOrigin = origin as { [key: string]: unknown }; - // Don't do anything if add isn't an object + // Don't do anything if add isn't an object (covers the optional/null options of inspect and formatWithOptions) if (!add || !isObject(add)) return origin; const clonedAdd = { ...add } as { [key: string]: unknown }; @@ -448,10 +446,8 @@ export function formatWithOptions(inspectOptions: InspectOptions, ...args: unkno stylize: stylizeNoColor, }; - if (inspectOptions != null) { - // got an "options" object - _extend(ctx, inspectOptions); - } + // Merge the caller's options (a missing or non-object value is a no-op inside _extend). + _extend(ctx, inspectOptions); const first = args[0]; let a = 0; diff --git a/src/render/json.ts b/src/render/json.ts index eb3f77dd..d8824647 100644 --- a/src/render/json.ts +++ b/src/render/json.ts @@ -719,14 +719,13 @@ function renderPlannedLine(record: LogObj & ILogObjMeta, settings: ISett let spreadSource: Record | undefined; const spreadShape = hasMessageKey ? undefined : getSpreadShapeHint(recordObj); if (spreadShape !== undefined) { - const leading = recordObj["0"]; - const trailing = recordObj["1"]; - if (spreadShape === "object-first" && typeof leading === "object" && leading !== null) { - messageValue = trailing; - spreadSource = leading as Record; - } else if (spreadShape === "message-first" && typeof trailing === "object" && trailing !== null) { - messageValue = leading; - spreadSource = trailing as Record; + // The hint names which positional slot holds the plain object to spread; the other slot is the message. + const fieldsKey = spreadShape === "object-first" ? "0" : "1"; + const fields = recordObj[fieldsKey]; + /* v8 ignore else -- unreachable: toLogObj sets the hint only when that slot held a plain object, in the same pass that stores it there, and nothing between toLogObj and rendering rewrites positional values (middleware and masking run on the args BEFORE toLogObj); the typeof guard only protects the cast on a hand-built record */ + if (typeof fields === "object" && fields !== null) { + messageValue = recordObj[fieldsKey === "0" ? "1" : "0"]; + spreadSource = fields as Record; } } const spreading = spreadSource !== undefined; diff --git a/src/subpaths/presets/otel.ts b/src/subpaths/presets/otel.ts index 9a553ae0..9e176170 100644 --- a/src/subpaths/presets/otel.ts +++ b/src/subpaths/presets/otel.ts @@ -565,14 +565,15 @@ function looksLikeErrorObject(value: unknown): value is IErrorObject { return candidate.nativeError instanceof Error && typeof candidate.name === "string" && Array.isArray(candidate.stack); } -/** Best-effort raw stack STRING for one error, preferring the native `Error#stack`. */ +/** + * Best-effort raw stack STRING for one error, preferring the native `Error#stack`. Every caller gates + * on {@link looksLikeErrorObject} / {@link isPlainErrorLike} first, so `nativeError` is always a real + * `Error` here (a JSON/worker round-tripped error object never passes those checks). + */ function ownStackString(error: IErrorObject): string | undefined { - const native = error.nativeError; - if (native != null) { - const stack = safeStringProp(native, "stack"); - if (stack !== undefined) { - return stack; - } + const stack = safeStringProp(error.nativeError, "stack"); + if (stack !== undefined) { + return stack; } if (!Array.isArray(error.stack) || error.stack.length === 0) { return undefined; diff --git a/src/subpaths/serializers/std.ts b/src/subpaths/serializers/std.ts index a3f075e8..200bde7f 100644 --- a/src/subpaths/serializers/std.ts +++ b/src/subpaths/serializers/std.ts @@ -146,12 +146,11 @@ function toErrorObject(error: Error, depth = 0, seen: Set = new Set()): return errorObject; } + // `toError` returns an Error cause as-is (already checked against `seen`) and wraps anything else in + // a FRESH Error that cannot be in `seen` yet, so the raw-value check is the only one needed. const causeValue = (error as { cause?: unknown }).cause; if (causeValue != null && !seen.has(causeValue)) { - const normalizedCause = toError(causeValue); - if (!seen.has(normalizedCause)) { - errorObject.cause = toErrorObject(normalizedCause, depth + 1, seen); - } + errorObject.cause = toErrorObject(toError(causeValue), depth + 1, seen); } return errorObject; diff --git a/src/subpaths/transports/worker.ts b/src/subpaths/transports/worker.ts index f0f89734..b4fd54de 100644 --- a/src/subpaths/transports/worker.ts +++ b/src/subpaths/transports/worker.ts @@ -91,7 +91,11 @@ export interface WorkerTransportOptions { * narrowed to required so callers can drive draining + shutdown directly in tests/teardown. */ export interface WorkerTransport extends Transport { - /** Round-trip the worker so it drains its queue; resolves once the worker acks. */ + /** + * Round-trip the worker so it drains its queue; resolves once the worker acks. Resolves immediately + * while writes go inline (off-Node, a failed spawn, or after maxRespawns): inline writes are + * synchronous, so there is nothing buffered to drain. + */ flush(): Promise; /** Flush, then close the worker's destination and terminate the worker thread. */ [Symbol.asyncDispose](): Promise; @@ -234,7 +238,6 @@ export function workerTransport(options: WorkerTransportOption let respawns = 0; // Set when the worker died more often than maxRespawns allows: every later write goes inline. let workerGaveUp = false; - let deathReported = false; let unregisterExitHook: (() => void) | null = null; // Set once we've learned the runtime has no worker_threads: we then write inline (synchronously) on the @@ -242,6 +245,8 @@ export function workerTransport(options: WorkerTransportOption let fallbackFs: FallbackFs | null | undefined; // Pending flush round-trips keyed by a monotonically increasing id; resolved when the worker acks. + // flushChain (below) serializes round-trips, so at most ONE entry is outstanding at any time; the id + // is what lets a late ack from an already-replaced worker be told apart from the live round-trip. const pendingFlushes = new Map void>(); let nextFlushId = 1; // Whether anything was posted since the last completed flush. A flush with nothing queued is a @@ -276,7 +281,11 @@ export function workerTransport(options: WorkerTransportOption } } - /** An unexpected worker death: reset so the next write respawns, or give up after maxRespawns. */ + /** + * An unexpected worker death: reset so the next write respawns, or give up after maxRespawns. Reported + * once per death: a real Worker emits `error` and then `exit`, and the first of the two nulls `worker`, + * so the second (and any later event from that thread) is dropped by the stale-worker guard. + */ function handleWorkerDeath(died: WorkerLike, error?: unknown): void { if (worker !== died) { return; // stale event from an already-replaced worker — must not settle the NEW worker's flushes @@ -291,16 +300,13 @@ export function workerTransport(options: WorkerTransportOption if (respawns > maxRespawns) { workerGaveUp = true; } - if (!deathReported) { - deathReported = true; - try { - nativeConsoleMethod("error")( - `tslog: worker transport "${options.name ?? "worker"}" thread died unexpectedly${workerGaveUp ? "; falling back to inline writes" : "; respawning on the next write"}`, - error, - ); - } catch { - // the report itself must never throw - } + try { + nativeConsoleMethod("error")( + `tslog: worker transport "${options.name ?? "worker"}" thread died unexpectedly${workerGaveUp ? "; falling back to inline writes" : "; respawning on the next write"}`, + error, + ); + } catch { + // the report itself must never throw } } @@ -339,7 +345,6 @@ export function workerTransport(options: WorkerTransportOption // refs the worker again so an awaited drain cannot be cut short by process exit. created.unref?.(); worker = created; - deathReported = false; return created; })(); } @@ -423,7 +428,9 @@ export function workerTransport(options: WorkerTransportOption return; } queuedSinceFlush = false; - const w = await ensureWorker(); + // A spawn that rejected (`new Worker()` threw) already routed every write inline, like the + // off-Node case below — so flush() resolves as "nothing to drain" instead of surfacing that error. + const w = await ensureWorker().catch(() => null); if (w == null) { // Inline fallback writes synchronously, so there is nothing buffered to drain. return; @@ -438,15 +445,16 @@ export function workerTransport(options: WorkerTransportOption w.ref?.(); w.postMessage({ type: "flush", id }); } catch { + // Worker died between check and post — nothing left to drain. This was the only outstanding + // round-trip (flushChain serializes them), so release the event-loop handle again. pendingFlushes.delete(id); - if (pendingFlushes.size === 0) { - w.unref?.(); - } - resolve(); // worker died between check and post — nothing left to drain + w.unref?.(); + resolve(); } }); }; const chained = flushChain.then(run); + /* v8 ignore next -- run() cannot reject: a failed spawn is absorbed at the ensureWorker() await and the round-trip executor guards ref()/postMessage(); the catch only keeps a future rejection from poisoning every later flush */ flushChain = chained.catch(() => undefined); return chained; }, diff --git a/src/subpaths/wrapConsole.ts b/src/subpaths/wrapConsole.ts index 2bcb58e9..9672f933 100644 --- a/src/subpaths/wrapConsole.ts +++ b/src/subpaths/wrapConsole.ts @@ -114,7 +114,8 @@ export function wrapConsole(logger: ConsoleLikeLogger): () => void { /** * Restore the native `console.log/info/debug/warn/error` methods captured by {@link wrapConsole}. * - * A no-op when the console was never wrapped (or was already restored). After restoring, the captured + * A no-op when the console was never wrapped (or was already restored). A method the console did not have + * before the wrap goes back to `undefined` rather than being left forwarding. After restoring, the captured * originals are released so a subsequent `wrapConsole` captures fresh references. */ export function restoreConsole(): void { @@ -123,10 +124,9 @@ export function restoreConsole(): void { } for (const method of WRAPPED_METHODS) { - const original = originalMethods[method]; - if (original != null) { - (console as Record void>)[method] = original; - } + // Put back exactly what was captured — including `undefined` for a method the console lacked before + // the wrap — so no forwarder is left behind routing into a stale logger. + (console as Partial void>>)[method] = originalMethods[method]; } originalMethods = undefined; diff --git a/tests/22_BaseLogger_Internals.test.ts b/tests/22_BaseLogger_Internals.test.ts index 61081400..e9d50a9b 100644 --- a/tests/22_BaseLogger_Internals.test.ts +++ b/tests/22_BaseLogger_Internals.test.ts @@ -109,6 +109,36 @@ describe("BaseLogger internals", () => { expect(inner[0]).toBe(cyclic); }); + test("a frozen default LogObj (read-only properties) is cloned per call instead of throwing", () => { + // Config constants are commonly frozen (`Object.freeze` / `as const`); the per-call clone used to copy + // the read-only descriptor first and then assign over it, which throws in strict-mode ESM. + const defaults = Object.freeze({ tenant: "acme", nested: Object.freeze({ region: "eu" }) }); + const logger = new Logger({ type: "hidden" }, defaults); + const record = logger.info("x") as unknown as Record; + expect(record.tenant).toBe("acme"); + expect(record.nested).toEqual({ region: "eu" }); + expect(record.nested).not.toBe(defaults.nested); + expect(Object.isFrozen(defaults)).toBe(true); + }); + + test("a getter on the default LogObj is evaluated once per log call, like a function field", () => { + let calls = 0; + const defaults = { + get seq(): number { + return ++calls; + }, + requestId: () => `req-${calls}`, + }; + const logger = new Logger({ type: "hidden" }, defaults); + const first = logger.info("first") as unknown as Record; + const second = logger.info("second") as unknown as Record; + expect([first.seq, second.seq]).toEqual([1, 2]); + expect([first.requestId, second.requestId]).toEqual(["req-1", "req-2"]); + // The clone holds the snapshot as a plain value: reading it again does not re-run the getter. + expect(second.seq).toBe(2); + expect(calls).toBe(2); + }); + test("mask key lookup caches normalized values in case-insensitive mode", () => { const logger = new Logger({ type: "json", diff --git a/tests/45_file_transport_internals.test.ts b/tests/45_file_transport_internals.test.ts index 5fe2ba59..15356449 100644 --- a/tests/45_file_transport_internals.test.ts +++ b/tests/45_file_transport_internals.test.ts @@ -152,6 +152,43 @@ describe.runIf(isNode)("fileTransport (opened-stream internals)", () => { }); }); + test("a late error from an already-abandoned stream does not tear down its replacement", async () => { + await withTempDir(async (dir) => { + const path = join(dir, "stale.log"); + const first = makeControllableStream(); + const second = makeControllableStream(); + let opened = 0; + const fileTransport = await loadFileTransport(() => (opened++ === 0 ? first.stream : second.stream)); + const seen: string[] = []; + const transport = fileTransport({ path, exitHooks: false, onError: (_error, context) => seen.push(context) }); + + // Open the first stream, break it (abandoned), and let the next write open the replacement. + transport.write(META, "one"); + await waitFor(() => first.chunks.length === 1); + first.confirmNext(); + await transport.flush(); + first.emitError(new Error("first failure")); + transport.write(META, "two"); + await waitFor(() => second.chunks.length === 1); + second.confirmNext(); + await transport.flush(); + expect(opened).toBe(2); + + // The abandoned stream fires ANOTHER error (a destroyed fs stream can still emit late). It is + // reported, but must not null out the healthy replacement: the next write lands on the second + // stream and no third stream is opened. + first.emitError(new Error("stale failure")); + expect(seen).toEqual(["write", "write"]); + transport.write(META, "three"); + await waitFor(() => second.chunks.length === 2); + second.confirmNext(); + await transport.flush(); + expect(second.chunks).toEqual(["two\n", "three\n"]); + expect(opened).toBe(2); + await transport[Symbol.asyncDispose](); + }); + }); + test("registered exit hook drives flushSync (drainSync) and flush (flushAsync)", async () => { await withTempDir(async (dir) => { const path = join(dir, "exit-hook.log"); diff --git a/tests/45_preset_otel.test.ts b/tests/45_preset_otel.test.ts index 2b56f871..b73f2648 100644 --- a/tests/45_preset_otel.test.ts +++ b/tests/45_preset_otel.test.ts @@ -25,9 +25,10 @@ import { function captureRecord( logArgs: unknown[], settingsParam: Record = {}, + defaultLogObj?: Record, ): { record: Record & ILogObjMeta; settings: ISettings } { let captured: (Record & ILogObjMeta) | undefined; - const logger = new Logger({ type: "hidden", ...settingsParam }); + const logger = new Logger({ type: "hidden", ...settingsParam }, defaultLogObj); logger.attachTransport((record) => { captured = record as Record & ILogObjMeta; }); @@ -126,6 +127,20 @@ describe("presets/otel", () => { expect(otel.SpanId).toBeUndefined(); }); + test("a span context without usable ids contributes no TraceId/SpanId (never an empty string)", () => { + const { record, settings } = captureRecord(["partially traced"]); + // No active span, but the shim still reports trace flags: there is nothing to correlate on. + const flagsOnly = toOtelRecord(record, settings, { getSpanContext: () => ({ traceFlags: 0 }) }); + expect(Object.hasOwn(flagsOnly, "TraceId")).toBe(false); + expect(Object.hasOwn(flagsOnly, "SpanId")).toBe(false); + expect(flagsOnly.TraceFlags).toBe(0); + // Empty-string ids (the "no span" placeholder some tracer shims return) are dropped the same way, + // so a backend never indexes an empty correlation key. + const emptyIds = toOtelRecord(record, settings, { getSpanContext: () => ({ traceId: "", spanId: "" }) }); + expect(Object.hasOwn(emptyIds, "TraceId")).toBe(false); + expect(Object.hasOwn(emptyIds, "SpanId")).toBe(false); + }); + test("isolates a throwing context getter (never breaks logging)", () => { const { record, settings } = captureRecord(["safe"]); const otel = toOtelRecord(record, settings, { @@ -279,6 +294,13 @@ describe("presets/otel OTLP/JSON (the collector wire format)", () => { expect(attr(otlp.attributes, "ok")).toEqual({ boolValue: true }); }); + test("omits observedTimeUnixNano when observedTimestamp is false (the downstream stamps its own)", () => { + const { record, settings } = captureRecord(["observed downstream"]); + const otlp = toOtlpLogRecord(record, settings, { observedTimestamp: false }); + expect(Object.hasOwn(otlp, "observedTimeUnixNano")).toBe(false); + expect(otlp.timeUnixNano).toMatch(/^\d+$/); + }); + test("carries a named logger as the logger.name attribute", () => { const { record, settings } = captureRecord(["hello"], { name: "checkout" }); const otlp = toOtlpLogRecord(record, settings); @@ -553,6 +575,32 @@ describe("presets/otel record-splitting and timestamp edges", () => { expect((otel.Attributes as Record)["0"]).toBeUndefined(); }); + test("spreading fields never assigns an own __proto__ key (no prototype pollution of Attributes)", () => { + // Fields parsed from untrusted JSON can carry an OWN `__proto__` key; assigning it onto the attribute + // bag would swap the bag's prototype instead of adding a field. The key is skipped outright. + const poisoned = JSON.parse('{"__proto__": {"polluted": true}, "x": 1}') as Record; + const { record, settings } = captureRecord([poisoned, "spread me"]); + const otel = toOtelRecord(record, settings); + expect(otel.Body).toBe("spread me"); + expect(otel.Attributes).toStrictEqual({ x: 1 }); + expect(Object.getPrototypeOf(otel.Attributes)).toBe(Object.prototype); + expect((otel.Attributes as { polluted?: unknown }).polluted).toBeUndefined(); + expect(Object.hasOwn(otel.Attributes, "__proto__")).toBe(false); + // The OTLP attribute list is built from the same split, so it carries no __proto__ entry either. + const otlp = toOtlpLogRecord(record, settings); + expect(otlp.attributes?.map((entry) => entry.key)).toEqual(["x"]); + expect(({} as { polluted?: unknown }).polluted).toBeUndefined(); + }); + + test("a spread field never overwrites a key already on the record (the default LogObj wins, like the JSON renderer)", () => { + // Fields of `new Logger(settings, defaultLogObj)` are merged into every record and win on collision; + // a per-call field of the same name must not clobber them in the OTel attribute bag either. + const { record, settings } = captureRecord([{ service: "impostor", region: "eu" }, "hi"], {}, { service: "api" }); + const otel = toOtelRecord(record, settings); + expect(otel.Body).toBe("hi"); + expect(otel.Attributes).toStrictEqual({ service: "api", region: "eu" }); + }); + test("no _logMeta block: OTLP severity is UNSPECIFIED and the timestamp falls back to Date.now()", () => { const settings = defaultSettings(); const before = BigInt(Date.now()) * 1_000_000n; @@ -603,6 +651,21 @@ describe("presets/otel toOtlpLogRecord error edges", () => { expect(causeKv.find((e) => e.key === "message")?.value).toEqual({ stringValue: "deep cause" }); }); + test("a compacted extra error with no stack at all omits the stack key instead of emitting an empty value", () => { + // The SECOND error gets the compact form; with its native stack scrubbed and therefore no parsed + // frames either, the compact kvlist carries name/message only — no `stack` entry holding an empty + // AnyValue, mirroring how the first error omits exception.stacktrace. + const stackless = new Error("no stack"); + stackless.stack = undefined; + const { record, settings } = captureRecord(["boom", new Error("primary"), stackless]); + const otlp = toOtlpLogRecord(record, settings); + const extra = attr(otlp.attributes, settings.json.errorKey)?.arrayValue?.values ?? []; + expect(extra).toHaveLength(1); + const kv = extra[0].kvlistValue?.values ?? []; + expect(kv.map((e) => e.key)).toEqual(["name", "message"]); + expect(kv.find((e) => e.key === "message")?.value).toEqual({ stringValue: "no stack" }); + }); + test("an attribute holding an ARRAY of serialized errors maps them all (first -> exception.*, rest compacted)", () => { // tslog does not produce this shape itself, but toOtlpLogRecord defends against an attribute value // that is an array of serialized errors: each is mapped in order. diff --git a/tests/45_std_serializers.test.ts b/tests/45_std_serializers.test.ts index 81e16249..8e8e8352 100644 --- a/tests/45_std_serializers.test.ts +++ b/tests/45_std_serializers.test.ts @@ -186,6 +186,14 @@ describe("stdSerializers.req", () => { expect(out.url).toBe("/koa"); }); + test("omits the url key entirely when the request carries no string url", () => { + // A partial/duck-typed request (e.g. a hand-built one in a job runner) may have no url at all; the + // serialized shape must then lack the key rather than carry an `undefined`-valued one. + const out = req({ method: "GET", headers: { host: "example.test" } }) as Record; + expect(Object.hasOwn(out, "url")).toBe(false); + expect(out).toStrictEqual({ method: "GET", headers: { host: "example.test" } }); + }); + test("redacts headers supplied as an array of [name, value] pairs", () => { const out = req({ method: "GET", @@ -228,6 +236,20 @@ describe("stdSerializers.res", () => { expect(webRes.statusCode).toBe(201); }); + test("omits statusCode when the response carries none (headers-only shape)", () => { + // A response whose status is not yet known (or a duck-typed one) yields no `statusCode` key at all. + const out = res({ headers: { etag: "abc" } }) as Record; + expect(Object.hasOwn(out, "statusCode")).toBe(false); + expect(out).toStrictEqual({ headers: { etag: "abc" } }); + }); + + test("omits headers when the response carries none (status-only shape)", () => { + // Neither `headers` nor `getHeaders()` present: the key is left out rather than set to undefined. + const out = res({ statusCode: 204 }) as Record; + expect(Object.hasOwn(out, "headers")).toBe(false); + expect(out).toStrictEqual({ statusCode: 204 }); + }); + test("passes through a non-object value unchanged", () => { expect(res(undefined)).toBe(undefined); }); diff --git a/tests/49_wrap_console.test.ts b/tests/49_wrap_console.test.ts index 593da69d..da3e08c3 100644 --- a/tests/49_wrap_console.test.ts +++ b/tests/49_wrap_console.test.ts @@ -106,6 +106,27 @@ describe("wrapConsole / restoreConsole (M3.10)", () => { expect(console.log).toBe(nativeLog); }); + test("a method the console lacked before the wrap is forwarded while wrapped and put back to undefined on restore", () => { + const nativeDebug = console.debug; + const { logger, captured } = makeLogger(); + // A minimal console (some embedded runtimes ship only a subset of the WHATWG methods). An own + // `undefined` is the faithful simulation here: a plain `delete` would fall through to + // Console.prototype.debug on Node. + (console as Partial).debug = undefined; + try { + wrapConsole(logger); + console.debug("routed anyway"); + expect(captured).toEqual([{ level: "DEBUG", message: "routed anyway" }]); + + restoreConsole(); + // Back to the pre-wrap shape: no forwarder is left behind still routing into the old logger. + expect(console.debug).toBeUndefined(); + expect(isConsoleWrapped()).toBe(false); + } finally { + console.debug = nativeDebug; + } + }); + test("restoreConsole is a no-op when the console was never wrapped", () => { const nativeLog = console.log; expect(isConsoleWrapped()).toBe(false); diff --git a/tests/50_cli.test.ts b/tests/50_cli.test.ts index 965948a2..c620fef5 100644 --- a/tests/50_cli.test.ts +++ b/tests/50_cli.test.ts @@ -253,6 +253,12 @@ describe("tslog/cli (M3.11)", () => { // The `--level=` numeric branch (cli.ts 243): a digits-only value becomes a number. expect(parseCliArgs(["--level=3"])).toEqual({ minLevel: 3 }); }); + + test("ignores unknown flags and positional args without derailing the known ones", () => { + // `kubectl logs api | npx tslog --follow -l warn app.log --no-color`: the unrecognized tokens are + // skipped and the recognized flags around them still take effect. + expect(parseCliArgs(["--follow", "-l", "warn", "app.log", "--no-color"])).toEqual({ minLevel: "warn", color: false }); + }); }); describe("color resolution (no explicit --color/--no-color)", () => { diff --git a/tests/51_set_min_level_persistence.test.ts b/tests/51_set_min_level_persistence.test.ts index 1ff19ba4..a49bf252 100644 --- a/tests/51_set_min_level_persistence.test.ts +++ b/tests/51_set_min_level_persistence.test.ts @@ -82,6 +82,16 @@ describe("browser log-level persistence (M4.6, stubbed localStorage)", () => { expect(logger.settings.minLevel).toBe(4); }); + test("leaves the configured minLevel alone when the persisted token resolves to no level", () => { + // A stale token — e.g. a custom level name persisted by a previous build that no longer registers it — + // must not disturb filtering: the configured minLevel stays in force. + (globalThis as { localStorage?: unknown }).localStorage = { getItem: () => "NOTICE", setItem: () => {} }; + const logger = new Logger({ type: "hidden", minLevel: 3, persistLevel: true }); + expect(logger.settings.minLevel).toBe(3); + expect(logger.log(2, "DEBUG", "x")).toBeUndefined(); + expect(logger.log(3, "INFO", "x")).toBeDefined(); + }); + test("honors a custom persistLevelKey", () => { const store: Record = { "myapp:lvl": "5" }; (globalThis as { localStorage?: unknown }).localStorage = { diff --git a/tests/51_testing_helper.test.ts b/tests/51_testing_helper.test.ts index 826053b8..5d1a1946 100644 --- a/tests/51_testing_helper.test.ts +++ b/tests/51_testing_helper.test.ts @@ -1,6 +1,6 @@ import { describe, expect, test, vi } from "vitest"; import type { ILogObjMeta, IMeta } from "../src/index.js"; -import { createTestLogger, mockLogger } from "../src/subpaths/testing.js"; +import { createTestLogger, mockLogger, normalizeMeta } from "../src/subpaths/testing.js"; // M4.5 — `tslog/testing`: createTestLogger (capture transport) + mockLogger (recording level methods). @@ -165,6 +165,21 @@ describe("mockLogger", () => { }); }); +describe("normalizeMeta", () => { + test("pins only the meta fields that exist — a slimmed meta block gets no date/hostname/runtimeVersion invented", () => { + // A line whose meta was trimmed before persisting (or produced by another tool) carries none of the + // volatile fields; normalizing it must leave the block exactly as it was rather than add pinned keys + // that would then show up in snapshots. + const slimMeta = { logLevelId: 3, logLevelName: "INFO" }; + const line = JSON.stringify({ message: "m", _logMeta: slimMeta }); + const normalizedLine = JSON.parse(normalizeMeta(line)) as Record; + expect(normalizedLine._logMeta).toEqual(slimMeta); + + const record = { message: "m", _logMeta: { ...slimMeta } }; + expect(normalizeMeta(record)._logMeta).toEqual(slimMeta); + }); +}); + describe("purity / no global mutation", () => { test("mockLogger does not patch console", () => { const spy = vi.spyOn(console, "log"); diff --git a/tests/54_worker_transport.test.ts b/tests/54_worker_transport.test.ts index 62fa0a78..8bf62320 100644 --- a/tests/54_worker_transport.test.ts +++ b/tests/54_worker_transport.test.ts @@ -134,13 +134,16 @@ class FakeWorker extends EventEmitter { unref(): void { this.unrefs++; } - /** Simulate an unexpected thread death via the "error" (or "exit") event the transport listens for. */ + /** + * Simulate an unexpected thread death. Like a real Worker, an uncaught exception emits "error" and + * THEN "exit" (the thread is terminated), so the transport sees two events for one death; a plain + * `die()` is a bare "exit" (the thread stopped without throwing). + */ die(error?: Error): void { if (error) { this.emit("error", error); - } else { - this.emit("exit", 1); } + this.emit("exit", 1); } } @@ -157,16 +160,20 @@ interface MockSetup { /** * Load a FRESH worker.ts with `node:worker_threads` mocked. `opts.workerThreadsThrows` makes the - * dynamic import reject (off-Node path). `opts.runnerFileExists` forces the built-runner branch by - * mocking `node:fs`'s existsSync; `opts.fsThrows` makes the fallback fs loader/runner-probe fail. + * dynamic import reject (off-Node path); `opts.ctorThrows` makes every `new Worker(...)` throw (a spawn + * that fails on Node). `opts.runnerFileExists` forces the built-runner branch by mocking `node:fs`'s + * existsSync; `opts.fsMock` overrides `node:fs` members (e.g. to capture the inline-fallback appends). */ async function loadMocked( - opts: { workerThreadsThrows?: boolean; runnerFileExists?: boolean; fsMock?: Record } = {}, + opts: { workerThreadsThrows?: boolean; ctorThrows?: boolean; runnerFileExists?: boolean; fsMock?: Record } = {}, ): Promise<{ mod: WorkerModule; setup: MockSetup }> { const queue: FakeWorker[] = []; const workers: FakeWorker[] = []; // The transport calls `new Worker(...)`, and Vitest 4 runs the implementation with `new`, so it cannot be an arrow. const ctor = vi.fn(function (_url: unknown, _o: unknown) { + if (opts.ctorThrows) { + throw new Error("spawn exploded"); + } const w = queue.shift() ?? new FakeWorker(); workers.push(w); return w; @@ -346,6 +353,8 @@ describe.runIf(isNode)("worker transport — main-thread logic (mocked worker_th await settle(); const first = setup.workers[0]; + // An uncaught exception in the thread surfaces as "error" followed by "exit" (see FakeWorker.die): + // ONE death, so the user gets ONE report — the trailing "exit" must not be reported again. first.die(new Error("thread boom")); // unexpected death → reset; next write respawns await settle(); expect(errSpy).toHaveBeenCalledTimes(1); @@ -421,7 +430,7 @@ describe.runIf(isNode)("worker transport — main-thread logic (mocked worker_th errSpy.mockRestore(); }); - test("off-Node: no worker_threads → writes fall back to an inline synchronous fs append", async () => { + test("off-Node: no worker_threads → writes fall back to inline synchronous fs appends, in order", async () => { const appended: Array<{ path: unknown; chunk: unknown; opts: unknown }> = []; const path = tmpFile(); const { mod } = await loadMocked({ @@ -435,9 +444,18 @@ describe.runIf(isNode)("worker transport — main-thread logic (mocked worker_th }, }); const t = mod.workerTransport({ destination: "file", path, format: "json" }); - t.write({} as never, "off-node"); - await settle(); - expect(appended).toEqual([{ path, chunk: "off-node\n", opts: { encoding: "utf8", flag: "a" } }]); + // The first write loads node:fs lazily; the later ones reuse the cached module. Each write is awaited + // before the next on purpose: Vitest hands the REAL module to the second of two concurrent dynamic + // imports of a doMock'd builtin, which would route a concurrent second line past the mock. + for (const line of ["off-node-1", "off-node-2", "off-node-3"]) { + t.write({} as never, line); + await settleUntil(() => appended.some((a) => a.chunk === `${line}\n`)); + } + expect(appended).toEqual([ + { path, chunk: "off-node-1\n", opts: { encoding: "utf8", flag: "a" } }, + { path, chunk: "off-node-2\n", opts: { encoding: "utf8", flag: "a" } }, + { path, chunk: "off-node-3\n", opts: { encoding: "utf8", flag: "a" } }, + ]); await t[Symbol.asyncDispose](); // off-Node dispose has no thread to tear down }); @@ -608,6 +626,83 @@ describe.runIf(isNode)("worker transport — main-thread logic (mocked worker_th await t[Symbol.asyncDispose](); }); + test("malformed or unknown worker messages are ignored and leave the pending round-trip (and its ref) intact", async () => { + const { mod, setup } = await loadMocked(); + const t = mod.workerTransport({ destination: "stdout" }); + t.write({} as never, "queued"); + await settleUntil(() => setup.workers.length > 0); + const w = setup.workers[0]; + w.autoAckFlush = false; + + let done = false; + const flushing = t.flush().then(() => { + done = true; + }); + await settleUntil(() => w.posted.some((m) => m.type === "flush")); + const id = w.posted.find((m) => m.type === "flush")?.id; + const unrefsBefore = w.unrefs; + + // Only a well-formed `{type:"flushed", id}` for the outstanding id may settle the round-trip; anything + // else the thread might post is dropped without throwing (a throw in a port listener would crash the process). + for (const junk of [undefined, null, "flushed", { type: "progress", id }, { type: "flushed" }, { type: "flushed", id: String(id) }]) { + expect(() => w.emit("message", junk)).not.toThrow(); + } + await settle(); + expect(done).toBe(false); + expect(w.unrefs).toBe(unrefsBefore); // still holding the event loop open for the drain + + w.emit("message", { type: "flushed", id }); + await flushing; + expect(done).toBe(true); + expect(w.unrefs).toBe(unrefsBefore + 1); // released once the real ack landed + + await t[Symbol.asyncDispose](); + }); + + test("a late ack from a dead worker is ignored and does not release the replacement's flush ref", async () => { + const errSpy = vi.spyOn(console, "error").mockImplementation(() => undefined); + const { mod, setup } = await loadMocked(); + const t = mod.workerTransport({ destination: "stdout" }); + t.write({} as never, "a"); + await settleUntil(() => setup.workers.length > 0); + const first = setup.workers[0]; + first.autoAckFlush = false; + + const f1 = t.flush(); // parked on `first` + await settleUntil(() => first.posted.some((m) => m.type === "flush")); + const staleId = first.posted.find((m) => m.type === "flush")?.id; + first.die(new Error("thread boom")); // the death settles f1, not an ack + await f1; + + t.write({} as never, "b"); // respawns → `second` is the live worker + await settleUntil(() => setup.workers.length > 1); + const second = setup.workers[1]; + second.autoAckFlush = false; + let secondDone = false; + const f2 = t.flush().then(() => { + secondDone = true; + }); + await settleUntil(() => second.posted.some((m) => m.type === "flush")); + const liveId = second.posted.find((m) => m.type === "flush")?.id; + const unrefsBefore = second.unrefs; + + // Node delivers a worker's port messages and its error/exit on different channels, so the dead + // thread's ack for the already-settled id can still arrive late. It must not throw, must not settle + // the replacement's round-trip, and must not drop the ref holding the loop open for that round-trip. + expect(() => first.emit("message", { type: "flushed", id: staleId })).not.toThrow(); + await settle(); + expect(secondDone).toBe(false); + expect(second.unrefs).toBe(unrefsBefore); + + second.emit("message", { type: "flushed", id: liveId }); // only the live worker's own ack settles it + await f2; + expect(secondDone).toBe(true); + expect(second.unrefs).toBe(unrefsBefore + 1); + + await t[Symbol.asyncDispose](); + errSpy.mockRestore(); + }); + test("a worker death with a flush outstanding settles that flush (it never hangs)", async () => { const { mod, setup } = await loadMocked(); const t = mod.workerTransport({ destination: "stdout" }); @@ -702,21 +797,16 @@ describe.runIf(isNode)("worker transport — main-thread logic (mocked worker_th test("a spawn that rejects unexpectedly falls back to an inline write", async () => { const appended: Array<{ fd: unknown; chunk: unknown }> = []; // Make the Worker ctor throw so the spawn promise rejects → write's reject handler runs inlineWrite. - const throwingCtor = vi.fn(function () { - throw new Error("spawn exploded"); - }); - const actualFs = await import("node:fs"); - vi.resetModules(); - vi.doMock("node:worker_threads", () => ({ Worker: throwingCtor })); - vi.doMock("node:fs", () => ({ - ...actualFs, - existsSync: () => false, - mkdirSync: () => undefined, - appendFileSync: (fd: unknown, chunk: unknown) => { - appended.push({ fd, chunk }); + const { mod } = await loadMocked({ + ctorThrows: true, + fsMock: { + existsSync: () => false, + mkdirSync: () => undefined, + appendFileSync: (fd: unknown, chunk: unknown) => { + appended.push({ fd, chunk }); + }, }, - })); - const mod = (await import("../src/subpaths/transports/worker.js")) as WorkerModule; + }); const t = mod.workerTransport({ destination: "stdout", eol: "\n" }); t.write({} as never, "after-spawn-fail"); await settleUntil(() => appended.length > 0); @@ -724,6 +814,35 @@ describe.runIf(isNode)("worker transport — main-thread logic (mocked worker_th await t[Symbol.asyncDispose](); }); + test("flush after a failed spawn resolves (inline writes are synchronous) and never surfaces the spawn error", async () => { + const appended: Array<{ fd: unknown; chunk: unknown }> = []; + const { mod } = await loadMocked({ + ctorThrows: true, + fsMock: { + existsSync: () => false, + mkdirSync: () => undefined, + appendFileSync: (fd: unknown, chunk: unknown) => { + appended.push({ fd, chunk }); + }, + }, + }); + const t = mod.workerTransport({ destination: "stdout", eol: "\n" }); + t.write({} as never, "first"); + await settleUntil(() => appended.length > 0); + // The line already landed inline, so there is nothing to drain: flush() resolves instead of rejecting + // with the (already handled) spawn failure — `await sink.flush()` in teardown must not throw. + await expect(t.flush()).resolves.toBeUndefined(); + // The transport keeps working inline afterwards, and each later flush resolves the same way. + t.write({} as never, "second"); + await settleUntil(() => appended.length > 1); + await expect(t.flush()).resolves.toBeUndefined(); + expect(appended).toEqual([ + { fd: 1, chunk: "first\n" }, + { fd: 1, chunk: "second\n" }, + ]); + await t[Symbol.asyncDispose](); + }); + test("flush on an off-Node transport (no worker) resolves without a round-trip", async () => { const { mod } = await loadMocked({ workerThreadsThrows: true, diff --git a/tests/56_json_line_plan.test.ts b/tests/56_json_line_plan.test.ts index aae9b259..318a6725 100644 --- a/tests/56_json_line_plan.test.ts +++ b/tests/56_json_line_plan.test.ts @@ -113,13 +113,24 @@ describe("JSON line plan is byte-identical to the object path", () => { logger.info({ userId: 1 }, "pino style"), logger.info("message first", { spread: true }), logger.info("msg", { tenant: "evil", fresh: 1 }), + logger.info({ tenant: "evil", fresh: 1 }, "msg"), logger.info("msg", { message: "smuggled", level: "fake", time: "fake", _logMeta: { v: 0 }, ok: true }), - logger.info({ message: "smuggled", level: "fake", ok: true }, "real message"), + logger.info({ message: "smuggled", level: "fake", time: "fake", _logMeta: { v: 0 }, ok: true }, "real message"), logger.info("msg", { 0: "zero", 5: "five" }), logger.info("msg", { fn: () => 1, missing: undefined, big: 5n }), ]; - for (const logObj of cases) { - expectPlannedLineMatchesObjectPath(logObj, logger.settings); + const lines = cases.map((logObj) => expectPlannedLineMatchesObjectPath(logObj, logger.settings)); + // Both orders apply the same collision rules: the default LogObj's `tenant` wins over the spread field, + // and a smuggled `_logMeta` never replaces (or duplicates) the runtime meta block. + for (const line of [lines[2], lines[3]]) { + expect(line).toContain('"tenant":"acme"'); + expect(line).not.toContain('"tenant":"evil"'); + expect(line).toContain('"fresh":1'); + } + for (const line of [lines[4], lines[5]]) { + expect(line).toContain('"v":5'); + expect(line).not.toContain('"v":0'); + expect(line.match(/"_logMeta":/g)).toHaveLength(1); } }); @@ -153,7 +164,8 @@ describe("JSON line plan is byte-identical to the object path", () => { test("__proto__ own keys are dropped on both paths without prototype pollution", () => { const logger = new Logger({ type: "hidden", stack: { capture: "off" } }); const poisoned = JSON.parse('{"__proto__": {"polluted": true}, "z": 2}'); - const cases = [logger.info(poisoned), logger.info("msg", poisoned)]; + // Single object, message-first spread, and pino object-first spread all drop the own __proto__ key. + const cases = [logger.info(poisoned), logger.info("msg", poisoned), logger.info(poisoned, "msg")]; for (const logObj of cases) { const line = expectPlannedLineMatchesObjectPath(logObj, logger.settings); expect(line).toContain('"z":2'); diff --git a/tests/57_transport_lifecycle.test.ts b/tests/57_transport_lifecycle.test.ts index b254da94..3ef33c89 100644 --- a/tests/57_transport_lifecycle.test.ts +++ b/tests/57_transport_lifecycle.test.ts @@ -77,6 +77,39 @@ describe("logger.flush() covers in-flight async writes", () => { errorSpy.mockRestore(); } }); + + test("flush() awaits every in-flight write on the same transport, not only the first", async () => { + const delivered: string[] = []; + const gates: Array<() => void> = []; + const logger = new Logger({ type: "hidden" }); + logger.attachTransport({ + name: "gated", + format: "json", + async write(_record, line): Promise { + // Each write blocks on its own manually-released gate (no wall clock). + await new Promise((resolve) => gates.push(resolve)); + delivered.push(line); + }, + }); + + logger.info("first"); + logger.info("second"); + expect(gates).toHaveLength(2); + let flushed = false; + const flush = logger.flush().then(() => { + flushed = true; + }); + // Release only the first write: flush must keep waiting on the second. + gates[0](); + await new Promise((resolve) => setTimeout(resolve, 0)); + expect(delivered).toHaveLength(1); + expect(delivered[0]).toContain('"first"'); + expect(flushed).toBe(false); + gates[1](); + await flush; + expect(delivered).toHaveLength(2); + expect(delivered[1]).toContain('"second"'); + }); }); describe("disposal ownership", () => { diff --git a/tests/58_bindings_and_levels.test.ts b/tests/58_bindings_and_levels.test.ts index 7e177134..0dbc7e11 100644 --- a/tests/58_bindings_and_levels.test.ts +++ b/tests/58_bindings_and_levels.test.ts @@ -33,6 +33,19 @@ describe("bindings", () => { } }); + test("several colliding keys are all overridden per call and the logger's own bindings stay intact", () => { + const logger = new Logger({ type: "hidden", ...capture, bindings: { env: "prod", region: "eu", tenant: "acme" } }); + const cases = [logger.info("msg", { env: "override", region: "us" }), logger.info({ env: "override", region: "us" }, "msg")]; + for (const logObj of cases) { + const parsed = JSON.parse(jsonLine(logObj, logger)) as Record; + expect(parsed).toMatchObject({ env: "override", region: "us", tenant: "acme" }); + } + // Dropping the colliding keys works on a per-call copy: the shared bindings are untouched, so a + // collision-free call still carries all three. + expect(logger.settings.bindings).toEqual({ env: "prod", region: "eu", tenant: "acme" }); + expect(JSON.parse(jsonLine(logger.info("plain"), logger))).toMatchObject({ env: "prod", region: "eu", tenant: "acme" }); + }); + test("bindings merge down the sub-logger chain, child keys win", () => { const root = new Logger({ type: "hidden", ...capture, bindings: { tenant: "acme", tier: "free" } }); const child = root.child({ bindings: { requestId: "r-1", tier: "paid" } }); @@ -160,6 +173,32 @@ describe("custom level methods", () => { } }); + test("production silences the collision and dropped-binding diagnostics without changing behavior", () => { + const savedNodeEnv = process.env.NODE_ENV; + process.env.NODE_ENV = "production"; + const warnSpy = vi.spyOn(console, "warn").mockImplementation(() => undefined); + try { + const logger = new Logger({ + type: "hidden", + ...capture, + // "constructor" passes validateCustomLevel but collides with the class constructor member. + customLevels: { constructor: 9 }, + bindings: { message: "hijack", kept: "yes" }, + }); + // No method was installed over the class constructor; the level still logs via log(id, name, ...). + expect(typeof (logger as unknown as { constructor: unknown }).constructor).toBe("function"); + const line = jsonLine(logger.log(9, "constructor", "real message"), logger); + expect(line).toContain('"message":"real message"'); + expect(line).toContain('"kept":"yes"'); + expect(line).not.toContain("hijack"); + expect(warnSpy).not.toHaveBeenCalled(); + } finally { + warnSpy.mockRestore(); + if (savedNodeEnv === undefined) delete process.env.NODE_ENV; + else process.env.NODE_ENV = savedNodeEnv; + } + }); + test("bindings stay at the top level when logging a lone Error", () => { const logger = new Logger({ type: "hidden", ...capture, bindings: { service: "checkout", region: "eu" } }); const line = jsonLine(logger.error(new Error("boom")), logger); diff --git a/tests/61_stdout_sink.test.ts b/tests/61_stdout_sink.test.ts index f663c37a..d69258b2 100644 --- a/tests/61_stdout_sink.test.ts +++ b/tests/61_stdout_sink.test.ts @@ -1,4 +1,5 @@ import { execFileSync } from "node:child_process"; +import { EventEmitter } from "node:events"; import { getStdoutJsonSink } from "../src/env/stdoutSink.node.js"; import { Logger as UniversalLogger } from "../src/index.js"; import { Logger as NodeLogger } from "../src/index.node.js"; @@ -306,4 +307,34 @@ describe("review fixes: accounting and hostile streams", () => { stdoutGetter.mockRestore(); } }); + + test("the error guard swallows a stream 'error' event (EPIPE) so it never becomes an uncaught exception", () => { + // A real EventEmitter: emitting "error" with no listener THROWS (Node's unhandled-error rule) — + // which is exactly what an EPIPE on process.stdout does to the process once the consumer closes + // the pipe. The guard the sink installs must absorb it, and logging must carry on afterwards. + const captured: string[] = []; + class FakeStdout extends EventEmitter { + write(chunk: string, cb?: () => void): boolean { + captured.push(chunk); + cb?.(); + return true; + } + } + const stdout = new FakeStdout(); + const stdoutGetter = vi.spyOn(process, "stdout", "get").mockReturnValue(stdout as unknown as NodeJS.WriteStream); + try { + const logger = jsonLogger(); + logger.info("before EPIPE"); + getStdoutJsonSink().flushSync(); + expect(stdout.listenerCount("error")).toBe(1); + const epipe = Object.assign(new Error("write EPIPE"), { code: "EPIPE" }); + expect(() => stdout.emit("error", epipe)).not.toThrow(); + logger.info("after EPIPE"); + getStdoutJsonSink().flushSync(); + expect(captured.join("")).toContain('"before EPIPE"'); + expect(captured.join("")).toContain('"after EPIPE"'); + } finally { + stdoutGetter.mockRestore(); + } + }); }); diff --git a/tests/63_inspect_polyfill.test.ts b/tests/63_inspect_polyfill.test.ts index 5b7f961f..d1b75910 100644 --- a/tests/63_inspect_polyfill.test.ts +++ b/tests/63_inspect_polyfill.test.ts @@ -448,6 +448,11 @@ describe("formatWithOptions - format specifiers", () => { test("an unrecognized specifier is left in place and the arg is appended", () => { expect(fmt("q %q x", "Y")).toBe("q %q x Y"); }); + test("a specifier left over once the args are used up stays literal (node:util.format parity)", () => { + // `%s` consumes the only arg; the trailing `%d` has nothing to bind and is kept as-is, exactly + // like `util.format("%s then %d", "X")`. + expect(fmt("%s then %d", "X")).toBe("X then %d"); + }); test("trailing extra args are appended, non-strings inspected", () => { expect(fmt("just", "extra", { o: 1 })).toBe("just extra {\n o: 1 \n}"); }); @@ -480,4 +485,10 @@ describe("formatWithOptions / inspect - non-object options are ignored (_extend // _extend early-returns when `add` isn't an object, so bogus options are a no-op. expect(strip(inspect({ a: 1 }, 5 as unknown as Record))).toBe("{\n a: 1 \n}"); }); + test("inspect with no options at all applies the defaults (colors on, depth 2)", () => { + const rendered = inspect({ a: { b: { c: { d: 1 } } } }); + const stripped = strip(rendered); + expect(stripped).not.toBe(rendered); // colorized by default + expect(stripped).toBe("{\n a: \n {\n b: \n {\n c: [Object] \n } \n } \n}"); + }); }); diff --git a/tests/65_core_gaps.test.ts b/tests/65_core_gaps.test.ts index a9e9dd2e..fbfa6929 100644 --- a/tests/65_core_gaps.test.ts +++ b/tests/65_core_gaps.test.ts @@ -1416,6 +1416,20 @@ describe("settings: warn-only mode (non-strict) emits diagnostics without throwi }); expect(() => validateSettingsParam(hostile as never)).not.toThrow(); }); + + test("a settings object whose contextStorage getter throws is skipped without crashing", () => { + const warnSpy = vi.spyOn(console, "warn").mockImplementation(() => undefined); + const hostile = { + minLevel: 3, + get contextStorage(): unknown { + throw new Error("no contextStorage read"); + }, + }; + // The read itself throws a plain Error (not a TslogConfigError), so the guard swallows it and the pass + // carries on: a valid minLevel and only known keys produce no diagnostic at all. + expect(() => validateSettingsParam(hostile as never)).not.toThrow(); + expect(warnSpy).not.toHaveBeenCalled(); + }); }); describe("settings: normalizeSettings resolution", () => { diff --git a/tests/66_worker_runner.test.ts b/tests/66_worker_runner.test.ts index 84fb4d67..f56ad579 100644 --- a/tests/66_worker_runner.test.ts +++ b/tests/66_worker_runner.test.ts @@ -191,6 +191,27 @@ describe.runIf(isNode)("worker.runner (worker-thread side)", () => { expect(port.close).toHaveBeenCalledTimes(1); }); + test("a message of an unknown type is ignored: no write, no ack, no close, and the runner stays usable", async () => { + const path = tmpLog(); + const port = await loadRunner({ destination: "file", path, eol: "\n", encoding: "utf8", append: true }); + + // Only write/flush/close are protocol messages; anything else (e.g. from a newer main-thread + // worker.js talking to an older runner) must be dropped rather than crash the thread or close it. + expect(() => port.emit("message", { type: "rotate" })).not.toThrow(); + expect(port.postMessage).not.toHaveBeenCalled(); + expect(port.close).not.toHaveBeenCalled(); + expect(existsSync(path)).toBe(false); // no stream was opened for it + + port.emit("message", { type: "write", line: "still-alive" }); + await untilFileHasBytes(path); + port.emit("message", { type: "flush", id: 3 }); + await until(() => port.postMessage.mock.calls.length > 0, 10000, "flush ack"); + // Exactly one ack, for the real flush: the unknown message produced none. + expect(port.postMessage).toHaveBeenCalledTimes(1); + expect(port.postMessage).toHaveBeenCalledWith({ type: "flushed", id: 3 }); + expect(readFileSync(path, "utf8")).toBe("still-alive\n"); + }); + test("a thrown destination error is swallowed — the worker never crashes", async () => { // Point at a path whose parent CANNOT be created (a regular file used as a directory) so the lazy // ensureStream()/mkdirSync throws inside the message handler's try. It must be swallowed. diff --git a/tests/67_exit_and_sink.test.ts b/tests/67_exit_and_sink.test.ts index 1a376885..01aeadb0 100644 --- a/tests/67_exit_and_sink.test.ts +++ b/tests/67_exit_and_sink.test.ts @@ -421,6 +421,31 @@ describe.runIf(isNode)("stdoutSink: synchronous exit drain (drainSync)", () => { } }); + test("a repeated exit drain reuses the fd path and writes only the lines buffered since the previous drain", async () => { + // `process.on("exit")` listeners can run more than once (user code or a harness calling + // `process.emit("exit")`): every drain must go through fs.writeSync — never the stream fallback — + // and emit only what was buffered after the previous drain, so no line prints twice. + const seen: string[] = []; + const writeSyncSpy = vi.spyOn(fs, "writeSync").mockImplementation(((_fd: number, data: Uint8Array) => { + seen.push(Buffer.from(data).toString("utf8")); + return data.length; + }) as never); + const stdout = fakeStdout(7); + const getter = vi.spyOn(process, "stdout", "get").mockReturnValue(stdout as unknown as NodeJS.WriteStream); + try { + const { sink, runExitDrain } = await freshSinkWithExitDrain(); + sink.write('{"m":"drain-1"}'); + runExitDrain(); + sink.write('{"m":"drain-2"}'); + runExitDrain(); + expect(seen).toEqual(['{"m":"drain-1"}\n', '{"m":"drain-2"}\n']); + expect(stdout.captured).toHaveLength(0); + } finally { + writeSyncSpy.mockRestore(); + getter.mockRestore(); + } + }); + test("drainSync on an empty buffer is a no-op (nothing written)", async () => { const stdout = fakeStdout(1); const getter = vi.spyOn(process, "stdout", "get").mockReturnValue(stdout as unknown as NodeJS.WriteStream); diff --git a/tests/68_browser_env.test.ts b/tests/68_browser_env.test.ts index 9ea57f62..18d7fe24 100644 --- a/tests/68_browser_env.test.ts +++ b/tests/68_browser_env.test.ts @@ -265,6 +265,12 @@ describe("shared.ts stack-line parsers", () => { expect(parseReactNativeStackLine("foo@[native code]:0:0", noCwd)).toBeUndefined(); }); + test("a JSC native-code frame without any position (`forEach@[native code]`) yields no frame", () => { + // JSC prints native frames with no :line:col at all, so the JSC regex cannot match the line; + // the browser parser finds no path either — the line is dropped instead of becoming a junk frame. + expect(parseReactNativeStackLine("forEach@[native code]", noCwd)).toBeUndefined(); + }); + test("falls through to the browser parser for a multi-segment URL frame", () => { const frame = parseReactNativeStackLine("bar@http://localhost:8081/index.bundle:117:42", noCwd) as IStackFrame; expect(frame).toBeDefined(); @@ -674,6 +680,27 @@ describe("createBrowserEnvironment provider", () => { const frame = env.getCallerStackFrame(Number.NaN, error, [/wrapper\/lib\.js/]); expect(frame.fileName).toBe("main.js"); }); + + test("own-file detection is best-effort: a provider built while Error.stackTraceLimit is 0 still resolves callers", () => { + makeBrowser(); + // With stack capture disabled (a common production perf setting) the Error captured at + // construction carries no frames, so no own-file pattern can be derived. Construction must not + // depend on it, and the default ignore patterns must still apply to later lookups. + const savedLimit = Error.stackTraceLimit; + Error.stackTraceLimit = 0; + let env: ReturnType; + try { + env = createBrowserEnvironment(); + } finally { + Error.stackTraceLimit = savedLimit; + } + const error = { + stack: "Error\nlog@http://h/node_modules/tslog/dist/browser/index.js:1:1\nuser@http://h/app/main.js:2:2", + } as Error; + const frame = env.getCallerStackFrame(Number.NaN, error); + expect(frame.fileName).toBe("main.js"); + expect(frame.fileLine).toBe("2"); + }); }); describe("isBuffer without a Buffer global", () => { diff --git a/tests/74_source_map_resolution.test.ts b/tests/74_source_map_resolution.test.ts index 2fcad316..b80de85a 100644 --- a/tests/74_source_map_resolution.test.ts +++ b/tests/74_source_map_resolution.test.ts @@ -307,6 +307,22 @@ describe("source-map resolution (issue #307)", () => { }); }); + test("a generated line holding only 1-field (unmapped) segments has no original position; later lines still resolve", async () => { + await withTempDir(async (dir) => { + const jsPath = join(dir, "unmapped.js"); + const mapPath = join(dir, "unmapped.js.map"); + await writeFile(jsPath, "line one\nline two\nline three\n//# sourceMappingURL=unmapped.js.map\n"); + // Minifiers emit 1-field segments ("A" = a generated column with no source) for unmapped output. + // Line 2 (index 1) carries only such a segment, so it gets no entry and the caller keeps the + // transpiled position; line 3 (index 2) is the SIMPLE_MAPPINGS segment and must still resolve + // with the running deltas intact. + await writeFile(mapPath, JSON.stringify({ version: 3, sources: ["unmapped.ts"], names: [], mappings: ";A;UACQ" })); + + expect(resolveOriginalPosition(jsPath, 2, 1)).toBeUndefined(); + expect(resolveOriginalPosition(jsPath, 3, 11)).toEqual({ source: join(dir, "unmapped.ts"), line: 2, column: 9 }); + }); + }); + test("findSegment stops scanning once a later segment's column exceeds the requested column", async () => { await withTempDir(async (dir) => { const jsPath = join(dir, "multi.js"); diff --git a/tests/75_bundler_compatibility.test.ts b/tests/75_bundler_compatibility.test.ts index f1c90350..eddd022a 100644 --- a/tests/75_bundler_compatibility.test.ts +++ b/tests/75_bundler_compatibility.test.ts @@ -340,6 +340,42 @@ describe("bundler source map compatibility (Rollup, Webpack, Turbopack)", () => }); }); + test("a malformed sectioned map whose section lacks `offset` is anchored at 0:0 instead of throwing", async () => { + await withTempDir(async (dir) => { + const jsPath = join(dir, "no-offset-chunk.js"); + const mapPath = join(dir, "no-offset-chunk.js.map"); + await writeFile(jsPath, "pre\n const x = 1;\n//# sourceMappingURL=no-offset-chunk.js.map\n"); + // `offset` is required by the spec, but the map parse runs outside any try/catch: a section + // without it must degrade (anchor at 0:0) rather than surface a TypeError into the log call. + const malformed = { version: 3, sections: [{ map: { version: 3, sources: ["[project]/src/x.ts"], names: [], mappings: ";UACI" } }] }; + await writeFile(mapPath, JSON.stringify(malformed)); + + let resolved: OriginalPosition | undefined; + expect(() => { + resolved = resolveOriginalPosition(jsPath, 2, 11); + }).not.toThrow(); + expect(resolved).toEqual({ source: "src/x.ts", line: 2, column: 5 }); + }); + }); + + test("a structurally hostile map (valid JSON, wrong shapes) degrades to the transpiled position instead of throwing", async () => { + await withTempDir(async (dir) => { + // Both parse without a JSON error and would blow up deeper in the walk (`null.offset`, `(123).split`): + // the resolver must swallow that, report "no original position", and cache the miss. + const hostile: Array<[string, unknown]> = [ + ["null-section.js", { version: 3, sections: [null] }], + ["numeric-mappings.js", { version: 3, sources: ["a.ts"], names: [], mappings: 123 }], + ]; + for (const [name, map] of hostile) { + const jsPath = join(dir, name); + await writeFile(jsPath, `const x = 1;\n//# sourceMappingURL=${name}.map\n`); + await writeFile(join(dir, `${name}.map`), JSON.stringify(map)); + expect(() => resolveOriginalPosition(jsPath, 1, 7)).not.toThrow(); + expect(resolveOriginalPosition(jsPath, 1, 7)).toBeUndefined(); + } + }); + }); + test("Rollup + Webpack outputs still work when the call site is inside an async function (realistic frame)", async () => { // This is mostly a regression guard: async functions produce slightly different stack shapes. const rollup = (await import("rollup")).rollup; diff --git a/vitest.config.ts b/vitest.config.ts index 98b286a0..730da119 100644 --- a/vitest.config.ts +++ b/vitest.config.ts @@ -22,6 +22,9 @@ export default defineConfig({ "src/index.browser.ts", ], reporter: ["text", "lcov", "clover", "json"], + // Hard floor: `npm run coverage` (CI's Node 20 job) fails below 100% on every metric instead of + // reporting a drop quietly — Codecov is not configured to enforce anything. + thresholds: { statements: 100, branches: 100, functions: 100, lines: 100 }, }, }, });