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 57b88d3e6c1d8..476ca467a98b9 100644 --- a/x-pack/plugins/actions/server/lib/action_executor.test.ts +++ b/x-pack/plugins/actions/server/lib/action_executor.test.ts @@ -105,6 +105,8 @@ test('successfully executes', async () => { }, params: { foo: true }, }); + + expect(loggerMock.debug).toBeCalledWith('executing action test:1: 1'); }); 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 d050bab9b0d9f..695613a59eff1 100644 --- a/x-pack/plugins/actions/server/lib/action_executor.ts +++ b/x-pack/plugins/actions/server/lib/action_executor.ts @@ -120,6 +120,8 @@ export class ActionExecutor { } const actionLabel = `${actionTypeId}:${actionId}: ${name}`; + logger.debug(`executing action ${actionLabel}`); + const event: IEvent = { event: { action: EVENT_LOG_ACTIONS.execute }, kibana: { diff --git a/x-pack/plugins/alerts/server/task_runner/task_runner.test.ts b/x-pack/plugins/alerts/server/task_runner/task_runner.test.ts index a2b281036d4cc..2c49eed0cf6e3 100644 --- a/x-pack/plugins/alerts/server/task_runner/task_runner.test.ts +++ b/x-pack/plugins/alerts/server/task_runner/task_runner.test.ts @@ -190,6 +190,14 @@ describe('Task Runner', () => { expect(call.services.callCluster).toBeTruthy(); expect(call.services).toBeTruthy(); + const logger = taskRunnerFactoryInitializerParams.logger; + expect(logger.debug).toHaveBeenCalledTimes(2); + expect(logger.debug).nthCalledWith(1, 'executing alert test:1 at 1970-01-01T00:00:00.000Z'); + expect(logger.debug).nthCalledWith( + 2, + 'alertExecutionStatus for test:1: {"lastExecutionDate":"1970-01-01T00:00:00.000Z","status":"ok"}' + ); + const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; expect(eventLogger.logEvent).toHaveBeenCalledTimes(1); expect(eventLogger.logEvent.mock.calls[0][0]).toMatchInlineSnapshot(` @@ -261,6 +269,18 @@ describe('Task Runner', () => { ] `); + const logger = taskRunnerFactoryInitializerParams.logger; + expect(logger.debug).toHaveBeenCalledTimes(3); + 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, + 'alertExecutionStatus for test:1: {"lastExecutionDate":"1970-01-01T00:00:00.000Z","status":"active"}' + ); + const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; expect(eventLogger.logEvent).toHaveBeenCalledTimes(4); expect(eventLogger.logEvent).toHaveBeenNthCalledWith(1, { @@ -352,6 +372,161 @@ describe('Task Runner', () => { }); }); + test('actionsPlugin.execute is skipped if muteAll is true', async () => { + taskRunnerFactoryInitializerParams.actionsPlugin.isActionTypeEnabled.mockReturnValue(true); + taskRunnerFactoryInitializerParams.actionsPlugin.isActionExecutable.mockReturnValue(true); + alertType.executor.mockImplementation( + ({ services: executorServices }: AlertExecutorOptions) => { + executorServices.alertInstanceFactory('1').scheduleActions('default'); + } + ); + const taskRunner = new TaskRunner( + alertType, + mockedTaskInstance, + taskRunnerFactoryInitializerParams + ); + alertsClient.get.mockResolvedValue({ + ...mockedAlertTypeSavedObject, + muteAll: true, + }); + encryptedSavedObjectsClient.getDecryptedAsInternalUser.mockResolvedValue({ + id: '1', + type: 'alert', + attributes: { + apiKey: Buffer.from('123:abc').toString('base64'), + }, + references: [], + }); + await taskRunner.run(); + expect(actionsClient.enqueueExecution).toHaveBeenCalledTimes(0); + + 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, + `no scheduling of actions for alert test:1: 'alert-name': alert is muted.` + ); + 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(3); + expect(eventLogger.logEvent).toHaveBeenNthCalledWith(1, { + event: { + action: 'new-instance', + }, + kibana: { + alerting: { + action_group_id: 'default', + instance_id: '1', + }, + saved_objects: [ + { + id: '1', + namespace: undefined, + rel: 'primary', + type: 'alert', + }, + ], + }, + message: "test:1: 'alert-name' created new instance: '1'", + }); + expect(eventLogger.logEvent).toHaveBeenNthCalledWith(2, { + event: { + action: 'active-instance', + }, + kibana: { + alerting: { + instance_id: '1', + action_group_id: 'default', + }, + saved_objects: [ + { + id: '1', + namespace: undefined, + rel: 'primary', + type: 'alert', + }, + ], + }, + message: "test:1: 'alert-name' active instance: '1' in actionGroup: 'default'", + }); + expect(eventLogger.logEvent).toHaveBeenNthCalledWith(3, { + '@timestamp': '1970-01-01T00:00:00.000Z', + event: { + action: 'execute', + outcome: 'success', + }, + kibana: { + alerting: { + status: 'active', + }, + saved_objects: [ + { + id: '1', + namespace: undefined, + rel: 'primary', + type: 'alert', + }, + ], + }, + message: "alert executed: test:1: 'alert-name'", + }); + }); + + test('skips firing actions for active instance if instance is muted', async () => { + taskRunnerFactoryInitializerParams.actionsPlugin.isActionTypeEnabled.mockReturnValue(true); + taskRunnerFactoryInitializerParams.actionsPlugin.isActionExecutable.mockReturnValue(true); + alertType.executor.mockImplementation( + ({ services: executorServices }: AlertExecutorOptions) => { + executorServices.alertInstanceFactory('1').scheduleActions('default'); + executorServices.alertInstanceFactory('2').scheduleActions('default'); + } + ); + const taskRunner = new TaskRunner( + alertType, + mockedTaskInstance, + taskRunnerFactoryInitializerParams + ); + alertsClient.get.mockResolvedValue({ + ...mockedAlertTypeSavedObject, + mutedInstanceIds: ['2'], + }); + encryptedSavedObjectsClient.getDecryptedAsInternalUser.mockResolvedValue({ + id: '1', + type: 'alert', + attributes: { + apiKey: Buffer.from('123:abc').toString('base64'), + }, + references: [], + }); + await taskRunner.run(); + expect(actionsClient.enqueueExecution).toHaveBeenCalledTimes(1); + + 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 2 active alert instances: [{\"instanceId\":\"1\",\"actionGroup\":\"default\"},{\"instanceId\":\"2\",\"actionGroup\":\"default\"}]` + ); + expect(logger.debug).nthCalledWith( + 3, + `skipping scheduling of actions for '2' in alert test:1: 'alert-name': instance is muted` + ); + expect(logger.debug).nthCalledWith( + 4, + 'alertExecutionStatus for test:1: {"lastExecutionDate":"1970-01-01T00:00:00.000Z","status":"active"}' + ); + }); + test('includes the apiKey in the request used to initialize the actionsClient', async () => { taskRunnerFactoryInitializerParams.actionsPlugin.isActionTypeEnabled.mockReturnValue(true); taskRunnerFactoryInitializerParams.actionsPlugin.isActionExecutable.mockReturnValue(true); @@ -567,6 +742,22 @@ describe('Task Runner', () => { } `); + 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); diff --git a/x-pack/plugins/alerts/server/task_runner/task_runner.ts b/x-pack/plugins/alerts/server/task_runner/task_runner.ts index 5cb86c32420e1..0c486dad070ef 100644 --- a/x-pack/plugins/alerts/server/task_runner/task_runner.ts +++ b/x-pack/plugins/alerts/server/task_runner/task_runner.ts @@ -218,38 +218,61 @@ export class TaskRunner { const instancesWithScheduledActions = pickBy(alertInstances, (alertInstance: AlertInstance) => alertInstance.hasScheduledActions() ); + const recoveredAlertInstances = pickBy( + alertInstances, + (alertInstance: AlertInstance) => !alertInstance.hasScheduledActions() + ); + + logActiveAndRecoveredInstances({ + logger: this.logger, + activeAlertInstances: instancesWithScheduledActions, + recoveredAlertInstances, + alertLabel, + }); generateNewAndRecoveredInstanceEvents({ eventLogger, originalAlertInstances, currentAlertInstances: instancesWithScheduledActions, + recoveredAlertInstances, alertId, alertLabel, namespace, }); if (!muteAll) { - scheduleActionsForRecoveredInstances( - this.alertType.recoveryActionGroup, - alertInstances, - executionHandler, - originalAlertInstances, - instancesWithScheduledActions, - alert.mutedInstanceIds - ); - const mutedInstanceIdsSet = new Set(mutedInstanceIds); + scheduleActionsForRecoveredInstances({ + recoveryActionGroup: this.alertType.recoveryActionGroup, + recoveredAlertInstances, + executionHandler, + mutedInstanceIdsSet, + logger: this.logger, + alertLabel, + }); + await Promise.all( Object.entries(instancesWithScheduledActions) - .filter( - ([alertInstanceName, alertInstance]: [string, AlertInstance]) => - !alertInstance.isThrottled(throttle) && !mutedInstanceIdsSet.has(alertInstanceName) - ) + .filter(([alertInstanceName, alertInstance]: [string, AlertInstance]) => { + const throttled = alertInstance.isThrottled(throttle); + const muted = mutedInstanceIdsSet.has(alertInstanceName); + const shouldExecuteAction = !throttled && !muted; + if (!shouldExecuteAction) { + this.logger.debug( + `skipping scheduling of actions for '${alertInstanceName}' in alert ${alertLabel}: instance is ${ + muted ? 'muted' : 'throttled' + }` + ); + } + return shouldExecuteAction; + }) .map(([id, alertInstance]: [string, AlertInstance]) => this.executeAlertInstance(id, alertInstance, executionHandler) ) ); + } else { + this.logger.debug(`no scheduling of actions for alert ${alertLabel}: alert is muted.`); } return { @@ -333,12 +356,15 @@ export class TaskRunner { schedule: taskSchedule, } = this.taskInstance; + const runDate = new Date().toISOString(); + this.logger.debug(`executing alert ${this.alertType.id}:${alertId} at ${runDate}`); + const namespace = this.context.spaceIdToNamespace(spaceId); const eventLogger = this.context.eventLogger; const event: IEvent = { // explicitly set execute timestamp so it will be before other events // generated here (new-instance, schedule-action, etc) - '@timestamp': new Date().toISOString(), + '@timestamp': runDate, event: { action: EVENT_LOG_ACTIONS.execute }, kibana: { saved_objects: [ @@ -441,6 +467,7 @@ interface GenerateNewAndRecoveredInstanceEventsParams { eventLogger: IEventLogger; originalAlertInstances: Dictionary; currentAlertInstances: Dictionary; + recoveredAlertInstances: Dictionary; alertId: string; alertLabel: string; namespace: string | undefined; @@ -449,14 +476,21 @@ interface GenerateNewAndRecoveredInstanceEventsParams { function generateNewAndRecoveredInstanceEvents( params: GenerateNewAndRecoveredInstanceEventsParams ) { - const { eventLogger, alertId, namespace, currentAlertInstances, originalAlertInstances } = params; + const { + eventLogger, + alertId, + namespace, + currentAlertInstances, + originalAlertInstances, + recoveredAlertInstances, + } = params; const originalAlertInstanceIds = Object.keys(originalAlertInstances); const currentAlertInstanceIds = Object.keys(currentAlertInstances); + const recoveredAlertInstanceIds = Object.keys(recoveredAlertInstances); const newIds = without(currentAlertInstanceIds, ...originalAlertInstanceIds); - const recoveredIds = without(originalAlertInstanceIds, ...currentAlertInstanceIds); - for (const id of recoveredIds) { + for (const id of recoveredAlertInstanceIds) { const actionGroup = originalAlertInstances[id].getLastScheduledActions()?.group; const message = `${params.alertLabel} instance '${id}' has recovered`; logInstanceEvent(id, EVENT_LOG_ACTIONS.recoveredInstance, message, actionGroup); @@ -499,32 +533,72 @@ function generateNewAndRecoveredInstanceEvents( } } -function scheduleActionsForRecoveredInstances( - recoveryActionGroup: ActionGroup, - alertInstancesMap: Record, - executionHandler: ReturnType, - originalAlertInstances: Record, - currentAlertInstances: Dictionary, - mutedInstanceIds: string[] -) { - const currentAlertInstanceIds = Object.keys(currentAlertInstances); - const originalAlertInstanceIds = Object.keys(originalAlertInstances); - const recoveredIds = without( - originalAlertInstanceIds, - ...currentAlertInstanceIds, - ...mutedInstanceIds - ); +interface ScheduleActionsForRecoveredInstancesParams { + logger: Logger; + recoveryActionGroup: ActionGroup; + recoveredAlertInstances: Dictionary; + executionHandler: ReturnType; + mutedInstanceIdsSet: Set; + alertLabel: string; +} + +function scheduleActionsForRecoveredInstances(params: ScheduleActionsForRecoveredInstancesParams) { + const { + logger, + recoveryActionGroup, + recoveredAlertInstances, + executionHandler, + mutedInstanceIdsSet, + alertLabel, + } = params; + const recoveredIds = Object.keys(recoveredAlertInstances); for (const id of recoveredIds) { - const instance = alertInstancesMap[id]; - instance.updateLastScheduledActions(recoveryActionGroup.id); - instance.unscheduleActions(); - executionHandler({ - actionGroup: recoveryActionGroup.id, - context: {}, - state: {}, - alertInstanceId: id, - }); - instance.scheduleActions(recoveryActionGroup.id); + if (mutedInstanceIdsSet.has(id)) { + logger.debug( + `skipping scheduling of actions for '${id}' in alert ${alertLabel}: instance is muted` + ); + } else { + const instance = recoveredAlertInstances[id]; + instance.updateLastScheduledActions(recoveryActionGroup.id); + instance.unscheduleActions(); + executionHandler({ + actionGroup: recoveryActionGroup.id, + context: {}, + state: {}, + alertInstanceId: id, + }); + instance.scheduleActions(recoveryActionGroup.id); + } + } +} + +interface LogActiveAndRecoveredInstancesParams { + logger: Logger; + activeAlertInstances: Dictionary; + recoveredAlertInstances: Dictionary; + alertLabel: string; +} + +function logActiveAndRecoveredInstances(params: LogActiveAndRecoveredInstancesParams) { + const { logger, activeAlertInstances, recoveredAlertInstances, alertLabel } = params; + const activeInstanceIds = Object.keys(activeAlertInstances); + const recoveredInstanceIds = Object.keys(recoveredAlertInstances); + if (activeInstanceIds.length > 0) { + logger.debug( + `alert ${alertLabel} has ${activeInstanceIds.length} active alert instances: ${JSON.stringify( + activeInstanceIds.map((instanceId) => ({ + instanceId, + actionGroup: activeAlertInstances[instanceId].getScheduledActionOptions()?.actionGroup, + })) + )}` + ); + } + if (recoveredInstanceIds.length > 0) { + logger.debug( + `alert ${alertLabel} has ${ + recoveredInstanceIds.length + } recovered alert instances: ${JSON.stringify(recoveredInstanceIds)}` + ); } }