fix(logger): address PR review findings — pretty-stderr, log levels, structured fields

Three findings from the multi-agent review on PR #1336:

**[CRITICAL] pino-pretty was writing to stdout, breaking piped CLI output.**
`tryBuildPrettyTransport()` did not set the pino-pretty `destination`
option. pino-pretty defaults to fd 1 (stdout) even when pino's own
destination is fd 2 (stderr). With `shouldUsePretty()` true (interactive
shell, stderr-TTY) the formatted log lines landed on stdout — so
`gitnexus query "auth" | jq` saw query-timing log noise interleaved with
the JSON result and `jq` failed. Fix: pass `destination: 2` to the
pino-pretty transport options. The non-pretty path already used
`pino.destination({dest: 2})`; this aligns the two paths.

**[HIGH] `logQueryTiming()` and MCP startup banner used `logger.error()`
for non-error conditions.** Migration artifacts. Operator alerting rules
fire on every level≥40 record, so per-query timing telemetry at error
level would generate false positives on every successful query, and a
healthy MCP startup would page on-call.

  - `local-backend.ts:logQueryTiming` → `logger.debug` with structured
    `{ query, totalMs, phases }` fields. Operators wanting per-query
    timing set the appropriate log level.
  - `local-backend.ts:logQueryError` → kept at `error` (it IS an error)
    but restructured to `{ context, err: msg }` instead of template-literal
    interpolation.
  - `mcp.ts` "starting with N repos" banner → `logger.info` with
    `{ repoCount, repos }` structured fields.
  - `mcp.ts` "no repos yet" notice → `logger.warn` (operator-actionable
    but non-fatal; server still starts and serves).

**[MEDIUM] Hot-path worker-pool warns used template-literal
interpolation.** Two `logger.warn` sites in `core/ingestion/workers/
worker-pool.ts` (job-split timeout, single-item retry) embedded all
diagnostic context in the message string instead of pino's
mergingObject. Restructured to canonical
`logger.warn({ workerIndex, items, estimatedBytes, ... }, 'msg')` so log
aggregators can query fields independently. Existing tests pin on
`r.msg.includes('Splitting into ...')` / `'Retrying with ...'` — preserved
in the message string so test assertions still pass.

