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

…lastic#102252)

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(),
	  })
	),

x-pack/plugins/actions/server/lib/action_executor.test.ts

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

x-pack/plugins/actions/server/lib/action_executor.ts

@@ -25,6 +25,9 @@ import { ActionsClient } from '../actions_client';
 import { ActionExecutionSource } from './action_execution_source';
 import { RelatedSavedObjects } from './related_saved_objects';
 
+// 1,000,000 nanoseconds in 1 millisecond
+const Millis2Nanos = 1000 * 1000;
+
 export interface ActionExecutorContext {
   logger: Logger;
   spaces?: SpacesServiceStart;
@@ -39,11 +42,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;
   relatedSavedObjects?: RelatedSavedObjects;
 }
 
@@ -71,6 +79,7 @@ export class ActionExecutor {
     params,
     request,
     source,
+    taskInfo,
     relatedSavedObjects,
   }: ExecuteOptions): Promise<ActionTypeExecutorResult<unknown>> {
     if (!this.isInitialized) {
@@ -143,9 +152,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,

x-pack/plugins/actions/server/lib/task_runner_factory.test.ts

@@ -133,6 +133,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];
@@ -255,6 +258,9 @@ test('uses API key when provided', async () => {
         authorization: 'ApiKey MTIzOmFiYw==',
       },
     }),
+    taskInfo: {
+      scheduled: new Date(),
+    },
   });
 
   const [executeParams] = mockedActionExecutor.execute.mock.calls[0];
@@ -300,6 +306,9 @@ test('uses relatedSavedObjects when provided', async () => {
         authorization: 'ApiKey MTIzOmFiYw==',
       },
     }),
+    taskInfo: {
+      scheduled: new Date(),
+    },
   });
 });
 
@@ -323,7 +332,6 @@ test('sanitizes invalid relatedSavedObjects when provided', async () => {
   });
 
   await taskRunner.run();
-
   expect(mockedActionExecutor.execute).toHaveBeenCalledWith({
     actionId: '2',
     params: { baz: true },
@@ -334,6 +342,9 @@ test('sanitizes invalid relatedSavedObjects when provided', async () => {
         authorization: 'ApiKey MTIzOmFiYw==',
       },
     }),
+    taskInfo: {
+      scheduled: new Date(),
+    },
   });
 });
 
@@ -363,6 +374,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];

x-pack/plugins/actions/server/lib/task_runner_factory.ts

@@ -72,6 +72,10 @@ export class TaskRunnerFactory {
       getUnsecuredSavedObjectsClient,
     } = this.taskRunnerContext!;
 
+    const taskInfo = {
+      scheduled: taskInstance.runAt,
+    };
+
     return {
       async run() {
         const { spaceId, actionTaskParamsId } = taskInstance.params as Record<string, string>;
@@ -118,6 +122,7 @@ export class TaskRunnerFactory {
             actionId,
             request: fakeRequest,
             ...getSourceFromReferences(references),
+            taskInfo,
             relatedSavedObjects: validatedRelatedSavedObjects(logger, relatedSavedObjects),
           });
         } catch (e) {

x-pack/plugins/alerting/server/task_runner/create_execution_handler.test.ts

@@ -195,7 +195,6 @@ test('enqueues execution per selected action', async () => {
             "id": "1",
             "license": "basic",
             "name": "name-of-alert",
-            "namespace": "test1",
             "ruleset": "alerts",
           },
         },

x-pack/plugins/alerting/server/task_runner/create_execution_handler.ts

@@ -209,7 +209,6 @@ export function createExecutionHandler<
           license: alertType.minimumLicenseRequired,
           category: alertType.id,
           ruleset: alertType.producer,
-          ...namespace,
           name: alertName,
         },
       };