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

#103172)

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

Note that these changes were previously merged to master in #102252 which had to be reverted - this PR contains the same commits, plus some additional ones to resolve the tests that were broken during the bad merge.

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

@@ -109,6 +109,96 @@ 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-start",
+          },
+          "kibana": Object {
+            "saved_objects": Array [
+              Object {
+                "id": "1",
+                "namespace": "some-namespace",
+                "rel": "primary",
+                "type": "action",
+                "type_id": "test",
+              },
+            ],
+          },
+          "message": "action started: test:1: 1",
+        },
+      ],
+      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,
         },
       };