From 02c397a4b5261afc25796e4ba9e20da7a17e7786 Mon Sep 17 00:00:00 2001 From: Gergo Magyar Date: Tue, 5 May 2026 17:07:42 +0100 Subject: [PATCH] =?UTF-8?q?fix(logger):=20address=20PR=20review=20findings?= =?UTF-8?q?=20=E2=80=94=20pretty-stderr,=20log=20levels,=20structured=20fi?= =?UTF-8?q?elds?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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. --- gitnexus/src/cli/mcp.ts | 9 ++++--- .../src/core/ingestion/workers/worker-pool.ts | 26 ++++++++++++++----- gitnexus/src/core/logger.ts | 4 +++ gitnexus/src/mcp/local/local-backend.ts | 26 +++++++++---------- 4 files changed, 41 insertions(+), 24 deletions(-) diff --git a/gitnexus/src/cli/mcp.ts b/gitnexus/src/cli/mcp.ts index 3bc708087..eccbb4318 100644 --- a/gitnexus/src/cli/mcp.ts +++ b/gitnexus/src/cli/mcp.ts @@ -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', ); } diff --git a/gitnexus/src/core/ingestion/workers/worker-pool.ts b/gitnexus/src/core/ingestion/workers/worker-pool.ts index bcc9aa544..b6f16de66 100644 --- a/gitnexus/src/core/ingestion/workers/worker-pool.ts +++ b/gitnexus/src/core/ingestion/workers/worker-pool.ts @@ -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, diff --git a/gitnexus/src/core/logger.ts b/gitnexus/src/core/logger.ts index d97146a61..3230b91a5 100644 --- a/gitnexus/src/core/logger.ts +++ b/gitnexus/src/core/logger.ts @@ -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', diff --git a/gitnexus/src/mcp/local/local-backend.ts b/gitnexus/src/mcp/local/local-backend.ts index fade093ea..47dbf31dd 100644 --- a/gitnexus/src/mcp/local/local-backend.ts +++ b/gitnexus/src/mcp/local/local-backend.ts @@ -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): 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 {