mirror of
https://github.com/abhigyanpatwari/GitNexus.git
synced 2026-10-09 03:17:54 +00:00
fix(mcp): make swallowed-failure callers surface degradation; narrow benign-error match (#2283)
Tri-review (#2283) found the `error → {debug|warn}` rework reduced telemetry for `logQueryError` callers that do NOT degrade safely, while the docstring over-claimed "every caller degrades to a safe fallback". Address the substance rather than only the log level: - rename apply-edit: track failed writes and return status:'partial' with `failed_files` instead of reporting `status:'success'` when a write was swallowed. A partial rename is no longer indistinguishable from a clean one. - detect_changes: a swallowed symbol/process query failure now sets `partial:true` (rendered by the existing eval-server partial path) so the pre-commit safety gate can't return a false-clean `risk_level:'low'` no-op. - isBenignMissingTableError: scope the `not (defined|found)` arm to a schema object (table/label/rel/column/property), mirroring lbug-adapter's isMissingColumnError. An unscoped "not found" matched operation failures like `rg: not found` / `Symbol not found` and silently demoted them to debug. - logQueryError docstring: state the contract honestly — level reflects telemetry severity, and mutating/safety-critical callers MUST also surface a result-level degradation signal; `warn` alone is not a substitute. - pdg dispatch: pass the normalized `effectiveLine` (not raw params.line) so the validation gate and engine share one source of truth (identity today). Tests: - _captureLogger(level?) lets tests capture below info; the benign-missing-table test now asserts the record IS emitted at debug (20), not merely absent — no longer a vacuous pass if the call were deleted. - new: a non-schema "not found" failure logs at warn (regex-narrowing guard); rename write-failure degrades to status:'partial'+failed_files; line:-1 on the callgraph path still errors (line:0 coercion is narrow); typed the it.each tuple to drop a `mode as` cast. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
This commit is contained in:
Gergo Magyar
parent
04a4fcbea7
commit
9f41f5e84b
3 changed files with 168 additions and 19 deletions
|
|
@ -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;
|
||||
},
|
||||
};
|
||||
|
|
|
|||
|
|
@ -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
|
||||
|
|
|
|||
|
|
@ -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 "<table|column|property|…> … 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();
|
||||
}
|
||||
|
|
|
|||
Loading…
Add table
Reference in a new issue