[alerting][actions] add task scheduled date and delay to event log

resolves elastic#98634 This adds a new object property to the event log kibana object named task, with two properties to track the time the task was scheduled to run, and the delay between when it was supposed to run and when it actually started. This task property is only added to the appropriate events. task: schema.maybe( schema.object({ scheduled: ecsDate(), schedule_delay: ecsNumber(), }) ),
pmuellr · Jun 20, 2021 · 6e368f1 · 6e368f1
1 parent 693823f
commit 6e368f1
Show file tree

Hide file tree

Showing 17 changed files with 764 additions and 503 deletions.
diff --git a/x-pack/plugins/actions/server/lib/action_executor.test.ts b/x-pack/plugins/actions/server/lib/action_executor.test.ts
@@ -23,6 +23,7 @@ const services = actionsMock.createServices();
 const actionsClient = actionsClientMock.create();
 const encryptedSavedObjectsClient = encryptedSavedObjectsMock.createClient();
 const actionTypeRegistry = actionTypeRegistryMock.create();
+const eventLogger = eventLoggerMock.create();
 
 const executeParams = {
   actionId: '1',
@@ -42,7 +43,7 @@ actionExecutor.initialize({
   getActionsClientWithRequest,
   actionTypeRegistry,
   encryptedSavedObjectsClient,
-  eventLogger: eventLoggerMock.create(),
+  eventLogger,
   preconfiguredActions: [],
 });
 
@@ -108,6 +109,77 @@ test('successfully executes', async () => {
   });
 
   expect(loggerMock.debug).toBeCalledWith('executing action test:1: 1');
+  expect(eventLogger.logEvent.mock.calls).toMatchInlineSnapshot(`
+    Array [
+      Array [
+        Object {
+          "event": Object {
+            "action": "execute",
+            "outcome": "success",
+          },
+          "kibana": Object {
+            "saved_objects": Array [
+              Object {
+                "id": "1",
+                "namespace": "some-namespace",
+                "rel": "primary",
+                "type": "action",
+                "type_id": "test",
+              },
+            ],
+          },
+          "message": "action executed: test:1: 1",
+        },
+      ],
+    ]
+  `);
+});
+
+test('successfully executes as a task', async () => {
+  const actionType: jest.Mocked<ActionType> = {
+    id: 'test',
+    name: 'Test',
+    minimumLicenseRequired: 'basic',
+    executor: jest.fn(),
+  };
+  const actionSavedObject = {
+    id: '1',
+    type: 'action',
+    attributes: {
+      actionTypeId: 'test',
+      config: {
+        bar: true,
+      },
+      secrets: {
+        baz: true,
+      },
+    },
+    references: [],
+  };
+  const actionResult = {
+    id: actionSavedObject.id,
+    name: actionSavedObject.id,
+    ...pick(actionSavedObject.attributes, 'actionTypeId', 'config'),
+    isPreconfigured: false,
+  };
+  actionsClient.get.mockResolvedValueOnce(actionResult);
+  encryptedSavedObjectsClient.getDecryptedAsInternalUser.mockResolvedValueOnce(actionSavedObject);
+  actionTypeRegistry.get.mockReturnValueOnce(actionType);
+
+  const scheduleDelay = 10000; // milliseconds
+  const scheduled = new Date(Date.now() - scheduleDelay);
+  await actionExecutor.execute({
+    ...executeParams,
+    taskInfo: {
+      scheduled,
+    },
+  });
+
+  const eventTask = eventLogger.logEvent.mock.calls[0][0]?.kibana?.task;
+  expect(eventTask).toBeDefined();
+  expect(eventTask?.scheduled).toBe(scheduled.toISOString());
+  expect(eventTask?.schedule_delay).toBeGreaterThanOrEqual(scheduleDelay * 1000 * 1000);
+  expect(eventTask?.schedule_delay).toBeLessThanOrEqual(2 * scheduleDelay * 1000 * 1000);
 });
 
 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
@@ -23,6 +23,9 @@ import { IEvent, IEventLogger, SAVED_OBJECT_REL_PRIMARY } from '../../../event_l
 import { ActionsClient } from '../actions_client';
 import { ActionExecutionSource } from './action_execution_source';
 
