diff --git a/gitnexus/src/core/logger.ts b/gitnexus/src/core/logger.ts index 3fd39193b..bf32f1045 100644 --- a/gitnexus/src/core/logger.ts +++ b/gitnexus/src/core/logger.ts @@ -38,6 +38,12 @@ export interface CreateLoggerOptions { debugEnvVar?: string; /** Override destination stream — primarily for tests. */ destination?: DestinationStream; + /** + * Explicit level for the destination-override path — primarily for tests that + * need to capture below the default `info` (e.g. asserting a `debug` record). + * Ignored unless `destination` is set; `debugEnvVar` still wins when truthy. + */ + level?: string; } function isTruthyEnv(value: string | undefined): boolean { @@ -219,7 +225,7 @@ export function createLogger(name: string, opts?: CreateLoggerOptions): Logger { if (opts?.destination) { return pino( - { level: debugRequested ? 'debug' : 'info', base: undefined, name }, + { level: debugRequested ? 'debug' : (opts.level ?? 'info'), base: undefined, name }, opts.destination, ); } @@ -247,6 +253,7 @@ export function createLogger(name: string, opts?: CreateLoggerOptions): Logger { /* ------------------------------------------------------------------ */ let _activeDestination: DestinationStream | undefined; +let _activeLevel: string | undefined; let _cached: Logger | undefined; function _getInner(): Logger { @@ -256,7 +263,7 @@ function _getInner(): Logger { // by `_captureLogger()` below. _cached = createLogger( 'gitnexus', - _activeDestination ? { destination: _activeDestination } : undefined, + _activeDestination ? { destination: _activeDestination, level: _activeLevel } : undefined, ); return _cached; } @@ -342,10 +349,13 @@ export interface LoggerCapture { * expect(cap.records().some(r => r.msg?.includes('clamping'))).toBe(true); * }); * + * Pass `level` (e.g. 'debug') to capture below the default 'info' — needed to + * assert that a record was emitted at debug rather than merely absent. + * * Not a public API; underscore-prefixed and called only from test code. * Throws if a previous capture is still active — see the body for context. */ -export function _captureLogger(): LoggerCapture { +export function _captureLogger(level?: string): LoggerCapture { // Guard against double-capture: forgetting `restore()` between two // `_captureLogger()` calls silently abandoned the previous capture and // corrupted logger state for the rest of the vitest worker. Throwing here @@ -358,6 +368,7 @@ export function _captureLogger(): LoggerCapture { } const w = new MemoryWritable(); _activeDestination = w; + _activeLevel = level; _cached = undefined; return { records: () => @@ -369,6 +380,7 @@ export function _captureLogger(): LoggerCapture { text: () => w.chunks.join(''), restore: () => { _activeDestination = undefined; + _activeLevel = undefined; _cached = undefined; }, }; diff --git a/gitnexus/src/mcp/local/local-backend.ts b/gitnexus/src/mcp/local/local-backend.ts index 7ea98463c..f5934c534 100644 --- a/gitnexus/src/mcp/local/local-backend.ts +++ b/gitnexus/src/mcp/local/local-backend.ts @@ -268,9 +268,10 @@ const confidenceForRelType = (relType: string | undefined): number => /** * Structured logging for *swallowed* query failures — replaces empty catch - * blocks. Every caller of this helper catches the failure and degrades to a - * safe fallback (the operation still returns a result), so these are NOT - * operation-level errors and must not be logged at `error`: + * blocks. The level reflects telemetry severity, NOT a promise about the + * caller: most callers catch the failure and degrade to a genuinely safe + * fallback (a usable result, usually with a caller-visible `partial`/`ftsUsed` + * flag), so these are not operation-level errors and must not log at `error`: * * - A benign missing optional table/label/column — a repo analyzed without * processes/communities, or a pre-v3 PDG index lacking the `calleeIds` @@ -283,6 +284,13 @@ const confidenceForRelType = (relType: string | undefined): number => * `error` is intentionally NOT used here — it is reserved for failures that * actually abort an operation, which log directly rather than through this * best-effort-degradation helper. + * + * Contract for callers (#2283 review): only route a failure here when the + * caller ALSO surfaces the degradation in its result (a `partial` flag, + * `failed_files`, `traversalComplete:false`, …). A mutating or safety-critical + * path that would otherwise report success/clean (e.g. `rename` apply, the + * `detect_changes` safety gate) MUST set that result-level signal — `warn` + * alone is not a substitute for an honest result. */ function logQueryError(context: string, err: unknown): void { const msg = err instanceof Error ? err.message : String(err); @@ -303,7 +311,12 @@ function logQueryError(context: string, err: unknown): void { */ function isBenignMissingTableError(err: unknown): boolean { const msg = err instanceof Error ? err.message : String(err ?? ''); - return /does not exist|no such (table|label|rel)|unknown (table|label)|not (defined|found)/i.test( + // The `not (defined|found)` arm is scoped to a schema object (table/label/ + // rel/column/property), mirroring lbug-adapter's isMissingColumnError + // (`/(table|column|property).*not found/i`): an unscoped "not found" matched + // operation failures like `rg: not found` (ripgrep absent) or `Symbol not + // found`, which this helper would then silently demote to `debug` (#2283). + return /does not exist|no such (table|label|rel)|unknown (table|label)|(table|label|rel|column|property)[^\n]*\bnot (defined|found)\b/i.test( msg, ); } @@ -3851,6 +3864,9 @@ export class LocalBackend { // Map diff hunks to indexed symbols via range overlap const changedSymbols: any[] = []; + // Set if a swallowed graph query fails below — surfaces `partial:true` so a + // degraded run cannot report a false-clean `risk_level:'low'` (#2283). + let queryDegraded = false; for (const fileDiff of fileDiffs) { if (fileDiff.hunks.length === 0) continue; @@ -3898,6 +3914,12 @@ export class LocalBackend { } } catch (e) { logQueryError('detect-changes:file-symbols', e); + // The symbol query failed: changedSymbols stays empty and the result + // would otherwise look like a clean no-op (`changed_count:0`, + // `risk_level:'low'`). detect_changes is the pre-commit safety gate, so + // flag the result `partial` rather than let a swallowed failure + // masquerade as "nothing changed" (#2283). + queryDegraded = true; } } @@ -3936,6 +3958,7 @@ export class LocalBackend { } } catch (e) { logQueryError('detect-changes:process-lookup', e); + queryDegraded = true; } } @@ -3958,6 +3981,9 @@ export class LocalBackend { }, changed_symbols: changedSymbols, affected_processes: Array.from(affectedProcesses.values()), + // A swallowed query failure makes the counts/risk above incomplete — tell + // the caller so the safety gate isn't trusted as a clean result (#2283). + ...(queryDegraded && { partial: true }), }; } @@ -4158,6 +4184,7 @@ export class LocalBackend { const allChanges = Array.from(changes.values()); const totalEdits = allChanges.reduce((sum, c) => sum + c.edits.length, 0); + const failedFiles: string[] = []; if (!dry_run) { // Apply edits to files for (const change of allChanges) { @@ -4168,13 +4195,17 @@ export class LocalBackend { content = content.replace(regex, new_name); await fs.writeFile(fullPath, content, 'utf-8'); } catch (e) { + // A swallowed write failure must not be reported as a full success + // (#2283): record the file so the result can degrade to 'partial' + // with the unwritten files listed, rather than masquerading as done. logQueryError('rename:apply-edit', e); + failedFiles.push(change.file_path); } } } return { - status: 'success', + status: failedFiles.length > 0 ? 'partial' : 'success', old_name: oldName, new_name, files_affected: allChanges.length, @@ -4183,6 +4214,7 @@ export class LocalBackend { text_search_edits: astSearchEdits, changes: allChanges, applied: !dry_run, + ...(failedFiles.length > 0 && { failed_files: failedFiles }), }; } @@ -4878,7 +4910,11 @@ export class LocalBackend { symType, direction, maxDepth, - line: params.line, + // Use the normalized line, not raw params.line, so the gate and the + // engine share one source of truth (#2283). Identity in pdg mode today + // — effectiveLine === params.line when mode === 'pdg' — but this stays + // correct if the normalization ever stops being an identity here. + line: effectiveLine, limit: Number.isFinite(params.limit) ? params.limit : 100, // KTD2 extraction-seam discipline: hand the engine its DB dependency // explicitly rather than `this.`-binding it. LocalBackend owns repo diff --git a/gitnexus/test/unit/calltool-dispatch.test.ts b/gitnexus/test/unit/calltool-dispatch.test.ts index e65d9c061..8369c1a9e 100644 --- a/gitnexus/test/unit/calltool-dispatch.test.ts +++ b/gitnexus/test/unit/calltool-dispatch.test.ts @@ -9,6 +9,7 @@ */ import { describe, it, expect, vi, beforeEach } from 'vitest'; import { mkdirSync, mkdtempSync, rmSync, writeFileSync } from 'fs'; +import fsPromises from 'fs/promises'; import os from 'os'; import path from 'path'; @@ -1299,6 +1300,46 @@ describe('LocalBackend.callTool', () => { expect(result.error).toContain('Either symbol_name or symbol_uid'); }); + it('rename: a swallowed apply-edit write failure degrades to status:partial + failed_files (#2283)', async () => { + // Resolve the definition, no graph refs. readFile succeeds (so a def edit is + // recorded), but writeFile fails on apply — the failure is swallowed via + // logQueryError. The result must NOT report a clean success: it degrades to + // 'partial' and lists the unwritten file, instead of status:'success'. + (executeParameterized as any) + .mockResolvedValueOnce([ + { + id: 'func:oldName', + name: 'oldName', + type: 'Function', + filePath: 'src/target.ts', + startLine: 1, + endLine: 5, + }, + ]) + .mockResolvedValue([]); + const readSpy = vi + .spyOn(fsPromises, 'readFile') + .mockResolvedValue('function oldName() {}\n' as unknown as Buffer); + const writeSpy = vi + .spyOn(fsPromises, 'writeFile') + .mockRejectedValue(new Error('EACCES: permission denied')); + try { + const result = await backend.callTool('rename', { + symbol_name: 'oldName', + new_name: 'newName', + dry_run: false, + }); + expect(result.status).toBe('partial'); + expect(result.failed_files).toContain('src/target.ts'); + // It DID attempt to apply (not a dry run) — `applied` stays true; the + // honest signal is the 'partial' status + failed_files, not `applied`. + expect(result.applied).toBe(true); + } finally { + readSpy.mockRestore(); + writeSpy.mockRestore(); + } + }); + // api_impact tool it('dispatches api_impact tool with route param', async () => { (executeParameterized as any).mockResolvedValue([ @@ -1658,7 +1699,7 @@ describe('LocalBackend impact mode (KTD1/KTD5/KTD12)', () => { // literal `line: 0` must be tolerated as omitted (NOT the PDG-only error) and // route to the normal BFS — distinct from a genuine positive `line` (above), // which stays a hard error. - it.each([['callgraph'], [undefined]])( + it.each<['callgraph' | undefined]>([['callgraph'], [undefined]])( 'mode:%j + adapter-materialized line:0 is treated as omitted and runs the BFS (#2279)', async (mode) => { resolveSingleTarget(); @@ -1666,7 +1707,7 @@ describe('LocalBackend impact mode (KTD1/KTD5/KTD12)', () => { const result = await backend.callTool('impact', { target: 'main', direction: 'upstream', - mode: mode as 'callgraph' | undefined, + mode, line: 0, }); // No PDG-only error, no positive-integer error — line:0 is swallowed. @@ -1677,6 +1718,22 @@ describe('LocalBackend impact mode (KTD1/KTD5/KTD12)', () => { }, ); + it.each<['callgraph' | undefined]>([['callgraph'], [undefined]])( + 'mode:%j + line:-1 still errors — the line:0 coercion is narrow, only literal 0 (#2279)', + async (mode) => { + resolveSingleTarget(); + const result = await backend.callTool('impact', { + target: 'main', + direction: 'upstream', + mode, + line: -1, + }); + // A negative line is a real mistake, not an adapter-materialized "omitted": + // it must NOT be swallowed like line:0, and stays the PDG-only hard error. + expect(result.error).toMatch(/'line' is only supported with mode:'pdg'/); + }, + ); + it("mode:'callgraph'/undefined + line:0 is byte-identical to omitting line (#2279)", async () => { resolveSingleTarget(); const omitted = await backend.callTool('impact', { target: 'main', direction: 'upstream' }); @@ -1905,10 +1962,11 @@ describe('LocalBackend impact mode (KTD1/KTD5/KTD12)', () => { // missing `calleeIds`, or a BasicBlock table that simply isn't there) makes the // slice-callees query fail with a benign "missing optional data" error. That is a // normal configuration, not a degradation, so logQueryError routes it to debug — - // suppressed at the default info level. The capture logger runs at info, so a - // debug record never reaches it: the assertion is that NO info+ record (warn/error) - // appears for this context, distinguishing the benign branch from the warn branch - // pinned by the test above. + // suppressed at the default info level. We capture AT debug so the record is + // visible: the assertion is that it was emitted AND at debug (level 10), which + // distinguishes "logged at debug" from "not logged at all" — an info-level + // absence check could not tell those apart and would pass vacuously if the + // logQueryError call were deleted. resolveSingleTarget(); vi.mocked(executeParameterized).mockImplementation(async (_repo, query) => { if (query.includes('RETURN b.callees')) throw new Error('Table BasicBlock does not exist'); @@ -1930,7 +1988,7 @@ describe('LocalBackend impact mode (KTD1/KTD5/KTD12)', () => { criterionLine: 8, }); const bfsSpy = vi.spyOn(backend as any, '_runImpactBFS'); - const cap = _captureLogger(); + const cap = _captureLogger('debug'); try { const result = await backend.callTool('impact', { target: 'main', @@ -1941,10 +1999,53 @@ describe('LocalBackend impact mode (KTD1/KTD5/KTD12)', () => { // Still degrades cleanly to no bridge / no surfaced error. expect(result.error).toBeUndefined(); expect(bfsSpy.mock.calls[0][4].pdgBridge).toBeUndefined(); - // The benign failure was routed to debug (suppressed at info): no warn/error - // record for this context. A regression to warn/error would surface here. + // The benign failure was emitted at debug (20) — NOT warn (40)/error (50). + // Capturing at debug proves the call fired and chose the suppressed level. const slice = cap.records().find((r) => r.context === 'impact:pdg-slice-callees'); - expect(slice).toBeUndefined(); + expect(slice).toBeDefined(); + expect(slice?.level).toBe(20); + } finally { + cap.restore(); + } + }); + + it("mode:'pdg' slice-callees failing with a non-schema 'not found' error logs at warn, not debug (#2283)", async () => { + // "Symbol not found" is an operation failure, not a benign missing optional + // table — isBenignMissingTableError must NOT match an unscoped "not found" + // (only " … not found"), so it stays visible at warn + // rather than being demoted to the suppressed debug level. + resolveSingleTarget(); + vi.mocked(executeParameterized).mockImplementation(async (_repo, query) => { + if (query.includes('RETURN b.callees')) throw new Error('Symbol not found'); + return [{ id: 'func:main', name: 'main', type: 'Function', filePath: 'src/index.ts' }]; + }); + vi.spyOn(backend as any, '_runImpactPDG').mockResolvedValueOnce({ + mode: 'pdg', + target: { id: 'func:main', name: 'main', type: 'Function', filePath: 'src/index.ts' }, + direction: 'downstream', + risk: 'UNKNOWN', + impactedCount: 0, + epistemic: 'pdg-intra-procedural', + reachableBlocks: ['BasicBlock:src/index.ts:8:0:1'], + intraReachableBlocks: ['BasicBlock:src/index.ts:8:0:1'], + seedBlocks: ['BasicBlock:src/index.ts:8:0:0'], + blockCount: 1, + affectedStatements: [{ line: 8, filePath: 'src/index.ts', text: 'callee()' }], + affectedStatementCount: 1, + criterionLine: 8, + }); + vi.spyOn(backend as any, '_runImpactBFS'); + const cap = _captureLogger(); + try { + await backend.callTool('impact', { + target: 'main', + direction: 'downstream', + mode: 'pdg', + line: 8, + }); + const slice = cap.records().find((r) => r.context === 'impact:pdg-slice-callees'); + expect(slice).toBeDefined(); + expect(slice?.level).toBe(40); } finally { cap.restore(); }