mirror of
https://github.com/danny-avila/LibreChat.git
synced 2026-10-22 01:53:33 +00:00
🔇 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:
parent
48fded564a
commit
b3c67082cd
4 changed files with 142 additions and 14 deletions
|
|
@ -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) {
|
||||
|
|
|
|||
|
|
@ -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) => {
|
||||
|
|
|
|||
|
|
@ -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', () => {
|
||||
|
|
|
|||
|
|
@ -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),
|
||||
|
|
|
|||
Loading…
Add table
Add a link
Reference in a new issue