Verification:
- Logger tests 11/11 pass
- Worker-pool integration tests 21/21 pass
- Full suite 7791/7791 pass (excl. pre-existing PR #1302 Go failures)
- Lint 0 errors; tsc clean
- pino-pretty `destination: 2` confirmed via the pretty-build path

Refs: PR #1336 review.
This commit is contained in:
Gergo Magyar 2026-05-05 17:07:42 +01:00
parent bb02b53aa2
commit 02c397a4b5
4 changed files with 41 additions and 24 deletions

View file

@ -31,12 +31,15 @@ export const mcpCommand = async () => {
const repos = await backend.listRepos();
if (repos.length === 0) {
logger.error(
// Operator-actionable but the server still starts and serves; warn-level,
// not error. Tools will discover newly-analyzed repos via lazy refresh.
logger.warn(
'GitNexus: No indexed repos yet. Run `gitnexus analyze` in a git repo — the server will pick it up automatically.',
);
} else {
logger.error(
`GitNexus: MCP server starting with ${repos.length} repo(s): ${repos.map((r) => r.name).join(', ')}`,
logger.info(
{ repoCount: repos.length, repos: repos.map((r) => r.name) },
'GitNexus: MCP server starting',
);
}

View file

@ -260,10 +260,17 @@ export const createWorkerPool = (
timeoutMs: nextTimeout,
};
logger.warn(
`Worker ${workerIndex} parse job idle timeout after ${job.timeoutMs / 1000}s ` +
`(${job.items.length} items, ${job.estimatedBytes} bytes, last progress: ${lastProgress}). ` +
`Splitting into ${first.items.length}/${second.items.length} item jobs with ` +
`${nextTimeout / 1000}s timeout.`,
{
workerIndex,
timeoutSec: job.timeoutMs / 1000,
items: job.items.length,
estimatedBytes: job.estimatedBytes,
lastProgress,
firstSplitItems: first.items.length,
secondSplitItems: second.items.length,
nextTimeoutSec: nextTimeout / 1000,
},
`Worker ${workerIndex} parse job idle timeout. Splitting into ${first.items.length}/${second.items.length} item jobs.`,
);
// Preserve intuitive retry order; final result order is still enforced by startIndex sort.
jobs.unshift(first, second);
@ -273,9 +280,14 @@ export const createWorkerPool = (
const nextAttempt = job.attempt + 1;
if (nextAttempt <= poolOptions.maxTimeoutRetries) {
logger.warn(
`Worker ${workerIndex} parse job idle timeout after ${job.timeoutMs / 1000}s ` +
`(single item, attempt ${nextAttempt}/${poolOptions.maxTimeoutRetries + 1}). ` +
`Retrying with ${nextTimeout / 1000}s timeout.`,
{
workerIndex,
timeoutSec: job.timeoutMs / 1000,
attempt: nextAttempt,
maxAttempts: poolOptions.maxTimeoutRetries + 1,
nextTimeoutSec: nextTimeout / 1000,
},
`Worker ${workerIndex} parse job idle timeout (single item). Retrying with ${nextTimeout / 1000}s timeout.`,
);
jobs.unshift({
...job,

View file

@ -69,6 +69,10 @@ function tryBuildPrettyTransport(): LoggerOptions['transport'] | undefined {
return {
target: 'pino-pretty',
options: {
// Route to stderr (fd 2) so pretty output doesn't contaminate
// CLI tool data on stdout (fd 1). pino-pretty's default is fd 1,
// which would interleave with `gitnexus query | jq` output.
destination: 2,
colorize: true,
translateTime: 'SYS:HH:MM:ss.l',
ignore: 'pid,hostname',

View file

@ -165,29 +165,27 @@ const confidenceForRelType = (relType: string | undefined): number =>
/** Structured error logging for query failures — replaces empty catch blocks */
function logQueryError(context: string, err: unknown): void {
const msg = err instanceof Error ? err.message : String(err);
logger.error(`GitNexus [${context}]: ${msg}`);
logger.error({ context, err: msg }, 'GitNexus query failed');
}
/**
* Structured per-query latency log for production aggregation (#553).
* Per-query latency telemetry for production aggregation (#553).
*
* Emitted on stderr — NOT stdout — because the MCP stdio transport uses
* stdout exclusively for JSON-RPC responses (#324), and the CLI e2e test
* `tool output goes to stdout via fd 1` asserts that stdout parses cleanly
* as JSON. Any `console.log` from inside a tool handler would corrupt the
* protocol. Matches the existing `logQueryError` convention above, which
* uses stderr for the same reason.
* Logged at `debug` level — timing is observability/telemetry, not an
* error. Operators wanting per-query timing set `GITNEXUS_LOG_LEVEL=debug`
* (or equivalent). Emitting at `error` level (the original migration
* artifact) caused alerting rules to fire on every successful query and
* inflated stderr noise for every MCP/CLI invocation.
*
* The `GitNexus [query:timing] …` prefix keeps lines greppable; the
* `phases` payload is JSON so log-scraping pipelines can parse it
* without custom format knowledge.
* Emitted via the project logger which routes to stderr — never stdout —
* because the MCP stdio transport uses stdout exclusively for JSON-RPC
* responses (#324) and the CLI e2e test `tool output goes to stdout via
* fd 1` asserts stdout parses cleanly as JSON.
*/
function logQueryTiming(query: string, phases: Record<string, number>): void {
const totalMs = phases.wall ?? Object.values(phases).reduce((a, b) => a + b, 0);
const truncated = query.length > 80 ? `${query.slice(0, 80)}…` : query;
logger.error(
`GitNexus [query:timing] query=${JSON.stringify(truncated)} totalMs=${totalMs} phases=${JSON.stringify(phases)}`,
);
logger.debug({ query: truncated, totalMs, phases }, 'GitNexus query timing');
}
export interface CodebaseContext {