🔇 fix: Keep Cancelled Tool Calls on the Filtered Path and Out of Error Logs

Addresses both findings from the Codex review of 48fded564a.

P1 — the cancellation branch returned before `filteredToolOutputResult`,
so with tool-output filtering configured an aborted call's error text
reached the turn uninspected. Worse, `runSignal.aborted` says the run is
over, not that this rejection was the cancellation: an unrelated failure
racing the Stop took the same unfiltered exit. Cancellation now only
selects the log level; filtering and the result shape are unchanged.

P2 — `createMCPTool` logs its own error before wrapping and rethrowing,
so every Stop during an MCP call still emitted an error-level MCP entry
and could pollute operational alerts. That catch now recognizes the abort
and logs at debug; the wrapped message still reaches the turn.

Both are covered by tests that fail against the previous commit.
This commit is contained in:
Danny Avila 2026-09-02 12:07:47 -04:00
parent 48fded564a
commit b3c67082cd
4 changed files with 142 additions and 14 deletions

View file

@ -1308,10 +1308,19 @@ function createToolInstance({
} }
return result; return result;
} catch (error) { } catch (error) {
logger.error( /** A user Stop aborts every in-flight call at once. The rejection that
`[MCP][${serverName}][${toolName}][User: ${userId}] Error calling MCP tool:`, * follows is the cancellation working, so it must not reach error-level
error, * operational alerts; the wrapping below still reports it to the turn. */
); if (config?.signal?.aborted === true) {
logger.debug(
`[MCP][${serverName}][${toolName}][User: ${userId}] Tool call cancelled by user abort`,
);
} else {
logger.error(
`[MCP][${serverName}][${toolName}][User: ${userId}] Error calling MCP tool:`,
error,
);
}
/** Carries the actionable re-auth message; the substring heuristic below would misreport it as an OAuth configuration problem */ /** Carries the actionable re-auth message; the substring heuristic below would misreport it as an OAuth configuration problem */
if (error instanceof OpenIDReauthRequiredError) { if (error instanceof OpenIDReauthRequiredError) {

View file

@ -1610,6 +1610,76 @@ describe('User parameter passing tests', () => {
expect(callTool).toHaveBeenCalledTimes(2); expect(callTool).toHaveBeenCalledTimes(2);
}); });
it('logs a user-aborted tool call as debug, not as an MCP error', async () => {
const mockUser = { id: 'cancel-user', role: 'USER' };
const mockRes = { write: jest.fn(), flush: jest.fn() };
const abortController = new AbortController();
const { getRoleByName } = require('~/models');
getRoleByName.mockResolvedValue({
permissions: {
[PermissionTypes.MCP_SERVERS]: {
[Permissions.USE]: true,
},
},
});
mockGetMCPManager.mockReturnValue({
callTool: jest.fn(
({ options }) =>
new Promise((_resolve, reject) => {
const signal = options?.signal;
signal?.addEventListener(
'abort',
() => reject(new Error('This operation was aborted')),
{
once: true,
},
);
}),
),
});
const mcpTool = await createMCPTool({
res: mockRes,
user: mockUser,
config: { url: 'https://cancel.example.com/mcp' },
toolKey: `test-tool${D}test-server`,
provider: 'openai',
userMCPAuthMap: {},
availableTools: {
[`test-tool${D}test-server`]: {
function: {
description: 'Cached tool',
parameters: { type: 'object', properties: {} },
},
},
},
});
const call = mcpTool.invoke(
{},
{
signal: abortController.signal,
configurable: { user: mockUser },
metadata: { provider: 'openai', thread_id: 'thread-1', run_id: 'run-1' },
toolCall: {},
},
);
await new Promise((resolve) => setImmediate(resolve));
abortController.abort();
await expect(call).rejects.toThrow();
/** The wrapper rejects on abort while `_call` is still unwinding; let its
* catch run before asserting on what it logged. */
await new Promise((resolve) => setImmediate(resolve));
expect(logger.error).not.toHaveBeenCalledWith(
expect.stringContaining('Error calling MCP tool'),
expect.anything(),
);
expect(logger.debug).toHaveBeenCalledWith(
expect.stringContaining('Tool call cancelled by user abort'),
);
});
it.each(['OAuth flow initiated - return early', 'Pending OAuth flow reused - return early'])( it.each(['OAuth flow initiated - return early', 'Pending OAuth flow reused - return early'])(
'preserves runtime-detected OAuth for the internal signal: %s', 'preserves runtime-detected OAuth for the internal signal: %s',
async (oauthSignal) => { async (oauthSignal) => {

View file

@ -384,6 +384,48 @@ describe('createToolExecuteHandler', () => {
), ),
).toHaveLength(0); ).toHaveLength(0);
}); });
/**
* An aborted run means the turn is over, not that this particular rejection
* was the cancellation — an unrelated failure can always race the Stop. The
* quiet-log branch must therefore never become a way around output filtering.
*/
it('still filters a tool failure that rejects after the run was aborted', async () => {
const protectedValue = 'PROTECTED-CANCELLED-TOOL-OUTPUT';
const controller = new AbortController();
const tool = {
name: 'slow_tool',
invoke: jest.fn(
(_args: unknown, config: Record<string, unknown>) =>
new Promise((_resolve, reject) => {
const signal = config.signal as AbortSignal;
signal.addEventListener('abort', () => reject(new Error(protectedValue)), {
once: true,
});
}),
),
};
const loadTools: ToolExecuteOptions['loadTools'] = jest.fn(async () => ({
loadedTools: [tool] as never[],
}));
const handler = createToolExecuteHandler({ loadTools });
const [result] = await new Promise<ToolExecuteResult[]>((resolve, reject) => {
const request: ToolExecuteBatchRequest = {
toolCalls: [{ id: 'call-1', name: 'slow_tool', args: {} }] as ToolCallRequest[],
configurable: { req: protectedToolOutputRequest() },
signal: controller.signal,
resolve,
reject,
};
handler.handle('on_tool_execute', request);
setTimeout(() => controller.abort(new Error('Operation aborted by user')), 10);
});
expect(result.status).toBe('error');
expect(result.errorMessage).toContain('content_filter_block');
expect(result.errorMessage).not.toContain(protectedValue);
});
}); });
describe('tool argument normalization', () => { describe('tool argument normalization', () => {

View file

@ -5997,26 +5997,33 @@ export function createToolExecuteHandler(options: ToolExecuteOptions): EventHand
} }
const { message, logContext } = getSafeToolError(toolError); const { message, logContext } = getSafeToolError(toolError);
/** A user Stop rejects every in-flight call at once. That is /** A user Stop rejects every in-flight call at once. That is
* the abort working, not a fault, so it stays out of the * the abort working, not a fault, so it is logged at debug.
* error log; the message still reaches the model turn. */ * It only ever changes the log level: an aborted run says
if (runSignal?.aborted === true) { * the turn is over, not that this particular rejection was
logger.debug(`[ON_TOOL_EXECUTE] Tool ${tc.name} cancelled by run abort`, { * the cancellation, so an unrelated failure racing the Stop
name: logContext.name, * must still take the same filtering and result path. */
}); const logToolFailure = (context: Record<string, unknown>): void => {
return errorResult(tc, message); if (runSignal?.aborted === true) {
} logger.debug(
`[ON_TOOL_EXECUTE] Tool ${tc.name} cancelled by run abort`,
context,
);
return;
}
logger.error(`[ON_TOOL_EXECUTE] Tool ${tc.name} error`, context);
};
const req = mergedConfigurable?.req as ServerRequest | undefined; const req = mergedConfigurable?.req as ServerRequest | undefined;
const filteredError = filteredToolOutputResult(tc, req, { const filteredError = filteredToolOutputResult(tc, req, {
errorMessage: message, errorMessage: message,
}); });
if (filteredError != null) { if (filteredError != null) {
logger.error(`[ON_TOOL_EXECUTE] Tool ${tc.name} error`, { logToolFailure({
name: logContext.name, name: logContext.name,
contentFiltered: true, contentFiltered: true,
}); });
return filteredError; return filteredError;
} }
logger.error(`[ON_TOOL_EXECUTE] Tool ${tc.name} error`, { logToolFailure({
...logContext, ...logContext,
toolCallArgsShape: getValueShape(tc.args), toolCallArgsShape: getValueShape(tc.args),
toolInputSchemaKind: getToolInputSchemaKind(tool), toolInputSchemaKind: getToolInputSchemaKind(tool),