[ResponseOps] log error when ES Query rules find docs out of time ran…

…ge (elastic#186332)

resolves elastic#175980

## Summary

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.

Note that the ES|QL flavor rule does not use this diagnostic, just
search source (KQL) and query dsl.

We check 3 things:
- ensure the `dateStart` sent to fetch was valid
- ensure the `dateEnd` sent to fetch was valid
- ensure the relevant time fields in hits are within the
dateStart/dateEnd range

These produce three different error messages:

`For rule '<rule-id>', hits were returned with invalid time range start
date '<date>' from field '<field>' using query <query>`

`For rule '<rule-id>', hits were returned with invalid time range end
date '<date>' from field '<field>' using query <query>`

`For rule '<rule-id>', the hit with date '<date>' from field '<field>'
is outside the query time range. Query: <query>. Document: <document>`

Each message has one tag on it: `query-result-out-of-time-range`

## To Verify

To test invalid dateStart/dateEnd, hack the Kibana code to set the
values to NaN's:

https://github.com/elastic/kibana/blob/d30da09707f85d84d7fd555733ba8e0cb595228b/x-pack/plugins/stack_alerts/server/rule_types/es_query/executor.ts#L263-L264

For instance, change that to:

    const epochStart = new Date('x').getTime();
    const epochEnd = new Date('y').getTime();

To test the invdivual document hits, first back out the change you made
above - when those error, the checks we're testing below do not run.
Hack the Kibana code to make the time out of range:

https://github.com/elastic/kibana/blob/d30da09707f85d84d7fd555733ba8e0cb595228b/x-pack/plugins/stack_alerts/server/rule_types/es_query/executor.ts#L294

For instance, change that to:

    const epochDate = epochStart - 100

For both tests, create an es query rule - kql or dsl - make the relevant
changes, and arrange for the rule to get hits each time. The relevant
messages should be logged in the Kibana console when the rule runs.

### Checklist

Delete any items that are not applicable to this PR.

- [x] [Unit or functional
tests](https://www.elastic.co/guide/en/kibana/master/development-tests.html)
were updated or added to match the most common scenarios

---------

Co-authored-by: Elastic Machine <[email protected]>
(cherry picked from commit e12e449)

# Conflicts:
#	x-pack/plugins/stack_alerts/server/rule_types/es_query/lib/fetch_search_source_query.ts

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<EsQueryRuleParams> = {
+        ...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<EsQueryRuleParams> = {
+        ...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<EsQueryRuleParams> = {
+        ...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<EsQueryRuleParams> = {
+        ...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', () => {