From 600ad4b0c48fec791b921a16d47e64b941a9473f Mon Sep 17 00:00:00 2001 From: Patrick Mueller Date: Mon, 17 Jun 2024 15:57:14 -0400 Subject: [PATCH 1/4] [ResponseOps] log error when ES Query rules find docs out of time range resolves https://github.com/elastic/kibana/issues/175980 Adds a check with logging if an ES Query rule returns hits which fall outside the time range it's searching. This shouldn't ever happen, but seems to be happening on rare occaisons, so we wanted to add some diagnostics to try to help narrow down the problem. --- .../server/rule_types/es_query/executor.ts | 49 ++++++++++++++++++- 1 file changed, 48 insertions(+), 1 deletion(-) diff --git a/x-pack/plugins/stack_alerts/server/rule_types/es_query/executor.ts b/x-pack/plugins/stack_alerts/server/rule_types/es_query/executor.ts index 5e23bf9498ec5..752693259969d 100644 --- a/x-pack/plugins/stack_alerts/server/rule_types/es_query/executor.ts +++ b/x-pack/plugins/stack_alerts/server/rule_types/es_query/executor.ts @@ -6,7 +6,7 @@ */ import { sha256 } from 'js-sha256'; import { i18n } from '@kbn/i18n'; -import { CoreSetup } from '@kbn/core/server'; +import { CoreSetup, Logger } from '@kbn/core/server'; import { isGroupAggregation, UngroupedGroupId } from '@kbn/triggers-actions-ui-plugin/common'; import { ALERT_EVALUATION_THRESHOLD, @@ -16,6 +16,9 @@ import { } from '@kbn/rule-data-utils'; import { AlertsClientError } from '@kbn/alerting-plugin/server'; +import { get } from 'lodash'; +import type * as estypes from '@elastic/elasticsearch/lib/api/typesWithBodyKey'; + import { ComparatorFns } from '../../../common'; import { addMessages, @@ -122,6 +125,9 @@ export async function executor(core: CoreSetup, options: ExecutorOptions>, + timeField: string | undefined, + dateStart: string, + dateEnd: string +) { + if (!timeField) return; + + const epochStart = new Date(dateStart).getTime(); + const epochEnd = new Date(dateEnd).getTime(); + + for (const hit of hits) { + const dateVal = get(hit, `_source.${timeField}`); + const epochDate = getEpochDateFromString(dateVal); + if (epochDate) { + if (epochDate < epochStart || epochDate > epochEnd) { + const meta = `id: ${hit._id}; index: ${hit._index}`; + logger.error( + `The hit with date ${dateVal} is outside the range of the rule's time window. Document info: ${meta}` + ); + } + } + } +} + +function getEpochDateFromString(dateString: string): number | null { + let date: Date; + try { + date = new Date(dateString); + } catch (e) { + return null; + } + + if (!isNaN(date.getTime())) return date.getTime(); + + const dateNum = parseInt(dateString, 10); + if (isNaN(dateNum)) return null; + return new Date(dateNum).getTime(); +} + export function getValidTimefieldSort( sortValues: Array = [] ): undefined | string { From dd6c86156c86e3ecd4d4adb2aa1d9a22d72a508c Mon Sep 17 00:00:00 2001 From: Patrick Mueller Date: Tue, 18 Jun 2024 14:30:53 -0400 Subject: [PATCH 2/4] check the start/end dates as well, and add rule id to message --- .../server/rule_types/es_query/executor.ts | 17 +++++++++++++++-- 1 file changed, 15 insertions(+), 2 deletions(-) diff --git a/x-pack/plugins/stack_alerts/server/rule_types/es_query/executor.ts b/x-pack/plugins/stack_alerts/server/rule_types/es_query/executor.ts index 752693259969d..4e380c8868650 100644 --- a/x-pack/plugins/stack_alerts/server/rule_types/es_query/executor.ts +++ b/x-pack/plugins/stack_alerts/server/rule_types/es_query/executor.ts @@ -126,7 +126,7 @@ export async function executor(core: CoreSetup, options: ExecutorOptions>, timeField: string | undefined, dateStart: string, @@ -248,6 +249,18 @@ function checkHitsForDateOutOfRange( const epochStart = new Date(dateStart).getTime(); const epochEnd = new Date(dateEnd).getTime(); + const messagePrefix = `For rule "${ruleId}"`; + if (isNaN(epochStart)) { + logger.error( + `${messagePrefix}, hits were returned with invalid time range start date "${dateStart}" from field "${timeField}"` + ); + } + + if (isNaN(epochEnd)) { + logger.error( + `${messagePrefix}, hits were returned with invalid time range end date "${dateEnd}" from field "${timeField}"` + ); + } for (const hit of hits) { const dateVal = get(hit, `_source.${timeField}`); @@ -256,7 +269,7 @@ function checkHitsForDateOutOfRange( if (epochDate < epochStart || epochDate > epochEnd) { const meta = `id: ${hit._id}; index: ${hit._index}`; logger.error( - `The hit with date ${dateVal} is outside the range of the rule's time window. Document info: ${meta}` + `${messagePrefix}, the hit with date "${dateVal}" from field "${timeField}" is outside the range of the rule's time window. Document info: ${meta}` ); } } From 88611be0b8fae3df1c12384d7c2c870b88ed1e61 Mon Sep 17 00:00:00 2001 From: Patrick Mueller Date: Fri, 12 Jul 2024 00:37:26 -0400 Subject: [PATCH 3/4] enhance the messages --- .../server/rule_types/es_query/executor.ts | 56 +++++++++++++++---- .../rule_types/es_query/lib/fetch_es_query.ts | 1 + .../es_query/lib/fetch_esql_query.ts | 1 + .../es_query/lib/fetch_search_source_query.ts | 7 +-- 4 files changed, 50 insertions(+), 15 deletions(-) diff --git a/x-pack/plugins/stack_alerts/server/rule_types/es_query/executor.ts b/x-pack/plugins/stack_alerts/server/rule_types/es_query/executor.ts index 4e380c8868650..3d72b11d13c30 100644 --- a/x-pack/plugins/stack_alerts/server/rule_types/es_query/executor.ts +++ b/x-pack/plugins/stack_alerts/server/rule_types/es_query/executor.ts @@ -74,7 +74,7 @@ export async function executor(core: CoreSetup, options: ExecutorOptions>, timeField: string | undefined, dateStart: string, - dateEnd: string + dateEnd: string, + query: unknown ) { if (!timeField) return; const epochStart = new Date(dateStart).getTime(); const epochEnd = new Date(dateEnd).getTime(); + const messageMeta = { tags: ['query-result-out-of-time-range'] }; + const messagePrefix = `For rule "${ruleId}"`; + const usingQuery = `using query <${JSON.stringify(query)}>`; + const hitsWereReturned = 'hits were returned with invalid time range'; + + let errors = 0; if (isNaN(epochStart)) { + errors++; logger.error( - `${messagePrefix}, hits were returned with invalid time range start date "${dateStart}" from field "${timeField}"` + `${messagePrefix}, ${hitsWereReturned} start date "${dateStart}" from field "${timeField}" ${usingQuery}`, + messageMeta ); } if (isNaN(epochEnd)) { + errors++; logger.error( - `${messagePrefix}, hits were returned with invalid time range end date "${dateEnd}" from field "${timeField}"` + `${messagePrefix}, ${hitsWereReturned} end date "${dateEnd}" from field "${timeField}" ${usingQuery}`, + messageMeta ); } + if (errors > 0) return; + + const outsideTimeRange = 'outside the query time range'; + for (const hit of hits) { const dateVal = get(hit, `_source.${timeField}`); const epochDate = getEpochDateFromString(dateVal); + if (epochDate) { if (epochDate < epochStart || epochDate > epochEnd) { - const meta = `id: ${hit._id}; index: ${hit._index}`; - logger.error( - `${messagePrefix}, the hit with date "${dateVal}" from field "${timeField}" is outside the range of the rule's time window. Document info: ${meta}` - ); + const message = `the hit with date "${dateVal}" from field "${timeField}" is ${outsideTimeRange}`; + const queryString = `Query: <${JSON.stringify(query)}>`; + const document = `Document: <${JSON.stringify(hit)}>`; + logger.error(`${messagePrefix}, ${message}. ${queryString}. ${document}`, messageMeta); } } } @@ -284,11 +312,17 @@ function getEpochDateFromString(dateString: string): number | null { return null; } - if (!isNaN(date.getTime())) return date.getTime(); + const time = date.getTime(); + if (!isNaN(time)) return time; + // if not a valid date string, try it as a stringified number const dateNum = parseInt(dateString, 10); if (isNaN(dateNum)) return null; - return new Date(dateNum).getTime(); + + const timeFromNumber = new Date(dateNum).getTime(); + if (isNaN(timeFromNumber)) return null; + + return timeFromNumber; } export function getValidTimefieldSort( diff --git a/x-pack/plugins/stack_alerts/server/rule_types/es_query/lib/fetch_es_query.ts b/x-pack/plugins/stack_alerts/server/rule_types/es_query/lib/fetch_es_query.ts index f1548abb7fcc7..9a3aba68039b9 100644 --- a/x-pack/plugins/stack_alerts/server/rule_types/es_query/lib/fetch_es_query.ts +++ b/x-pack/plugins/stack_alerts/server/rule_types/es_query/lib/fetch_es_query.ts @@ -145,6 +145,7 @@ export async function fetchEsQuery({ sourceFieldsParams: params.sourceFields, }), link, + query: sortedQuery, index: params.index, }; } diff --git a/x-pack/plugins/stack_alerts/server/rule_types/es_query/lib/fetch_esql_query.ts b/x-pack/plugins/stack_alerts/server/rule_types/es_query/lib/fetch_esql_query.ts index 2f6a750fc2de6..d6b8215bd2a37 100644 --- a/x-pack/plugins/stack_alerts/server/rule_types/es_query/lib/fetch_esql_query.ts +++ b/x-pack/plugins/stack_alerts/server/rule_types/es_query/lib/fetch_esql_query.ts @@ -66,6 +66,7 @@ export async function fetchEsqlQuery({ return { link, + query, numMatches: Number(response.values.length), parsedResults: parseAggregationResults({ isCountAgg: true, diff --git a/x-pack/plugins/stack_alerts/server/rule_types/es_query/lib/fetch_search_source_query.ts b/x-pack/plugins/stack_alerts/server/rule_types/es_query/lib/fetch_search_source_query.ts index 1a48fbef1adc4..bc281b3a08f0d 100644 --- a/x-pack/plugins/stack_alerts/server/rule_types/es_query/lib/fetch_search_source_query.ts +++ b/x-pack/plugins/stack_alerts/server/rule_types/es_query/lib/fetch_search_source_query.ts @@ -69,11 +69,9 @@ export async function fetchSearchSourceQuery({ alertLimit ); + const searchRequestBody: unknown = searchSource.getSearchRequestBody(); logger.debug( - () => - `search source query rule (${ruleId}) query: ${JSON.stringify( - searchSource.getSearchRequestBody() - )}` + () => `search source query rule (${ruleId}) query: ${JSON.stringify(searchRequestBody)}` ); const searchResult = await searchSource.fetch(); @@ -99,6 +97,7 @@ export async function fetchSearchSourceQuery({ sourceFieldsParams: params.sourceFields, }), index: [index.name], + query: searchRequestBody, }; } From d30da09707f85d84d7fd555733ba8e0cb595228b Mon Sep 17 00:00:00 2001 From: Patrick Mueller Date: Fri, 12 Jul 2024 12:46:23 -0400 Subject: [PATCH 4/4] add jest tests --- .../rule_types/es_query/executor.test.ts | 276 ++++++++++++++++++ .../server/rule_types/es_query/executor.ts | 8 +- 2 files changed, 280 insertions(+), 4 deletions(-) diff --git a/x-pack/plugins/stack_alerts/server/rule_types/es_query/executor.test.ts b/x-pack/plugins/stack_alerts/server/rule_types/es_query/executor.test.ts index 7ab974dc8d82b..99819eca3c26e 100644 --- a/x-pack/plugins/stack_alerts/server/rule_types/es_query/executor.test.ts +++ b/x-pack/plugins/stack_alerts/server/rule_types/es_query/executor.test.ts @@ -882,6 +882,282 @@ describe('es_query executor', () => { expect(mockSetLimitReached).toHaveBeenCalledTimes(1); expect(mockSetLimitReached).toHaveBeenCalledWith(false); }); + + it('should log messages for hits with out-of-range dates for search source', async () => { + const epoch = Date.now(); + const oneYear = 1000 * 60 * 60 * 24 * 365; + const dateEarly = new Date(epoch - oneYear).toISOString(); + const dateStart = new Date(epoch - 1000).toISOString(); + const dateMiddle = new Date(epoch - 500).toISOString(); + const dateEnd = new Date(epoch).toISOString(); + const dateLate = new Date(epoch + oneYear).toISOString(); + + function getTimeRange() { + return { dateStart, dateEnd }; + } + + mockFetchSearchSourceQuery.mockResolvedValueOnce({ + parsedResults: { + results: [ + { + group: 'all documents', + count: 3, + hits: [ + { _source: { '@timestamp': dateEarly, value: 1 } }, + { _source: { '@timestamp': dateMiddle, value: 2 } }, + { _source: { '@timestamp': dateLate, value: 3 } }, + ], + }, + ], + }, + truncated: false, + query: 'the query would go here', + }); + + const executorOptions: ExecutorOptions = { + ...defaultExecutorOptions, + getTimeRange, + params: { + ...defaultProps, + searchType: 'searchSource', + timeField: '@timestamp', + }, + }; + await executor(coreMock, executorOptions); + + const allLogCalls = loggerMock.collect(logger); + const messages: string[] = []; + for (const parms of allLogCalls.error) { + const message = parms.shift(); + messages.push(`${message}`); + } + + expect(messages).toEqual([ + `For rule 'test-rule-id', the hit with date '${dateEarly}' from field '@timestamp' is outside the query time range. Query: <\"the query would go here\">. Document: <{\"_source\":{\"@timestamp\":\"${dateEarly}\",\"value\":1}}>`, + `For rule 'test-rule-id', the hit with date '${dateLate}' from field '@timestamp' is outside the query time range. Query: <\"the query would go here\">. Document: <{\"_source\":{\"@timestamp\":\"${dateLate}\",\"value\":3}}>`, + ]); + expect(allLogCalls).toMatchInlineSnapshot(` + Object { + "debug": Array [], + "error": Array [ + Array [ + Object { + "tags": Array [ + "query-result-out-of-time-range", + ], + }, + ], + Array [ + Object { + "tags": Array [ + "query-result-out-of-time-range", + ], + }, + ], + ], + "fatal": Array [], + "info": Array [], + "log": Array [], + "trace": Array [], + "warn": Array [], + } + `); + }); + + it('should log messages for bad start / end dates for search source', async () => { + function getTimeRange() { + return { dateStart: 'x', dateEnd: 'y' }; + } + + mockFetchSearchSourceQuery.mockResolvedValueOnce({ + parsedResults: { + results: [ + { + group: 'all documents', + count: 1, + hits: [{ _source: { '@timestamp': new Date().toISOString() } }], + }, + ], + }, + truncated: false, + query: 'the query would go here', + }); + + const executorOptions: ExecutorOptions = { + ...defaultExecutorOptions, + getTimeRange, + params: { + ...defaultProps, + searchType: 'searchSource', + timeField: '@timestamp', + }, + }; + await executor(coreMock, executorOptions); + + const allLogCalls = loggerMock.collect(logger); + const messages: string[] = []; + for (const parms of allLogCalls.error) { + const message = parms.shift(); + messages.push(`${message}`); + } + + expect(messages).toEqual([ + `For rule 'test-rule-id', hits were returned with invalid time range start date 'x' from field '@timestamp' using query <"the query would go here">`, + `For rule 'test-rule-id', hits were returned with invalid time range end date 'y' from field '@timestamp' using query <"the query would go here">`, + ]); + expect(allLogCalls.error).toMatchInlineSnapshot(` + Array [ + Array [ + Object { + "tags": Array [ + "query-result-out-of-time-range", + ], + }, + ], + Array [ + Object { + "tags": Array [ + "query-result-out-of-time-range", + ], + }, + ], + ] + `); + }); + + it('should log messages for hits with out-of-range dates for query dsl', async () => { + const epoch = Date.now(); + const oneYear = 1000 * 60 * 60 * 24 * 365; + const dateEarly = new Date(epoch - oneYear).toISOString(); + const dateStart = new Date(epoch - 1000).toISOString(); + const dateMiddle = new Date(epoch - 500).toISOString(); + const dateEnd = new Date(epoch).toISOString(); + const dateLate = new Date(epoch + oneYear).toISOString(); + + function getTimeRange() { + return { dateStart, dateEnd }; + } + + mockFetchEsQuery.mockResolvedValueOnce({ + parsedResults: { + results: [ + { + group: 'all documents', + count: 3, + hits: [ + { _source: { '@timestamp': dateEarly, value: 1 } }, + { _source: { '@timestamp': dateMiddle, value: 2 } }, + { _source: { '@timestamp': dateLate, value: 3 } }, + ], + }, + ], + }, + truncated: false, + query: 'the query would go here', + }); + + const executorOptions: ExecutorOptions = { + ...defaultExecutorOptions, + getTimeRange, + params: { + ...defaultProps, + searchType: 'esQuery', + timeField: '@timestamp', + }, + }; + await executor(coreMock, executorOptions); + + const allLogCalls = loggerMock.collect(logger); + const messages: string[] = []; + for (const parms of allLogCalls.error) { + const message = parms.shift(); + messages.push(`${message}`); + } + + expect(messages).toEqual([ + `For rule 'test-rule-id', the hit with date '${dateEarly}' from field '@timestamp' is outside the query time range. Query: <\"the query would go here\">. Document: <{\"_source\":{\"@timestamp\":\"${dateEarly}\",\"value\":1}}>`, + `For rule 'test-rule-id', the hit with date '${dateLate}' from field '@timestamp' is outside the query time range. Query: <\"the query would go here\">. Document: <{\"_source\":{\"@timestamp\":\"${dateLate}\",\"value\":3}}>`, + ]); + expect(allLogCalls.error).toMatchInlineSnapshot(` + Array [ + Array [ + Object { + "tags": Array [ + "query-result-out-of-time-range", + ], + }, + ], + Array [ + Object { + "tags": Array [ + "query-result-out-of-time-range", + ], + }, + ], + ] + `); + }); + + it('should log messages for bad start / end dates for query dsl', async () => { + function getTimeRange() { + return { dateStart: 'x', dateEnd: 'y' }; + } + + mockFetchEsQuery.mockResolvedValueOnce({ + parsedResults: { + results: [ + { + group: 'all documents', + count: 1, + hits: [{ _source: { '@timestamp': new Date().toISOString() } }], + }, + ], + }, + truncated: false, + query: 'the query would go here', + }); + + const executorOptions: ExecutorOptions = { + ...defaultExecutorOptions, + getTimeRange, + params: { + ...defaultProps, + searchType: 'esQuery', + timeField: '@timestamp', + }, + }; + await executor(coreMock, executorOptions); + + const allLogCalls = loggerMock.collect(logger); + const messages: string[] = []; + for (const parms of allLogCalls.error) { + const message = parms.shift(); + messages.push(`${message}`); + } + + expect(messages).toEqual([ + `For rule 'test-rule-id', hits were returned with invalid time range start date 'x' from field '@timestamp' using query <"the query would go here">`, + `For rule 'test-rule-id', hits were returned with invalid time range end date 'y' from field '@timestamp' using query <"the query would go here">`, + ]); + expect(allLogCalls.error).toMatchInlineSnapshot(` + Array [ + Array [ + Object { + "tags": Array [ + "query-result-out-of-time-range", + ], + }, + ], + Array [ + Object { + "tags": Array [ + "query-result-out-of-time-range", + ], + }, + ], + ] + `); + }); }); describe('tryToParseAsDate', () => { diff --git a/x-pack/plugins/stack_alerts/server/rule_types/es_query/executor.ts b/x-pack/plugins/stack_alerts/server/rule_types/es_query/executor.ts index 3d72b11d13c30..6f84e73118ec4 100644 --- a/x-pack/plugins/stack_alerts/server/rule_types/es_query/executor.ts +++ b/x-pack/plugins/stack_alerts/server/rule_types/es_query/executor.ts @@ -264,7 +264,7 @@ function checkHitsForDateOutOfRange( const epochEnd = new Date(dateEnd).getTime(); const messageMeta = { tags: ['query-result-out-of-time-range'] }; - const messagePrefix = `For rule "${ruleId}"`; + const messagePrefix = `For rule '${ruleId}'`; const usingQuery = `using query <${JSON.stringify(query)}>`; const hitsWereReturned = 'hits were returned with invalid time range'; @@ -272,7 +272,7 @@ function checkHitsForDateOutOfRange( if (isNaN(epochStart)) { errors++; logger.error( - `${messagePrefix}, ${hitsWereReturned} start date "${dateStart}" from field "${timeField}" ${usingQuery}`, + `${messagePrefix}, ${hitsWereReturned} start date '${dateStart}' from field '${timeField}' ${usingQuery}`, messageMeta ); } @@ -280,7 +280,7 @@ function checkHitsForDateOutOfRange( if (isNaN(epochEnd)) { errors++; logger.error( - `${messagePrefix}, ${hitsWereReturned} end date "${dateEnd}" from field "${timeField}" ${usingQuery}`, + `${messagePrefix}, ${hitsWereReturned} end date '${dateEnd}' from field '${timeField}' ${usingQuery}`, messageMeta ); } @@ -295,7 +295,7 @@ function checkHitsForDateOutOfRange( if (epochDate) { if (epochDate < epochStart || epochDate > epochEnd) { - const message = `the hit with date "${dateVal}" from field "${timeField}" is ${outsideTimeRange}`; + const message = `the hit with date '${dateVal}' from field '${timeField}' is ${outsideTimeRange}`; const queryString = `Query: <${JSON.stringify(query)}>`; const document = `Document: <${JSON.stringify(hit)}>`; logger.error(`${messagePrefix}, ${message}. ${queryString}. ${document}`, messageMeta);