diff --git a/x-pack/plugins/alerting/server/plugin.ts b/x-pack/plugins/alerting/server/plugin.ts index 41ae9f15d9af9..5afa1b235a8c1 100644 --- a/x-pack/plugins/alerting/server/plugin.ts +++ b/x-pack/plugins/alerting/server/plugin.ts @@ -74,6 +74,7 @@ import { AlertingAuthorization } from './authorization'; export const EVENT_LOG_PROVIDER = 'alerting'; export const EVENT_LOG_ACTIONS = { execute: 'execute', + executeStart: 'execute-start', executeAction: 'execute-action', newInstance: 'new-instance', recoveredInstance: 'recovered-instance', 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 4893e509f6b6a..39a45584631d2 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 @@ -214,10 +214,10 @@ describe('Task Runner', () => { expect(call.rule.consumer).toBe('bar'); expect(call.rule.enabled).toBe(true); expect(call.rule.schedule).toMatchInlineSnapshot(` - Object { - "interval": "10s", - } - `); + Object { + "interval": "10s", + } + `); expect(call.rule.createdBy).toBe('alert-creator'); expect(call.rule.updatedBy).toBe('alert-updater'); expect(call.rule.createdAt).toBe(mockDate); @@ -228,25 +228,25 @@ describe('Task Runner', () => { expect(call.rule.ruleTypeId).toBe('test'); expect(call.rule.ruleTypeName).toBe('My test alert'); expect(call.rule.actions).toMatchInlineSnapshot(` - Array [ - Object { - "actionTypeId": "action", - "group": "default", - "id": "1", - "params": Object { - "foo": true, - }, - }, - Object { - "actionTypeId": "action", - "group": "recovered", - "id": "2", - "params": Object { - "isResolved": true, - }, - }, - ] - `); + Array [ + Object { + "actionTypeId": "action", + "group": "default", + "id": "1", + "params": Object { + "foo": true, + }, + }, + Object { + "actionTypeId": "action", + "group": "recovered", + "id": "2", + "params": Object { + "isResolved": true, + }, + }, + ] + `); expect(call.services.alertInstanceFactory).toBeTruthy(); expect(call.services.scopedClusterClient).toBeTruthy(); expect(call.services).toBeTruthy(); @@ -260,22 +260,19 @@ describe('Task Runner', () => { ); const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; - expect(eventLogger.logEvent).toHaveBeenCalledTimes(1); + expect(eventLogger.logEvent).toHaveBeenCalledTimes(2); + expect(eventLogger.startTiming).toHaveBeenCalledTimes(1); expect(eventLogger.logEvent.mock.calls[0][0]).toMatchInlineSnapshot(` Object { "@timestamp": "1970-01-01T00:00:00.000Z", "event": Object { - "action": "execute", + "action": "execute-start", "category": Array [ "alerts", ], "kind": "alert", - "outcome": "success", }, "kibana": Object { - "alerting": Object { - "status": "ok", - }, "saved_objects": Array [ Object { "id": "1", @@ -286,12 +283,11 @@ describe('Task Runner', () => { }, ], }, - "message": "alert executed: test:1: 'alert-name'", + "message": "alert execution start: \\"1\\"", "rule": Object { "category": "test", "id": "1", "license": "basic", - "name": "alert-name", "namespace": undefined, "ruleset": "alerts", }, @@ -381,8 +377,35 @@ describe('Task Runner', () => { ); const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; - expect(eventLogger.logEvent).toHaveBeenCalledTimes(4); + expect(eventLogger.logEvent).toHaveBeenCalledTimes(5); expect(eventLogger.logEvent).toHaveBeenNthCalledWith(1, { + '@timestamp': '1970-01-01T00:00:00.000Z', + event: { + action: 'execute-start', + category: ['alerts'], + kind: 'alert', + }, + kibana: { + saved_objects: [ + { + id: '1', + namespace: undefined, + rel: 'primary', + type: 'alert', + type_id: 'test', + }, + ], + }, + message: `alert execution start: "1"`, + rule: { + category: 'test', + id: '1', + license: 'basic', + namespace: undefined, + ruleset: 'alerts', + }, + }); + expect(eventLogger.logEvent).toHaveBeenNthCalledWith(2, { event: { action: 'new-instance', category: ['alerts'], @@ -416,7 +439,7 @@ describe('Task Runner', () => { ruleset: 'alerts', }, }); - expect(eventLogger.logEvent).toHaveBeenNthCalledWith(2, { + expect(eventLogger.logEvent).toHaveBeenNthCalledWith(3, { event: { action: 'active-instance', category: ['alerts'], @@ -441,7 +464,7 @@ describe('Task Runner', () => { ruleset: 'alerts', }, }); - expect(eventLogger.logEvent).toHaveBeenNthCalledWith(3, { + expect(eventLogger.logEvent).toHaveBeenNthCalledWith(4, { event: { action: 'execute-action', category: ['alerts'], @@ -480,7 +503,7 @@ describe('Task Runner', () => { ruleset: 'alerts', }, }); - expect(eventLogger.logEvent).toHaveBeenNthCalledWith(4, { + expect(eventLogger.logEvent).toHaveBeenNthCalledWith(5, { '@timestamp': '1970-01-01T00:00:00.000Z', event: { action: 'execute', category: ['alerts'], kind: 'alert', outcome: 'success' }, kibana: { @@ -562,8 +585,36 @@ describe('Task Runner', () => { ); const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; - expect(eventLogger.logEvent).toHaveBeenCalledTimes(3); + expect(eventLogger.startTiming).toHaveBeenCalledTimes(1); + expect(eventLogger.logEvent).toHaveBeenCalledTimes(4); expect(eventLogger.logEvent).toHaveBeenNthCalledWith(1, { + '@timestamp': '1970-01-01T00:00:00.000Z', + event: { + action: 'execute-start', + category: ['alerts'], + kind: 'alert', + }, + kibana: { + saved_objects: [ + { + id: '1', + namespace: undefined, + rel: 'primary', + type: 'alert', + type_id: 'test', + }, + ], + }, + message: `alert execution start: \"1\"`, + rule: { + category: 'test', + id: '1', + license: 'basic', + namespace: undefined, + ruleset: 'alerts', + }, + }); + expect(eventLogger.logEvent).toHaveBeenNthCalledWith(2, { event: { action: 'new-instance', category: ['alerts'], @@ -596,7 +647,7 @@ describe('Task Runner', () => { ruleset: 'alerts', }, }); - expect(eventLogger.logEvent).toHaveBeenNthCalledWith(2, { + expect(eventLogger.logEvent).toHaveBeenNthCalledWith(3, { event: { action: 'active-instance', category: ['alerts'], @@ -629,7 +680,7 @@ describe('Task Runner', () => { ruleset: 'alerts', }, }); - expect(eventLogger.logEvent).toHaveBeenNthCalledWith(3, { + expect(eventLogger.logEvent).toHaveBeenNthCalledWith(4, { '@timestamp': '1970-01-01T00:00:00.000Z', event: { action: 'execute', @@ -771,9 +822,41 @@ describe('Task Runner', () => { expect(actionsClient.enqueueExecution).toHaveBeenCalledTimes(0); const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; - expect(eventLogger.logEvent).toHaveBeenCalledTimes(2); + expect(eventLogger.logEvent).toHaveBeenCalledTimes(3); + expect(eventLogger.startTiming).toHaveBeenCalledTimes(1); expect(eventLogger.logEvent.mock.calls).toMatchInlineSnapshot(` Array [ + Array [ + Object { + "@timestamp": "1970-01-01T00:00:00.000Z", + "event": Object { + "action": "execute-start", + "category": Array [ + "alerts", + ], + "kind": "alert", + }, + "kibana": Object { + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + ], + }, + "message": "alert execution start: \\"1\\"", + "rule": Object { + "category": "test", + "id": "1", + "license": "basic", + "namespace": undefined, + "ruleset": "alerts", + }, + }, + ], Array [ Object { "event": Object { @@ -1028,163 +1111,195 @@ describe('Task Runner', () => { `); const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; - expect(eventLogger.logEvent).toHaveBeenCalledTimes(4); + expect(eventLogger.logEvent).toHaveBeenCalledTimes(5); + expect(eventLogger.startTiming).toHaveBeenCalledTimes(1); expect(eventLogger.logEvent.mock.calls).toMatchInlineSnapshot(` - Array [ Array [ - Object { - "event": Object { - "action": "new-instance", - "category": Array [ - "alerts", - ], - "duration": 0, - "kind": "alert", - "start": "1970-01-01T00:00:00.000Z", - }, - "kibana": Object { - "alerting": Object { - "action_group_id": "default", - "instance_id": "1", - }, - "saved_objects": Array [ - Object { - "id": "1", - "namespace": undefined, - "rel": "primary", - "type": "alert", - "type_id": "test", - }, - ], - }, - "message": "test:1: 'alert-name' created new instance: '1'", - "rule": Object { - "category": "test", - "id": "1", - "license": "basic", - "name": "alert-name", - "namespace": undefined, - "ruleset": "alerts", + Array [ + Object { + "@timestamp": "1970-01-01T00:00:00.000Z", + "event": Object { + "action": "execute-start", + "category": Array [ + "alerts", + ], + "kind": "alert", + }, + "kibana": Object { + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + ], + }, + "message": "alert execution start: \\"1\\"", + "rule": Object { + "category": "test", + "id": "1", + "license": "basic", + "namespace": undefined, + "ruleset": "alerts", + }, }, - }, - ], - Array [ - Object { - "event": Object { - "action": "active-instance", - "category": Array [ - "alerts", - ], - "duration": 0, - "kind": "alert", - "start": "1970-01-01T00:00:00.000Z", - }, - "kibana": Object { - "alerting": Object { - "action_group_id": "default", - "instance_id": "1", - }, - "saved_objects": Array [ - Object { - "id": "1", - "namespace": undefined, - "rel": "primary", - "type": "alert", - "type_id": "test", + ], + Array [ + Object { + "event": Object { + "action": "new-instance", + "category": Array [ + "alerts", + ], + "duration": 0, + "kind": "alert", + "start": "1970-01-01T00:00:00.000Z", + }, + "kibana": Object { + "alerting": Object { + "action_group_id": "default", + "instance_id": "1", }, - ], - }, - "message": "test:1: 'alert-name' active instance: '1' in actionGroup: 'default'", - "rule": Object { - "category": "test", - "id": "1", - "license": "basic", - "name": "alert-name", - "namespace": undefined, - "ruleset": "alerts", + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + ], + }, + "message": "test:1: 'alert-name' created new instance: '1'", + "rule": Object { + "category": "test", + "id": "1", + "license": "basic", + "name": "alert-name", + "namespace": undefined, + "ruleset": "alerts", + }, }, - }, - ], - Array [ - Object { - "event": Object { - "action": "execute-action", - "category": Array [ - "alerts", - ], - "kind": "alert", - }, - "kibana": Object { - "alerting": Object { - "action_group_id": "default", - "action_subgroup": undefined, - "instance_id": "1", - }, - "saved_objects": Array [ - Object { - "id": "1", - "namespace": undefined, - "rel": "primary", - "type": "alert", - "type_id": "test", - }, - Object { - "id": "1", - "namespace": undefined, - "type": "action", - "type_id": "action", + ], + Array [ + Object { + "event": Object { + "action": "active-instance", + "category": Array [ + "alerts", + ], + "duration": 0, + "kind": "alert", + "start": "1970-01-01T00:00:00.000Z", + }, + "kibana": Object { + "alerting": Object { + "action_group_id": "default", + "instance_id": "1", }, - ], - }, - "message": "alert: test:1: 'alert-name' instanceId: '1' scheduled actionGroup: 'default' action: action:1", - "rule": Object { - "category": "test", - "id": "1", - "license": "basic", - "name": "alert-name", - "namespace": undefined, - "ruleset": "alerts", + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + ], + }, + "message": "test:1: 'alert-name' active instance: '1' in actionGroup: 'default'", + "rule": Object { + "category": "test", + "id": "1", + "license": "basic", + "name": "alert-name", + "namespace": undefined, + "ruleset": "alerts", + }, }, - }, - ], - Array [ - Object { - "@timestamp": "1970-01-01T00:00:00.000Z", - "event": Object { - "action": "execute", - "category": Array [ - "alerts", - ], - "kind": "alert", - "outcome": "success", - }, - "kibana": Object { - "alerting": Object { - "status": "active", - }, - "saved_objects": Array [ - Object { - "id": "1", - "namespace": undefined, - "rel": "primary", - "type": "alert", - "type_id": "test", + ], + Array [ + Object { + "event": Object { + "action": "execute-action", + "category": Array [ + "alerts", + ], + "kind": "alert", + }, + "kibana": Object { + "alerting": Object { + "action_group_id": "default", + "action_subgroup": undefined, + "instance_id": "1", }, - ], + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + Object { + "id": "1", + "namespace": undefined, + "type": "action", + "type_id": "action", + }, + ], + }, + "message": "alert: test:1: 'alert-name' instanceId: '1' scheduled actionGroup: 'default' action: action:1", + "rule": Object { + "category": "test", + "id": "1", + "license": "basic", + "name": "alert-name", + "namespace": undefined, + "ruleset": "alerts", + }, }, - "message": "alert executed: test:1: 'alert-name'", - "rule": Object { - "category": "test", - "id": "1", - "license": "basic", - "name": "alert-name", - "namespace": undefined, - "ruleset": "alerts", + ], + Array [ + Object { + "@timestamp": "1970-01-01T00:00:00.000Z", + "event": Object { + "action": "execute", + "category": Array [ + "alerts", + ], + "kind": "alert", + "outcome": "success", + }, + "kibana": Object { + "alerting": Object { + "status": "active", + }, + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + ], + }, + "message": "alert executed: test:1: 'alert-name'", + "rule": Object { + "category": "test", + "id": "1", + "license": "basic", + "name": "alert-name", + "namespace": undefined, + "ruleset": "alerts", + }, }, - }, - ], - ] - `); + ], + ] + `); }); test('fire recovered actions for execution for the alertInstances which is in the recovered state', async () => { @@ -1243,23 +1358,23 @@ describe('Task Runner', () => { }); const runnerResult = await taskRunner.run(); expect(runnerResult.state.alertInstances).toMatchInlineSnapshot(` - Object { - "1": Object { - "meta": Object { - "lastScheduledActions": Object { - "date": 1970-01-01T00:00:00.000Z, - "group": "default", - "subgroup": undefined, - }, - }, - "state": Object { - "bar": false, - "duration": 86400000000000, - "start": "1969-12-31T00:00:00.000Z", - }, - }, - } - `); + Object { + "1": Object { + "meta": Object { + "lastScheduledActions": Object { + "date": 1970-01-01T00:00:00.000Z, + "group": "default", + "subgroup": undefined, + }, + }, + "state": Object { + "bar": false, + "duration": 86400000000000, + "start": "1969-12-31T00:00:00.000Z", + }, + }, + } + `); const logger = taskRunnerFactoryInitializerParams.logger; expect(logger.debug).toHaveBeenCalledTimes(4); @@ -1278,9 +1393,41 @@ describe('Task Runner', () => { ); const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; - expect(eventLogger.logEvent).toHaveBeenCalledTimes(5); + expect(eventLogger.logEvent).toHaveBeenCalledTimes(6); + expect(eventLogger.startTiming).toHaveBeenCalledTimes(1); expect(eventLogger.logEvent.mock.calls).toMatchInlineSnapshot(` Array [ + Array [ + Object { + "@timestamp": "1970-01-01T00:00:00.000Z", + "event": Object { + "action": "execute-start", + "category": Array [ + "alerts", + ], + "kind": "alert", + }, + "kibana": Object { + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + ], + }, + "message": "alert execution start: \\"1\\"", + "rule": Object { + "category": "test", + "id": "1", + "license": "basic", + "namespace": undefined, + "ruleset": "alerts", + }, + }, + ], Array [ Object { "event": Object { @@ -1574,7 +1721,7 @@ describe('Task Runner', () => { ); const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; - expect(eventLogger.logEvent).toHaveBeenCalledTimes(5); + expect(eventLogger.logEvent).toHaveBeenCalledTimes(6); expect(actionsClient.enqueueExecution).toHaveBeenCalledTimes(2); expect(actionsClient.enqueueExecution.mock.calls[1][0].id).toEqual('1'); expect(actionsClient.enqueueExecution.mock.calls[0][0].id).toEqual('2'); @@ -1669,7 +1816,7 @@ describe('Task Runner', () => { `); const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; - expect(eventLogger.logEvent).toHaveBeenCalledTimes(5); + expect(eventLogger.logEvent).toHaveBeenCalledTimes(6); expect(actionsClient.enqueueExecution).toHaveBeenCalledTimes(2); expect(actionsClient.enqueueExecution.mock.calls[0]).toMatchInlineSnapshot(` Array [ @@ -1765,9 +1912,41 @@ describe('Task Runner', () => { `); const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; - expect(eventLogger.logEvent).toHaveBeenCalledTimes(3); + expect(eventLogger.logEvent).toHaveBeenCalledTimes(4); + expect(eventLogger.startTiming).toHaveBeenCalledTimes(1); expect(eventLogger.logEvent.mock.calls).toMatchInlineSnapshot(` Array [ + Array [ + Object { + "@timestamp": "1970-01-01T00:00:00.000Z", + "event": Object { + "action": "execute-start", + "category": Array [ + "alerts", + ], + "kind": "alert", + }, + "kibana": Object { + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + ], + }, + "message": "alert execution start: \\"1\\"", + "rule": Object { + "category": "test", + "id": "1", + "license": "basic", + "namespace": undefined, + "ruleset": "alerts", + }, + }, + ], Array [ Object { "event": Object { @@ -2059,9 +2238,41 @@ describe('Task Runner', () => { `); const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; - expect(eventLogger.logEvent).toHaveBeenCalledTimes(1); + expect(eventLogger.logEvent).toHaveBeenCalledTimes(2); + expect(eventLogger.startTiming).toHaveBeenCalledTimes(1); expect(eventLogger.logEvent.mock.calls).toMatchInlineSnapshot(` Array [ + Array [ + Object { + "@timestamp": "1970-01-01T00:00:00.000Z", + "event": Object { + "action": "execute-start", + "category": Array [ + "alerts", + ], + "kind": "alert", + }, + "kibana": Object { + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + ], + }, + "message": "alert execution start: \\"1\\"", + "rule": Object { + "category": "test", + "id": "1", + "license": "basic", + "namespace": undefined, + "ruleset": "alerts", + }, + }, + ], Array [ Object { "@timestamp": "1970-01-01T00:00:00.000Z", @@ -2130,9 +2341,41 @@ describe('Task Runner', () => { `); const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; - expect(eventLogger.logEvent).toHaveBeenCalledTimes(1); + expect(eventLogger.logEvent).toHaveBeenCalledTimes(2); + expect(eventLogger.startTiming).toHaveBeenCalledTimes(1); expect(eventLogger.logEvent.mock.calls).toMatchInlineSnapshot(` Array [ + Array [ + Object { + "@timestamp": "1970-01-01T00:00:00.000Z", + "event": Object { + "action": "execute-start", + "category": Array [ + "alerts", + ], + "kind": "alert", + }, + "kibana": Object { + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + ], + }, + "message": "alert execution start: \\"1\\"", + "rule": Object { + "category": "test", + "id": "1", + "license": "basic", + "namespace": undefined, + "ruleset": "alerts", + }, + }, + ], Array [ Object { "@timestamp": "1970-01-01T00:00:00.000Z", @@ -2209,9 +2452,41 @@ describe('Task Runner', () => { `); const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; - expect(eventLogger.logEvent).toHaveBeenCalledTimes(1); + expect(eventLogger.logEvent).toHaveBeenCalledTimes(2); + expect(eventLogger.startTiming).toHaveBeenCalledTimes(1); expect(eventLogger.logEvent.mock.calls).toMatchInlineSnapshot(` Array [ + Array [ + Object { + "@timestamp": "1970-01-01T00:00:00.000Z", + "event": Object { + "action": "execute-start", + "category": Array [ + "alerts", + ], + "kind": "alert", + }, + "kibana": Object { + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + ], + }, + "message": "alert execution start: \\"1\\"", + "rule": Object { + "category": "test", + "id": "1", + "license": "basic", + "namespace": undefined, + "ruleset": "alerts", + }, + }, + ], Array [ Object { "@timestamp": "1970-01-01T00:00:00.000Z", @@ -2288,9 +2563,41 @@ describe('Task Runner', () => { `); const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; - expect(eventLogger.logEvent).toHaveBeenCalledTimes(1); + expect(eventLogger.logEvent).toHaveBeenCalledTimes(2); + expect(eventLogger.startTiming).toHaveBeenCalledTimes(1); expect(eventLogger.logEvent.mock.calls).toMatchInlineSnapshot(` Array [ + Array [ + Object { + "@timestamp": "1970-01-01T00:00:00.000Z", + "event": Object { + "action": "execute-start", + "category": Array [ + "alerts", + ], + "kind": "alert", + }, + "kibana": Object { + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + ], + }, + "message": "alert execution start: \\"1\\"", + "rule": Object { + "category": "test", + "id": "1", + "license": "basic", + "namespace": undefined, + "ruleset": "alerts", + }, + }, + ], Array [ Object { "@timestamp": "1970-01-01T00:00:00.000Z", @@ -2366,9 +2673,41 @@ describe('Task Runner', () => { `); const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; - expect(eventLogger.logEvent).toHaveBeenCalledTimes(1); + expect(eventLogger.logEvent).toHaveBeenCalledTimes(2); + expect(eventLogger.startTiming).toHaveBeenCalledTimes(1); expect(eventLogger.logEvent.mock.calls).toMatchInlineSnapshot(` Array [ + Array [ + Object { + "@timestamp": "1970-01-01T00:00:00.000Z", + "event": Object { + "action": "execute-start", + "category": Array [ + "alerts", + ], + "kind": "alert", + }, + "kibana": Object { + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + ], + }, + "message": "alert execution start: \\"1\\"", + "rule": Object { + "category": "test", + "id": "1", + "license": "basic", + "namespace": undefined, + "ruleset": "alerts", + }, + }, + ], Array [ Object { "@timestamp": "1970-01-01T00:00:00.000Z", @@ -2612,9 +2951,41 @@ describe('Task Runner', () => { await taskRunner.run(); const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; - expect(eventLogger.logEvent).toHaveBeenCalledTimes(5); + expect(eventLogger.logEvent).toHaveBeenCalledTimes(6); + expect(eventLogger.startTiming).toHaveBeenCalledTimes(1); expect(eventLogger.logEvent.mock.calls).toMatchInlineSnapshot(` Array [ + Array [ + Object { + "@timestamp": "1970-01-01T00:00:00.000Z", + "event": Object { + "action": "execute-start", + "category": Array [ + "alerts", + ], + "kind": "alert", + }, + "kibana": Object { + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + ], + }, + "message": "alert execution start: \\"1\\"", + "rule": Object { + "category": "test", + "id": "1", + "license": "basic", + "namespace": undefined, + "ruleset": "alerts", + }, + }, + ], Array [ Object { "event": Object { @@ -2864,9 +3235,41 @@ describe('Task Runner', () => { await taskRunner.run(); const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; - expect(eventLogger.logEvent).toHaveBeenCalledTimes(3); + expect(eventLogger.logEvent).toHaveBeenCalledTimes(4); + expect(eventLogger.startTiming).toHaveBeenCalledTimes(1); expect(eventLogger.logEvent.mock.calls).toMatchInlineSnapshot(` Array [ + Array [ + Object { + "@timestamp": "1970-01-01T00:00:00.000Z", + "event": Object { + "action": "execute-start", + "category": Array [ + "alerts", + ], + "kind": "alert", + }, + "kibana": Object { + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + ], + }, + "message": "alert execution start: \\"1\\"", + "rule": Object { + "category": "test", + "id": "1", + "license": "basic", + "namespace": undefined, + "ruleset": "alerts", + }, + }, + ], Array [ Object { "event": Object { @@ -3034,9 +3437,41 @@ describe('Task Runner', () => { await taskRunner.run(); const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; - expect(eventLogger.logEvent).toHaveBeenCalledTimes(3); + expect(eventLogger.logEvent).toHaveBeenCalledTimes(4); + expect(eventLogger.startTiming).toHaveBeenCalledTimes(1); expect(eventLogger.logEvent.mock.calls).toMatchInlineSnapshot(` Array [ + Array [ + Object { + "@timestamp": "1970-01-01T00:00:00.000Z", + "event": Object { + "action": "execute-start", + "category": Array [ + "alerts", + ], + "kind": "alert", + }, + "kibana": Object { + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + ], + }, + "message": "alert execution start: \\"1\\"", + "rule": Object { + "category": "test", + "id": "1", + "license": "basic", + "namespace": undefined, + "ruleset": "alerts", + }, + }, + ], Array [ Object { "event": Object { @@ -3195,9 +3630,41 @@ describe('Task Runner', () => { await taskRunner.run(); const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; - expect(eventLogger.logEvent).toHaveBeenCalledTimes(3); + expect(eventLogger.logEvent).toHaveBeenCalledTimes(4); + expect(eventLogger.startTiming).toHaveBeenCalledTimes(1); expect(eventLogger.logEvent.mock.calls).toMatchInlineSnapshot(` Array [ + Array [ + Object { + "@timestamp": "1970-01-01T00:00:00.000Z", + "event": Object { + "action": "execute-start", + "category": Array [ + "alerts", + ], + "kind": "alert", + }, + "kibana": Object { + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + ], + }, + "message": "alert execution start: \\"1\\"", + "rule": Object { + "category": "test", + "id": "1", + "license": "basic", + "namespace": undefined, + "ruleset": "alerts", + }, + }, + ], Array [ Object { "event": Object { @@ -3362,9 +3829,41 @@ describe('Task Runner', () => { await taskRunner.run(); const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; - expect(eventLogger.logEvent).toHaveBeenCalledTimes(3); + expect(eventLogger.logEvent).toHaveBeenCalledTimes(4); + expect(eventLogger.startTiming).toHaveBeenCalledTimes(1); expect(eventLogger.logEvent.mock.calls).toMatchInlineSnapshot(` Array [ + Array [ + Object { + "@timestamp": "1970-01-01T00:00:00.000Z", + "event": Object { + "action": "execute-start", + "category": Array [ + "alerts", + ], + "kind": "alert", + }, + "kibana": Object { + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + ], + }, + "message": "alert execution start: \\"1\\"", + "rule": Object { + "category": "test", + "id": "1", + "license": "basic", + "namespace": undefined, + "ruleset": "alerts", + }, + }, + ], Array [ Object { "event": Object { 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 c9ca5d85e5116..b712b6237c8a7 100644 --- a/x-pack/plugins/alerting/server/task_runner/task_runner.ts +++ b/x-pack/plugins/alerting/server/task_runner/task_runner.ts @@ -522,8 +522,19 @@ export class TaskRunner< namespace, }, }; + eventLogger.startTiming(event); + const startEvent = cloneDeep({ + ...event, + event: { + ...event.event, + action: EVENT_LOG_ACTIONS.executeStart, + }, + message: `alert execution start: "${alertId}"`, + }); + eventLogger.logEvent(startEvent); + const { state, schedule } = await errorAsAlertTaskRunResult( this.loadAlertAttributesAndRun(event) ); 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 781967ff5596a..fae5958d7827a 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 @@ -76,6 +76,7 @@ export default function eventLogTests({ getService }: FtrProviderContext) { 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 }], @@ -103,12 +104,14 @@ export default function eventLogTests({ getService }: FtrProviderContext) { 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); @@ -118,6 +121,8 @@ export default function eventLogTests({ getService }: FtrProviderContext) { 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 @@ -125,6 +130,22 @@ export default function eventLogTests({ getService }: FtrProviderContext) { 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, @@ -262,6 +283,7 @@ export default function eventLogTests({ getService }: FtrProviderContext) { 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 }], @@ -272,12 +294,14 @@ export default function eventLogTests({ getService }: FtrProviderContext) { }); 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); @@ -287,6 +311,8 @@ export default function eventLogTests({ getService }: FtrProviderContext) { 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 @@ -294,6 +320,22 @@ export default function eventLogTests({ getService }: FtrProviderContext) { 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, @@ -407,14 +449,35 @@ export default function eventLogTests({ getService }: FtrProviderContext) { type: 'alert', id: alertId, provider: 'alerting', - actions: new Map([['execute', { gte: 1 }]]), + actions: new Map([ + ['execute-start', { gte: 1 }], + ['execute', { gte: 1 }], + ]), }); }); - const event = events[0]; - expect(event).to.be.ok(); + 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, + }, + }); - validateEvent(event, { + validateEvent(executeEvent, { spaceId: Spaces.space1.id, savedObjects: [{ type: 'alert', id: alertId, rel: 'primary', type_id: 'test.throw' }], outcome: 'failure',