[Actions] Fixed ad-hoc actions tasks remain as "running" when they ti…

…meout by adding cancellation support (#120853) * [Actions] Fixed ad-hoc actions tasks remain as "running" when they timeout by adding cancellation support * fixed test * fixed tests * fixed test * removed test data * fixed typechecks * fixed typechecks * fixed typechecks * fixed tests * fixed typechecks * fixed tests * fixed typechecks * fixed test * fixed tests * fixed tests * changed unit tests * fixed tests * fixed jest tests * fixed typechecks Co-authored-by: Kibana Machine <[email protected]> (cherry picked from commit 158a9a5)
elastic · Jan 19, 2022 · e964783 · e964783
1 parent e629bb2
commit e964783
Show file tree

Hide file tree

Showing 10 changed files with 423 additions and 60 deletions.
diff --git a/x-pack/plugins/actions/server/constants/event_log.ts b/x-pack/plugins/actions/server/constants/event_log.ts
@@ -10,4 +10,5 @@ export const EVENT_LOG_ACTIONS = {
   execute: 'execute',
   executeStart: 'execute-start',
   executeViaHttp: 'execute-via-http',
+  executeTimeout: 'execute-timeout',
 };
diff --git a/x-pack/plugins/actions/server/lib/action_executor.mock.ts b/x-pack/plugins/actions/server/lib/action_executor.mock.ts
@@ -11,6 +11,7 @@ const createActionExecutorMock = () => {
   const mocked: jest.Mocked<ActionExecutorContract> = {
     initialize: jest.fn(),
     execute: jest.fn().mockResolvedValue({ status: 'ok', actionId: '' }),
+    logCancellation: jest.fn(),
   };
   return mocked;
 };

diff --git a/x-pack/plugins/actions/server/lib/action_executor.test.ts b/x-pack/plugins/actions/server/lib/action_executor.test.ts
@@ -115,6 +115,7 @@ test('successfully executes', async () => {
         Object {
           "event": Object {
             "action": "execute-start",
+            "kind": "action",
           },
           "kibana": Object {
             "saved_objects": Array [
@@ -134,6 +135,7 @@ test('successfully executes', async () => {
         Object {
           "event": Object {
             "action": "execute",
+            "kind": "action",
             "outcome": "success",
           },
           "kibana": Object {
@@ -511,6 +513,34 @@ test('logs a warning when alert executor returns invalid status', async () => {
   );
 });
 
+test('writes to event log for execute timeout', async () => {
+  setupActionExecutorMock();
+
+  await actionExecutor.logCancellation({
+    actionId: 'action1',
+    relatedSavedObjects: [],
+    request: {} as KibanaRequest,
+  });
+  expect(eventLogger.logEvent).toHaveBeenCalledTimes(1);
+  expect(eventLogger.logEvent.mock.calls[0][0]).toMatchObject({
+    event: {
+      action: 'execute-timeout',
+    },
+    kibana: {
+      saved_objects: [
+        {
+          rel: 'primary',
+          type: 'action',
+          id: 'action1',
+          type_id: 'test',
+          namespace: 'some-namespace',
+        },
+      ],
+    },
+    message: `action: test:action1: 'action-1' execution cancelled due to timeout - exceeded default timeout of "5m"`,
+  });
+});
+
 test('writes to event log for execute and execute start', async () => {
   const executorMock = setupActionExecutorMock();
   executorMock.mockResolvedValue({

diff --git a/x-pack/plugins/actions/server/lib/action_executor.ts b/x-pack/plugins/actions/server/lib/action_executor.ts
@@ -19,16 +19,17 @@ import {
   ActionTypeExecutorResult,
   ActionTypeRegistryContract,
   GetServicesFunction,
-  RawAction,
   PreConfiguredAction,
+  RawAction,
 } from '../types';
 import { EncryptedSavedObjectsClient } from '../../../encrypted_saved_objects/server';
 import { SpacesServiceStart } from '../../../spaces/server';
 import { EVENT_LOG_ACTIONS } from '../constants/event_log';
-import { IEvent, IEventLogger, SAVED_OBJECT_REL_PRIMARY } from '../../../event_log/server';
+import { IEventLogger, SAVED_OBJECT_REL_PRIMARY } from '../../../event_log/server';
 import { ActionsClient } from '../actions_client';
 import { ActionExecutionSource } from './action_execution_source';
 import { RelatedSavedObjects } from './related_saved_objects';
+import { createActionEventLogRecordObject } from './create_action_event_log_record_object';
 
 // 1,000,000 nanoseconds in 1 millisecond
 const Millis2Nanos = 1000 * 1000;
@@ -68,6 +69,7 @@ export class ActionExecutor {
   private isInitialized = false;
   private actionExecutorContext?: ActionExecutorContext;
   private readonly isESOCanEncrypt: boolean;
+  private actionInfo: ActionInfo | undefined;
 
   constructor({ isESOCanEncrypt }: { isESOCanEncrypt: boolean }) {
     this.isESOCanEncrypt = isESOCanEncrypt;
@@ -124,14 +126,20 @@ export class ActionExecutor {
         const spaceId = spaces && spaces.getSpaceId(request);
         const namespace = spaceId && spaceId !== 'default' ? { namespace: spaceId } : {};
 
-        const { actionTypeId, name, config, secrets } = await getActionInfo(
+        const actionInfo = await getActionInfoInternal(
           await getActionsClientWithRequest(request, source),
           encryptedSavedObjectsClient,
           preconfiguredActions,
           actionId,
           namespace.namespace
         );
 
+        const { actionTypeId, name, config, secrets } = actionInfo;
+
+        if (!this.actionInfo || this.actionInfo.actionId !== actionId) {
+          this.actionInfo = actionInfo;
+        }
+
         if (span) {
           span.name = `execute_action ${actionTypeId}`;
           span.addLabels({
@@ -169,26 +177,25 @@ export class ActionExecutor {
           ? {
               task: {
                 scheduled: taskInfo.scheduled.toISOString(),
-                schedule_delay: Millis2Nanos * (Date.now() - taskInfo.scheduled.getTime()),
+                scheduleDelay: Millis2Nanos * (Date.now() - taskInfo.scheduled.getTime()),
               },
             }
           : {};
 
-        const event: IEvent = {
-          event: { action: EVENT_LOG_ACTIONS.execute },
-          kibana: {
-            ...task,
-            saved_objects: [
-              {
-                rel: SAVED_OBJECT_REL_PRIMARY,
-                type: 'action',
-                id: actionId,
-                type_id: actionTypeId,
-                ...namespace,
-              },
-            ],
-          },
-        };
+        const event = createActionEventLogRecordObject({
+          actionId,
+          action: EVENT_LOG_ACTIONS.execute,
+          ...namespace,
+          ...task,
+          savedObjects: [
+            {
+              type: 'action',
+              id: actionId,
+              typeId: actionTypeId,
+              relation: SAVED_OBJECT_REL_PRIMARY,
+            },
+          ],
+        });
 
         for (const relatedSavedObject of relatedSavedObjects || []) {
           event.kibana?.saved_objects?.push({
@@ -210,6 +217,7 @@ export class ActionExecutor {
           },
           message: `action started: ${actionLabel}`,
         });
+
         eventLogger.logEvent(startEvent);
 
         let rawResult: ActionTypeExecutorResult<unknown>;
@@ -269,32 +277,88 @@ export class ActionExecutor {
       }
     );
   }
-}
 
-function actionErrorToMessage(result: ActionTypeExecutorResult<unknown>): string {
-  let message = result.message || 'unknown error running action';
-
-  if (result.serviceMessage) {
-    message = `${message}: ${result.serviceMessage}`;
-  }
-
-  if (result.retry instanceof Date) {
-    message = `${message}; retry at ${result.retry.toISOString()}`;
-  } else if (result.retry) {
-    message = `${message}; retry: ${JSON.stringify(result.retry)}`;
+  public async logCancellation<Source = unknown>({
+    actionId,
+    request,
+    relatedSavedObjects,
+    source,
+    taskInfo,
+  }: {
+    actionId: string;
+    request: KibanaRequest;
+    taskInfo?: TaskInfo;
+    relatedSavedObjects: RelatedSavedObjects;
+    source?: ActionExecutionSource<Source>;
+  }) {
+    const {
+      spaces,
+      encryptedSavedObjectsClient,
+      preconfiguredActions,
+      eventLogger,
+      getActionsClientWithRequest,
+    } = this.actionExecutorContext!;
+
+    const spaceId = spaces && spaces.getSpaceId(request);
+    const namespace = spaceId && spaceId !== 'default' ? { namespace: spaceId } : {};
+    if (!this.actionInfo || this.actionInfo.actionId !== actionId) {
+      this.actionInfo = await getActionInfoInternal(
+        await getActionsClientWithRequest(request, source),
+        encryptedSavedObjectsClient,
+        preconfiguredActions,
+        actionId,
+        namespace.namespace
+      );
+    }
+    const task = taskInfo
+      ? {
+          task: {
+            scheduled: taskInfo.scheduled.toISOString(),
+            scheduleDelay: Millis2Nanos * (Date.now() - taskInfo.scheduled.getTime()),
+          },
+        }
+      : {};
+    // Write event log entry
+    const event = createActionEventLogRecordObject({
+      actionId,
+      action: EVENT_LOG_ACTIONS.executeTimeout,
+      message: `action: ${this.actionInfo.actionTypeId}:${actionId}: '${
+        this.actionInfo.name ?? ''
+      }' execution cancelled due to timeout - exceeded default timeout of "5m"`,
+      ...namespace,
+      ...task,
+      savedObjects: [
+        {
+          type: 'action',
+          id: actionId,
+          typeId: this.actionInfo.actionTypeId,
+          relation: SAVED_OBJECT_REL_PRIMARY,
+        },
+      ],
+    });
+
+    for (const relatedSavedObject of (relatedSavedObjects || []) as RelatedSavedObjects) {
+      event.kibana?.saved_objects?.push({
+        rel: SAVED_OBJECT_REL_PRIMARY,
+        type: relatedSavedObject.type,
+        id: relatedSavedObject.id,
+        type_id: relatedSavedObject.typeId,
+        namespace: relatedSavedObject.namespace,
+      });
+    }
+    eventLogger.logEvent(event);
   }
-
-  return message;
 }
 
 interface ActionInfo {
   actionTypeId: string;
   name: string;
   config: unknown;
   secrets: unknown;
+  actionId: string;
 }
 
-async function getActionInfo(
+async function getActionInfoInternal(
   actionsClient: PublicMethodsOf<ActionsClient>,
   encryptedSavedObjectsClient: EncryptedSavedObjectsClient,
   preconfiguredActions: PreConfiguredAction[],
@@ -311,6 +375,7 @@ async function getActionInfo(
       name: pcAction.name,
       config: pcAction.config,
       secrets: pcAction.secrets,
+      actionId,
     };
   }
 
@@ -329,5 +394,22 @@ async function getActionInfo(
     name,
     config,
     secrets,
+    actionId,
   };
 }
+
+function actionErrorToMessage(result: ActionTypeExecutorResult<unknown>): string {
+  let message = result.message || 'unknown error running action';
+
+  if (result.serviceMessage) {
+    message = `${message}: ${result.serviceMessage}`;
+  }
+
+  if (result.retry instanceof Date) {
+    message = `${message}; retry at ${result.retry.toISOString()}`;
+  } else if (result.retry) {
+    message = `${message}; retry: ${JSON.stringify(result.retry)}`;
+  }
+
+  return message;
+}