From 6e368f1df778c7dc2e1af279462864a5728b432d Mon Sep 17 00:00:00 2001 From: Patrick Mueller Date: Tue, 15 Jun 2021 13:39:50 -0400 Subject: [PATCH 1/3] [alerting][actions] add task scheduled date and delay to event log 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 | 74 +- .../actions/server/lib/action_executor.ts | 19 + .../server/lib/task_runner_factory.test.ts | 9 + .../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 | 10 +- 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, 764 insertions(+), 503 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 8ec94c4d4a552..e204fa0b9c065 100644 --- a/x-pack/plugins/actions/server/lib/action_executor.test.ts +++ b/x-pack/plugins/actions/server/lib/action_executor.test.ts @@ -23,6 +23,7 @@ const services = actionsMock.createServices(); const actionsClient = actionsClientMock.create(); const encryptedSavedObjectsClient = encryptedSavedObjectsMock.createClient(); const actionTypeRegistry = actionTypeRegistryMock.create(); +const eventLogger = eventLoggerMock.create(); const executeParams = { actionId: '1', @@ -42,7 +43,7 @@ actionExecutor.initialize({ getActionsClientWithRequest, actionTypeRegistry, encryptedSavedObjectsClient, - eventLogger: eventLoggerMock.create(), + eventLogger, preconfiguredActions: [], }); @@ -108,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 0737e0ce3f071..fe742f0e6c560 100644 --- a/x-pack/plugins/actions/server/lib/action_executor.ts +++ b/x-pack/plugins/actions/server/lib/action_executor.ts @@ -23,6 +23,9 @@ import { IEvent, IEventLogger, SAVED_OBJECT_REL_PRIMARY } from '../../../event_l import { ActionsClient } from '../actions_client'; import { ActionExecutionSource } from './action_execution_source'; +// 1,000,000 nanoseconds in 1 millisecond +const Millis2Nanos = 1000 * 1000; + export interface ActionExecutorContext { logger: Logger; spaces?: SpacesServiceStart; @@ -37,11 +40,16 @@ export interface ActionExecutorContext { preconfiguredActions: PreConfiguredAction[]; } +export interface TaskInfo { + scheduled: Date; +} + export interface ExecuteOptions { actionId: string; request: KibanaRequest; params: Record; source?: ActionExecutionSource; + taskInfo?: TaskInfo; } export type ActionExecutorContract = PublicMethodsOf; @@ -68,6 +76,7 @@ export class ActionExecutor { params, request, source, + taskInfo, }: ExecuteOptions): Promise> { if (!this.isInitialized) { throw new Error('ActionExecutor not initialized'); @@ -139,9 +148,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 229324c1f0df3..25b5fb8f29663 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 @@ -132,6 +132,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]; @@ -253,6 +256,9 @@ test('uses API key when provided', async () => { authorization: 'ApiKey MTIzOmFiYw==', }, }), + taskInfo: { + scheduled: new Date(), + }, }); const [executeParams] = mockedActionExecutor.execute.mock.calls[0]; @@ -287,6 +293,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 cf4b1576f2778..d2dc3c9646186 100644 --- a/x-pack/plugins/actions/server/lib/task_runner_factory.ts +++ b/x-pack/plugins/actions/server/lib/task_runner_factory.ts @@ -71,6 +71,10 @@ export class TaskRunnerFactory { getUnsecuredSavedObjectsClient, } = this.taskRunnerContext!; + const taskInfo = { + scheduled: taskInstance.runAt, + }; + return { async run() { const { spaceId, actionTaskParamsId } = taskInstance.params as Record; @@ -117,6 +121,7 @@ export class TaskRunnerFactory { actionId, request: fakeRequest, ...getSourceFromReferences(references), + taskInfo, }); } catch (e) { if (e instanceof ActionTypeDisabledError) { 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 25f0656163f5d..f5c9151f042e3 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 @@ -187,7 +187,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 c3a36297c217a..c72a6b5948e8d 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 @@ -201,7 +201,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 39a45584631d2..514f2fa0ba1ca 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", }, } @@ -386,6 +389,10 @@ describe('Task Runner', () => { kind: 'alert', }, kibana: { + task: { + schedule_delay: 0, + scheduled: '1970-01-01T00:00:00.000Z', + }, saved_objects: [ { id: '1', @@ -401,7 +408,6 @@ describe('Task Runner', () => { category: 'test', id: '1', license: 'basic', - namespace: undefined, ruleset: 'alerts', }, }); @@ -510,6 +516,10 @@ describe('Task Runner', () => { alerting: { status: 'active', }, + task: { + schedule_delay: 0, + scheduled: '1970-01-01T00:00:00.000Z', + }, saved_objects: [ { id: '1', @@ -526,7 +536,6 @@ describe('Task Runner', () => { id: '1', license: 'basic', name: 'alert-name', - namespace: undefined, ruleset: 'alerts', }, }); @@ -595,6 +604,10 @@ describe('Task Runner', () => { kind: 'alert', }, kibana: { + task: { + schedule_delay: 0, + scheduled: '1970-01-01T00:00:00.000Z', + }, saved_objects: [ { id: '1', @@ -610,7 +623,6 @@ describe('Task Runner', () => { category: 'test', id: '1', license: 'basic', - namespace: undefined, ruleset: 'alerts', }, }); @@ -692,6 +704,10 @@ describe('Task Runner', () => { alerting: { status: 'active', }, + task: { + schedule_delay: 0, + scheduled: '1970-01-01T00:00:00.000Z', + }, saved_objects: [ { id: '1', @@ -708,7 +724,6 @@ describe('Task Runner', () => { id: '1', license: 'basic', name: 'alert-name', - namespace: undefined, ruleset: 'alerts', }, }); @@ -846,13 +861,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", }, }, @@ -889,7 +907,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -918,6 +935,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 { @@ -925,7 +946,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -1135,13 +1155,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", }, }, @@ -1178,7 +1201,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -1215,7 +1237,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -1257,7 +1278,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -1286,6 +1306,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 { @@ -1293,7 +1317,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -1417,13 +1440,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", }, }, @@ -1460,7 +1486,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -1497,7 +1522,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -1539,7 +1563,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -1581,7 +1604,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -1610,6 +1632,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 { @@ -1617,7 +1643,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -1936,13 +1961,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", }, }, @@ -1980,7 +2008,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -2017,7 +2044,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -2046,6 +2072,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 { @@ -2053,7 +2083,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -2262,13 +2291,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", }, }, @@ -2301,13 +2333,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", }, }, @@ -2365,13 +2400,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", }, }, @@ -2404,13 +2442,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", }, }, @@ -2476,13 +2517,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", }, }, @@ -2515,13 +2559,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", }, }, @@ -2587,13 +2634,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", }, }, @@ -2626,13 +2676,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", }, }, @@ -2697,13 +2750,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", }, }, @@ -2736,13 +2792,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", }, }, @@ -2975,13 +3034,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", }, }, @@ -3018,7 +3080,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3055,7 +3116,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3092,7 +3152,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3129,7 +3188,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3158,6 +3216,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 { @@ -3165,7 +3227,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3259,13 +3320,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", }, }, @@ -3302,7 +3366,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3339,7 +3402,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3368,6 +3430,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 { @@ -3375,7 +3441,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3461,13 +3526,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", }, }, @@ -3502,7 +3570,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3537,7 +3604,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3566,6 +3632,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 { @@ -3573,7 +3643,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3654,13 +3723,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", }, }, @@ -3697,7 +3769,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3734,7 +3805,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3763,6 +3833,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 { @@ -3770,7 +3844,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3853,13 +3926,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", }, }, @@ -3893,7 +3969,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3927,7 +4002,6 @@ describe('Task Runner', () => { "id": "1", "license": "basic", "name": "alert-name", - "namespace": undefined, "ruleset": "alerts", }, }, @@ -3956,6 +4030,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 { @@ -3963,7 +4041,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..653e79242fe0c 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 { @@ -494,6 +497,7 @@ export class TaskRunner< const namespace = this.context.spaceIdToNamespace(spaceId); const eventLogger = this.context.eventLogger; + const scheduleDelay = Date.now() - 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) @@ -513,13 +517,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 +821,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 032f77543acb9..e6d554af8a2ee 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 of when this task was supposed to start", + }, 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 147b6abfb88d1..36c5b90326377 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 @@ -386,6 +386,8 @@ export default function ({ getService }: FtrProviderContext) { expect(event?.message).to.eql(message); + expect(event?.kibana?.task).to.eql(undefined); + if (errorMessage) { expect(event?.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 ( From 4e58a8aaebcb9a7caf4ec94774fcafcb57aa795b Mon Sep 17 00:00:00 2001 From: Patrick Mueller Date: Mon, 21 Jun 2021 15:01:30 -0400 Subject: [PATCH 2/3] fix some issues from PR review --- .../plugins/alerting/server/task_runner/task_runner.ts | 9 +++++---- x-pack/plugins/event_log/README.md | 2 +- 2 files changed, 6 insertions(+), 5 deletions(-) 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 653e79242fe0c..c66c054bc8ac3 100644 --- a/x-pack/plugins/alerting/server/task_runner/task_runner.ts +++ b/x-pack/plugins/alerting/server/task_runner/task_runner.ts @@ -492,16 +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 = Date.now() - this.taskInstance.runAt.getTime(); + 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', diff --git a/x-pack/plugins/event_log/README.md b/x-pack/plugins/event_log/README.md index e6d554af8a2ee..b205148c3f3f8 100644 --- a/x-pack/plugins/event_log/README.md +++ b/x-pack/plugins/event_log/README.md @@ -129,7 +129,7 @@ Below is a document in the expected structure, with descriptions of the fields: 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 of when this task 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", From 62acce5627de85f10a12d2fce1baffd22edf6d51 Mon Sep 17 00:00:00 2001 From: Patrick Mueller Date: Tue, 22 Jun 2021 18:28:02 -0400 Subject: [PATCH 3/3] fix broken tests after merge from master --- .../plugins/actions/server/lib/task_runner_factory.test.ts | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) 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 44d08499382ff..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 @@ -306,6 +306,9 @@ test('uses relatedSavedObjects when provided', async () => { authorization: 'ApiKey MTIzOmFiYw==', }, }), + taskInfo: { + scheduled: new Date(), + }, }); }); @@ -329,7 +332,6 @@ test('sanitizes invalid relatedSavedObjects when provided', async () => { }); await taskRunner.run(); - expect(mockedActionExecutor.execute).toHaveBeenCalledWith({ actionId: '2', params: { baz: true }, @@ -340,6 +342,9 @@ test('sanitizes invalid relatedSavedObjects when provided', async () => { authorization: 'ApiKey MTIzOmFiYw==', }, }), + taskInfo: { + scheduled: new Date(), + }, }); });