Skip to content

Commit c2e21cf

Browse files
fix(mcp): return partial describe_source results on timeout (#3259)
## Why `clickstack_describe_source` times out often in production, and successful calls run close to the 10s cap. Our server instructions tell agents to run describe_source before querying, so when it fails they fall back to `clickstack_sql`. Two problems: - The 10s budget is a third of what the other MCP query tools get (`max_execution_time` 30, request timeout 32s via `MCP_REQUEST_TIMEOUT`). - On timeout, `Promise.race` rejected and threw away everything gathered so far, including the column schema. The existing `skippedStages` partial-result logic never ran. ## What changed - `DESCRIBE_TIMEOUT_MS` 10s → 30s. - At the deadline the handler aborts the signal. Discovery skips its remaining stages and returns columns plus whatever else finished, with `partial: true` and `skippedStages`. - A 2s backstop (32s total) covers ClickHouse calls that ignore the signal: it answers from a snapshot of what discovery has gathered so far. - The "Schema discovery timed out" error is now only returned when the column schema never loaded. - Metric sources now report `metricNames` in `skippedStages` when the abort lands before that stage (it was silently omitted). - Tool description mentions the 30s limit and the partial-result shape. - Span attribute `mcp.describe_source.outcome` (`complete` / `partial` / `timeout`) so we can track the effect. ## Testing - New unit tests in `describeSourceTimeout.test.ts` (fake timers): complete path, abort mid-map-keys, abort mid-value-sampling, backstop when a call ignores the signal, and the column-schema-never-loads error. - `yarn ci:unit` in `packages/api`: 1080 passed. - `make dev-int FILE=src/mcp/__tests__/sources.int.test.ts`: 55 passed. 🤖 Generated with [Claude Code](https://claude.com/claude-code)
1 parent 0ddfe7d commit c2e21cf

3 files changed

Lines changed: 552 additions & 62 deletions

File tree

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,10 @@
1+
---
2+
'@hyperdx/api': patch
3+
---
4+
5+
fix(mcp): return partial `clickstack_describe_source` results on timeout
6+
7+
The describe deadline is raised from 10s to 30s to match the other MCP query
8+
tools. When it is hit, the tool now returns the schema and samples gathered so
9+
far, flagged `partial` with `skippedStages`, instead of failing outright. It
10+
only returns a timeout error if the column schema never loaded.
Lines changed: 356 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,356 @@
1+
const mockMetadata = {
2+
getColumns: jest.fn(),
3+
getMapKeys: jest.fn(),
4+
getAllKeyValues: jest.fn(),
5+
};
6+
7+
jest.mock('@/models/source', () => ({}));
8+
jest.mock('@/controllers/sources', () => ({ getSource: jest.fn() }));
9+
jest.mock('@/controllers/connection', () => ({
10+
getConnectionById: jest.fn(),
11+
}));
12+
jest.mock('@/clickhouse', () => ({ ClickhouseClient: jest.fn() }));
13+
jest.mock('@hyperdx/common-utils/dist/core/metadata', () => ({
14+
getMetadata: () => mockMetadata,
15+
}));
16+
jest.mock('@/mcp/tools/sources/metricNames', () => ({
17+
sampleMetricNamesWithLookback: jest.fn(),
18+
}));
19+
jest.mock('@/utils/trimToolResponse', () => ({
20+
trimToolResponse: (data: unknown) => ({ data, isTrimmed: false }),
21+
}));
22+
23+
import { SourceKind } from '@hyperdx/common-utils/dist/types';
24+
25+
import { getConnectionById } from '@/controllers/connection';
26+
import { getSource } from '@/controllers/sources';
27+
import {
28+
DESCRIBE_BACKSTOP_MS,
29+
DESCRIBE_TIMEOUT_MS,
30+
registerDescribeSource,
31+
} from '@/mcp/tools/sources/describeSource';
32+
import { sampleMetricNamesWithLookback } from '@/mcp/tools/sources/metricNames';
33+
import type { ToolRegistrar, ToolResult } from '@/mcp/tools/types';
34+
35+
const COLUMNS = [
36+
{ name: 'Timestamp', type: 'DateTime64(9)' },
37+
{ name: 'ServiceName', type: 'LowCardinality(String)' },
38+
{ name: 'SpanAttributes', type: 'Map(LowCardinality(String), String)' },
39+
];
40+
41+
const traceSource = {
42+
_id: 'source-1',
43+
name: 'Traces',
44+
kind: SourceKind.Trace,
45+
connection: 'conn-1',
46+
timestampValueExpression: 'Timestamp',
47+
from: { databaseName: 'default', tableName: 'otel_traces' },
48+
toObject() {
49+
return { ...this };
50+
},
51+
};
52+
53+
const metricSource = {
54+
...traceSource,
55+
kind: SourceKind.Metric,
56+
timestampValueExpression: 'TimeUnix',
57+
from: { databaseName: 'default', tableName: '' },
58+
metricTables: { gauge: 'otel_metrics_gauge', sum: 'otel_metrics_sum' },
59+
};
60+
61+
const never = () => new Promise<never>(() => {});
62+
63+
const rejectOnAbort = (signal: AbortSignal) =>
64+
new Promise<never>((_, reject) => {
65+
signal.addEventListener('abort', () => reject(new Error('aborted')));
66+
});
67+
68+
function getHandler() {
69+
let handler: ((args: { sourceId: string }) => Promise<ToolResult>) | null =
70+
null;
71+
registerDescribeSource({
72+
server: {},
73+
context: { teamId: 'team-1', userId: 'user-1' },
74+
registerTool: (_name: string, _config: unknown, h: typeof handler) => {
75+
handler = h;
76+
},
77+
} as unknown as ToolRegistrar);
78+
return handler!;
79+
}
80+
81+
async function runWithClock(advanceMs: number) {
82+
const pending = getHandler()({ sourceId: 'source-1' });
83+
await jest.advanceTimersByTimeAsync(advanceMs);
84+
return pending;
85+
}
86+
87+
const parse = (result: ToolResult) => JSON.parse(result.content[0].text);
88+
89+
describe('clickstack_describe_source deadline', () => {
90+
beforeEach(() => {
91+
jest.useFakeTimers();
92+
jest
93+
.mocked(getSource)
94+
.mockResolvedValue(
95+
traceSource as unknown as Awaited<ReturnType<typeof getSource>>,
96+
);
97+
jest.mocked(getConnectionById).mockResolvedValue({
98+
host: 'http://localhost:8123',
99+
username: 'default',
100+
password: '',
101+
} as unknown as Awaited<ReturnType<typeof getConnectionById>>);
102+
mockMetadata.getColumns.mockResolvedValue(COLUMNS);
103+
mockMetadata.getMapKeys.mockResolvedValue(['http.method']);
104+
mockMetadata.getAllKeyValues.mockResolvedValue([
105+
{ key: 'ServiceName', value: ['api'] },
106+
]);
107+
});
108+
109+
afterEach(() => {
110+
jest.useRealTimers();
111+
jest.resetAllMocks();
112+
});
113+
114+
it('returns a complete result when discovery finishes before the deadline', async () => {
115+
const result = await runWithClock(0);
116+
117+
expect(result.isError).toBeFalsy();
118+
const { source } = parse(result);
119+
expect(source.columns).toHaveLength(COLUMNS.length);
120+
expect(source.mapAttributeKeys).toEqual({
121+
SpanAttributes: ['http.method'],
122+
});
123+
expect(source.partial).toBeUndefined();
124+
expect(source.skippedStages).toBeUndefined();
125+
});
126+
127+
it('returns columns with skippedStages when sampling is aborted at the deadline', async () => {
128+
mockMetadata.getMapKeys.mockImplementation(({ signal }) =>
129+
rejectOnAbort(signal),
130+
);
131+
132+
const result = await runWithClock(DESCRIBE_TIMEOUT_MS);
133+
134+
expect(result.isError).toBeFalsy();
135+
const { source, usage } = parse(result);
136+
expect(source.columns).toHaveLength(COLUMNS.length);
137+
expect(source.partial).toBe(true);
138+
expect(source.skippedStages).toEqual([
139+
'mapAttributeKeys',
140+
'mapAttributeValues',
141+
'lowCardinalityValues',
142+
]);
143+
expect(usage.lowCardinalityValues).toContain('skipped due to timeout');
144+
});
145+
146+
it('flags value sampling that returns some keys after the abort', async () => {
147+
mockMetadata.getAllKeyValues.mockImplementation(
148+
({ signal }) =>
149+
new Promise(resolve =>
150+
signal.addEventListener('abort', () =>
151+
resolve([{ key: 'ServiceName', value: ['api'] }]),
152+
),
153+
),
154+
);
155+
156+
const { source } = parse(await runWithClock(DESCRIBE_TIMEOUT_MS));
157+
158+
expect(source.lowCardinalityValues).toEqual({ ServiceName: ['api'] });
159+
expect(source.partial).toBe(true);
160+
expect(source.skippedStages).toEqual([
161+
'lowCardinalityValues',
162+
'mapAttributeValues',
163+
]);
164+
});
165+
166+
it('keeps stages that finished before the deadline', async () => {
167+
mockMetadata.getAllKeyValues.mockImplementation(({ signal }) =>
168+
rejectOnAbort(signal),
169+
);
170+
171+
const { source } = parse(await runWithClock(DESCRIBE_TIMEOUT_MS));
172+
173+
expect(source.mapAttributeKeys).toEqual({
174+
SpanAttributes: ['http.method'],
175+
});
176+
expect(source.partial).toBe(true);
177+
expect(source.skippedStages).toEqual([
178+
'lowCardinalityValues',
179+
'mapAttributeValues',
180+
]);
181+
});
182+
183+
it('answers from the snapshot at the backstop when a call ignores the signal', async () => {
184+
mockMetadata.getMapKeys.mockImplementation(never);
185+
const handler = getHandler();
186+
let settled = false;
187+
const pending = handler({ sourceId: 'source-1' }).finally(() => {
188+
settled = true;
189+
});
190+
191+
await jest.advanceTimersByTimeAsync(DESCRIBE_TIMEOUT_MS);
192+
expect(settled).toBe(false);
193+
await jest.advanceTimersByTimeAsync(DESCRIBE_BACKSTOP_MS);
194+
195+
const result = await pending;
196+
expect(result.isError).toBeFalsy();
197+
const { source } = parse(result);
198+
expect(source.columns).toHaveLength(COLUMNS.length);
199+
expect(source.partial).toBe(true);
200+
expect(source.skippedStages).toEqual([
201+
'mapAttributeKeys',
202+
'lowCardinalityValues',
203+
'mapAttributeValues',
204+
]);
205+
});
206+
207+
it('returns the timeout error only when the column schema never loads', async () => {
208+
mockMetadata.getColumns.mockImplementation(never);
209+
210+
const result = await runWithClock(
211+
DESCRIBE_TIMEOUT_MS + DESCRIBE_BACKSTOP_MS,
212+
);
213+
214+
expect(result.isError).toBe(true);
215+
expect(result.content[0].text).toContain('Schema discovery timed out');
216+
});
217+
218+
it('rethrows errors raised before the deadline', async () => {
219+
mockMetadata.getColumns.mockRejectedValue(new Error('connection refused'));
220+
221+
await expect(getHandler()({ sourceId: 'source-1' })).rejects.toThrow(
222+
'connection refused',
223+
);
224+
});
225+
226+
it('reports map keys as skipped when only some Map columns finish', async () => {
227+
mockMetadata.getColumns.mockResolvedValue([
228+
...COLUMNS,
229+
{
230+
name: 'ResourceAttributes',
231+
type: 'Map(LowCardinality(String), String)',
232+
},
233+
]);
234+
mockMetadata.getMapKeys.mockImplementation(({ column, signal }) =>
235+
column === 'SpanAttributes'
236+
? Promise.resolve(['http.method'])
237+
: rejectOnAbort(signal),
238+
);
239+
240+
const { source } = parse(await runWithClock(DESCRIBE_TIMEOUT_MS));
241+
242+
expect(source.mapAttributeKeys).toEqual({
243+
SpanAttributes: ['http.method'],
244+
});
245+
expect(source.partial).toBe(true);
246+
expect(source.skippedStages).toContain('mapAttributeKeys');
247+
});
248+
249+
it('keeps finished map keys in the backstop snapshot', async () => {
250+
mockMetadata.getColumns.mockResolvedValue([
251+
...COLUMNS,
252+
{
253+
name: 'ResourceAttributes',
254+
type: 'Map(LowCardinality(String), String)',
255+
},
256+
]);
257+
mockMetadata.getMapKeys.mockImplementation(({ column }) =>
258+
column === 'SpanAttributes' ? Promise.resolve(['http.method']) : never(),
259+
);
260+
261+
const { source } = parse(
262+
await runWithClock(DESCRIBE_TIMEOUT_MS + DESCRIBE_BACKSTOP_MS),
263+
);
264+
265+
expect(source.mapAttributeKeys).toEqual({
266+
SpanAttributes: ['http.method'],
267+
});
268+
expect(source.skippedStages).toContain('mapAttributeKeys');
269+
});
270+
271+
it('does not report stages with nothing to sample in the backstop snapshot', async () => {
272+
mockMetadata.getColumns.mockResolvedValue([
273+
{ name: 'Timestamp', type: 'DateTime64(9)' },
274+
{ name: 'ServiceName', type: 'LowCardinality(String)' },
275+
]);
276+
mockMetadata.getAllKeyValues.mockImplementation(never);
277+
278+
const { source } = parse(
279+
await runWithClock(DESCRIBE_TIMEOUT_MS + DESCRIBE_BACKSTOP_MS),
280+
);
281+
282+
expect(source.skippedStages).toEqual(['lowCardinalityValues']);
283+
});
284+
285+
describe('metric sources', () => {
286+
beforeEach(() => {
287+
jest
288+
.mocked(getSource)
289+
.mockResolvedValue(
290+
metricSource as unknown as Awaited<ReturnType<typeof getSource>>,
291+
);
292+
mockMetadata.getColumns.mockResolvedValue([
293+
{ name: 'TimeUnix', type: 'DateTime64(9)' },
294+
{ name: 'MetricName', type: 'LowCardinality(String)' },
295+
]);
296+
});
297+
298+
it('returns metric names when sampling finishes', async () => {
299+
jest
300+
.mocked(sampleMetricNamesWithLookback)
301+
.mockResolvedValue([{ name: 'cpu.usage' }]);
302+
303+
const { source } = parse(await runWithClock(0));
304+
305+
expect(source.metricNames).toEqual({
306+
gauge: [{ name: 'cpu.usage' }],
307+
sum: [{ name: 'cpu.usage' }],
308+
});
309+
expect(source.partial).toBeUndefined();
310+
});
311+
312+
it('reports metricNames as skipped when one kind is cut short', async () => {
313+
jest
314+
.mocked(sampleMetricNamesWithLookback)
315+
.mockImplementation(({ tableName, signal }) =>
316+
tableName === 'otel_metrics_gauge'
317+
? Promise.resolve([{ name: 'cpu.usage' }])
318+
: rejectOnAbort(signal),
319+
);
320+
321+
const { source } = parse(await runWithClock(DESCRIBE_TIMEOUT_MS));
322+
323+
expect(source.metricNames).toEqual({ gauge: [{ name: 'cpu.usage' }] });
324+
expect(source.partial).toBe(true);
325+
expect(source.skippedStages).toEqual(['metricNames']);
326+
});
327+
328+
it('reports metricNames as skipped when an aborted lookback returns no names', async () => {
329+
jest
330+
.mocked(sampleMetricNamesWithLookback)
331+
.mockImplementation(
332+
({ signal }) =>
333+
new Promise(resolve =>
334+
signal.addEventListener('abort', () => resolve([])),
335+
),
336+
);
337+
338+
const { source } = parse(await runWithClock(DESCRIBE_TIMEOUT_MS));
339+
340+
expect(source.metricNames).toBeUndefined();
341+
expect(source.partial).toBe(true);
342+
expect(source.skippedStages).toEqual(['metricNames']);
343+
});
344+
345+
it('lists metricNames in the backstop snapshot when sampling hangs', async () => {
346+
jest.mocked(sampleMetricNamesWithLookback).mockImplementation(never);
347+
348+
const { source } = parse(
349+
await runWithClock(DESCRIBE_TIMEOUT_MS + DESCRIBE_BACKSTOP_MS),
350+
);
351+
352+
expect(source.partial).toBe(true);
353+
expect(source.skippedStages).toEqual(['metricNames']);
354+
});
355+
});
356+
});

0 commit comments

Comments
 (0)