🔇 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;
} catch (error) {
logger.error(
`[MCP][${serverName}][${toolName}][User: ${userId}] Error calling MCP tool:`,
error,
);
/** A user Stop aborts every in-flight call at once. The rejection that
* follows is the cancellation working, so it must not reach error-level
* 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 */
if (error instanceof OpenIDReauthRequiredError) {

View file

@ -1610,6 +1610,76 @@ describe('User parameter passing tests', () => {
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'])(
'preserves runtime-detected OAuth for the internal signal: %s',
async (oauthSignal) => {

View file

@ -384,6 +384,48 @@ describe('createToolExecuteHandler', () => {
),
).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', () => {

View file

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