From cc6a64514d9bad6c0ff5dbb9e4c0231939eedde4 Mon Sep 17 00:00:00 2001 From: Patrick Mueller Date: Thu, 24 Jun 2021 10:06:01 -0400 Subject: [PATCH] [alerting][actions] add task scheduled date and delay to event log - 2 (#103172) resolves #98634 This adds a new object property to the event log kibana object named task, with two properties to track the time the task was scheduled to run, and the delay between when it was supposed to run and when it actually started. This task property is only added to the appropriate events. task: schema.maybe( schema.object({ scheduled: ecsDate(), schedule_delay: ecsNumber(), }) ), Note that these changes were previously merged to master in https://github.com/elastic/kibana/pull/102252 which had to be reverted - this PR contains the same commits, plus some additional ones to resolve the tests that were broken during the bad merge. --- .../server/lib/action_executor.test.ts | 90 ++ .../actions/server/lib/action_executor.ts | 19 + .../server/lib/task_runner_factory.test.ts | 16 +- .../actions/server/lib/task_runner_factory.ts | 5 + .../create_execution_handler.test.ts | 1 - .../task_runner/create_execution_handler.ts | 1 - .../server/task_runner/task_runner.test.ts | 187 ++-- .../server/task_runner/task_runner.ts | 17 +- x-pack/plugins/event_log/README.md | 4 + .../plugins/event_log/generated/mappings.json | 14 +- x-pack/plugins/event_log/generated/schemas.ts | 7 +- x-pack/plugins/event_log/scripts/mappings.js | 11 + .../plugins/event_log/server/event_logger.ts | 2 +- .../tests/alerting/alerts.ts | 1 - .../tests/alerting/event_log.ts | 2 +- .../spaces_only/tests/actions/execute.ts | 2 + .../spaces_only/tests/alerting/event_log.ts | 918 +++++++++--------- 17 files changed, 791 insertions(+), 506 deletions(-) diff --git a/x-pack/plugins/actions/server/lib/action_executor.test.ts b/x-pack/plugins/actions/server/lib/action_executor.test.ts index 37d461d6b2a50..440de161490aa 100644 --- a/x-pack/plugins/actions/server/lib/action_executor.test.ts +++ b/x-pack/plugins/actions/server/lib/action_executor.test.ts @@ -109,6 +109,96 @@ test('successfully executes', async () => { }); expect(loggerMock.debug).toBeCalledWith('executing action test:1: 1'); + expect(eventLogger.logEvent.mock.calls).toMatchInlineSnapshot(` + Array [ + Array [ + Object { + "event": Object { + "action": "execute-start", + }, + "kibana": Object { + "saved_objects": Array [ + Object { + "id": "1", + "namespace": "some-namespace", + "rel": "primary", + "type": "action", + "type_id": "test", + }, + ], + }, + "message": "action started: test:1: 1", + }, + ], + Array [ + Object { + "event": Object { + "action": "execute", + "outcome": "success", + }, + "kibana": Object { + "saved_objects": Array [ + Object { + "id": "1", + "namespace": "some-namespace", + "rel": "primary", + "type": "action", + "type_id": "test", + }, + ], + }, + "message": "action executed: test:1: 1", + }, + ], + ] + `); +}); + +test('successfully executes as a task', async () => { + const actionType: jest.Mocked = { + id: 'test', + name: 'Test', + minimumLicenseRequired: 'basic', + executor: jest.fn(), + }; + const actionSavedObject = { + id: '1', + type: 'action', + attributes: { + actionTypeId: 'test', + config: { + bar: true, + }, + secrets: { + baz: true, + }, + }, + references: [], + }; + const actionResult = { + id: actionSavedObject.id, + name: actionSavedObject.id, + ...pick(actionSavedObject.attributes, 'actionTypeId', 'config'), + isPreconfigured: false, + }; + actionsClient.get.mockResolvedValueOnce(actionResult); + encryptedSavedObjectsClient.getDecryptedAsInternalUser.mockResolvedValueOnce(actionSavedObject); + actionTypeRegistry.get.mockReturnValueOnce(actionType); + + const scheduleDelay = 10000; // milliseconds + const scheduled = new Date(Date.now() - scheduleDelay); + await actionExecutor.execute({ + ...executeParams, + taskInfo: { + scheduled, + }, + }); + + const eventTask = eventLogger.logEvent.mock.calls[0][0]?.kibana?.task; + expect(eventTask).toBeDefined(); + expect(eventTask?.scheduled).toBe(scheduled.toISOString()); + expect(eventTask?.schedule_delay).toBeGreaterThanOrEqual(scheduleDelay * 1000 * 1000); + expect(eventTask?.schedule_delay).toBeLessThanOrEqual(2 * scheduleDelay * 1000 * 1000); }); test('provides empty config when config and / or secrets is empty', async () => { diff --git a/x-pack/plugins/actions/server/lib/action_executor.ts b/x-pack/plugins/actions/server/lib/action_executor.ts index e9e7b17288611..9e62b123951df 100644 --- a/x-pack/plugins/actions/server/lib/action_executor.ts +++ b/x-pack/plugins/actions/server/lib/action_executor.ts @@ -25,6 +25,9 @@ import { ActionsClient } from '../actions_client'; import { ActionExecutionSource } from './action_execution_source'; import { RelatedSavedObjects } from './related_saved_objects'; +// 1,000,000 nanoseconds in 1 millisecond +const Millis2Nanos = 1000 * 1000; + export interface ActionExecutorContext { logger: Logger; spaces?: SpacesServiceStart; @@ -39,11 +42,16 @@ export interface ActionExecutorContext { preconfiguredActions: PreConfiguredAction[]; } +export interface TaskInfo { + scheduled: Date; +} + export interface ExecuteOptions { actionId: string; request: KibanaRequest; params: Record; source?: ActionExecutionSource; + taskInfo?: TaskInfo; relatedSavedObjects?: RelatedSavedObjects; } @@ -71,6 +79,7 @@ export class ActionExecutor { params, request, source, + taskInfo, relatedSavedObjects, }: ExecuteOptions): Promise> { if (!this.isInitialized) { @@ -143,9 +152,19 @@ export class ActionExecutor { const actionLabel = `${actionTypeId}:${actionId}: ${name}`; logger.debug(`executing action ${actionLabel}`); + const task = taskInfo + ? { + task: { + scheduled: taskInfo.scheduled.toISOString(), + schedule_delay: Millis2Nanos * (Date.now() - taskInfo.scheduled.getTime()), + }, + } + : {}; + const event: IEvent = { event: { action: EVENT_LOG_ACTIONS.execute }, kibana: { + ...task, saved_objects: [ { rel: SAVED_OBJECT_REL_PRIMARY, diff --git a/x-pack/plugins/actions/server/lib/task_runner_factory.test.ts b/x-pack/plugins/actions/server/lib/task_runner_factory.test.ts index 2292994e3ccfd..495d638951b56 100644 --- a/x-pack/plugins/actions/server/lib/task_runner_factory.test.ts +++ b/x-pack/plugins/actions/server/lib/task_runner_factory.test.ts @@ -133,6 +133,9 @@ test('executes the task by calling the executor with proper parameters', async ( authorization: 'ApiKey MTIzOmFiYw==', }, }), + taskInfo: { + scheduled: new Date(), + }, }); const [executeParams] = mockedActionExecutor.execute.mock.calls[0]; @@ -255,6 +258,9 @@ test('uses API key when provided', async () => { authorization: 'ApiKey MTIzOmFiYw==', }, }), + taskInfo: { + scheduled: new Date(), + }, }); const [executeParams] = mockedActionExecutor.execute.mock.calls[0]; @@ -300,6 +306,9 @@ test('uses relatedSavedObjects when provided', async () => { authorization: 'ApiKey MTIzOmFiYw==', }, }), + taskInfo: { + scheduled: new Date(), + }, }); }); @@ -323,7 +332,6 @@ test('sanitizes invalid relatedSavedObjects when provided', async () => { }); await taskRunner.run(); - expect(mockedActionExecutor.execute).toHaveBeenCalledWith({ actionId: '2', params: { baz: true }, @@ -334,6 +342,9 @@ test('sanitizes invalid relatedSavedObjects when provided', async () => { authorization: 'ApiKey MTIzOmFiYw==', }, }), + taskInfo: { + scheduled: new Date(), + }, }); }); @@ -363,6 +374,9 @@ test(`doesn't use API key when not provided`, async () => { request: expect.objectContaining({ headers: {}, }), + taskInfo: { + scheduled: new Date(), + }, }); const [executeParams] = mockedActionExecutor.execute.mock.calls[0]; diff --git a/x-pack/plugins/actions/server/lib/task_runner_factory.ts b/x-pack/plugins/actions/server/lib/task_runner_factory.ts index 0515963ab82f4..64169de728f75 100644 --- a/x-pack/plugins/actions/server/lib/task_runner_factory.ts +++ b/x-pack/plugins/actions/server/lib/task_runner_factory.ts @@ -72,6 +72,10 @@ export class TaskRunnerFactory { getUnsecuredSavedObjectsClient, } = this.taskRunnerContext!; + const taskInfo = { + scheduled: taskInstance.runAt, + }; + return { async run() { const { spaceId, actionTaskParamsId } = taskInstance.params as Record; @@ -118,6 +122,7 @@ export class TaskRunnerFactory { actionId, request: fakeRequest, ...getSourceFromReferences(references), + taskInfo, relatedSavedObjects: validatedRelatedSavedObjects(logger, relatedSavedObjects), }); } catch (e) { diff --git a/x-pack/plugins/alerting/server/task_runner/create_execution_handler.test.ts b/x-pack/plugins/alerting/server/task_runner/create_execution_handler.test.ts index 033ffcceb6a0a..1dcd19119b6fd 100644 --- a/x-pack/plugins/alerting/server/task_runner/create_execution_handler.test.ts +++ b/x-pack/plugins/alerting/server/task_runner/create_execution_handler.test.ts @@ -195,7 +195,6 @@ test('enqueues execution per selected action', async () => { "id": "1", "license": "basic", "name": "name-of-alert", - "namespace": "test1", "ruleset": "alerts", }, }, diff --git a/x-pack/plugins/alerting/server/task_runner/create_execution_handler.ts b/x-pack/plugins/alerting/server/task_runner/create_execution_handler.ts index 968fff540dc03..3004ed599128e 100644 --- a/x-pack/plugins/alerting/server/task_runner/create_execution_handler.ts +++ b/x-pack/plugins/alerting/server/task_runner/create_execution_handler.ts @@ -209,7 +209,6 @@ export function createExecutionHandler< license: alertType.minimumLicenseRequired, category: alertType.id, ruleset: alertType.producer, - ...namespace, name: alertName, }, }; diff --git a/x-pack/plugins/alerting/server/task_runner/task_runner.test.ts b/x-pack/plugins/alerting/server/task_runner/task_runner.test.ts index 8ab267a5610d3..88d1b1b24a4ec 100644 --- a/x-pack/plugins/alerting/server/task_runner/task_runner.test.ts +++ b/x-pack/plugins/alerting/server/task_runner/task_runner.test.ts @@ -282,13 +282,16 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "alert execution start: \\"1\\"", "rule": Object { "category": "test", "id": "1", "license": "basic", - "namespace": undefined, "ruleset": "alerts", }, } @@ -394,6 +397,10 @@ describe('Task Runner', () => { kind: 'alert', }, kibana: { + task: { + schedule_delay: 0, + scheduled: '1970-01-01T00:00:00.000Z', + }, saved_objects: [ { id: '1', @@ -409,7 +416,6 @@ describe('Task Runner', () => { category: 'test', id: '1', license: 'basic', - namespace: undefined, ruleset: 'alerts', }, }); @@ -518,6 +524,10 @@ describe('Task Runner', () => { alerting: { status: 'active', }, + task: { + schedule_delay: 0, + scheduled: '1970-01-01T00:00:00.000Z', + }, saved_objects: [ { id: '1', @@ -534,7 +544,6 @@ describe('Task Runner', () => { id: '1', license: 'basic', name: 'alert-name', - namespace: undefined, ruleset: 'alerts', }, }); @@ -603,6 +612,10 @@ describe('Task Runner', () => { kind: 'alert', }, kibana: { + task: { + schedule_delay: 0, + scheduled: '1970-01-01T00:00:00.000Z', + }, saved_objects: [ { id: '1', @@ -618,7 +631,6 @@ describe('Task Runner', () => { category: 'test', id: '1', license: 'basic', - namespace: undefined, ruleset: 'alerts', }, }); @@ -700,6 +712,10 @@ describe('Task Runner', () => { alerting: { status: 'active', }, + task: { + schedule_delay: 0, + scheduled: '1970-01-01T00:00:00.000Z', + }, saved_objects: [ { id: '1', @@ -716,7 +732,6 @@ describe('Task Runner', () => { id: '1', license: 'basic', name: 'alert-name', - namespace: undefined, ruleset: 'alerts', }, }); @@ -854,13 +869,16 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "alert execution start: \\"1\\"", "rule": Object { "category": "test", "id": "1", "license": "basic", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -897,7 +915,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -926,6 +943,10 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "alert executed: test:1: 'alert-name'", "rule": Object { @@ -933,7 +954,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -1151,13 +1171,16 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "alert execution start: \\"1\\"", "rule": Object { "category": "test", "id": "1", "license": "basic", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -1194,7 +1217,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -1231,7 +1253,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -1273,7 +1294,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -1302,6 +1322,10 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "alert executed: test:1: 'alert-name'", "rule": Object { @@ -1309,7 +1333,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -1433,13 +1456,16 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "alert execution start: \\"1\\"", "rule": Object { "category": "test", "id": "1", "license": "basic", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -1476,7 +1502,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -1513,7 +1538,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -1555,7 +1579,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -1597,7 +1620,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -1626,6 +1648,10 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "alert executed: test:1: 'alert-name'", "rule": Object { @@ -1633,7 +1659,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -1968,13 +1993,16 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "alert execution start: \\"1\\"", "rule": Object { "category": "test", "id": "1", "license": "basic", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -2012,7 +2040,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -2049,7 +2076,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -2078,6 +2104,10 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "alert executed: test:1: 'alert-name'", "rule": Object { @@ -2085,7 +2115,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -2294,13 +2323,16 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "alert execution start: \\"1\\"", "rule": Object { "category": "test", "id": "1", "license": "basic", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -2333,13 +2365,16 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "alert execution failure: test:1: 'alert-name'", "rule": Object { "category": "test", "id": "1", "license": "basic", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -2397,13 +2432,16 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "alert execution start: \\"1\\"", "rule": Object { "category": "test", "id": "1", "license": "basic", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -2436,13 +2474,16 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "test:1: execution failed", "rule": Object { "category": "test", "id": "1", "license": "basic", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -2508,13 +2549,16 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "alert execution start: \\"1\\"", "rule": Object { "category": "test", "id": "1", "license": "basic", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -2547,13 +2591,16 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "test:1: execution failed", "rule": Object { "category": "test", "id": "1", "license": "basic", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -2619,13 +2666,16 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "alert execution start: \\"1\\"", "rule": Object { "category": "test", "id": "1", "license": "basic", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -2658,13 +2708,16 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "test:1: execution failed", "rule": Object { "category": "test", "id": "1", "license": "basic", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -2729,13 +2782,16 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "alert execution start: \\"1\\"", "rule": Object { "category": "test", "id": "1", "license": "basic", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -2768,13 +2824,16 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "test:1: execution failed", "rule": Object { "category": "test", "id": "1", "license": "basic", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3007,13 +3066,16 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "alert execution start: \\"1\\"", "rule": Object { "category": "test", "id": "1", "license": "basic", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3050,7 +3112,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3087,7 +3148,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3124,7 +3184,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3161,7 +3220,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3190,6 +3248,10 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "alert executed: test:1: 'alert-name'", "rule": Object { @@ -3197,7 +3259,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3291,13 +3352,16 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "alert execution start: \\"1\\"", "rule": Object { "category": "test", "id": "1", "license": "basic", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3334,7 +3398,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3371,7 +3434,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3400,6 +3462,10 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "alert executed: test:1: 'alert-name'", "rule": Object { @@ -3407,7 +3473,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3493,13 +3558,16 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "alert execution start: \\"1\\"", "rule": Object { "category": "test", "id": "1", "license": "basic", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3534,7 +3602,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3569,7 +3636,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3598,6 +3664,10 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "alert executed: test:1: 'alert-name'", "rule": Object { @@ -3605,7 +3675,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3686,13 +3755,16 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "alert execution start: \\"1\\"", "rule": Object { "category": "test", "id": "1", "license": "basic", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3729,7 +3801,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3766,7 +3837,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3795,6 +3865,10 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "alert executed: test:1: 'alert-name'", "rule": Object { @@ -3802,7 +3876,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3885,13 +3958,16 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "alert execution start: \\"1\\"", "rule": Object { "category": "test", "id": "1", "license": "basic", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3925,7 +4001,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3959,7 +4034,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3988,6 +4062,10 @@ describe('Task Runner', () => { "type_id": "test", }, ], + "task": Object { + "schedule_delay": 0, + "scheduled": "1970-01-01T00:00:00.000Z", + }, }, "message": "alert executed: test:1: 'alert-name'", "rule": Object { @@ -3995,7 +4073,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, diff --git a/x-pack/plugins/alerting/server/task_runner/task_runner.ts b/x-pack/plugins/alerting/server/task_runner/task_runner.ts index b712b6237c8a7..c66c054bc8ac3 100644 --- a/x-pack/plugins/alerting/server/task_runner/task_runner.ts +++ b/x-pack/plugins/alerting/server/task_runner/task_runner.ts @@ -54,6 +54,9 @@ import { getEsErrorMessage } from '../lib/errors'; const FALLBACK_RETRY_INTERVAL = '5m'; +// 1,000,000 nanoseconds in 1 millisecond +const Millis2Nanos = 1000 * 1000; + type Event = Exclude; interface AlertTaskRunResult { @@ -489,15 +492,17 @@ export class TaskRunner< schedule: taskSchedule, } = this.taskInstance; - const runDate = new Date().toISOString(); - this.logger.debug(`executing alert ${this.alertType.id}:${alertId} at ${runDate}`); + const runDate = new Date(); + const runDateString = runDate.toISOString(); + this.logger.debug(`executing alert ${this.alertType.id}:${alertId} at ${runDateString}`); const namespace = this.context.spaceIdToNamespace(spaceId); const eventLogger = this.context.eventLogger; + const scheduleDelay = runDate.getTime() - this.taskInstance.runAt.getTime(); const event: IEvent = { // explicitly set execute timestamp so it will be before other events // generated here (new-instance, schedule-action, etc) - '@timestamp': runDate, + '@timestamp': runDateString, event: { action: EVENT_LOG_ACTIONS.execute, kind: 'alert', @@ -513,13 +518,16 @@ export class TaskRunner< namespace, }, ], + task: { + scheduled: this.taskInstance.runAt.toISOString(), + schedule_delay: Millis2Nanos * scheduleDelay, + }, }, rule: { id: alertId, license: this.alertType.minimumLicenseRequired, category: this.alertType.id, ruleset: this.alertType.producer, - namespace, }, }; @@ -814,7 +822,6 @@ function generateNewAndRecoveredInstanceEvents< license: ruleType.minimumLicenseRequired, category: ruleType.id, ruleset: ruleType.producer, - namespace, name: rule.name, }, }; diff --git a/x-pack/plugins/event_log/README.md b/x-pack/plugins/event_log/README.md index ffbd20dd6f2be..682bf2660c78b 100644 --- a/x-pack/plugins/event_log/README.md +++ b/x-pack/plugins/event_log/README.md @@ -127,6 +127,10 @@ Below is a document in the expected structure, with descriptions of the fields: // Custom fields that are not part of ECS. kibana: { server_uuid: "UUID of kibana server, for diagnosing multi-Kibana scenarios", + task: { + scheduled: "ISO date of when the task for this event was supposed to start", + schedule_delay: "delay in nanoseconds between when this task was supposed to start and when it actually started", + }, alerting: { instance_id: "alert instance id, for relevant documents", action_group_id: "alert action group, for relevant documents", diff --git a/x-pack/plugins/event_log/generated/mappings.json b/x-pack/plugins/event_log/generated/mappings.json index 3eadcc21257b0..0f5f4af2052ee 100644 --- a/x-pack/plugins/event_log/generated/mappings.json +++ b/x-pack/plugins/event_log/generated/mappings.json @@ -214,10 +214,6 @@ "version": { "ignore_above": 1024, "type": "keyword" - }, - "namespace": { - "ignore_above": 1024, - "type": "keyword" } } }, @@ -241,6 +237,16 @@ "type": "keyword", "ignore_above": 1024 }, + "task": { + "properties": { + "scheduled": { + "type": "date" + }, + "schedule_delay": { + "type": "long" + } + } + }, "alerting": { "properties": { "instance_id": { diff --git a/x-pack/plugins/event_log/generated/schemas.ts b/x-pack/plugins/event_log/generated/schemas.ts index 2a066ca0bd15b..556ddec5a7001 100644 --- a/x-pack/plugins/event_log/generated/schemas.ts +++ b/x-pack/plugins/event_log/generated/schemas.ts @@ -91,7 +91,6 @@ export const EventSchema = schema.maybe( ruleset: ecsString(), uuid: ecsString(), version: ecsString(), - namespace: ecsString(), }) ), user: schema.maybe( @@ -102,6 +101,12 @@ export const EventSchema = schema.maybe( kibana: schema.maybe( schema.object({ server_uuid: ecsString(), + task: schema.maybe( + schema.object({ + scheduled: ecsDate(), + schedule_delay: ecsNumber(), + }) + ), alerting: schema.maybe( schema.object({ instance_id: ecsString(), diff --git a/x-pack/plugins/event_log/scripts/mappings.js b/x-pack/plugins/event_log/scripts/mappings.js index f2020e76b46ba..93fe053bd0cdf 100644 --- a/x-pack/plugins/event_log/scripts/mappings.js +++ b/x-pack/plugins/event_log/scripts/mappings.js @@ -17,6 +17,17 @@ exports.EcsCustomPropertyMappings = { type: 'keyword', ignore_above: 1024, }, + // task specific fields + task: { + properties: { + scheduled: { + type: 'date', + }, + schedule_delay: { + type: 'long', + }, + }, + }, // alerting specific fields alerting: { properties: { diff --git a/x-pack/plugins/event_log/server/event_logger.ts b/x-pack/plugins/event_log/server/event_logger.ts index 4af69de0f47a0..b985a173ccdbf 100644 --- a/x-pack/plugins/event_log/server/event_logger.ts +++ b/x-pack/plugins/event_log/server/event_logger.ts @@ -88,7 +88,7 @@ export class EventLogger implements IEventLogger { try { validatedEvent = validateEvent(this.eventLogService, event); } catch (err) { - this.systemLogger.warn(`invalid event logged: ${err.message}`); + this.systemLogger.warn(`invalid event logged: ${err.message}; ${JSON.stringify(event)})`); return; } diff --git a/x-pack/test/alerting_api_integration/security_and_spaces/tests/alerting/alerts.ts b/x-pack/test/alerting_api_integration/security_and_spaces/tests/alerting/alerts.ts index e9ed14fbcddcd..b3d83ae22f330 100644 --- a/x-pack/test/alerting_api_integration/security_and_spaces/tests/alerting/alerts.ts +++ b/x-pack/test/alerting_api_integration/security_and_spaces/tests/alerting/alerts.ts @@ -1304,7 +1304,6 @@ instanceStateValue: true license: 'basic', category: ruleObject.alertInfo.ruleTypeId, ruleset: ruleObject.alertInfo.producer, - namespace: spaceId, name: ruleObject.alertInfo.name, }); diff --git a/x-pack/test/alerting_api_integration/security_and_spaces/tests/alerting/event_log.ts b/x-pack/test/alerting_api_integration/security_and_spaces/tests/alerting/event_log.ts index 5d13d641367a4..940203a9b1f8c 100644 --- a/x-pack/test/alerting_api_integration/security_and_spaces/tests/alerting/event_log.ts +++ b/x-pack/test/alerting_api_integration/security_and_spaces/tests/alerting/event_log.ts @@ -81,12 +81,12 @@ export default function eventLogTests({ getService }: FtrProviderContext) { errorMessage: 'Unable to decrypt attribute "apiKey"', status: 'error', reason: 'decrypt', + shouldHaveTask: true, rule: { id: alertId, category: response.body.rule_type_id, license: 'basic', ruleset: 'alertsFixture', - namespace: spaceId, }, }); }); diff --git a/x-pack/test/alerting_api_integration/spaces_only/tests/actions/execute.ts b/x-pack/test/alerting_api_integration/spaces_only/tests/actions/execute.ts index d494c99c80e8f..38f3a17f317c2 100644 --- a/x-pack/test/alerting_api_integration/spaces_only/tests/actions/execute.ts +++ b/x-pack/test/alerting_api_integration/spaces_only/tests/actions/execute.ts @@ -406,6 +406,8 @@ export default function ({ getService }: FtrProviderContext) { expect(startExecuteEvent?.message).to.eql(startMessage); } + expect(executeEvent?.kibana?.task).to.eql(undefined); + if (errorMessage) { expect(executeEvent?.error?.message).to.eql(errorMessage); } diff --git a/x-pack/test/alerting_api_integration/spaces_only/tests/alerting/event_log.ts b/x-pack/test/alerting_api_integration/spaces_only/tests/alerting/event_log.ts index fae5958d7827a..9bf7baf95d8d2 100644 --- a/x-pack/test/alerting_api_integration/spaces_only/tests/alerting/event_log.ts +++ b/x-pack/test/alerting_api_integration/spaces_only/tests/alerting/event_log.ts @@ -24,476 +24,512 @@ export default function eventLogTests({ getService }: FtrProviderContext) { after(() => objectRemover.removeAll()); - it('should generate expected events for normal operation', async () => { - const { body: createdAction } = await supertest - .post(`${getUrlPrefix(Spaces.space1.id)}/api/actions/connector`) - .set('kbn-xsrf', 'foo') - .send({ - name: 'MY action', - connector_type_id: 'test.noop', - config: {}, - secrets: {}, - }) - .expect(200); - - // pattern of when the alert should fire - const pattern = { - instance: [false, true, true], - }; - - const response = await supertest - .post(`${getUrlPrefix(Spaces.space1.id)}/api/alerting/rule`) - .set('kbn-xsrf', 'foo') - .send( - getTestAlertData({ - rule_type_id: 'test.patternFiring', - schedule: { interval: '1s' }, - throttle: null, - params: { - pattern, - }, - actions: [ - { - id: createdAction.id, - group: 'default', - params: {}, - }, - ], - }) - ); - - expect(response.status).to.eql(200); - const alertId = response.body.id; - objectRemover.add(Spaces.space1.id, alertId, 'rule', 'alerting'); - - // get the events we're expecting - const events = await retry.try(async () => { - return await getEventLog({ - getService, - spaceId: Spaces.space1.id, - type: 'alert', - id: alertId, - provider: 'alerting', - actions: new Map([ - // make sure the counts of the # of events per type are as expected - ['execute-start', { gte: 4 }], - ['execute', { gte: 4 }], - ['execute-action', { equal: 2 }], - ['new-instance', { equal: 1 }], - ['active-instance', { gte: 1 }], - ['recovered-instance', { equal: 1 }], - ]), - }); - }); - - // get the filtered events only with action 'new-instance' - const filteredEvents = await retry.try(async () => { - return await getEventLog({ - getService, - spaceId: Spaces.space1.id, - type: 'alert', - id: alertId, - provider: 'alerting', - actions: new Map([['new-instance', { equal: 1 }]]), - filter: 'event.action:(new-instance)', - }); - }); + for (const space of [Spaces.default, Spaces.space1]) { + describe(`in space ${space.id}`, () => { + it('should generate expected events for normal operation', async () => { + const { body: createdAction } = await supertest + .post(`${getUrlPrefix(space.id)}/api/actions/connector`) + .set('kbn-xsrf', 'foo') + .send({ + name: 'MY action', + connector_type_id: 'test.noop', + config: {}, + secrets: {}, + }) + .expect(200); + + // pattern of when the alert should fire + const pattern = { + instance: [false, true, true], + }; + + const response = await supertest + .post(`${getUrlPrefix(space.id)}/api/alerting/rule`) + .set('kbn-xsrf', 'foo') + .send( + getTestAlertData({ + rule_type_id: 'test.patternFiring', + schedule: { interval: '1s' }, + throttle: null, + params: { + pattern, + }, + actions: [ + { + id: createdAction.id, + group: 'default', + params: {}, + }, + ], + }) + ); - expect(getEventsByAction(filteredEvents, 'execute').length).equal(0); - expect(getEventsByAction(filteredEvents, 'execute-action').length).equal(0); - expect(getEventsByAction(events, 'new-instance').length).equal(1); - - const executeEvents = getEventsByAction(events, 'execute'); - const executeStartEvents = getEventsByAction(events, 'execute-start'); - const executeActionEvents = getEventsByAction(events, 'execute-action'); - const newInstanceEvents = getEventsByAction(events, 'new-instance'); - const recoveredInstanceEvents = getEventsByAction(events, 'recovered-instance'); - - // make sure the events are in the right temporal order - const executeTimes = getTimestamps(executeEvents); - const executeStartTimes = getTimestamps(executeStartEvents); - const executeActionTimes = getTimestamps(executeActionEvents); - const newInstanceTimes = getTimestamps(newInstanceEvents); - const recoveredInstanceTimes = getTimestamps(recoveredInstanceEvents); - - expect(executeTimes[0] < newInstanceTimes[0]).to.be(true); - expect(executeTimes[1] <= newInstanceTimes[0]).to.be(true); - expect(executeTimes[2] > newInstanceTimes[0]).to.be(true); - expect(executeTimes[1] <= executeActionTimes[0]).to.be(true); - expect(executeTimes[2] > executeActionTimes[0]).to.be(true); - expect(executeStartTimes.length === executeTimes.length).to.be(true); - executeStartTimes.forEach((est, index) => expect(est === executeTimes[index]).to.be(true)); - expect(recoveredInstanceTimes[0] > newInstanceTimes[0]).to.be(true); - - // validate each event - let executeCount = 0; - const executeStatuses = ['ok', 'active', 'active']; - for (const event of events) { - switch (event?.event?.action) { - case 'execute-start': - validateEvent(event, { - spaceId: Spaces.space1.id, - savedObjects: [ - { type: 'alert', id: alertId, rel: 'primary', type_id: 'test.patternFiring' }, - ], - message: `alert execution start: "${alertId}"`, - rule: { - id: alertId, - category: response.body.rule_type_id, - license: 'basic', - ruleset: 'alertsFixture', - namespace: Spaces.space1.id, - }, + expect(response.status).to.eql(200); + const alertId = response.body.id; + objectRemover.add(space.id, alertId, 'rule', 'alerting'); + + // get the events we're expecting + const events = await retry.try(async () => { + return await getEventLog({ + getService, + spaceId: space.id, + type: 'alert', + id: alertId, + provider: 'alerting', + actions: new Map([ + // make sure the counts of the # of events per type are as expected + ['execute-start', { gte: 4 }], + ['execute', { gte: 4 }], + ['execute-action', { equal: 2 }], + ['new-instance', { equal: 1 }], + ['active-instance', { gte: 1 }], + ['recovered-instance', { equal: 1 }], + ]), }); - break; - case 'execute': - validateEvent(event, { - spaceId: Spaces.space1.id, - savedObjects: [ - { type: 'alert', id: alertId, rel: 'primary', type_id: 'test.patternFiring' }, - ], - outcome: 'success', - message: `alert executed: test.patternFiring:${alertId}: 'abc'`, - status: executeStatuses[executeCount++], - rule: { - id: alertId, - category: response.body.rule_type_id, - license: 'basic', - ruleset: 'alertsFixture', - namespace: Spaces.space1.id, - name: response.body.name, - }, + }); + + // get the filtered events only with action 'new-instance' + const filteredEvents = await retry.try(async () => { + return await getEventLog({ + getService, + spaceId: space.id, + type: 'alert', + id: alertId, + provider: 'alerting', + actions: new Map([['new-instance', { equal: 1 }]]), + filter: 'event.action:(new-instance)', }); - break; - case 'execute-action': + }); + + expect(getEventsByAction(filteredEvents, 'execute').length).equal(0); + expect(getEventsByAction(filteredEvents, 'execute-action').length).equal(0); + expect(getEventsByAction(events, 'new-instance').length).equal(1); + + const executeEvents = getEventsByAction(events, 'execute'); + const executeStartEvents = getEventsByAction(events, 'execute-start'); + const executeActionEvents = getEventsByAction(events, 'execute-action'); + const newInstanceEvents = getEventsByAction(events, 'new-instance'); + const recoveredInstanceEvents = getEventsByAction(events, 'recovered-instance'); + + // make sure the events are in the right temporal order + const executeTimes = getTimestamps(executeEvents); + const executeStartTimes = getTimestamps(executeStartEvents); + const executeActionTimes = getTimestamps(executeActionEvents); + const newInstanceTimes = getTimestamps(newInstanceEvents); + const recoveredInstanceTimes = getTimestamps(recoveredInstanceEvents); + + expect(executeTimes[0] < newInstanceTimes[0]).to.be(true); + expect(executeTimes[1] <= newInstanceTimes[0]).to.be(true); + expect(executeTimes[2] > newInstanceTimes[0]).to.be(true); + expect(executeTimes[1] <= executeActionTimes[0]).to.be(true); + expect(executeTimes[2] > executeActionTimes[0]).to.be(true); + expect(executeStartTimes.length === executeTimes.length).to.be(true); + executeStartTimes.forEach((est, index) => + expect(est === executeTimes[index]).to.be(true) + ); + expect(recoveredInstanceTimes[0] > newInstanceTimes[0]).to.be(true); + + // validate each event + let executeCount = 0; + const executeStatuses = ['ok', 'active', 'active']; + for (const event of events) { + switch (event?.event?.action) { + case 'execute-start': + validateEvent(event, { + spaceId: space.id, + savedObjects: [ + { type: 'alert', id: alertId, rel: 'primary', type_id: 'test.patternFiring' }, + ], + message: `alert execution start: "${alertId}"`, + shouldHaveTask: true, + rule: { + id: alertId, + category: response.body.rule_type_id, + license: 'basic', + ruleset: 'alertsFixture', + }, + }); + break; + case 'execute': + validateEvent(event, { + spaceId: space.id, + savedObjects: [ + { type: 'alert', id: alertId, rel: 'primary', type_id: 'test.patternFiring' }, + ], + outcome: 'success', + message: `alert executed: test.patternFiring:${alertId}: 'abc'`, + status: executeStatuses[executeCount++], + shouldHaveTask: true, + rule: { + id: alertId, + category: response.body.rule_type_id, + license: 'basic', + ruleset: 'alertsFixture', + name: response.body.name, + }, + }); + break; + case 'execute-action': + validateEvent(event, { + spaceId: space.id, + savedObjects: [ + { type: 'alert', id: alertId, rel: 'primary', type_id: 'test.patternFiring' }, + { type: 'action', id: createdAction.id, type_id: 'test.noop' }, + ], + message: `alert: test.patternFiring:${alertId}: 'abc' instanceId: 'instance' scheduled actionGroup: 'default' action: test.noop:${createdAction.id}`, + instanceId: 'instance', + actionGroupId: 'default', + rule: { + id: alertId, + category: response.body.rule_type_id, + license: 'basic', + ruleset: 'alertsFixture', + name: response.body.name, + }, + }); + break; + case 'new-instance': + validateInstanceEvent(event, `created new instance: 'instance'`, false); + break; + case 'recovered-instance': + validateInstanceEvent(event, `instance 'instance' has recovered`, true); + break; + case 'active-instance': + validateInstanceEvent( + event, + `active instance: 'instance' in actionGroup: 'default'`, + false + ); + break; + // this will get triggered as we add new event actions + default: + throw new Error(`unexpected event action "${event?.event?.action}"`); + } + } + + const actionEvents = await retry.try(async () => { + return await getEventLog({ + getService, + spaceId: space.id, + type: 'action', + id: createdAction.id, + provider: 'actions', + actions: new Map([['execute', { gte: 1 }]]), + }); + }); + + for (const event of actionEvents) { + switch (event?.event?.action) { + case 'execute': + validateEvent(event, { + spaceId: space.id, + savedObjects: [ + { type: 'action', id: createdAction.id, rel: 'primary', type_id: 'test.noop' }, + ], + message: `action executed: test.noop:${createdAction.id}: MY action`, + outcome: 'success', + shouldHaveTask: true, + rule: undefined, + }); + break; + } + } + + function validateInstanceEvent( + event: IValidatedEvent, + subMessage: string, + shouldHaveEventEnd: boolean + ) { validateEvent(event, { - spaceId: Spaces.space1.id, + spaceId: space.id, savedObjects: [ { type: 'alert', id: alertId, rel: 'primary', type_id: 'test.patternFiring' }, - { type: 'action', id: createdAction.id, type_id: 'test.noop' }, ], - message: `alert: test.patternFiring:${alertId}: 'abc' instanceId: 'instance' scheduled actionGroup: 'default' action: test.noop:${createdAction.id}`, + message: `test.patternFiring:${alertId}: 'abc' ${subMessage}`, instanceId: 'instance', actionGroupId: 'default', + shouldHaveEventEnd, rule: { id: alertId, category: response.body.rule_type_id, license: 'basic', ruleset: 'alertsFixture', - namespace: Spaces.space1.id, name: response.body.name, }, }); - break; - case 'new-instance': - validateInstanceEvent(event, `created new instance: 'instance'`, false); - break; - case 'recovered-instance': - validateInstanceEvent(event, `instance 'instance' has recovered`, true); - break; - case 'active-instance': - validateInstanceEvent( - event, - `active instance: 'instance' in actionGroup: 'default'`, - false - ); - break; - // this will get triggered as we add new event actions - default: - throw new Error(`unexpected event action "${event?.event?.action}"`); - } - } - - function validateInstanceEvent( - event: IValidatedEvent, - subMessage: string, - shouldHaveEventEnd: boolean - ) { - validateEvent(event, { - spaceId: Spaces.space1.id, - savedObjects: [ - { type: 'alert', id: alertId, rel: 'primary', type_id: 'test.patternFiring' }, - ], - message: `test.patternFiring:${alertId}: 'abc' ${subMessage}`, - instanceId: 'instance', - actionGroupId: 'default', - shouldHaveEventEnd, - rule: { - id: alertId, - category: response.body.rule_type_id, - license: 'basic', - ruleset: 'alertsFixture', - namespace: Spaces.space1.id, - name: response.body.name, - }, + } }); - } - }); - - it('should generate expected events for normal operation with subgroups', async () => { - const { body: createdAction } = await supertest - .post(`${getUrlPrefix(Spaces.space1.id)}/api/actions/connector`) - .set('kbn-xsrf', 'foo') - .send({ - name: 'MY action', - connector_type_id: 'test.noop', - config: {}, - secrets: {}, - }) - .expect(200); - - // pattern of when the alert should fire - const [firstSubgroup, secondSubgroup] = [uuid.v4(), uuid.v4()]; - const pattern = { - instance: [false, firstSubgroup, secondSubgroup], - }; - - const response = await supertest - .post(`${getUrlPrefix(Spaces.space1.id)}/api/alerting/rule`) - .set('kbn-xsrf', 'foo') - .send( - getTestAlertData({ - rule_type_id: 'test.patternFiring', - schedule: { interval: '1s' }, - throttle: null, - params: { - pattern, - }, - actions: [ - { - id: createdAction.id, - group: 'default', - params: {}, - }, - ], - }) - ); - - expect(response.status).to.eql(200); - const alertId = response.body.id; - objectRemover.add(Spaces.space1.id, alertId, 'rule', 'alerting'); - - // get the events we're expecting - const events = await retry.try(async () => { - return await getEventLog({ - getService, - spaceId: Spaces.space1.id, - type: 'alert', - id: alertId, - provider: 'alerting', - actions: new Map([ - // make sure the counts of the # of events per type are as expected - ['execute-start', { gte: 4 }], - ['execute', { gte: 4 }], - ['execute-action', { equal: 2 }], - ['new-instance', { equal: 1 }], - ['active-instance', { gte: 2 }], - ['recovered-instance', { equal: 1 }], - ]), - }); - }); - const executeEvents = getEventsByAction(events, 'execute'); - const executeStartEvents = getEventsByAction(events, 'execute-start'); - const executeActionEvents = getEventsByAction(events, 'execute-action'); - const newInstanceEvents = getEventsByAction(events, 'new-instance'); - const recoveredInstanceEvents = getEventsByAction(events, 'recovered-instance'); - - // make sure the events are in the right temporal order - const executeTimes = getTimestamps(executeEvents); - const executeStartTimes = getTimestamps(executeStartEvents); - const executeActionTimes = getTimestamps(executeActionEvents); - const newInstanceTimes = getTimestamps(newInstanceEvents); - const recoveredInstanceTimes = getTimestamps(recoveredInstanceEvents); - - expect(executeTimes[0] < newInstanceTimes[0]).to.be(true); - expect(executeTimes[1] <= newInstanceTimes[0]).to.be(true); - expect(executeTimes[2] > newInstanceTimes[0]).to.be(true); - expect(executeTimes[1] <= executeActionTimes[0]).to.be(true); - expect(executeTimes[2] > executeActionTimes[0]).to.be(true); - expect(executeStartTimes.length === executeTimes.length).to.be(true); - executeStartTimes.forEach((est, index) => expect(est === executeTimes[index]).to.be(true)); - expect(recoveredInstanceTimes[0] > newInstanceTimes[0]).to.be(true); - - // validate each event - let executeCount = 0; - const executeStatuses = ['ok', 'active', 'active']; - for (const event of events) { - switch (event?.event?.action) { - case 'execute-start': - validateEvent(event, { - spaceId: Spaces.space1.id, - savedObjects: [ - { type: 'alert', id: alertId, rel: 'primary', type_id: 'test.patternFiring' }, - ], - message: `alert execution start: "${alertId}"`, - rule: { - id: alertId, - category: response.body.rule_type_id, - license: 'basic', - ruleset: 'alertsFixture', - namespace: Spaces.space1.id, - }, - }); - break; - case 'execute': - validateEvent(event, { - spaceId: Spaces.space1.id, - savedObjects: [ - { type: 'alert', id: alertId, rel: 'primary', type_id: 'test.patternFiring' }, - ], - outcome: 'success', - message: `alert executed: test.patternFiring:${alertId}: 'abc'`, - status: executeStatuses[executeCount++], - rule: { - id: alertId, - category: response.body.rule_type_id, - license: 'basic', - ruleset: 'alertsFixture', - namespace: Spaces.space1.id, - name: response.body.name, - }, + it('should generate expected events for normal operation with subgroups', async () => { + const { body: createdAction } = await supertest + .post(`${getUrlPrefix(space.id)}/api/actions/connector`) + .set('kbn-xsrf', 'foo') + .send({ + name: 'MY action', + connector_type_id: 'test.noop', + config: {}, + secrets: {}, + }) + .expect(200); + + // pattern of when the alert should fire + const [firstSubgroup, secondSubgroup] = [uuid.v4(), uuid.v4()]; + const pattern = { + instance: [false, firstSubgroup, secondSubgroup], + }; + + const response = await supertest + .post(`${getUrlPrefix(space.id)}/api/alerting/rule`) + .set('kbn-xsrf', 'foo') + .send( + getTestAlertData({ + rule_type_id: 'test.patternFiring', + schedule: { interval: '1s' }, + throttle: null, + params: { + pattern, + }, + actions: [ + { + id: createdAction.id, + group: 'default', + params: {}, + }, + ], + }) + ); + + expect(response.status).to.eql(200); + const alertId = response.body.id; + objectRemover.add(space.id, alertId, 'rule', 'alerting'); + + // get the events we're expecting + const events = await retry.try(async () => { + return await getEventLog({ + getService, + spaceId: space.id, + type: 'alert', + id: alertId, + provider: 'alerting', + actions: new Map([ + // make sure the counts of the # of events per type are as expected + ['execute-start', { gte: 4 }], + ['execute', { gte: 4 }], + ['execute-action', { equal: 2 }], + ['new-instance', { equal: 1 }], + ['active-instance', { gte: 2 }], + ['recovered-instance', { equal: 1 }], + ]), }); - break; - case 'execute-action': - expect( - [firstSubgroup, secondSubgroup].includes(event?.kibana?.alerting?.action_subgroup!) - ).to.be(true); + }); + + const executeEvents = getEventsByAction(events, 'execute'); + const executeStartEvents = getEventsByAction(events, 'execute-start'); + const executeActionEvents = getEventsByAction(events, 'execute-action'); + const newInstanceEvents = getEventsByAction(events, 'new-instance'); + const recoveredInstanceEvents = getEventsByAction(events, 'recovered-instance'); + + // make sure the events are in the right temporal order + const executeTimes = getTimestamps(executeEvents); + const executeStartTimes = getTimestamps(executeStartEvents); + const executeActionTimes = getTimestamps(executeActionEvents); + const newInstanceTimes = getTimestamps(newInstanceEvents); + const recoveredInstanceTimes = getTimestamps(recoveredInstanceEvents); + + expect(executeTimes[0] < newInstanceTimes[0]).to.be(true); + expect(executeTimes[1] <= newInstanceTimes[0]).to.be(true); + expect(executeTimes[2] > newInstanceTimes[0]).to.be(true); + expect(executeTimes[1] <= executeActionTimes[0]).to.be(true); + expect(executeTimes[2] > executeActionTimes[0]).to.be(true); + expect(executeStartTimes.length === executeTimes.length).to.be(true); + executeStartTimes.forEach((est, index) => + expect(est === executeTimes[index]).to.be(true) + ); + expect(recoveredInstanceTimes[0] > newInstanceTimes[0]).to.be(true); + + // validate each event + let executeCount = 0; + const executeStatuses = ['ok', 'active', 'active']; + for (const event of events) { + switch (event?.event?.action) { + case 'execute-start': + validateEvent(event, { + spaceId: space.id, + savedObjects: [ + { type: 'alert', id: alertId, rel: 'primary', type_id: 'test.patternFiring' }, + ], + message: `alert execution start: "${alertId}"`, + shouldHaveTask: true, + rule: { + id: alertId, + category: response.body.rule_type_id, + license: 'basic', + ruleset: 'alertsFixture', + }, + }); + break; + case 'execute': + validateEvent(event, { + spaceId: space.id, + savedObjects: [ + { type: 'alert', id: alertId, rel: 'primary', type_id: 'test.patternFiring' }, + ], + outcome: 'success', + message: `alert executed: test.patternFiring:${alertId}: 'abc'`, + status: executeStatuses[executeCount++], + shouldHaveTask: true, + rule: { + id: alertId, + category: response.body.rule_type_id, + license: 'basic', + ruleset: 'alertsFixture', + name: response.body.name, + }, + }); + break; + case 'execute-action': + expect( + [firstSubgroup, secondSubgroup].includes( + event?.kibana?.alerting?.action_subgroup! + ) + ).to.be(true); + validateEvent(event, { + spaceId: space.id, + savedObjects: [ + { type: 'alert', id: alertId, rel: 'primary', type_id: 'test.patternFiring' }, + { type: 'action', id: createdAction.id, type_id: 'test.noop' }, + ], + message: `alert: test.patternFiring:${alertId}: 'abc' instanceId: 'instance' scheduled actionGroup(subgroup): 'default(${event?.kibana?.alerting?.action_subgroup})' action: test.noop:${createdAction.id}`, + instanceId: 'instance', + actionGroupId: 'default', + rule: { + id: alertId, + category: response.body.rule_type_id, + license: 'basic', + ruleset: 'alertsFixture', + name: response.body.name, + }, + }); + break; + case 'new-instance': + validateInstanceEvent(event, `created new instance: 'instance'`, false); + break; + case 'recovered-instance': + validateInstanceEvent(event, `instance 'instance' has recovered`, true); + break; + case 'active-instance': + expect( + [firstSubgroup, secondSubgroup].includes( + event?.kibana?.alerting?.action_subgroup! + ) + ).to.be(true); + validateInstanceEvent( + event, + `active instance: 'instance' in actionGroup(subgroup): 'default(${event?.kibana?.alerting?.action_subgroup})'`, + false + ); + break; + // this will get triggered as we add new event actions + default: + throw new Error(`unexpected event action "${event?.event?.action}"`); + } + } + + function validateInstanceEvent( + event: IValidatedEvent, + subMessage: string, + shouldHaveEventEnd: boolean + ) { validateEvent(event, { - spaceId: Spaces.space1.id, + spaceId: space.id, savedObjects: [ { type: 'alert', id: alertId, rel: 'primary', type_id: 'test.patternFiring' }, - { type: 'action', id: createdAction.id, type_id: 'test.noop' }, ], - message: `alert: test.patternFiring:${alertId}: 'abc' instanceId: 'instance' scheduled actionGroup(subgroup): 'default(${event?.kibana?.alerting?.action_subgroup})' action: test.noop:${createdAction.id}`, + message: `test.patternFiring:${alertId}: 'abc' ${subMessage}`, instanceId: 'instance', actionGroupId: 'default', + shouldHaveEventEnd, rule: { id: alertId, category: response.body.rule_type_id, license: 'basic', ruleset: 'alertsFixture', - namespace: Spaces.space1.id, name: response.body.name, }, }); - break; - case 'new-instance': - validateInstanceEvent(event, `created new instance: 'instance'`, false); - break; - case 'recovered-instance': - validateInstanceEvent(event, `instance 'instance' has recovered`, true); - break; - case 'active-instance': - expect( - [firstSubgroup, secondSubgroup].includes(event?.kibana?.alerting?.action_subgroup!) - ).to.be(true); - validateInstanceEvent( - event, - `active instance: 'instance' in actionGroup(subgroup): 'default(${event?.kibana?.alerting?.action_subgroup})'`, - false - ); - break; - // this will get triggered as we add new event actions - default: - throw new Error(`unexpected event action "${event?.event?.action}"`); - } - } - - function validateInstanceEvent( - event: IValidatedEvent, - subMessage: string, - shouldHaveEventEnd: boolean - ) { - validateEvent(event, { - spaceId: Spaces.space1.id, - savedObjects: [ - { type: 'alert', id: alertId, rel: 'primary', type_id: 'test.patternFiring' }, - ], - message: `test.patternFiring:${alertId}: 'abc' ${subMessage}`, - instanceId: 'instance', - actionGroupId: 'default', - shouldHaveEventEnd, - rule: { - id: alertId, - category: response.body.rule_type_id, - license: 'basic', - ruleset: 'alertsFixture', - namespace: Spaces.space1.id, - name: response.body.name, - }, - }); - } - }); - - it('should generate events for execution errors', async () => { - const response = await supertest - .post(`${getUrlPrefix(Spaces.space1.id)}/api/alerting/rule`) - .set('kbn-xsrf', 'foo') - .send( - getTestAlertData({ - rule_type_id: 'test.throw', - schedule: { interval: '1s' }, - throttle: null, - }) - ); - - expect(response.status).to.eql(200); - const alertId = response.body.id; - objectRemover.add(Spaces.space1.id, alertId, 'rule', 'alerting'); - - const events = await retry.try(async () => { - return await getEventLog({ - getService, - spaceId: Spaces.space1.id, - type: 'alert', - id: alertId, - provider: 'alerting', - actions: new Map([ - ['execute-start', { gte: 1 }], - ['execute', { gte: 1 }], - ]), + } }); - }); - const startEvent = events[0]; - const executeEvent = events[1]; - - expect(startEvent).to.be.ok(); - expect(executeEvent).to.be.ok(); - - validateEvent(startEvent, { - spaceId: Spaces.space1.id, - savedObjects: [ - { type: 'alert', id: alertId, rel: 'primary', type_id: 'test.patternFiring' }, - ], - message: `alert execution start: "${alertId}"`, - rule: { - id: alertId, - category: response.body.rule_type_id, - license: 'basic', - ruleset: 'alertsFixture', - namespace: Spaces.space1.id, - }, - }); + it('should generate events for execution errors', async () => { + const response = await supertest + .post(`${getUrlPrefix(space.id)}/api/alerting/rule`) + .set('kbn-xsrf', 'foo') + .send( + getTestAlertData({ + rule_type_id: 'test.throw', + schedule: { interval: '1s' }, + throttle: null, + }) + ); + + expect(response.status).to.eql(200); + const alertId = response.body.id; + objectRemover.add(space.id, alertId, 'rule', 'alerting'); + + const events = await retry.try(async () => { + return await getEventLog({ + getService, + spaceId: space.id, + type: 'alert', + id: alertId, + provider: 'alerting', + actions: new Map([ + ['execute-start', { gte: 1 }], + ['execute', { gte: 1 }], + ]), + }); + }); - validateEvent(executeEvent, { - spaceId: Spaces.space1.id, - savedObjects: [{ type: 'alert', id: alertId, rel: 'primary', type_id: 'test.throw' }], - outcome: 'failure', - message: `alert execution failure: test.throw:${alertId}: 'abc'`, - errorMessage: 'this alert is intended to fail', - status: 'error', - reason: 'execute', - rule: { - id: alertId, - category: response.body.rule_type_id, - license: 'basic', - ruleset: 'alertsFixture', - namespace: Spaces.space1.id, - }, + const startEvent = events[0]; + const executeEvent = events[1]; + + expect(startEvent).to.be.ok(); + expect(executeEvent).to.be.ok(); + + validateEvent(startEvent, { + spaceId: space.id, + savedObjects: [ + { type: 'alert', id: alertId, rel: 'primary', type_id: 'test.patternFiring' }, + ], + message: `alert execution start: "${alertId}"`, + shouldHaveTask: true, + rule: { + id: alertId, + category: response.body.rule_type_id, + license: 'basic', + ruleset: 'alertsFixture', + }, + }); + + validateEvent(executeEvent, { + spaceId: space.id, + savedObjects: [{ type: 'alert', id: alertId, rel: 'primary', type_id: 'test.throw' }], + outcome: 'failure', + message: `alert execution failure: test.throw:${alertId}: 'abc'`, + errorMessage: 'this alert is intended to fail', + status: 'error', + reason: 'execute', + shouldHaveTask: true, + rule: { + id: alertId, + category: response.body.rule_type_id, + license: 'basic', + ruleset: 'alertsFixture', + }, + }); + }); }); - }); + } }); } @@ -510,12 +546,13 @@ interface ValidateEventLogParams { outcome?: string; message: string; shouldHaveEventEnd?: boolean; + shouldHaveTask?: boolean; errorMessage?: string; status?: string; actionGroupId?: string; instanceId?: string; reason?: string; - rule: { + rule?: { id: string; name?: string; version?: string; @@ -529,7 +566,7 @@ interface ValidateEventLogParams { } export function validateEvent(event: IValidatedEvent, params: ValidateEventLogParams): void { - const { spaceId, savedObjects, outcome, message, errorMessage, rule } = params; + const { spaceId, savedObjects, outcome, message, errorMessage, rule, shouldHaveTask } = params; const { status, actionGroupId, instanceId, reason, shouldHaveEventEnd } = params; if (status) { @@ -587,6 +624,16 @@ export function validateEvent(event: IValidatedEvent, params: ValidateEventLogPa expect(event?.rule).to.eql(rule); + if (shouldHaveTask) { + const task = event?.kibana?.task; + expect(task).to.be.ok(); + expect(typeof Date.parse(typeof task?.scheduled)).to.be('number'); + expect(typeof task?.schedule_delay).to.be('number'); + expect(task?.schedule_delay).to.be.greaterThan(-1); + } else { + expect(event?.kibana?.task).to.be(undefined); + } + if (errorMessage) { expect(event?.error?.message).to.eql(errorMessage); } @@ -602,12 +649,13 @@ function getTimestamps(events: IValidatedEvent[]) { function isSavedObjectInEvent( event: IValidatedEvent, - namespace: string, + spaceId: string, type: string, id: string, rel?: string ): boolean { const savedObjects = event?.kibana?.saved_objects ?? []; + const namespace = spaceId === 'default' ? undefined : spaceId; for (const savedObject of savedObjects) { if (