From bb77fa6967d5a4f0817b1df951411da99edfcf8d Mon Sep 17 00:00:00 2001 From: Patrick Mueller Date: Tue, 22 Jun 2021 20:57:26 -0400 Subject: [PATCH] [alerting][actions] add task scheduled date and delay to event log (#102252) 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(), }) ), --- .../server/lib/action_executor.test.ts | 71 ++ .../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, 772 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 37d461d6b2a501..188a9a0b9e08a9 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,77 @@ 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", + "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 e9e7b17288611b..9e62b123951df4 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 2292994e3ccfde..495d638951b56d 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 0515963ab82f4e..64169de728f75a 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 033ffcceb6a0ae..1dcd19119b6fd8 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 968fff540dc030..3004ed599128e5 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 8ab267a5610d3b..88d1b1b24a4ec9 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 b712b6237c8a7c..c66c054bc8ac3a 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 ffbd20dd6f2bec..682bf2660c78be 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 3eadcc21257b08..0f5f4af2052eef 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 2a066ca0bd15bc..556ddec5a7001a 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 f2020e76b46baa..93fe053bd0cdf4 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 4af69de0f47a03..b985a173ccdbf6 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 e9ed14fbcddcd7..b3d83ae22f3304 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 5d13d641367a4c..940203a9b1f8c5 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 d494c99c80e8f9..1fa138149f29c1 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(event?.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 fae5958d7827ab..9bf7baf95d8d24 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 (