[Alerting & Actions ] More debug logging (#85149)

* Adding debug messages

* Adding timestamp to action execution log

* Jest tests

* Merging in master

* PR fixes

* Cleanup

* PR fixes

Co-authored-by: Kibana Machine <42973632+kibanamachine@users.noreply.github.com>

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 () => {

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: {

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);

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<AlertInstance>;
   currentAlertInstances: Dictionary<AlertInstance>;
+  recoveredAlertInstances: Dictionary<AlertInstance>;
   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<string, AlertInstance>,
-  executionHandler: ReturnType<typeof createExecutionHandler>,
-  originalAlertInstances: Record<string, AlertInstance>,
-  currentAlertInstances: Dictionary<AlertInstance>,
-  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<AlertInstance>;
+  executionHandler: ReturnType<typeof createExecutionHandler>;
+  mutedInstanceIdsSet: Set<string>;
+  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<AlertInstance>;
+  recoveredAlertInstances: Dictionary<AlertInstance>;
+  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)}`
+    );
   }
 }