+// 1,000,000 nanoseconds in 1 millisecond
+const Millis2Nanos = 1000 * 1000;
+
 export interface ActionExecutorContext {
   logger: Logger;
   spaces?: SpacesServiceStart;
@@ -37,11 +40,16 @@ export interface ActionExecutorContext {
   preconfiguredActions: PreConfiguredAction[];
 }
 
+export interface TaskInfo {
+  scheduled: Date;
+}
+
 export interface ExecuteOptions<Source = unknown> {
   actionId: string;
   request: KibanaRequest;
   params: Record<string, unknown>;
   source?: ActionExecutionSource<Source>;
+  taskInfo?: TaskInfo;
 }
 
 export type ActionExecutorContract = PublicMethodsOf<ActionExecutor>;
@@ -68,6 +76,7 @@ export class ActionExecutor {
     params,
     request,
     source,
+    taskInfo,
   }: ExecuteOptions): Promise<ActionTypeExecutorResult<unknown>> {
     if (!this.isInitialized) {
       throw new Error('ActionExecutor not initialized');
@@ -139,9 +148,19 @@ export class ActionExecutor {
         const actionLabel = `${actionTypeId}:${actionId}: ${name}`;
         logger.debug(`executing action ${actionLabel}`);
 
+        const task = taskInfo
+          ? {
+              task: {
+                scheduled: taskInfo.scheduled.toISOString(),
+                schedule_delay: Millis2Nanos * (Date.now() - taskInfo.scheduled.getTime()),
+              },
+            }
+          : {};
+
         const event: IEvent = {
           event: { action: EVENT_LOG_ACTIONS.execute },
           kibana: {
+            ...task,
             saved_objects: [
               {
                 rel: SAVED_OBJECT_REL_PRIMARY,

diff --git a/x-pack/plugins/actions/server/lib/task_runner_factory.test.ts b/x-pack/plugins/actions/server/lib/task_runner_factory.test.ts
@@ -132,6 +132,9 @@ test('executes the task by calling the executor with proper parameters', async (
         authorization: 'ApiKey MTIzOmFiYw==',
       },
     }),
+    taskInfo: {
+      scheduled: new Date(),
+    },
   });
 
   const [executeParams] = mockedActionExecutor.execute.mock.calls[0];
@@ -253,6 +256,9 @@ test('uses API key when provided', async () => {
         authorization: 'ApiKey MTIzOmFiYw==',
       },
     }),
+    taskInfo: {
+      scheduled: new Date(),
+    },
   });
 
   const [executeParams] = mockedActionExecutor.execute.mock.calls[0];
@@ -287,6 +293,9 @@ test(`doesn't use API key when not provided`, async () => {
     request: expect.objectContaining({
       headers: {},
     }),
+    taskInfo: {
+      scheduled: new Date(),
+    },
   });
 
   const [executeParams] = mockedActionExecutor.execute.mock.calls[0];

diff --git a/x-pack/plugins/actions/server/lib/task_runner_factory.ts b/x-pack/plugins/actions/server/lib/task_runner_factory.ts
@@ -71,6 +71,10 @@ export class TaskRunnerFactory {
       getUnsecuredSavedObjectsClient,
     } = this.taskRunnerContext!;
 
+    const taskInfo = {
+      scheduled: taskInstance.runAt,
+    };
+
     return {
       async run() {
         const { spaceId, actionTaskParamsId } = taskInstance.params as Record<string, string>;
@@ -117,6 +121,7 @@ export class TaskRunnerFactory {
             actionId,
             request: fakeRequest,
             ...getSourceFromReferences(references),
+            taskInfo,
           });
         } catch (e) {
           if (e instanceof ActionTypeDisabledError) {

diff --git a/x-pack/plugins/alerting/server/task_runner/create_execution_handler.test.ts b/x-pack/plugins/alerting/server/task_runner/create_execution_handler.test.ts
@@ -187,7 +187,6 @@ test('enqueues execution per selected action', async () => {
             "id": "1",
             "license": "basic",
             "name": "name-of-alert",
-            "namespace": "test1",
             "ruleset": "alerts",
           },
         },

diff --git a/x-pack/plugins/alerting/server/task_runner/create_execution_handler.ts b/x-pack/plugins/alerting/server/task_runner/create_execution_handler.ts
@@ -201,7 +201,6 @@ export function createExecutionHandler<
           license: alertType.minimumLicenseRequired,
           category: alertType.id,
           ruleset: alertType.producer,
-          ...namespace,
           name: alertName,
         },
       };