feat(logger): let a host route GitNexus records into its own sink (#3729)

* 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 <gergomagyar@icloud.com>

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<string, unknown>;
+}
+
+interface ActiveSink {
+  readonly destination: DestinationStream;
+  readonly level: string | undefined;
+  readonly mixin: (() => Record<string, unknown>) | 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<string, unknown>): () => Record<string, unknown> {
+  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,

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);
+  });
+});