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 c157765afb359..7f31aead1e83c 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 @@ -37,7 +37,7 @@ import { Alert, RecoveredActionGroup } from '../../common'; import { omit } from 'lodash'; import { UntypedNormalizedAlertType } from '../alert_type_registry'; import { alertTypeRegistryMock } from '../alert_type_registry.mock'; -import uuid from 'uuid'; + const alertType: jest.Mocked = { id: 'test', name: 'My test alert', @@ -373,6 +373,8 @@ describe('Task Runner', () => { expect(eventLogger.logEvent).toHaveBeenNthCalledWith(1, { event: { action: 'new-instance', + duration: 0, + start: '1970-01-01T00:00:00.000Z', }, kibana: { alerting: { @@ -395,6 +397,8 @@ describe('Task Runner', () => { expect(eventLogger.logEvent).toHaveBeenNthCalledWith(2, { event: { action: 'active-instance', + duration: 0, + start: '1970-01-01T00:00:00.000Z', }, kibana: { alerting: { @@ -525,6 +529,8 @@ describe('Task Runner', () => { expect(eventLogger.logEvent).toHaveBeenNthCalledWith(1, { event: { action: 'new-instance', + duration: 0, + start: '1970-01-01T00:00:00.000Z', }, kibana: { alerting: { @@ -546,6 +552,8 @@ describe('Task Runner', () => { expect(eventLogger.logEvent).toHaveBeenNthCalledWith(2, { event: { action: 'active-instance', + duration: 0, + start: '1970-01-01T00:00:00.000Z', }, kibana: { alerting: { @@ -669,7 +677,11 @@ describe('Task Runner', () => { meta: { lastScheduledActions: { date: '1970-01-01T00:00:00.000Z', group: 'default' }, }, - state: { bar: false }, + state: { + bar: false, + start: '1969-12-31T00:00:00.000Z', + duration: 86400000000000, + }, }, }, }, @@ -699,6 +711,8 @@ describe('Task Runner', () => { Object { "event": Object { "action": "active-instance", + "duration": 86400000000000, + "start": "1969-12-31T00:00:00.000Z", }, "kibana": Object { "alerting": Object { @@ -924,17 +938,221 @@ describe('Task Runner', () => { const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; expect(eventLogger.logEvent).toHaveBeenCalledTimes(4); + expect(eventLogger.logEvent.mock.calls).toMatchInlineSnapshot(` + Array [ + Array [ + Object { + "event": Object { + "action": "new-instance", + "duration": 0, + "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'", + }, + ], + Array [ + Object { + "event": Object { + "action": "active-instance", + "duration": 0, + "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' active instance: '1' in actionGroup: 'default'", + }, + ], + Array [ + Object { + "event": Object { + "action": "execute-action", + }, + "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", + }, + ], + Array [ + Object { + "@timestamp": "1970-01-01T00:00:00.000Z", + "event": Object { + "action": "execute", + "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'", + }, + ], + ] + `); + }); + + test('fire recovered actions for execution for the alertInstances which is in the recovered state', async () => { + taskRunnerFactoryInitializerParams.actionsPlugin.isActionTypeEnabled.mockReturnValue(true); + taskRunnerFactoryInitializerParams.actionsPlugin.isActionExecutable.mockReturnValue(true); + + alertType.executor.mockImplementation( + async ({ + services: executorServices, + }: AlertExecutorOptions< + AlertTypeParams, + AlertTypeState, + AlertInstanceState, + AlertInstanceContext, + string + >) => { + executorServices.alertInstanceFactory('1').scheduleActions('default'); + } + ); + const taskRunner = new TaskRunner( + alertType, + { + ...mockedTaskInstance, + state: { + ...mockedTaskInstance.state, + alertInstances: { + '1': { + meta: {}, + state: { + bar: false, + start: '1969-12-31T00:00:00.000Z', + duration: 80000000000, + }, + }, + '2': { + meta: {}, + state: { + bar: false, + start: '1969-12-31T06:00:00.000Z', + duration: 70000000000, + }, + }, + }, + }, + }, + taskRunnerFactoryInitializerParams + ); + alertsClient.get.mockResolvedValue(mockedAlertTypeSavedObject); + encryptedSavedObjectsClient.getDecryptedAsInternalUser.mockResolvedValue({ + id: '1', + type: 'alert', + attributes: { + apiKey: Buffer.from('123:abc').toString('base64'), + }, + references: [], + }); + 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", + }, + }, + } + `); + + const logger = taskRunnerFactoryInitializerParams.logger; + expect(logger.debug).toHaveBeenCalledTimes(4); + expect(logger.debug).nthCalledWith(1, 'executing alert test:1 at 1970-01-01T00:00:00.000Z'); + expect(logger.debug).nthCalledWith( + 2, + `alert test:1: 'alert-name' has 1 active alert instances: [{\"instanceId\":\"1\",\"actionGroup\":\"default\"}]` + ); + expect(logger.debug).nthCalledWith( + 3, + `alert test:1: 'alert-name' has 1 recovered alert instances: [\"2\"]` + ); + expect(logger.debug).nthCalledWith( + 4, + 'alertExecutionStatus for test:1: {"lastExecutionDate":"1970-01-01T00:00:00.000Z","status":"active"}' + ); + + const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; + expect(eventLogger.logEvent).toHaveBeenCalledTimes(5); expect(eventLogger.logEvent.mock.calls).toMatchInlineSnapshot(` Array [ Array [ Object { "event": Object { - "action": "new-instance", + "action": "recovered-instance", + "duration": 64800000000000, + "end": "1970-01-01T00:00:00.000Z", + "start": "1969-12-31T06:00:00.000Z", }, "kibana": Object { "alerting": Object { - "action_group_id": "default", - "instance_id": "1", + "instance_id": "2", }, "saved_objects": Array [ Object { @@ -946,13 +1164,15 @@ describe('Task Runner', () => { }, ], }, - "message": "test:1: 'alert-name' created new instance: '1'", + "message": "test:1: 'alert-name' instance '2' has recovered", }, ], Array [ Object { "event": Object { "action": "active-instance", + "duration": 86400000000000, + "start": "1969-12-31T00:00:00.000Z", }, "kibana": Object { "alerting": Object { @@ -972,6 +1192,36 @@ describe('Task Runner', () => { "message": "test:1: 'alert-name' active instance: '1' in actionGroup: 'default'", }, ], + Array [ + Object { + "event": Object { + "action": "execute-action", + }, + "kibana": Object { + "alerting": Object { + "action_group_id": "recovered", + "action_subgroup": undefined, + "instance_id": "2", + }, + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + Object { + "id": "2", + "namespace": undefined, + "type": "action", + "type_id": "action", + }, + ], + }, + "message": "alert: test:1: 'alert-name' instanceId: '2' scheduled actionGroup: 'recovered' action: action:2", + }, + ], Array [ Object { "event": Object { @@ -1028,84 +1278,7 @@ describe('Task Runner', () => { ], ] `); - }); - - test('fire recovered actions for execution for the alertInstances which is in the recovered state', async () => { - taskRunnerFactoryInitializerParams.actionsPlugin.isActionTypeEnabled.mockReturnValue(true); - taskRunnerFactoryInitializerParams.actionsPlugin.isActionExecutable.mockReturnValue(true); - - alertType.executor.mockImplementation( - async ({ - services: executorServices, - }: AlertExecutorOptions< - AlertTypeParams, - AlertTypeState, - AlertInstanceState, - AlertInstanceContext, - string - >) => { - executorServices.alertInstanceFactory('1').scheduleActions('default'); - } - ); - const taskRunner = new TaskRunner( - alertType, - { - ...mockedTaskInstance, - state: { - ...mockedTaskInstance.state, - alertInstances: { - '1': { meta: {}, state: { bar: false } }, - '2': { meta: {}, state: { bar: false } }, - }, - }, - }, - taskRunnerFactoryInitializerParams - ); - alertsClient.get.mockResolvedValue(mockedAlertTypeSavedObject); - encryptedSavedObjectsClient.getDecryptedAsInternalUser.mockResolvedValue({ - id: '1', - type: 'alert', - attributes: { - apiKey: Buffer.from('123:abc').toString('base64'), - }, - references: [], - }); - 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, - }, - }, - } - `); - - const logger = taskRunnerFactoryInitializerParams.logger; - expect(logger.debug).toHaveBeenCalledTimes(4); - expect(logger.debug).nthCalledWith(1, 'executing alert test:1 at 1970-01-01T00:00:00.000Z'); - expect(logger.debug).nthCalledWith( - 2, - `alert test:1: 'alert-name' has 1 active alert instances: [{\"instanceId\":\"1\",\"actionGroup\":\"default\"}]` - ); - expect(logger.debug).nthCalledWith( - 3, - `alert test:1: 'alert-name' has 1 recovered alert instances: [\"2\"]` - ); - expect(logger.debug).nthCalledWith( - 4, - 'alertExecutionStatus for test:1: {"lastExecutionDate":"1970-01-01T00:00:00.000Z","status":"active"}' - ); - const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; - expect(eventLogger.logEvent).toHaveBeenCalledTimes(5); expect(actionsClient.enqueueExecution).toHaveBeenCalledTimes(2); expect(actionsClient.enqueueExecution.mock.calls[0]).toMatchInlineSnapshot(` Array [ @@ -1129,7 +1302,7 @@ describe('Task Runner', () => { }); test('should skip alertInstances which werent active on the previous execution', async () => { - const alertId = uuid.v4(); + const alertId = 'e558aaad-fd81-46d2-96fc-3bd8fc3dc03f'; taskRunnerFactoryInitializerParams.actionsPlugin.isActionTypeEnabled.mockReturnValue(true); taskRunnerFactoryInitializerParams.actionsPlugin.isActionExecutable.mockReturnValue(true); @@ -1344,11 +1517,19 @@ describe('Task Runner', () => { alertInstances: { '1': { meta: { lastScheduledActions: { group: 'default', date } }, - state: { bar: false }, + state: { + bar: false, + start: '1969-12-31T00:00:00.000Z', + duration: 80000000000, + }, }, '2': { meta: { lastScheduledActions: { group: 'default', date } }, - state: { bar: false }, + state: { + bar: false, + start: '1969-12-31T06:00:00.000Z', + duration: 70000000000, + }, }, }, }, @@ -1377,6 +1558,8 @@ describe('Task Runner', () => { }, "state": Object { "bar": false, + "duration": 86400000000000, + "start": "1969-12-31T00:00:00.000Z", }, }, } @@ -1390,6 +1573,9 @@ describe('Task Runner', () => { Object { "event": Object { "action": "recovered-instance", + "duration": 64800000000000, + "end": "1970-01-01T00:00:00.000Z", + "start": "1969-12-31T06:00:00.000Z", }, "kibana": Object { "alerting": Object { @@ -1413,6 +1599,8 @@ describe('Task Runner', () => { Object { "event": Object { "action": "active-instance", + "duration": 86400000000000, + "start": "1969-12-31T00:00:00.000Z", }, "kibana": Object { "alerting": Object { @@ -2040,4 +2228,705 @@ describe('Task Runner', () => { expect(isUnrecoverableError(ex)).toBeTruthy(); }); }); + + test('start time is logged for new alerts', async () => { + taskRunnerFactoryInitializerParams.actionsPlugin.isActionTypeEnabled.mockReturnValue(true); + taskRunnerFactoryInitializerParams.actionsPlugin.isActionExecutable.mockReturnValue(true); + alertType.executor.mockImplementation( + async ({ + services: executorServices, + }: AlertExecutorOptions< + AlertTypeParams, + AlertTypeState, + AlertInstanceState, + AlertInstanceContext, + string + >) => { + executorServices.alertInstanceFactory('1').scheduleActions('default'); + executorServices.alertInstanceFactory('2').scheduleActions('default'); + } + ); + const taskRunner = new TaskRunner( + alertType, + { + ...mockedTaskInstance, + state: { + ...mockedTaskInstance.state, + alertInstances: {}, + }, + }, + taskRunnerFactoryInitializerParams + ); + alertsClient.get.mockResolvedValue({ + ...mockedAlertTypeSavedObject, + notifyWhen: 'onActionGroupChange', + actions: [], + }); + encryptedSavedObjectsClient.getDecryptedAsInternalUser.mockResolvedValue({ + id: '1', + type: 'alert', + attributes: { + apiKey: Buffer.from('123:abc').toString('base64'), + }, + references: [], + }); + await taskRunner.run(); + + const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; + expect(eventLogger.logEvent).toHaveBeenCalledTimes(5); + expect(eventLogger.logEvent.mock.calls).toMatchInlineSnapshot(` + Array [ + Array [ + Object { + "event": Object { + "action": "new-instance", + "duration": 0, + "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'", + }, + ], + Array [ + Object { + "event": Object { + "action": "new-instance", + "duration": 0, + "start": "1970-01-01T00:00:00.000Z", + }, + "kibana": Object { + "alerting": Object { + "action_group_id": "default", + "instance_id": "2", + }, + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + ], + }, + "message": "test:1: 'alert-name' created new instance: '2'", + }, + ], + Array [ + Object { + "event": Object { + "action": "active-instance", + "duration": 0, + "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' active instance: '1' in actionGroup: 'default'", + }, + ], + Array [ + Object { + "event": Object { + "action": "active-instance", + "duration": 0, + "start": "1970-01-01T00:00:00.000Z", + }, + "kibana": Object { + "alerting": Object { + "action_group_id": "default", + "instance_id": "2", + }, + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + ], + }, + "message": "test:1: 'alert-name' active instance: '2' in actionGroup: 'default'", + }, + ], + Array [ + Object { + "@timestamp": "1970-01-01T00:00:00.000Z", + "event": Object { + "action": "execute", + "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'", + }, + ], + ] + `); + }); + + test('duration is updated for active alerts when alert state contains start time', async () => { + taskRunnerFactoryInitializerParams.actionsPlugin.isActionTypeEnabled.mockReturnValue(true); + taskRunnerFactoryInitializerParams.actionsPlugin.isActionExecutable.mockReturnValue(true); + alertType.executor.mockImplementation( + async ({ + services: executorServices, + }: AlertExecutorOptions< + AlertTypeParams, + AlertTypeState, + AlertInstanceState, + AlertInstanceContext, + string + >) => { + executorServices.alertInstanceFactory('1').scheduleActions('default'); + executorServices.alertInstanceFactory('2').scheduleActions('default'); + } + ); + const taskRunner = new TaskRunner( + alertType, + { + ...mockedTaskInstance, + state: { + ...mockedTaskInstance.state, + alertInstances: { + '1': { + meta: {}, + state: { + bar: false, + start: '1969-12-31T00:00:00.000Z', + duration: 80000000000, + }, + }, + '2': { + meta: {}, + state: { + bar: false, + start: '1969-12-31T06:00:00.000Z', + duration: 70000000000, + }, + }, + }, + }, + }, + taskRunnerFactoryInitializerParams + ); + alertsClient.get.mockResolvedValue({ + ...mockedAlertTypeSavedObject, + notifyWhen: 'onActionGroupChange', + actions: [], + }); + encryptedSavedObjectsClient.getDecryptedAsInternalUser.mockResolvedValue({ + id: '1', + type: 'alert', + attributes: { + apiKey: Buffer.from('123:abc').toString('base64'), + }, + references: [], + }); + await taskRunner.run(); + + const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; + expect(eventLogger.logEvent).toHaveBeenCalledTimes(3); + expect(eventLogger.logEvent.mock.calls).toMatchInlineSnapshot(` + Array [ + Array [ + Object { + "event": Object { + "action": "active-instance", + "duration": 86400000000000, + "start": "1969-12-31T00: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' active instance: '1' in actionGroup: 'default'", + }, + ], + Array [ + Object { + "event": Object { + "action": "active-instance", + "duration": 64800000000000, + "start": "1969-12-31T06:00:00.000Z", + }, + "kibana": Object { + "alerting": Object { + "action_group_id": "default", + "instance_id": "2", + }, + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + ], + }, + "message": "test:1: 'alert-name' active instance: '2' in actionGroup: 'default'", + }, + ], + Array [ + Object { + "@timestamp": "1970-01-01T00:00:00.000Z", + "event": Object { + "action": "execute", + "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'", + }, + ], + ] + `); + }); + + test('duration is not calculated for active alerts when alert state does not contain start time', async () => { + taskRunnerFactoryInitializerParams.actionsPlugin.isActionTypeEnabled.mockReturnValue(true); + taskRunnerFactoryInitializerParams.actionsPlugin.isActionExecutable.mockReturnValue(true); + alertType.executor.mockImplementation( + async ({ + services: executorServices, + }: AlertExecutorOptions< + AlertTypeParams, + AlertTypeState, + AlertInstanceState, + AlertInstanceContext, + string + >) => { + executorServices.alertInstanceFactory('1').scheduleActions('default'); + executorServices.alertInstanceFactory('2').scheduleActions('default'); + } + ); + const taskRunner = new TaskRunner( + alertType, + { + ...mockedTaskInstance, + state: { + ...mockedTaskInstance.state, + alertInstances: { + '1': { + meta: {}, + state: { bar: false }, + }, + '2': { + meta: {}, + state: { bar: false }, + }, + }, + }, + }, + taskRunnerFactoryInitializerParams + ); + alertsClient.get.mockResolvedValue({ + ...mockedAlertTypeSavedObject, + notifyWhen: 'onActionGroupChange', + actions: [], + }); + encryptedSavedObjectsClient.getDecryptedAsInternalUser.mockResolvedValue({ + id: '1', + type: 'alert', + attributes: { + apiKey: Buffer.from('123:abc').toString('base64'), + }, + references: [], + }); + await taskRunner.run(); + + const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; + expect(eventLogger.logEvent).toHaveBeenCalledTimes(3); + expect(eventLogger.logEvent.mock.calls).toMatchInlineSnapshot(` + Array [ + Array [ + Object { + "event": Object { + "action": "active-instance", + }, + "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' active instance: '1' in actionGroup: 'default'", + }, + ], + Array [ + Object { + "event": Object { + "action": "active-instance", + }, + "kibana": Object { + "alerting": Object { + "action_group_id": "default", + "instance_id": "2", + }, + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + ], + }, + "message": "test:1: 'alert-name' active instance: '2' in actionGroup: 'default'", + }, + ], + Array [ + Object { + "@timestamp": "1970-01-01T00:00:00.000Z", + "event": Object { + "action": "execute", + "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'", + }, + ], + ] + `); + }); + + test('end is logged for active alerts when alert state contains start time and alert recovers', async () => { + taskRunnerFactoryInitializerParams.actionsPlugin.isActionTypeEnabled.mockReturnValue(true); + taskRunnerFactoryInitializerParams.actionsPlugin.isActionExecutable.mockReturnValue(true); + alertType.executor.mockImplementation(async () => {}); + const taskRunner = new TaskRunner( + alertType, + { + ...mockedTaskInstance, + state: { + ...mockedTaskInstance.state, + alertInstances: { + '1': { + meta: {}, + state: { + bar: false, + start: '1969-12-31T00:00:00.000Z', + duration: 80000000000, + }, + }, + '2': { + meta: {}, + state: { + bar: false, + start: '1969-12-31T06:00:00.000Z', + duration: 70000000000, + }, + }, + }, + }, + }, + taskRunnerFactoryInitializerParams + ); + alertsClient.get.mockResolvedValue({ + ...mockedAlertTypeSavedObject, + notifyWhen: 'onActionGroupChange', + actions: [], + }); + encryptedSavedObjectsClient.getDecryptedAsInternalUser.mockResolvedValue({ + id: '1', + type: 'alert', + attributes: { + apiKey: Buffer.from('123:abc').toString('base64'), + }, + references: [], + }); + await taskRunner.run(); + + const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; + expect(eventLogger.logEvent).toHaveBeenCalledTimes(3); + expect(eventLogger.logEvent.mock.calls).toMatchInlineSnapshot(` + Array [ + Array [ + Object { + "event": Object { + "action": "recovered-instance", + "duration": 86400000000000, + "end": "1970-01-01T00:00:00.000Z", + "start": "1969-12-31T00:00:00.000Z", + }, + "kibana": Object { + "alerting": Object { + "instance_id": "1", + }, + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + ], + }, + "message": "test:1: 'alert-name' instance '1' has recovered", + }, + ], + Array [ + Object { + "event": Object { + "action": "recovered-instance", + "duration": 64800000000000, + "end": "1970-01-01T00:00:00.000Z", + "start": "1969-12-31T06:00:00.000Z", + }, + "kibana": Object { + "alerting": Object { + "instance_id": "2", + }, + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + ], + }, + "message": "test:1: 'alert-name' instance '2' has recovered", + }, + ], + Array [ + Object { + "@timestamp": "1970-01-01T00:00:00.000Z", + "event": Object { + "action": "execute", + "outcome": "success", + }, + "kibana": Object { + "alerting": Object { + "status": "ok", + }, + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + ], + }, + "message": "alert executed: test:1: 'alert-name'", + }, + ], + ] + `); + }); + + test('end calculation is skipped for active alerts when alert state does not contain start time and alert recovers', async () => { + taskRunnerFactoryInitializerParams.actionsPlugin.isActionTypeEnabled.mockReturnValue(true); + taskRunnerFactoryInitializerParams.actionsPlugin.isActionExecutable.mockReturnValue(true); + alertType.executor.mockImplementation( + async ({ + services: executorServices, + }: AlertExecutorOptions< + AlertTypeParams, + AlertTypeState, + AlertInstanceState, + AlertInstanceContext, + string + >) => {} + ); + const taskRunner = new TaskRunner( + alertType, + { + ...mockedTaskInstance, + state: { + ...mockedTaskInstance.state, + alertInstances: { + '1': { + meta: {}, + state: { bar: false }, + }, + '2': { + meta: {}, + state: { bar: false }, + }, + }, + }, + }, + taskRunnerFactoryInitializerParams + ); + alertsClient.get.mockResolvedValue({ + ...mockedAlertTypeSavedObject, + notifyWhen: 'onActionGroupChange', + actions: [], + }); + encryptedSavedObjectsClient.getDecryptedAsInternalUser.mockResolvedValue({ + id: '1', + type: 'alert', + attributes: { + apiKey: Buffer.from('123:abc').toString('base64'), + }, + references: [], + }); + await taskRunner.run(); + + const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; + expect(eventLogger.logEvent).toHaveBeenCalledTimes(3); + expect(eventLogger.logEvent.mock.calls).toMatchInlineSnapshot(` + Array [ + Array [ + Object { + "event": Object { + "action": "recovered-instance", + }, + "kibana": Object { + "alerting": Object { + "instance_id": "1", + }, + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + ], + }, + "message": "test:1: 'alert-name' instance '1' has recovered", + }, + ], + Array [ + Object { + "event": Object { + "action": "recovered-instance", + }, + "kibana": Object { + "alerting": Object { + "instance_id": "2", + }, + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + ], + }, + "message": "test:1: 'alert-name' instance '2' has recovered", + }, + ], + Array [ + Object { + "@timestamp": "1970-01-01T00:00:00.000Z", + "event": Object { + "action": "execute", + "outcome": "success", + }, + "kibana": Object { + "alerting": Object { + "status": "ok", + }, + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + "type_id": "test", + }, + ], + }, + "message": "alert executed: test:1: 'alert-name'", + }, + ], + ] + `); + }); }); 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 fd82b38b493d7..f139617291a84 100644 --- a/x-pack/plugins/alerting/server/task_runner/task_runner.ts +++ b/x-pack/plugins/alerting/server/task_runner/task_runner.ts @@ -323,6 +323,12 @@ export class TaskRunner< alertLabel, }); + trackAlertDurations({ + originalAlerts: originalAlertInstances, + currentAlerts: instancesWithScheduledActions, + recoveredAlerts: recoveredAlertInstances, + }); + generateNewAndRecoveredInstanceEvents({ eventLogger, originalAlertInstances, @@ -589,6 +595,61 @@ export class TaskRunner< } } +interface TrackAlertDurationsParams< + InstanceState extends AlertInstanceState, + InstanceContext extends AlertInstanceContext +> { + originalAlerts: Dictionary>; + currentAlerts: Dictionary>; + recoveredAlerts: Dictionary>; +} + +function trackAlertDurations< + InstanceState extends AlertInstanceState, + InstanceContext extends AlertInstanceContext +>(params: TrackAlertDurationsParams) { + const currentTime = new Date().toISOString(); + const { currentAlerts, originalAlerts, recoveredAlerts } = params; + const originalAlertIds = Object.keys(originalAlerts); + const currentAlertIds = Object.keys(currentAlerts); + const recoveredAlertIds = Object.keys(recoveredAlerts); + const newAlertIds = without(currentAlertIds, ...originalAlertIds); + + // Inject start time into instance state of new instances + for (const id of newAlertIds) { + const state = currentAlerts[id].getState(); + currentAlerts[id].replaceState({ ...state, start: currentTime }); + } + + // Calculate duration to date for active instances + for (const id of currentAlertIds) { + const state = originalAlertIds.includes(id) + ? originalAlerts[id].getState() + : currentAlerts[id].getState(); + const duration = state.start + ? (new Date(currentTime).valueOf() - new Date(state.start as string).valueOf()) * 1000 * 1000 // nanoseconds + : undefined; + currentAlerts[id].replaceState({ + ...state, + ...(state.start ? { start: state.start } : {}), + ...(duration !== undefined ? { duration } : {}), + }); + } + + // Inject end time into instance state of recovered instances + for (const id of recoveredAlertIds) { + const state = recoveredAlerts[id].getState(); + const duration = state.start + ? (new Date(currentTime).valueOf() - new Date(state.start as string).valueOf()) * 1000 * 1000 // nanoseconds + : undefined; + recoveredAlerts[id].replaceState({ + ...state, + ...(duration ? { duration } : {}), + ...(state.start ? { end: currentTime } : {}), + }); + } +} + interface GenerateNewAndRecoveredInstanceEventsParams< InstanceState extends AlertInstanceState, InstanceContext extends AlertInstanceContext @@ -624,38 +685,66 @@ function generateNewAndRecoveredInstanceEvents< for (const id of recoveredAlertInstanceIds) { const { group: actionGroup, subgroup: actionSubgroup } = recoveredAlertInstances[id].getLastScheduledActions() ?? {}; + const state = recoveredAlertInstances[id].getState(); const message = `${params.alertLabel} instance '${id}' has recovered`; - logInstanceEvent(id, EVENT_LOG_ACTIONS.recoveredInstance, message, actionGroup, actionSubgroup); + logInstanceEvent( + id, + EVENT_LOG_ACTIONS.recoveredInstance, + message, + state, + actionGroup, + actionSubgroup + ); } for (const id of newIds) { const { actionGroup, subgroup: actionSubgroup } = currentAlertInstances[id].getScheduledActionOptions() ?? {}; + const state = currentAlertInstances[id].getState(); const message = `${params.alertLabel} created new instance: '${id}'`; - logInstanceEvent(id, EVENT_LOG_ACTIONS.newInstance, message, actionGroup, actionSubgroup); + logInstanceEvent( + id, + EVENT_LOG_ACTIONS.newInstance, + message, + state, + actionGroup, + actionSubgroup + ); } for (const id of currentAlertInstanceIds) { const { actionGroup, subgroup: actionSubgroup } = currentAlertInstances[id].getScheduledActionOptions() ?? {}; + const state = currentAlertInstances[id].getState(); const message = `${params.alertLabel} active instance: '${id}' in ${ actionSubgroup ? `actionGroup(subgroup): '${actionGroup}(${actionSubgroup})'` : `actionGroup: '${actionGroup}'` }`; - logInstanceEvent(id, EVENT_LOG_ACTIONS.activeInstance, message, actionGroup, actionSubgroup); + logInstanceEvent( + id, + EVENT_LOG_ACTIONS.activeInstance, + message, + state, + actionGroup, + actionSubgroup + ); } function logInstanceEvent( instanceId: string, action: string, message: string, + state: InstanceState, group?: string, subgroup?: string ) { const event: IEvent = { event: { action, + ...(state?.start ? { start: state.start as string } : {}), + ...(state?.end ? { end: state.end as string } : {}), + ...(state?.duration !== undefined ? { duration: state.duration as number } : {}), }, kibana: { alerting: { 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 40c0fe398bc57..c1f6bcb9e1510 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 @@ -149,13 +149,17 @@ export default function eventLogTests({ getService }: FtrProviderContext) { }); break; case 'new-instance': - validateInstanceEvent(event, `created new instance: 'instance'`); + validateInstanceEvent(event, `created new instance: 'instance'`, false); break; case 'recovered-instance': - validateInstanceEvent(event, `instance 'instance' has recovered`); + validateInstanceEvent(event, `instance 'instance' has recovered`, true); break; case 'active-instance': - validateInstanceEvent(event, `active instance: 'instance' in actionGroup: 'default'`); + validateInstanceEvent( + event, + `active instance: 'instance' in actionGroup: 'default'`, + false + ); break; // this will get triggered as we add new event actions default: @@ -163,7 +167,11 @@ export default function eventLogTests({ getService }: FtrProviderContext) { } } - function validateInstanceEvent(event: IValidatedEvent, subMessage: string) { + function validateInstanceEvent( + event: IValidatedEvent, + subMessage: string, + shouldHaveEventEnd: boolean + ) { validateEvent(event, { spaceId: Spaces.space1.id, savedObjects: [ @@ -172,6 +180,7 @@ export default function eventLogTests({ getService }: FtrProviderContext) { message: `test.patternFiring:${alertId}: 'abc' ${subMessage}`, instanceId: 'instance', actionGroupId: 'default', + shouldHaveEventEnd, }); } }); @@ -288,10 +297,10 @@ export default function eventLogTests({ getService }: FtrProviderContext) { }); break; case 'new-instance': - validateInstanceEvent(event, `created new instance: 'instance'`); + validateInstanceEvent(event, `created new instance: 'instance'`, false); break; case 'recovered-instance': - validateInstanceEvent(event, `instance 'instance' has recovered`); + validateInstanceEvent(event, `instance 'instance' has recovered`, true); break; case 'active-instance': expect( @@ -299,7 +308,8 @@ export default function eventLogTests({ getService }: FtrProviderContext) { ).to.be(true); validateInstanceEvent( event, - `active instance: 'instance' in actionGroup(subgroup): 'default(${event?.kibana?.alerting?.action_subgroup})'` + `active instance: 'instance' in actionGroup(subgroup): 'default(${event?.kibana?.alerting?.action_subgroup})'`, + false ); break; // this will get triggered as we add new event actions @@ -308,7 +318,11 @@ export default function eventLogTests({ getService }: FtrProviderContext) { } } - function validateInstanceEvent(event: IValidatedEvent, subMessage: string) { + function validateInstanceEvent( + event: IValidatedEvent, + subMessage: string, + shouldHaveEventEnd: boolean + ) { validateEvent(event, { spaceId: Spaces.space1.id, savedObjects: [ @@ -317,6 +331,7 @@ export default function eventLogTests({ getService }: FtrProviderContext) { message: `test.patternFiring:${alertId}: 'abc' ${subMessage}`, instanceId: 'instance', actionGroupId: 'default', + shouldHaveEventEnd, }); } }); @@ -376,6 +391,7 @@ interface ValidateEventLogParams { savedObjects: SavedObject[]; outcome?: string; message: string; + shouldHaveEventEnd?: boolean; errorMessage?: string; status?: string; actionGroupId?: string; @@ -385,7 +401,7 @@ interface ValidateEventLogParams { export function validateEvent(event: IValidatedEvent, params: ValidateEventLogParams): void { const { spaceId, savedObjects, outcome, message, errorMessage } = params; - const { status, actionGroupId, instanceId, reason } = params; + const { status, actionGroupId, instanceId, reason, shouldHaveEventEnd } = params; if (status) { expect(event?.kibana?.alerting?.status).to.be(status); @@ -411,16 +427,23 @@ export function validateEvent(event: IValidatedEvent, params: ValidateEventLogPa if (duration !== undefined) { expect(typeof duration).to.be('number'); expect(eventStart).to.be.ok(); - expect(eventEnd).to.be.ok(); - const durationDiff = Math.abs( - Math.round(duration! / NANOS_IN_MILLIS) - (eventEnd - eventStart) - ); + if (shouldHaveEventEnd !== false) { + expect(eventEnd).to.be.ok(); + + const durationDiff = Math.abs( + Math.round(duration! / NANOS_IN_MILLIS) - (eventEnd - eventStart) + ); - // account for rounding errors - expect(durationDiff < 1).to.equal(true); - expect(eventStart <= eventEnd).to.equal(true); - expect(eventEnd <= dateNow).to.equal(true); + // account for rounding errors + expect(durationDiff < 1).to.equal(true); + expect(eventStart <= eventEnd).to.equal(true); + expect(eventEnd <= dateNow).to.equal(true); + } + + if (shouldHaveEventEnd === false) { + expect(eventEnd).not.to.be.ok(); + } } expect(event?.event?.outcome).to.equal(outcome); diff --git a/x-pack/test/alerting_api_integration/spaces_only/tests/alerting/event_log_alerts.ts b/x-pack/test/alerting_api_integration/spaces_only/tests/alerting/event_log_alerts.ts new file mode 100644 index 0000000000000..2b92562b9bde5 --- /dev/null +++ b/x-pack/test/alerting_api_integration/spaces_only/tests/alerting/event_log_alerts.ts @@ -0,0 +1,115 @@ +/* + * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one + * or more contributor license agreements. Licensed under the Elastic License + * 2.0; you may not use this file except in compliance with the Elastic License + * 2.0. + */ + +import expect from '@kbn/expect'; +import { Spaces } from '../../scenarios'; +import { getUrlPrefix, getTestAlertData, ObjectRemover, getEventLog } from '../../../common/lib'; +import { FtrProviderContext } from '../../../common/ftr_provider_context'; +import { IValidatedEvent } from '../../../../../plugins/event_log/server'; + +// eslint-disable-next-line import/no-default-export +export default function eventLogAlertTests({ getService }: FtrProviderContext) { + const supertest = getService('supertest'); + const retry = getService('retry'); + + describe('eventLog alerts', () => { + const objectRemover = new ObjectRemover(supertest); + + after(() => objectRemover.removeAll()); + + it('should generate expected alert events for normal operation', async () => { + // pattern of when the alert should fire + const pattern = { + instance: [false, true, true, false, false, true, 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: [], + }) + ); + + expect(response.status).to.eql(200); + const ruleId = response.body.id; + objectRemover.add(Spaces.space1.id, ruleId, 'rule', 'alerting'); + + // wait for the events we're expecting + const events = await retry.try(async () => { + return await getEventLog({ + getService, + spaceId: Spaces.space1.id, + type: 'alert', + id: ruleId, + provider: 'alerting', + actions: new Map([ + // make sure the counts of the # of events per type are as expected + ['execute', { gte: 9 }], + ['new-instance', { equal: 2 }], + ['active-instance', { gte: 4 }], + ['recovered-instance', { equal: 2 }], + ]), + }); + }); + + // filter out the execute event actions + const instanceEvents = events.filter( + (event: IValidatedEvent) => event?.event?.action !== 'execute' + ); + + const currentAlertSpan: { + alertId?: string; + start?: string; + durationToDate?: number; + } = {}; + for (let i = 0; i < instanceEvents.length; ++i) { + switch (instanceEvents[i]?.event?.action) { + case 'new-instance': + expect(instanceEvents[i]?.kibana?.alerting?.instance_id).to.equal('instance'); + // a new alert should generate a unique UUID for the duration of its activeness + expect(instanceEvents[i]?.event?.end).to.be(undefined); + + currentAlertSpan.alertId = instanceEvents[i]?.kibana?.alerting?.instance_id; + currentAlertSpan.start = instanceEvents[i]?.event?.start; + currentAlertSpan.durationToDate = instanceEvents[i]?.event?.duration; + break; + + case 'active-instance': + expect(instanceEvents[i]?.kibana?.alerting?.instance_id).to.equal('instance'); + expect(instanceEvents[i]?.event?.start).to.equal(currentAlertSpan.start); + expect(instanceEvents[i]?.event?.end).to.be(undefined); + + if (instanceEvents[i]?.event?.duration! !== 0) { + expect(instanceEvents[i]?.event?.duration! > currentAlertSpan.durationToDate!).to.be( + true + ); + } + currentAlertSpan.durationToDate = instanceEvents[i]?.event?.duration; + break; + + case 'recovered-instance': + expect(instanceEvents[i]?.kibana?.alerting?.instance_id).to.equal('instance'); + expect(instanceEvents[i]?.event?.start).to.equal(currentAlertSpan.start); + expect(instanceEvents[i]?.event?.end).not.to.be(undefined); + expect( + new Date(instanceEvents[i]?.event?.end!).valueOf() - + new Date(instanceEvents[i]?.event?.start!).valueOf() + ).to.equal(instanceEvents[i]?.event?.duration! / 1000 / 1000); + break; + } + } + }); + }); +} diff --git a/x-pack/test/alerting_api_integration/spaces_only/tests/alerting/get_alert_state.ts b/x-pack/test/alerting_api_integration/spaces_only/tests/alerting/get_alert_state.ts index 9154c85af1bc7..318dfdfe065df 100644 --- a/x-pack/test/alerting_api_integration/spaces_only/tests/alerting/get_alert_state.ts +++ b/x-pack/test/alerting_api_integration/spaces_only/tests/alerting/get_alert_state.ts @@ -76,7 +76,9 @@ export default function createGetAlertStateTests({ getService }: FtrProviderCont expect(alertInstances.length).to.eql(response.body.rule_type_state.runCount); alertInstances.forEach(([key, value], index) => { expect(key).to.eql(`instance-${index}`); - expect(value.state).to.eql({ instanceStateValue: true }); + expect(value.state.instanceStateValue).to.be(true); + expect(value.state.start).not.to.be(undefined); + expect(value.state.duration).not.to.be(undefined); }); }); @@ -131,7 +133,9 @@ export default function createGetAlertStateTests({ getService }: FtrProviderCont expect(alertInstances.length).to.eql(response.body.rule_type_state.runCount); alertInstances.forEach(([key, value], index) => { expect(key).to.eql(`instance-${index}`); - expect(value.state).to.eql({ instanceStateValue: true }); + expect(value.state.instanceStateValue).to.be(true); + expect(value.state.start).not.to.be(undefined); + expect(value.state.duration).not.to.be(undefined); }); }); }); diff --git a/x-pack/test/alerting_api_integration/spaces_only/tests/alerting/index.ts b/x-pack/test/alerting_api_integration/spaces_only/tests/alerting/index.ts index e9aeec1717c96..5c3374a4d9c70 100644 --- a/x-pack/test/alerting_api_integration/spaces_only/tests/alerting/index.ts +++ b/x-pack/test/alerting_api_integration/spaces_only/tests/alerting/index.ts @@ -37,6 +37,7 @@ export default function alertingTests({ loadTestFile, getService }: FtrProviderC loadTestFile(require.resolve('./builtin_alert_types')); loadTestFile(require.resolve('./mustache_templates.ts')); loadTestFile(require.resolve('./notify_when')); + loadTestFile(require.resolve('./event_log_alerts')); // note that this test will destroy existing spaces loadTestFile(require.resolve('./migrations'));