From 42d97802ea6a8ea4cdef6ca06e2b7d989409edee Mon Sep 17 00:00:00 2001 From: samuel mbabhazi <111171386+samuelmbabhazi@users.noreply.github.com> Date: Tue, 27 Oct 2026 21:38:00 +0200 Subject: [PATCH] feat(logger): let a host route GitNexus records into its own sink (#3729) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * feat(logger): let a host route GitNexus records into its own sink A process that embeds GitNexus had no supported way to send the logger's records into its own logging: the singleton and every named child write to stderr, and the only redirect was the test-only capture (#3620). configureLoggerSink({ destination, level, mixin }) routes the default logger and every later createLogger() child to the host's destination, with the mixin's fields on each record, and returns a function that puts the previous state back. flushLoggerSync() flushes a sink destination that has flushSync. Without a call nothing changes: the default path gains one branch at logger construction and none per record, no pretty transport or exit hook is installed for a host sink, and a test capture keeps precedence while it is active. * fix(logger): retire a sink on restore so an out-of-order restore cannot revive it A restore that found its sink displaced by a later one returned without a trace, and the later sink's restore then handed the state back to the sink whose owner had already restored it (review on #3729). A restore now retires its sink for good: when active, the nearest earlier sink that is still live becomes active again, else stderr; when displaced, the active state is left alone but the sink can no longer come back. * test(logger): cover a warn-level host sink and a restore across two retired owners A sink that already enables debug cannot tell whether a child honoured debugEnvVar or only inherited the sink level: dropping debugRequested from the host-sink branch left all 32 tests green. The warn-level case drops an ordinary child's debug record and keeps the debugEnvVar child's. The three-sink case walked past a single retired owner, so a one-hop lookup in nearestLiveSink also passed. Four sinks, with both middle owners retired before the newest restores, reach the oldest live sink only through the loop. --------- Co-authored-by: Gergő Magyar --- gitnexus/src/core/logger.ts | 157 ++++++++++++++++- gitnexus/test/unit/logger.test.ts | 284 ++++++++++++++++++++++++++++++ 2 files changed, 439 insertions(+), 2 deletions(-) diff --git a/gitnexus/src/core/logger.ts b/gitnexus/src/core/logger.ts index bf32f1045..efb7d15b6 100644 --- a/gitnexus/src/core/logger.ts +++ b/gitnexus/src/core/logger.ts @@ -22,12 +22,22 @@ * when stdout is a TTY AND CI is unset AND VITEST is unset, so test * and pipeline output stay parseable. * + * Host sink (#3620): + * A process that embeds GitNexus (its own service around `serve` or the MCP + * server) can route the records into its own logging with + * `configureLoggerSink({ destination, level, mixin })`: the `logger` + * singleton and every `createLogger()` call made after it write to that + * destination instead of stderr, with the mixin's fields on each record. The + * returned function restores what was there before. Without a call nothing + * changes, and the check costs one branch at logger construction, not per + * record. + * * Test capture: * The exported `logger` singleton is a Proxy that forwards every call to a * lazily-built pino instance. Tests use `_captureLogger()` to redirect that * inner instance to a memory stream so they can assert on records the * production code logged. See `gitnexus/test/unit/logger.test.ts` for the - * pattern. + * pattern. A capture takes precedence over a host sink while it is active. */ import pino, { type Logger, type LoggerOptions, type DestinationStream } from 'pino'; import { Writable } from 'node:stream'; @@ -101,6 +111,17 @@ function defaultDestination(): DestinationStream { * test mode (tests use an in-memory destination). */ export function flushLoggerSync(): void { + // A host sink that buffers (a SonicBoom, a file stream of its own) is + // flushed the same way; one without `flushSync` has nothing to flush here. + const sinkDestination = _sink?.destination as { flushSync?: () => void } | undefined; + if (typeof sinkDestination?.flushSync === 'function') { + try { + sinkDestination.flushSync(); + } catch { + // Same trade-off as below: a closed destination must not turn a + // shutdown into a crash. + } + } if (!_dest) return; try { _dest.flushSync(); @@ -215,10 +236,129 @@ function buildBaseOptions(): LoggerOptions { return opts; } +/* ------------------------------------------------------------------ */ +/* Host sink (#3620) */ +/* ------------------------------------------------------------------ */ + +export interface LoggerSinkOptions { + /** Where records go instead of stderr: any writable stream, a pino destination included. */ + destination: DestinationStream; + /** + * Base level for the singleton and for later children. When unset, + * `GITNEXUS_LOG_LEVEL` applies as it does on stderr. A child's `debugEnvVar` + * still wins when truthy. + */ + level?: string; + /** + * Extra fields merged into every record (pino's `mixin`), for example a + * request id read from an AsyncLocalStorage. Called once per record; a field + * the record carries itself wins over the mixin's. A mixin that throws does + * not break the record: it is written without the mixin's fields and the + * failure is reported on stderr once. + */ + mixin?: () => Record; +} + +interface ActiveSink { + readonly destination: DestinationStream; + readonly level: string | undefined; + readonly mixin: (() => Record) | undefined; + /** The sink that was active when this one was configured. */ + readonly previous: ActiveSink | undefined; + /** Set by this sink's restore; a retired sink is never made active again. */ + retired: boolean; +} + +let _sink: ActiveSink | undefined; + +/** The nearest sink in the chain whose owner has not restored it yet. */ +function nearestLiveSink(from: ActiveSink | undefined): ActiveSink | undefined { + let sink = from; + while (sink !== undefined && sink.retired) sink = sink.previous; + return sink; +} + +/** + * A host mixin runs inside every log call of GitNexus, so a bug in it must not + * turn a `logger.warn` deep in the ingestion into a crash. The record goes out + * without the mixin's fields, and the failure is reported once, the same way + * a missing pino-pretty is: on stderr directly, since the logger is what is + * failing. + */ +function guardMixin(mixin: () => Record): () => Record { + let warned = false; + return () => { + try { + const fields = mixin(); + return fields !== null && typeof fields === 'object' ? fields : {}; + } catch (error) { + if (!warned) { + warned = true; + const message = error instanceof Error ? error.message : String(error); + process.stderr.write( + `[gitnexus:logger] host mixin threw; records continue without its fields: ${message}\n`, + ); + } + return {}; + } + }; +} + +/** + * Route the default `logger` and every `createLogger()` call made from now on + * into the host's own sink. The singleton is a Proxy, so modules that imported + * it before this call pick the sink up on their next record; a named child + * built before this call keeps the destination it was built with. + * + * Returns a function that retires this sink. When it is the active one, the + * nearest earlier sink that has not been retired itself becomes active again, + * or stderr when there is none. When a later `configureLoggerSink()` has + * replaced it, the active state is left alone, but the sink stays retired, so + * a later restore never brings it back: host and plugin lifetimes do not have + * to end in strict LIFO order. + * + * No pretty transport and no `beforeExit` flush hook are installed for a host + * sink: the destination belongs to the host, which decides how it is flushed + * (`flushLoggerSync()` calls the destination's `flushSync` when it has one). + */ +export function configureLoggerSink(opts: LoggerSinkOptions): () => void { + const destination = opts?.destination as { write?: unknown } | undefined; + if (typeof destination?.write !== 'function') { + throw new TypeError( + 'configureLoggerSink: `destination` must be a writable stream (an object with a write() method)', + ); + } + if (opts.level !== undefined && !PINO_LEVELS.has(opts.level.toLowerCase())) { + throw new RangeError( + `configureLoggerSink: unknown level "${opts.level}"; expected one of ${[...PINO_LEVELS].join(', ')}`, + ); + } + if (opts.mixin !== undefined && typeof opts.mixin !== 'function') { + throw new TypeError('configureLoggerSink: `mixin` must be a function returning an object'); + } + const sink: ActiveSink = { + destination: opts.destination, + level: opts.level?.toLowerCase(), + mixin: opts.mixin ? guardMixin(opts.mixin) : undefined, + previous: _sink, + retired: false, + }; + _sink = sink; + // The singleton is rebuilt on its next call so it picks the sink up. + _cached = undefined; + return () => { + sink.retired = true; + if (_sink !== sink) return; + _sink = nearestLiveSink(sink.previous); + _cached = undefined; + }; +} + /** * Create a named child logger. When `opts.destination` is provided it bypasses * the default stdout sink (useful for test capture). When `opts.debugEnvVar` is - * set and truthy at call time, the child runs at 'debug' level. + * set and truthy at call time, the child runs at 'debug' level. With a host + * sink configured (`configureLoggerSink`), the child writes there. */ export function createLogger(name: string, opts?: CreateLoggerOptions): Logger { const debugRequested = opts?.debugEnvVar ? isTruthyEnv(process.env[opts.debugEnvVar]) : false; @@ -230,6 +370,19 @@ export function createLogger(name: string, opts?: CreateLoggerOptions): Logger { ); } + const sink = _sink; + if (sink) { + return pino( + { + level: debugRequested ? 'debug' : (sink.level ?? resolveBaseLevel()), + base: undefined, + name, + ...(sink.mixin ? { mixin: sink.mixin } : {}), + }, + sink.destination, + ); + } + const base = buildBaseOptions(); // When using a transport (pino-pretty), pino manages the destination // internally and we cannot pass one explicitly. When transport is absent, diff --git a/gitnexus/test/unit/logger.test.ts b/gitnexus/test/unit/logger.test.ts index 7d92d40c5..de6a850cf 100644 --- a/gitnexus/test/unit/logger.test.ts +++ b/gitnexus/test/unit/logger.test.ts @@ -21,6 +21,7 @@ import { _tryBuildPrettyTransport, _resetPrettyAvailableCache, flushLoggerSync, + configureLoggerSink, } from '../../src/core/logger.js'; describe('createLogger — API surface', () => { @@ -277,3 +278,286 @@ describe('_tryBuildPrettyTransport — pino-pretty availability probe', () => { } }); }); + +// #3620: a host that embeds GitNexus routes the records into its own sink. +describe('configureLoggerSink — host sink', () => { + it('routes the singleton and later children to the destination, with mixin fields, and never builds the stderr destination', async () => { + // A fresh module instance, so no earlier test has built the stderr + // destination: if the sink works, `pino.destination` is never called. + vi.resetModules(); + const pinoModule = await import('pino'); + const destinationSpy = vi.spyOn(pinoModule.default, 'destination'); + const fresh = await import('../../src/core/logger.js'); + const sink = new fresh.MemoryWritable(); + let requestId = 'req-1'; + const restore = fresh.configureLoggerSink({ + destination: sink, + mixin: () => ({ requestId }), + }); + try { + fresh.logger.warn({ k: 'v' }, 'from the singleton'); + requestId = 'req-2'; + fresh.createLogger('child').info('from a child'); + const recs = sink.records(); + expect(recs.map((r) => [r.name, r.msg, r.requestId])).toEqual([ + ['gitnexus', 'from the singleton', 'req-1'], + ['child', 'from a child', 'req-2'], + ]); + expect(recs[0].k).toBe('v'); + expect(destinationSpy).not.toHaveBeenCalled(); + } finally { + restore(); + destinationSpy.mockRestore(); + vi.resetModules(); + } + }); + + it('applies the sink level, and a child debugEnvVar still wins', () => { + const sink = new MemoryWritable(); + const restore = configureLoggerSink({ destination: sink, level: 'debug' }); + try { + logger.debug('singleton debug'); + createLogger('quiet').trace('child trace'); + process.env.GITNEXUS_TEST_SINK_DEBUG = '1'; + try { + createLogger('loud', { debugEnvVar: 'GITNEXUS_TEST_SINK_DEBUG' }).debug('child debug'); + } finally { + delete process.env.GITNEXUS_TEST_SINK_DEBUG; + } + expect(sink.records().map((r) => r.msg)).toEqual(['singleton debug', 'child debug']); + } finally { + restore(); + } + }); + + it('a restrictive sink level drops an ordinary child debug record, and debugEnvVar still emits one', () => { + // The sink above already enables debug, so it cannot tell whether the + // child honoured debugEnvVar or only inherited the sink level. + const sink = new MemoryWritable(); + const restore = configureLoggerSink({ destination: sink, level: 'warn' }); + process.env.GITNEXUS_TEST_SINK_DEBUG = '1'; + try { + createLogger('quiet').debug('dropped by the sink level'); + createLogger('loud', { debugEnvVar: 'GITNEXUS_TEST_SINK_DEBUG' }).debug( + 'kept by debugEnvVar', + ); + createLogger('quiet').warn('kept by the sink level'); + expect(sink.records().map((r) => [r.name, r.msg])).toEqual([ + ['loud', 'kept by debugEnvVar'], + ['quiet', 'kept by the sink level'], + ]); + } finally { + delete process.env.GITNEXUS_TEST_SINK_DEBUG; + restore(); + } + }); + + it('restore() returns the singleton to the previous destination', () => { + const sink = new MemoryWritable(); + const restore = configureLoggerSink({ destination: sink }); + logger.warn('while routed'); + restore(); + // A test capture is the previous-destination seam that can be observed. + const cap = _captureLogger(); + try { + logger.warn('after restore'); + expect(cap.records().map((r) => r.msg)).toEqual(['after restore']); + expect(sink.records().map((r) => r.msg)).toEqual(['while routed']); + } finally { + cap.restore(); + } + }); + + it('a sink restored out of order never comes back: restoreFirst then restoreSecond ends on stderr', () => { + // Host and plugin lifetimes do not end in strict LIFO order. The first + // owner's restore ran while the second sink was active; once the second + // owner restores too, nothing may resurrect the first. + const first = new MemoryWritable(); + const second = new MemoryWritable(); + const restoreFirst = configureLoggerSink({ destination: first }); + const restoreSecond = configureLoggerSink({ destination: second }); + restoreFirst(); + restoreSecond(); + // No capture here: a capture would take precedence over any sink and hide + // a resurrected one. The record goes to stderr, and neither stream sees it. + logger.warn('after both owners restored'); + expect(first.records()).toEqual([]); + expect(second.records()).toEqual([]); + }); + + it('skips every retired predecessor, not only the nearest one', () => { + const first = new MemoryWritable(); + const second = new MemoryWritable(); + const third = new MemoryWritable(); + const restoreFirst = configureLoggerSink({ destination: first }); + const restoreSecond = configureLoggerSink({ destination: second }); + const restoreThird = configureLoggerSink({ destination: third }); + restoreSecond(); + restoreThird(); + try { + logger.warn('back on the first, the only live owner'); + expect(first.records().map((r) => r.msg)).toEqual(['back on the first, the only live owner']); + expect(second.records()).toEqual([]); + expect(third.records()).toEqual([]); + } finally { + restoreFirst(); + } + }); + + it('restoring the newest sink walks past two retired owners to the oldest live one', () => { + // Two middle owners retire while the newest sink is active; their sinks + // stay in the chain as retired links. The newest owner's restore must skip + // both, not only the nearest one. + const first = new MemoryWritable(); + const second = new MemoryWritable(); + const third = new MemoryWritable(); + const fourth = new MemoryWritable(); + const restoreFirst = configureLoggerSink({ destination: first }); + const restoreSecond = configureLoggerSink({ destination: second }); + const restoreThird = configureLoggerSink({ destination: third }); + const restoreFourth = configureLoggerSink({ destination: fourth }); + restoreSecond(); + restoreThird(); + restoreFourth(); + try { + logger.warn('only the oldest owner is still live'); + expect(first.records().map((r) => r.msg)).toEqual(['only the oldest owner is still live']); + expect(second.records()).toEqual([]); + expect(third.records()).toEqual([]); + expect(fourth.records()).toEqual([]); + } finally { + restoreFirst(); + } + }); + + it('a later sink replaces the earlier one, whose restore leaves the active state alone', () => { + const first = new MemoryWritable(); + const second = new MemoryWritable(); + const restoreFirst = configureLoggerSink({ destination: first }); + const restoreSecond = configureLoggerSink({ destination: second }); + try { + logger.warn('to the second'); + restoreFirst(); + logger.warn('still the second'); + expect(second.records().map((r) => r.msg)).toEqual(['to the second', 'still the second']); + expect(first.records()).toEqual([]); + } finally { + restoreSecond(); + } + }); + + it('a test capture takes precedence over the sink while it is active', () => { + const sink = new MemoryWritable(); + const restore = configureLoggerSink({ destination: sink }); + try { + const cap = _captureLogger(); + try { + logger.warn('captured, not sunk'); + expect(cap.records().map((r) => r.msg)).toEqual(['captured, not sunk']); + } finally { + cap.restore(); + } + logger.warn('sunk again'); + expect(sink.records().map((r) => r.msg)).toEqual(['sunk again']); + } finally { + restore(); + } + }); + + it('restores through a chain: second, then first, then the previous destination', () => { + const first = new MemoryWritable(); + const second = new MemoryWritable(); + const restoreFirst = configureLoggerSink({ destination: first }); + const restoreSecond = configureLoggerSink({ destination: second }); + restoreSecond(); + logger.warn('back on the first'); + restoreFirst(); + const cap = _captureLogger(); + try { + logger.warn('back on the default'); + expect(first.records().map((r) => r.msg)).toEqual(['back on the first']); + expect(second.records()).toEqual([]); + expect(cap.records().map((r) => r.msg)).toEqual(['back on the default']); + } finally { + cap.restore(); + } + }); + + it('reads the level case-insensitively and lets it win over GITNEXUS_LOG_LEVEL', () => { + const sink = new MemoryWritable(); + const previous = process.env.GITNEXUS_LOG_LEVEL; + process.env.GITNEXUS_LOG_LEVEL = 'debug'; + const restore = configureLoggerSink({ destination: sink, level: 'WARN' }); + try { + logger.info('dropped by the sink level'); + logger.warn('kept'); + expect(sink.records().map((r) => r.msg)).toEqual(['kept']); + } finally { + restore(); + if (previous === undefined) delete process.env.GITNEXUS_LOG_LEVEL; + else process.env.GITNEXUS_LOG_LEVEL = previous; + } + }); + + it("a record's own field wins over the mixin's", () => { + const sink = new MemoryWritable(); + const restore = configureLoggerSink({ + destination: sink, + mixin: () => ({ requestId: 'from-mixin', host: 'h' }), + }); + try { + logger.warn({ requestId: 'own' }, 'precedence'); + const [rec] = sink.records(); + expect(rec.requestId).toBe('own'); + expect(rec.host).toBe('h'); + } finally { + restore(); + } + }); + + it('a mixin that throws does not lose the record, and is reported on stderr once', () => { + const sink = new MemoryWritable(); + const stderr = vi.spyOn(process.stderr, 'write').mockImplementation(() => true); + const restore = configureLoggerSink({ + destination: sink, + mixin: () => { + throw new Error('host bug'); + }, + }); + try { + logger.warn('first'); + createLogger('child').warn('second'); + expect(sink.records().map((r) => r.msg)).toEqual(['first', 'second']); + const warnings = stderr.mock.calls + .map((c) => String(c[0])) + .filter((line) => line.includes('host mixin threw')); + expect(warnings).toHaveLength(1); + expect(warnings[0]).toContain('host bug'); + } finally { + restore(); + stderr.mockRestore(); + } + }); + + it('flushLoggerSync flushes a sink destination that has flushSync', () => { + const flushSync = vi.fn(); + const sink = Object.assign(new MemoryWritable(), { flushSync }); + const restore = configureLoggerSink({ destination: sink }); + try { + flushLoggerSync(); + expect(flushSync).toHaveBeenCalledTimes(1); + } finally { + restore(); + } + }); + + it('rejects a destination without write(), an unknown level, and a non-function mixin', () => { + expect(() => configureLoggerSink({ destination: {} as never })).toThrow(TypeError); + expect(() => configureLoggerSink({ destination: new MemoryWritable(), level: 'loud' })).toThrow( + RangeError, + ); + expect(() => + configureLoggerSink({ destination: new MemoryWritable(), mixin: 42 as never }), + ).toThrow(TypeError); + }); +});