diff --git a/.changeset/alert-evaluation-error-persistence.md b/.changeset/alert-evaluation-error-persistence.md new file mode 100644 index 0000000000..860110ffef --- /dev/null +++ b/.changeset/alert-evaluation-error-persistence.md @@ -0,0 +1,13 @@ +--- +'@hyperdx/common-utils': minor +'@hyperdx/api': minor +--- + +Persist alert evaluation errors (query errors, timeouts, webhook failures) as +ERROR-state AlertHistory records instead of only a latest-only snapshot, +upserted per evaluation window so retries collapse into a single row. Query +timeouts are classified separately (QUERY_TIMEOUT, including timeouts wrapped +by the ClickHouse query client) with an actionable message. ERROR rows are +excluded from scheduling/backfill computations so failed windows are still +retried and backfilled, and evaluation analytics (query/webhook durations, +backfilled buckets) are recorded on every history row. diff --git a/packages/api/openapi.json b/packages/api/openapi.json index c2fbbb9aee..ead070641f 100644 --- a/packages/api/openapi.json +++ b/packages/api/openapi.json @@ -118,6 +118,7 @@ "type": "string", "enum": [ "QUERY_ERROR", + "QUERY_TIMEOUT", "WEBHOOK_ERROR", "INVALID_ALERT", "UNKNOWN" diff --git a/packages/api/src/routers/external-api/v2/alerts.ts b/packages/api/src/routers/external-api/v2/alerts.ts index e53aedf4bc..4f0e53d24e 100644 --- a/packages/api/src/routers/external-api/v2/alerts.ts +++ b/packages/api/src/routers/external-api/v2/alerts.ts @@ -56,7 +56,7 @@ import { alertSchema, objectIdSchema } from '@/utils/zod'; * description: Channel type. * AlertErrorType: * type: string - * enum: [QUERY_ERROR, WEBHOOK_ERROR, INVALID_ALERT, UNKNOWN] + * enum: [QUERY_ERROR, QUERY_TIMEOUT, WEBHOOK_ERROR, INVALID_ALERT, UNKNOWN] * description: Category of error recorded during alert execution. * AlertExecutionError: * type: object diff --git a/packages/api/src/tasks/checkAlerts/__tests__/checkAlerts.int.test.ts b/packages/api/src/tasks/checkAlerts/__tests__/checkAlerts.int.test.ts index 6700ef161e..86e4e76696 100644 --- a/packages/api/src/tasks/checkAlerts/__tests__/checkAlerts.int.test.ts +++ b/packages/api/src/tasks/checkAlerts/__tests__/checkAlerts.int.test.ts @@ -2849,12 +2849,26 @@ describe('checkAlerts', () => { teamWebhooksById, ); - // Alert should remain in its default OK state and no history/webhooks should be emitted + // Alert should remain in its default OK state and no normal + // history/webhooks should be emitted. The failure is recorded as an + // ERROR-state history row for the window. const updated = await Alert.findById(details.alert.id); expect(updated!.state).toBe('OK'); expect( - await AlertHistory.countDocuments({ alert: details.alert.id }), + await AlertHistory.countDocuments({ + alert: details.alert.id, + state: { $ne: AlertState.ERROR }, + }), ).toBe(0); + const errorHistories = await AlertHistory.find({ + alert: details.alert.id, + state: AlertState.ERROR, + }); + expect(errorHistories).toHaveLength(1); + expect(errorHistories[0].errors).toHaveLength(1); + expect(errorHistories[0].errors![0].type).toBe( + AlertErrorType.INVALID_ALERT, + ); expect(slack.postMessageToWebhook).not.toHaveBeenCalled(); // The invalid alert configuration should be recorded on the Alert @@ -2966,13 +2980,16 @@ describe('checkAlerts', () => { const updated = await Alert.findById(details.alert.id); // State must be untouched — still ALERT expect(updated!.state).toBe(AlertState.ALERT); - // No AlertHistory created + // No normal AlertHistory created expect( - await AlertHistory.countDocuments({ alert: details.alert.id }), + await AlertHistory.countDocuments({ + alert: details.alert.id, + state: { $ne: AlertState.ERROR }, + }), ).toBe(0); // No webhook fired expect(slack.postMessageToWebhook).not.toHaveBeenCalled(); - // Error recorded + // Error recorded on the alert (latest-only snapshot) expect(updated!.executionErrors).toBeDefined(); expect(updated!.executionErrors!.length).toBe(1); expect(updated!.executionErrors![0].type).toBe( @@ -2981,6 +2998,25 @@ describe('checkAlerts', () => { expect(updated!.executionErrors![0].message).toContain( 'clickhouse kaput', ); + // ...and persisted as an ERROR history row for the evaluation window + // (5m interval at 22:12 → window start 22:10) + const errorHistories = await AlertHistory.find({ + alert: details.alert.id, + state: AlertState.ERROR, + }); + expect(errorHistories).toHaveLength(1); + expect(errorHistories[0].createdAt.toISOString()).toBe( + '2023-11-16T22:10:00.000Z', + ); + expect(errorHistories[0].counts).toBe(0); + expect(errorHistories[0].lastValues).toHaveLength(0); + expect(errorHistories[0].errors).toHaveLength(1); + expect(errorHistories[0].errors![0].type).toBe( + AlertErrorType.QUERY_ERROR, + ); + expect(errorHistories[0].errors![0].message).toContain( + 'clickhouse kaput', + ); }); it('leaves OK state untouched when the ClickHouse query fails', async () => { @@ -3031,13 +3067,449 @@ describe('checkAlerts', () => { // Default state is OK — must stay OK (not flipped to ALERT or anything else) expect(updated!.state).toBe(AlertState.OK); expect( - await AlertHistory.countDocuments({ alert: details.alert.id }), + await AlertHistory.countDocuments({ + alert: details.alert.id, + state: { $ne: AlertState.ERROR }, + }), ).toBe(0); expect(updated!.executionErrors![0].type).toBe( AlertErrorType.QUERY_ERROR, ); }); + it('records a QUERY_TIMEOUT with an actionable message when the query times out', async () => { + const { + team, + webhook, + connection, + source, + savedSearch, + teamWebhooksById, + clickhouseClient, + } = await setupSavedSearchAlertTest(); + + const details = await createAlertDetails( + team, + source, + { + source: AlertSource.SAVED_SEARCH, + channel: { + type: 'webhook', + webhookId: webhook._id.toString(), + }, + interval: '5m', + thresholdType: AlertThresholdType.ABOVE, + threshold: 1, + savedSearchId: savedSearch.id, + }, + { + taskType: AlertTaskType.SAVED_SEARCH, + savedSearch, + }, + ); + + // The exact message the ClickHouse client rejects with when + // request_timeout elapses. + jest + .spyOn(clickhouseClient, 'queryChartConfig') + .mockRejectedValueOnce(new Error('Timeout error.')); + + await processAlertAtTime( + new Date('2023-11-16T22:12:00.000Z'), + details, + clickhouseClient, + connection.id, + alertProvider, + teamWebhooksById, + ); + + const updated = await Alert.findById(details.alert.id); + expect(updated!.executionErrors).toHaveLength(1); + expect(updated!.executionErrors![0].type).toBe( + AlertErrorType.QUERY_TIMEOUT, + ); + expect(updated!.executionErrors![0].message).toMatch( + /did not complete within the \d+s evaluation timeout/, + ); + expect(updated!.executionErrors![0].message).toContain( + 'the alert will not fire until the query completes in time', + ); + + const errorHistories = await AlertHistory.find({ + alert: details.alert.id, + state: AlertState.ERROR, + }); + expect(errorHistories).toHaveLength(1); + expect(errorHistories[0].errors![0].type).toBe( + AlertErrorType.QUERY_TIMEOUT, + ); + // The ERROR row records the query's time-to-failure + expect(errorHistories[0].analytics?.queryDurationMs).toEqual( + expect.any(Number), + ); + }); + + it('dedupes error history rows per evaluation window and separates windows', async () => { + const { + team, + webhook, + connection, + source, + savedSearch, + teamWebhooksById, + clickhouseClient, + } = await setupSavedSearchAlertTest(); + + const details = await createAlertDetails( + team, + source, + { + source: AlertSource.SAVED_SEARCH, + channel: { + type: 'webhook', + webhookId: webhook._id.toString(), + }, + interval: '5m', + thresholdType: AlertThresholdType.ABOVE, + threshold: 1, + savedSearchId: savedSearch.id, + }, + { + taskType: AlertTaskType.SAVED_SEARCH, + savedSearch, + }, + ); + + const querySpy = jest + .spyOn(clickhouseClient, 'queryChartConfig') + .mockRejectedValueOnce(new Error('boom 1')) + .mockRejectedValueOnce(new Error('boom 2')) + .mockRejectedValueOnce(new Error('boom 3')); + + // Two failing ticks within the same 5m window (22:10) — the retry + // must not be skipped (the ERROR row is excluded from the due-ness + // gate) and must not accumulate a second row (upsert per window). + await processAlertAtTime( + new Date('2023-11-16T22:12:00.000Z'), + details, + clickhouseClient, + connection.id, + alertProvider, + teamWebhooksById, + ); + await processAlertAtTime( + new Date('2023-11-16T22:13:00.000Z'), + details, + clickhouseClient, + connection.id, + alertProvider, + teamWebhooksById, + ); + + expect(querySpy).toHaveBeenCalledTimes(2); + let errorHistories = await AlertHistory.find({ + alert: details.alert.id, + state: AlertState.ERROR, + }); + expect(errorHistories).toHaveLength(1); + expect(errorHistories[0].createdAt.toISOString()).toBe( + '2023-11-16T22:10:00.000Z', + ); + // The row carries the latest attempt's error + expect(errorHistories[0].errors).toHaveLength(1); + expect(errorHistories[0].errors![0].message).toContain('boom 2'); + + // A failing tick in the NEXT window gets its own row + await processAlertAtTime( + new Date('2023-11-16T22:16:00.000Z'), + details, + clickhouseClient, + connection.id, + alertProvider, + teamWebhooksById, + ); + errorHistories = await AlertHistory.find({ + alert: details.alert.id, + state: AlertState.ERROR, + }).sort({ createdAt: 1 }); + expect(errorHistories).toHaveLength(2); + expect(errorHistories[1].createdAt.toISOString()).toBe( + '2023-11-16T22:15:00.000Z', + ); + + // No normal history was ever written + expect( + await AlertHistory.countDocuments({ + alert: details.alert.id, + state: { $ne: AlertState.ERROR }, + }), + ).toBe(0); + }); + + it('still evaluates and fires for a window whose earlier attempt failed', async () => { + const { + team, + webhook, + connection, + source, + savedSearch, + teamWebhooksById, + clickhouseClient, + } = await setupSavedSearchAlertTest(); + + // Data inside the window evaluated at 22:10 (range [22:05, 22:10)) + await bulkInsertLogs([ + { + ServiceName: 'api', + Timestamp: new Date('2023-11-16T22:05:00.000Z'), + SeverityText: 'error', + Body: 'oh no', + }, + { + ServiceName: 'api', + Timestamp: new Date('2023-11-16T22:05:00.000Z'), + SeverityText: 'error', + Body: 'oh no', + }, + ]); + + const details = await createAlertDetails( + team, + source, + { + source: AlertSource.SAVED_SEARCH, + channel: { + type: 'webhook', + webhookId: webhook._id.toString(), + }, + interval: '5m', + thresholdType: AlertThresholdType.ABOVE, + threshold: 1, + savedSearchId: savedSearch.id, + }, + { + taskType: AlertTaskType.SAVED_SEARCH, + savedSearch, + }, + ); + + // First tick fails — records an ERROR row, no state/history change + jest + .spyOn(clickhouseClient, 'queryChartConfig') + .mockRejectedValueOnce(new Error('transient failure')); + + await processAlertAtTime( + new Date('2023-11-16T22:12:00.000Z'), + details, + clickhouseClient, + connection.id, + alertProvider, + teamWebhooksById, + ); + expect((await Alert.findById(details.alert.id))!.state).toBe( + AlertState.OK, + ); + + // Next tick (same window): the real query runs and the alert fires. + // If the ERROR row counted as "window evaluated", this tick would be + // skipped and the alert would never fire. + await processAlertAtTime( + new Date('2023-11-16T22:13:00.000Z'), + details, + clickhouseClient, + connection.id, + alertProvider, + teamWebhooksById, + ); + + const updated = await Alert.findById(details.alert.id); + expect(updated!.state).toBe(AlertState.ALERT); + // Errors on the alert are cleared by the successful execution + expect(updated!.executionErrors ?? []).toHaveLength(0); + + // The normal history was written for the retried window, and the + // failed attempt's ERROR row was removed — otherwise the window + // would render as ERROR forever (the evaluations view ranks ERROR + // above OK/ALERT) even though the retry succeeded. + const normalHistories = await AlertHistory.find({ + alert: details.alert.id, + state: { $ne: AlertState.ERROR }, + }); + expect(normalHistories).toHaveLength(1); + expect(normalHistories[0].state).toBe(AlertState.ALERT); + expect(normalHistories[0].createdAt.toISOString()).toBe( + '2023-11-16T22:10:00.000Z', + ); + expect( + await AlertHistory.countDocuments({ + alert: details.alert.id, + state: AlertState.ERROR, + }), + ).toBe(0); + // Evaluation analytics: single-window evaluation → no backfill; + // query duration recorded; notification sent → delivery time recorded + expect(normalHistories[0].analytics).toBeDefined(); + expect(normalHistories[0].analytics!.backfilledBuckets).toBe(0); + expect(normalHistories[0].analytics!.queryDurationMs).toEqual( + expect.any(Number), + ); + expect(normalHistories[0].analytics!.webhookDurationMs).toEqual( + expect.any(Number), + ); + }); + + it('keeps ERROR rows from older windows when a later window succeeds', async () => { + const { + team, + webhook, + connection, + source, + savedSearch, + teamWebhooksById, + clickhouseClient, + } = await setupSavedSearchAlertTest(); + + // Non-breaching data in the 22:15 window (range [22:10, 22:15)) + await bulkInsertLogs([ + { + ServiceName: 'api', + Timestamp: new Date('2023-11-16T22:11:00.000Z'), + SeverityText: 'error', + Body: 'oh no', + }, + ]); + + const details = await createAlertDetails( + team, + source, + { + source: AlertSource.SAVED_SEARCH, + channel: { + type: 'webhook', + webhookId: webhook._id.toString(), + }, + interval: '5m', + thresholdType: AlertThresholdType.ABOVE, + threshold: 1, + savedSearchId: savedSearch.id, + }, + { + taskType: AlertTaskType.SAVED_SEARCH, + savedSearch, + }, + ); + + // Tick in the 22:10 window fails — ERROR row at 22:10 + jest + .spyOn(clickhouseClient, 'queryChartConfig') + .mockRejectedValueOnce(new Error('transient failure')); + await processAlertAtTime( + new Date('2023-11-16T22:12:00.000Z'), + details, + clickhouseClient, + connection.id, + alertProvider, + teamWebhooksById, + ); + + // The next window (22:15) evaluates cleanly. Only a same-window + // success clears an ERROR row — the 22:10 row is a truthful record + // of a tick that failed, so it must survive. + await processAlertAtTime( + new Date('2023-11-16T22:17:00.000Z'), + details, + clickhouseClient, + connection.id, + alertProvider, + teamWebhooksById, + ); + + const normalHistories = await AlertHistory.find({ + alert: details.alert.id, + state: { $ne: AlertState.ERROR }, + }); + expect(normalHistories).toHaveLength(1); + expect(normalHistories[0].createdAt.toISOString()).toBe( + '2023-11-16T22:15:00.000Z', + ); + + const errorHistories = await AlertHistory.find({ + alert: details.alert.id, + state: AlertState.ERROR, + }); + expect(errorHistories).toHaveLength(1); + expect(errorHistories[0].createdAt.toISOString()).toBe( + '2023-11-16T22:10:00.000Z', + ); + }); + + it('records backfilled buckets when an evaluation catches up missed windows', async () => { + const { + team, + webhook, + connection, + source, + savedSearch, + teamWebhooksById, + clickhouseClient, + } = await setupSavedSearchAlertTest(); + + const details = await createAlertDetails( + team, + source, + { + source: AlertSource.SAVED_SEARCH, + channel: { + type: 'webhook', + webhookId: webhook._id.toString(), + }, + interval: '5m', + thresholdType: AlertThresholdType.ABOVE, + threshold: 1, + savedSearchId: savedSearch.id, + }, + { + taskType: AlertTaskType.SAVED_SEARCH, + savedSearch, + }, + ); + + // First evaluation: steady state, covers a single bucket + await processAlertAtTime( + new Date('2023-11-16T22:12:00.000Z'), + details, + clickhouseClient, + connection.id, + alertProvider, + teamWebhooksById, + ); + const first = await AlertHistory.findOne({ + alert: details.alert.id, + createdAt: new Date('2023-11-16T22:10:00.000Z'), + }); + expect(first!.analytics!.backfilledBuckets).toBe(0); + + // Next evaluation runs 15 minutes late (missed the 22:15 and 22:20 + // ticks): the 22:25 window backfills the two missed buckets. + await processAlertAtTime( + new Date('2023-11-16T22:27:00.000Z'), + details, + clickhouseClient, + connection.id, + alertProvider, + teamWebhooksById, + ); + const second = await AlertHistory.findOne({ + alert: details.alert.id, + createdAt: new Date('2023-11-16T22:25:00.000Z'), + }); + expect(second).toBeDefined(); + expect(second!.analytics!.backfilledBuckets).toBe(2); + expect(second!.analytics!.queryDurationMs).toEqual(expect.any(Number)); + // No notification fired in this evaluation → no delivery time + expect(second!.analytics!.webhookDurationMs).toBeUndefined(); + }); + it.each([ { responseDescription: 'an error response', @@ -3141,10 +3613,31 @@ describe('checkAlerts', () => { const updated = await Alert.findById(details.alert.id); expect(updated!.state).toBe(AlertState.ALERT); - // Query succeeded, so AlertHistory should have been written + // Query succeeded, so normal AlertHistory should have been written expect( - await AlertHistory.countDocuments({ alert: details.alert.id }), + await AlertHistory.countDocuments({ + alert: details.alert.id, + state: { $ne: AlertState.ERROR }, + }), ).toBe(1); + // The webhook failure is also persisted as an ERROR history row + const errorHistories = await AlertHistory.find({ + alert: details.alert.id, + state: AlertState.ERROR, + }); + expect(errorHistories).toHaveLength(1); + expect(errorHistories[0].errors).toHaveLength(1); + expect(errorHistories[0].errors![0].type).toBe( + AlertErrorType.WEBHOOK_ERROR, + ); + expect(errorHistories[0].errors![0].message).toBe( + expectedErrorMessage, + ); + // ...carrying the evaluation's analytics, including the time spent + // attempting the webhook delivery + expect(errorHistories[0].analytics?.webhookDurationMs).toEqual( + expect.any(Number), + ); expect(updated!.executionErrors).toBeDefined(); expect(updated!.executionErrors!.length).toBe(1); expect(updated!.executionErrors![0].type).toBe( @@ -3525,10 +4018,25 @@ describe('checkAlerts', () => { expect(updated!.state).toBe(AlertState.ALERT); const histories = await AlertHistory.find({ alert: details.alert.id, + state: { $ne: AlertState.ERROR }, }); expect(histories.length).toBe(2); expect(histories.every(h => h.state === AlertState.ALERT)).toBe(true); + // Both groups' webhook failures land on a single ERROR history row + // for the evaluation window. + const errorHistories = await AlertHistory.find({ + alert: details.alert.id, + state: AlertState.ERROR, + }); + expect(errorHistories).toHaveLength(1); + expect(errorHistories[0].errors).toHaveLength(2); + expect( + errorHistories[0].errors!.every( + e => e.type === AlertErrorType.WEBHOOK_ERROR, + ), + ).toBe(true); + // Each group attempted to send a webhook and each one failed. withRetry // retries up to 3 times per group (2 groups × 3 attempts = 6 total calls). expect(fetchMock).toHaveBeenCalledTimes(6); @@ -3614,9 +4122,19 @@ describe('checkAlerts', () => { const updated = await Alert.findById(details.alert.id); // Query succeeded, state should flip to ALERT, history written + // (plus an ERROR row recording the webhook failure) expect(updated!.state).toBe(AlertState.ALERT); expect( - await AlertHistory.countDocuments({ alert: details.alert.id }), + await AlertHistory.countDocuments({ + alert: details.alert.id, + state: { $ne: AlertState.ERROR }, + }), + ).toBe(1); + expect( + await AlertHistory.countDocuments({ + alert: details.alert.id, + state: AlertState.ERROR, + }), ).toBe(1); // A WEBHOOK_ERROR should be recorded. The message is hardcoded for diff --git a/packages/api/src/tasks/checkAlerts/__tests__/errors.test.ts b/packages/api/src/tasks/checkAlerts/__tests__/errors.test.ts new file mode 100644 index 0000000000..8ba891fd4c --- /dev/null +++ b/packages/api/src/tasks/checkAlerts/__tests__/errors.test.ts @@ -0,0 +1,134 @@ +import { ClickHouseError } from '@clickhouse/client-common'; + +import { + isClientTimeoutOrAbortError, + isQueryTimeoutError, +} from '@/tasks/checkAlerts/errors'; + +describe('checkAlerts errors', () => { + describe('isQueryTimeoutError', () => { + it('detects the ClickHouse client request timeout', () => { + expect(isQueryTimeoutError(new Error('Timeout error.'))).toBe(true); + }); + + it('detects aborted requests', () => { + expect( + isQueryTimeoutError(new Error('The user aborted a request.')), + ).toBe(true); + }); + + it('detects server-side TIMEOUT_EXCEEDED by type', () => { + expect( + isQueryTimeoutError( + new ClickHouseError({ + code: '159', + type: 'TIMEOUT_EXCEEDED', + message: 'Timeout exceeded: elapsed 301.1 seconds', + }), + ), + ).toBe(true); + }); + + it('detects server-side timeouts by code when the type is not populated', () => { + expect( + isQueryTimeoutError( + new ClickHouseError({ + code: '159', + type: '', + message: 'Timeout exceeded', + }), + ), + ).toBe(true); + }); + + it('detects TCP-level socket timeouts', () => { + const err: NodeJS.ErrnoException = new Error('connect ETIMEDOUT'); + err.code = 'ETIMEDOUT'; + expect(isQueryTimeoutError(err)).toBe(true); + }); + + // BaseClickhouseClient.query wraps failures in a ClickHouseQueryError + // that copies the message but keeps the original error only on `cause`. + it('detects server-side TIMEOUT_EXCEEDED wrapped by the query client', () => { + const wrapper = new Error('Timeout exceeded: elapsed 301.1 seconds'); + wrapper.cause = new ClickHouseError({ + code: '159', + type: 'TIMEOUT_EXCEEDED', + message: 'Timeout exceeded: elapsed 301.1 seconds', + }); + expect(isQueryTimeoutError(wrapper)).toBe(true); + }); + + it('detects socket timeouts wrapped by the query client', () => { + const inner: NodeJS.ErrnoException = new Error('connect ETIMEDOUT'); + inner.code = 'ETIMEDOUT'; + const wrapper = new Error('connect ETIMEDOUT'); + wrapper.cause = inner; + expect(isQueryTimeoutError(wrapper)).toBe(true); + }); + + it('detects timeouts nested multiple causes deep', () => { + const inner = new ClickHouseError({ + code: '159', + type: 'TIMEOUT_EXCEEDED', + message: 'Timeout exceeded', + }); + const middle = new Error('query failed'); + middle.cause = inner; + const outer = new Error('evaluation failed'); + outer.cause = middle; + expect(isQueryTimeoutError(outer)).toBe(true); + }); + + it('does not classify wrapped non-timeout errors as timeouts', () => { + const wrapper = new Error("Table default.foo doesn't exist"); + wrapper.cause = new ClickHouseError({ + code: '60', + type: 'UNKNOWN_TABLE', + message: "Table default.foo doesn't exist", + }); + expect(isQueryTimeoutError(wrapper)).toBe(false); + }); + + it('terminates on self-referential cause chains', () => { + const err = new Error('recursive'); + err.cause = err; + expect(isQueryTimeoutError(err)).toBe(false); + }); + + it('does not classify other ClickHouse errors as timeouts', () => { + expect( + isQueryTimeoutError( + new ClickHouseError({ + code: '60', + type: 'UNKNOWN_TABLE', + message: "Table default.foo doesn't exist", + }), + ), + ).toBe(false); + expect(isQueryTimeoutError(new Error('clickhouse kaput'))).toBe(false); + expect(isQueryTimeoutError('Timeout error.')).toBe(false); + expect(isQueryTimeoutError(undefined)).toBe(false); + }); + }); + + describe('isClientTimeoutOrAbortError', () => { + it('only matches the client timeout/abort messages', () => { + expect(isClientTimeoutOrAbortError(new Error('Timeout error.'))).toBe( + true, + ); + expect( + isClientTimeoutOrAbortError(new Error('The user aborted a request.')), + ).toBe(true); + expect( + isClientTimeoutOrAbortError( + new ClickHouseError({ + code: '159', + type: 'TIMEOUT_EXCEEDED', + message: 'Timeout exceeded', + }), + ), + ).toBe(false); + }); + }); +}); diff --git a/packages/api/src/tasks/checkAlerts/errors.ts b/packages/api/src/tasks/checkAlerts/errors.ts index 37d7bb0b2c..73faa1994c 100644 --- a/packages/api/src/tasks/checkAlerts/errors.ts +++ b/packages/api/src/tasks/checkAlerts/errors.ts @@ -1,3 +1,5 @@ +import { ClickHouseError } from '@clickhouse/client-common'; + export const WEBHOOK_REDIRECT_ERROR_MESSAGE = 'Webhook destination responded with a redirect. Redirects are not supported.'; @@ -10,3 +12,85 @@ export class WebhookRedirectError extends Error { this.status = status; } } + +// @clickhouse/client (Node) rejects with these exact messages when the +// configured request_timeout elapses or the request is aborted. See +// clickhouse-js packages/client-node/src/connection/socket_pool.ts. +const CLIENT_TIMEOUT_MESSAGE = 'Timeout error.'; +const CLIENT_ABORT_MESSAGE = 'The user aborted a request.'; + +// ClickHouse server-side error for exceeded execution limits +// (e.g. max_execution_time): TIMEOUT_EXCEEDED, code 159. +const CH_TIMEOUT_TYPE = 'TIMEOUT_EXCEEDED'; +const CH_TIMEOUT_CODE = '159'; + +/** + * Check whether an error is a ClickHouseError, using both `instanceof` and a + * constructor-name fallback. The fallback handles the case where multiple + * copies of `@clickhouse/client-common` are installed (e.g. the api package + * uses one version while `common-utils` bundles another) — `instanceof` fails + * across the two class identities even though the shapes are identical. + */ +const isClickHouseError = ( + err: unknown, +): err is ClickHouseError & { type?: string; code?: string } => { + if (err instanceof ClickHouseError) return true; + return err instanceof Error && err.constructor?.name === 'ClickHouseError'; +}; + +/** + * Check whether an error is the ClickHouse client's own request_timeout + * firing (or the request being aborted) — i.e. the client-side evaluation + * timeout, as opposed to a server-side TIMEOUT_EXCEEDED. + */ +export const isClientTimeoutOrAbortError = (e: unknown): boolean => + e instanceof Error && + (e.message === CLIENT_TIMEOUT_MESSAGE || e.message === CLIENT_ABORT_MESSAGE); + +const isTimeoutErrorShallow = (e: Error): boolean => { + if (isClientTimeoutOrAbortError(e)) { + return true; + } + + if ( + isClickHouseError(e) && + (e.type === CH_TIMEOUT_TYPE || e.code === CH_TIMEOUT_CODE) + ) { + return true; + } + + return (e as NodeJS.ErrnoException).code === 'ETIMEDOUT'; +}; + +// Guard against pathological/self-referential cause chains. +const MAX_CAUSE_DEPTH = 5; + +/** + * Classify whether an alert query failure is a timeout/abort (rather than a + * query or connection error). Covers: + * - the ClickHouse client's request_timeout ("Timeout error.") + * - aborted requests ("The user aborted a request.") + * - server-side TIMEOUT_EXCEEDED (code 159, e.g. max_execution_time) + * - TCP-level socket timeouts (ETIMEDOUT) + * + * Walks the `cause` chain: `BaseClickhouseClient.query` wraps failures in a + * `ClickHouseQueryError` that preserves the message but keeps the original + * error (and its identifying type/code) only on `cause`, so server-side + * TIMEOUT_EXCEEDED and socket ETIMEDOUT would otherwise misclassify as + * generic query errors. + */ +export const isQueryTimeoutError = (e: unknown): boolean => { + const seen = new Set(); + let current = e; + for (let depth = 0; depth < MAX_CAUSE_DEPTH; depth++) { + if (!(current instanceof Error) || seen.has(current)) { + return false; + } + if (isTimeoutErrorShallow(current)) { + return true; + } + seen.add(current); + current = current.cause; + } + return false; +}; diff --git a/packages/api/src/tasks/checkAlerts/index.ts b/packages/api/src/tasks/checkAlerts/index.ts index 81195eec23..981d04b6d0 100644 --- a/packages/api/src/tasks/checkAlerts/index.ts +++ b/packages/api/src/tasks/checkAlerts/index.ts @@ -51,12 +51,17 @@ import { serializeError } from 'serialize-error'; import { ALERT_HISTORY_QUERY_CONCURRENCY } from '@/controllers/alertHistory'; import { AlertState, IAlert, IAlertError } from '@/models/alert'; -import AlertHistory, { IAlertHistory } from '@/models/alertHistory'; +import AlertHistory, { + IAlertHistory, + IAlertHistoryAnalytics, +} from '@/models/alertHistory'; import { IDashboard } from '@/models/dashboard'; import { ISavedSearch } from '@/models/savedSearch'; import { ISource } from '@/models/source'; import { IWebhook } from '@/models/webhook'; import { + isClientTimeoutOrAbortError, + isQueryTimeoutError, WEBHOOK_REDIRECT_ERROR_MESSAGE, WebhookRedirectError, } from '@/tasks/checkAlerts/errors'; @@ -215,6 +220,29 @@ const getErrorMessage = (e: unknown): string => { return String(e); }; +const QUERY_TIMEOUT_RETRY_NOTE = + 'The evaluation is retried on every check, but the alert will not fire until the query completes in time.'; + +/** + * Build the IAlertError for a failed alert query, classifying timeouts + * (client request timeout/abort, server-side TIMEOUT_EXCEEDED, socket + * timeouts) separately from other query errors so the message is actionable. + */ +const makeQueryAlertError = ( + e: unknown, + requestTimeoutMs: number, +): IAlertError => { + if (!isQueryTimeoutError(e)) { + return makeAlertError(AlertErrorType.QUERY_ERROR, getErrorMessage(e)); + } + // For the client's own request timeout we know the configured limit; for + // server-side timeouts the original ClickHouse message carries the limit. + const message = isClientTimeoutOrAbortError(e) + ? `Alert query did not complete within the ${Math.round(requestTimeoutMs / 1000)}s evaluation timeout. ${QUERY_TIMEOUT_RETRY_NOTE}` + : `Alert query timed out before completing: ${getErrorMessage(e)}. ${QUERY_TIMEOUT_RETRY_NOTE}`; + return makeAlertError(AlertErrorType.QUERY_TIMEOUT, message); +}; + // Most webhook errors show a hardcoded message to avoid leaking sensitive request details in the UI. // Redirect errors are a known class of errors which we want to surface to the user, so it has a specific message. const makeWebhookAlertError = (error: unknown): IAlertError => { @@ -797,6 +825,13 @@ export const processAlert = async ( // availability SLIs cover every real evaluation regardless of exit point. const evalStartedAt = performance.now(); let evalOutcome: OperationOutcome | 'skipped' = 'success'; + // Scheduled start of the window being evaluated. Hoisted so the catch + // blocks can attribute error history records to the correct window. + let evaluationWindowStart: Date | undefined; + // Diagnostics persisted on every history record this evaluation writes + // (query duration, webhook delivery time, backfilled buckets). Populated + // progressively; hoisted so the catch blocks can attach what was measured. + const evaluationAnalytics: IAlertHistoryAnalytics = {}; try { const windowSizeInMins = ms(alert.interval) / 60000; const scheduleStartAt = normalizeScheduleStartAt({ @@ -838,6 +873,7 @@ export const processAlert = async ( scheduleOffsetMinutes, scheduleStartAt, ); + evaluationWindowStart = nowInMinsRoundDown; const hasGroupBy = alertHasGroupBy(details); // Check if we should skip this alert check based on last evaluation time @@ -971,31 +1007,53 @@ export const processAlert = async ( }); // SLO signal for alert data fetching (distinct from the end-to-end // evaluation SLI): did ClickHouse serve the alert query, and how fast. + const queryDurationMs = performance.now() - queryStartedAt; + evaluationAnalytics.queryDurationMs = Math.round(queryDurationMs); recordOperationOutcome({ operation: 'alerts.query', outcome: 'success', - durationMs: performance.now() - queryStartedAt, + durationMs: queryDurationMs, attributes: { alert_source: alert.source ?? 'unknown' }, }); } catch (e) { + const queryDurationMs = performance.now() - queryStartedAt; + // Time-to-failure — for QUERY_TIMEOUT this is roughly the configured + // evaluation timeout. + evaluationAnalytics.queryDurationMs = Math.round(queryDurationMs); recordOperationOutcome({ operation: 'alerts.query', outcome: 'error', - durationMs: performance.now() - queryStartedAt, + durationMs: queryDurationMs, attributes: { alert_source: alert.source ?? 'unknown' }, }); evalOutcome = 'error'; - alertQueryFailuresCounter.add(1); + const alertError = makeQueryAlertError( + e, + clickhouseClient.requestTimeoutMs, + ); + alertQueryFailuresCounter.add(1, { + error_type: + alertError.type === AlertErrorType.QUERY_TIMEOUT + ? 'timeout' + : 'error', + }); logger.error( { alertId: alert.id, + errorType: alertError.type, error: serializeError(e), }, 'Alert query failed, skipping state/history update', ); - await alertProvider.recordAlertErrors(alert.id, [ - makeAlertError(AlertErrorType.QUERY_ERROR, getErrorMessage(e)), - ]); + // Record the error on the alert and as an ERROR history row for this + // window. ERROR rows are excluded from the due-ness gate and date-range + // computation, so the failed window is still retried/backfilled. + await alertProvider.recordAlertErrors( + alert.id, + [alertError], + nowInMinsRoundDown, + evaluationAnalytics, + ); return; } @@ -1075,6 +1133,7 @@ export const processAlert = async ( : `Alert resolved for group "${group}", triggering ${alert.channel.type} notification`, ); + const notificationStartedAt = performance.now(); try { // Casts to any here because this is where I stopped unraveling the // alert logic requiring large, nested objects. We should look at @@ -1104,6 +1163,12 @@ export const processAlert = async ( 'Failed to fire channel event', ); executionErrors.push(makeWebhookAlertError(e)); + } finally { + // Total wall time spent delivering notifications in this evaluation + // (summed across groups/resolves, includes retries and failures). + evaluationAnalytics.webhookDurationMs = + (evaluationAnalytics.webhookDurationMs ?? 0) + + Math.round(performance.now() - notificationStartedAt); } }; @@ -1196,7 +1261,12 @@ export const processAlert = async ( // Auto-resolve await sendNotificationIfResolved(previous, history, ''); + // Single-value evaluations always cover exactly the current window. + evaluationAnalytics.backfilledBuckets = 0; const historyRecords = Array.from(histories.values()); + for (const record of historyRecords) { + record.analytics = evaluationAnalytics; + } await alertProvider.updateAlertState( alert.id, historyRecords, @@ -1211,6 +1281,12 @@ export const processAlert = async ( dateRange[1], `${windowSizeInMins} minute`, ); + // Buckets beyond the current window were backfilled in this run — + // earlier evaluation ticks were missed (job delay, failed evaluations). + evaluationAnalytics.backfilledBuckets = Math.max( + 0, + expectedBuckets.length - 1, + ); // Group data by time bucket (grouped alerts may have multiple entries per time bucket) const checkDataByBucket = new Map< @@ -1409,6 +1485,9 @@ export const processAlert = async ( // Save all history records and update alert state const historyRecords = Array.from(histories.values()); + for (const record of historyRecords) { + record.analytics = evaluationAnalytics; + } await alertProvider.updateAlertState( alert.id, historyRecords, @@ -1433,9 +1512,14 @@ export const processAlert = async ( ? AlertErrorType.INVALID_ALERT : AlertErrorType.UNKNOWN; try { - await alertProvider.recordAlertErrors(alert.id, [ - makeAlertError(type, message), - ]); + await alertProvider.recordAlertErrors( + alert.id, + [makeAlertError(type, message)], + evaluationWindowStart, + Object.keys(evaluationAnalytics).length > 0 + ? evaluationAnalytics + : undefined, + ); } catch (recordErr) { logger.error( { @@ -1507,6 +1591,10 @@ export const getPreviousAlertHistories = async ( $match: { alert: id, createdAt: { $lte: now, $gte: lookbackDate }, + // ERROR rows record failed evaluations; they must not count as + // "window evaluated" or the failed window would never be + // retried/backfilled. + state: { $ne: AlertState.ERROR }, }, }, // With a single alert value, the compound index {alert: 1, group: 1, createdAt: -1} @@ -1605,6 +1693,9 @@ export const getConsecutiveWindowHistories = async ( $match: { alert: id, createdAt: { $gte: earliestAllowedTime, $lt: windowStart }, + // Failed evaluations (ERROR rows) are not evaluated windows and + // must not affect consecutive-window counting. + state: { $ne: AlertState.ERROR }, }, }, { $sort: { alert: 1, group: 1, createdAt: -1 } }, diff --git a/packages/api/src/tasks/checkAlerts/providers/default.ts b/packages/api/src/tasks/checkAlerts/providers/default.ts index 079cdcc89d..30c89dea70 100644 --- a/packages/api/src/tasks/checkAlerts/providers/default.ts +++ b/packages/api/src/tasks/checkAlerts/providers/default.ts @@ -17,7 +17,10 @@ import Alert, { type IAlert, type IAlertError, } from '@/models/alert'; -import AlertHistory, { IAlertHistory } from '@/models/alertHistory'; +import AlertHistory, { + IAlertHistory, + IAlertHistoryAnalytics, +} from '@/models/alertHistory'; import Connection, { IConnection } from '@/models/connection'; import Dashboard from '@/models/dashboard'; import { type ISavedSearch, SavedSearch } from '@/models/savedSearch'; @@ -413,13 +416,83 @@ export default class DefaultAlertProvider implements AlertProvider { { _id: new mongoose.Types.ObjectId(alertId) }, { $set: { state: finalState, executionErrors: errors } }, ); + + // Notification (e.g. webhook) failures happened during this evaluation: + // record them as an ERROR history row alongside the normal rows so the + // failure is visible in the alert's evaluation history. All histories in + // one execution share the same createdAt (the evaluation window start) + // and the same evaluation-level analytics. + const evaluationWindowStart = histories[0]?.createdAt; + if (errors.length > 0 && evaluationWindowStart != null) { + await this.upsertErrorHistory( + alertId, + evaluationWindowStart, + errors, + histories[0]?.analytics, + ); + } else if ( + evaluationWindowStart != null && + successfulHistories.length > 0 + ) { + // A failed earlier tick may have left an ERROR row for this window + // (recordAlertErrors upserts one, and ERROR rows don't mark the window + // as evaluated so it's retried). The window has now evaluated cleanly — + // remove the stale ERROR row so the window doesn't render as ERROR + // forever (the evaluations view ranks ERROR above OK). + await AlertHistory.deleteOne({ + alert: new mongoose.Types.ObjectId(alertId), + createdAt: evaluationWindowStart, + state: AlertState.ERROR, + }); + } } - async recordAlertErrors(alertId: string, errors: IAlertError[]) { + async recordAlertErrors( + alertId: string, + errors: IAlertError[], + evaluationWindowStart?: Date, + analytics?: IAlertHistoryAnalytics, + ) { await Alert.updateOne( { _id: new mongoose.Types.ObjectId(alertId) }, { $set: { executionErrors: errors } }, ); + + if (evaluationWindowStart != null) { + await this.upsertErrorHistory( + alertId, + evaluationWindowStart, + errors, + analytics, + ); + } + } + + /** + * Upsert the ERROR-state history row for the given evaluation window. + * Keyed on {alert, createdAt, state} so retries within the same window + * update a single row instead of accumulating one row per tick — a + * permanently failing 1d alert produces one error row per day, not one per + * minute. Rows expire with the collection's existing TTL index. + */ + private async upsertErrorHistory( + alertId: string, + evaluationWindowStart: Date, + errors: IAlertError[], + analytics?: IAlertHistoryAnalytics, + ) { + await AlertHistory.updateOne( + { + alert: new mongoose.Types.ObjectId(alertId), + createdAt: evaluationWindowStart, + state: AlertState.ERROR, + }, + { + $set: { errors, ...(analytics != null && { analytics }) }, + $setOnInsert: { counts: 0, lastValues: [] }, + }, + { upsert: true }, + ); } async getWebhooks(teamId: string | ObjectId) { diff --git a/packages/api/src/tasks/checkAlerts/providers/index.ts b/packages/api/src/tasks/checkAlerts/providers/index.ts index aeed3e5407..159a352081 100644 --- a/packages/api/src/tasks/checkAlerts/providers/index.ts +++ b/packages/api/src/tasks/checkAlerts/providers/index.ts @@ -4,7 +4,7 @@ import _ from 'lodash'; import { ObjectId } from '@/models'; import { IAlert, IAlertError } from '@/models/alert'; -import { IAlertHistory } from '@/models/alertHistory'; +import { IAlertHistory, IAlertHistoryAnalytics } from '@/models/alertHistory'; import { IConnection } from '@/models/connection'; import { IDashboard } from '@/models/dashboard'; import { ISavedSearch } from '@/models/savedSearch'; @@ -83,6 +83,9 @@ export interface AlertProvider { * Uses Promise.allSettled to handle partial failures gracefully. * The alert state is determined from successfully saved histories, or falls back to all histories if all saves fail. * Also replaces the alert's `executionErrors` field with the provided errors from the current execution. + * When errors are present (e.g. webhook failures), an ERROR-state history + * row is additionally upserted for the evaluation window so the failure is + * visible in the alert's evaluation history. */ updateAlertState( alertId: string, @@ -91,11 +94,23 @@ export interface AlertProvider { ): Promise; /** - * Replace the alert's `executionErrors` field without changing state or creating history. - * Use this when an error prevents the normal state/history update from running - * (e.g. a ClickHouse query error). + * Replace the alert's `executionErrors` field without changing state or the + * alert's normal history. Use this when an error prevents the normal + * state/history update from running (e.g. a ClickHouse query error). + * + * When `evaluationWindowStart` is provided, the errors are also upserted as + * an ERROR-state AlertHistory row for that window (one row per window, + * regardless of retries). ERROR rows are excluded from scheduling/backfill + * computations, so recording them does not mark the window as evaluated. + * `analytics` carries whatever diagnostics the failed evaluation measured + * (e.g. the query's time-to-failure) onto that ERROR row. */ - recordAlertErrors(alertId: string, errors: IAlertError[]): Promise; + recordAlertErrors( + alertId: string, + errors: IAlertError[], + evaluationWindowStart?: Date, + analytics?: IAlertHistoryAnalytics, + ): Promise; /** Fetch all webhooks for the given team, returning a map of webhook ID to webhook */ getWebhooks(teamId: string | ObjectId): Promise>; diff --git a/packages/common-utils/src/clickhouse/index.ts b/packages/common-utils/src/clickhouse/index.ts index 7e24cd5793..4bdd8ba097 100644 --- a/packages/common-utils/src/clickhouse/index.ts +++ b/packages/common-utils/src/clickhouse/index.ts @@ -667,6 +667,15 @@ export abstract class BaseClickhouseClient { } } + /** + * The configured request timeout in milliseconds. Exposed so callers (e.g. + * the alert task) can produce actionable error messages when a query is + * aborted by this timeout. + */ + get requestTimeoutMs(): number { + return this.requestTimeout; + } + protected getClient(): WebClickHouseClient | NodeClickHouseClient { if (!this.client) { throw new Error(