fix action execution event logging

elastic · Jan 17, 2020 · f5e3148 · f5e3148
1 parent 28ff98f
commit f5e3148
Show file tree

Hide file tree

Showing 8 changed files with 100 additions and 39 deletions.
diff --git a/x-pack/legacy/plugins/actions/server/lib/action_executor.ts b/x-pack/legacy/plugins/actions/server/lib/action_executor.ts
@@ -57,7 +57,6 @@ export class ActionExecutor {
     }
 
     const {
-      logger,
       spaces,
       getServices,
       encryptedSavedObjectsPlugin,
@@ -93,9 +92,9 @@ export class ActionExecutor {
     );
     const actionType = actionTypeRegistry.get(actionTypeId);
 
-    let validatedParams;
-    let validatedConfig;
-    let validatedSecrets;
+    let validatedParams: Record<string, any>;
+    let validatedConfig: Record<string, any>;
+    let validatedSecrets: Record<string, any>;
 
     try {
       validatedParams = validateParams(actionType, params);
@@ -105,54 +104,68 @@ export class ActionExecutor {
       return { status: 'error', actionId, message: err.message, retry: false };
     }
 
-    let result: ActionTypeExecutorResult | null = null;
-    const actionLabel = `${actionId} - ${actionTypeId} - ${name}`;
-
-    const loggedEvent: IEvent = {
-      event: {
-        action: EVENT_LOG_ACTIONS.execute,
-      },
-      kibana: {
-        namespace,
-        saved_objects: [
-          {
-            type: 'action',
-            id: actionId,
-          },
-        ],
-      },
+    const actionLabel = `${actionTypeId}:${actionId}: ${name}`;
+    const event: IEvent = {
+      event: { action: EVENT_LOG_ACTIONS.execute },
+      kibana: { namespace, saved_objects: [{ type: 'action', id: actionId }] },
     };
 
-    eventLogger.startTiming(loggedEvent);
-    let error: any;
-
+    eventLogger.startTiming(event);
+    let rawResult: ActionTypeExecutorResult | null | undefined | void;
     try {
-      result = await actionType.executor({
+      rawResult = await actionType.executor({
         actionId,
         services,
         params: validatedParams,
         config: validatedConfig,
         secrets: validatedSecrets,
       });
-      loggedEvent.message = `action executed successfully: ${actionLabel}`;
     } catch (err) {
-      error = err;
-      loggedEvent.message = `action executed unsuccessfully: ${actionLabel} - ${err.message}`;
-      logger.warn(loggedEvent.message);
+      rawResult = {
+        actionId,
+        status: 'error',
+        message: 'an error occurred while running the action executor',
+        serviceMessage: err.message,
+        retry: false,
+      };
     }
+    eventLogger.stopTiming(event);
 
-    eventLogger.stopTiming(loggedEvent);
-    eventLogger.logEvent(loggedEvent);
+    // allow null-ish return to indicate success
+    const result = rawResult || {
+      actionId,
+      status: 'ok',
+    };
 
-    if (error != null) {
-      throw error;
+    if (result.status === 'ok') {
+      event.message = `action executed: ${actionLabel}`;
+    } else if (result.status === 'error') {
+      event.message = `action execution failure: ${actionLabel}`;
+      event.error = event.error || {};
+      event.error.message = actionErrorToMessage(result);
+    } else {
+      event.message = `action execution returned unexpected result: ${actionLabel}`;
+      event.error = event.error || {};
+      event.error.message = 'action execution returned unexpected result';
     }
 
-    logger.debug(`action executed successfully: ${actionLabel}`);
+    eventLogger.logEvent(event);
+    return result;
+  }
+}
 
-    // return basic response if none provided
-    if (result == null) return { status: 'ok', actionId };
+function actionErrorToMessage(result: ActionTypeExecutorResult): string {
+  let message = result.message || 'unknown error running action';
 
-    return result;
+  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;
 }
diff --git a/x-pack/legacy/plugins/actions/server/types.ts b/x-pack/legacy/plugins/actions/server/types.ts
@@ -63,7 +63,7 @@ export interface ActionTypeExecutorResult {
 // signature of the action type executor function
 export type ExecutorType = (
   options: ActionTypeExecutorOptions
-) => Promise<ActionTypeExecutorResult>;
+) => Promise<ActionTypeExecutorResult | null | undefined | void>;
 
 interface ValidatorType {
   validate<T>(value: any): any;

diff --git a/x-pack/plugins/event_log/generated/mappings.json b/x-pack/plugins/event_log/generated/mappings.json
@@ -43,6 +43,15 @@
             },
             "dynamic": "strict"
         },
+        "error": {
+            "properties": {
+                "message": {
+                    "norms": false,
+                    "type": "text"
+                }
+            },
+            "dynamic": "strict"
+        },
         "user": {
             "properties": {
                 "name": {

diff --git a/x-pack/plugins/event_log/generated/schemas.ts b/x-pack/plugins/event_log/generated/schemas.ts
@@ -43,6 +43,11 @@ export const EventSchema = schema.maybe(
         end: ecsDate(),
       })
     ),
+    error: schema.maybe(
+      schema.object({
+        message: ecsString(),
+      })
+    ),
     user: schema.maybe(
       schema.object({
         name: ecsString(),

diff --git a/x-pack/plugins/event_log/scripts/mappings.js b/x-pack/plugins/event_log/scripts/mappings.js
@@ -49,6 +49,7 @@ exports.EcsEventLogProperties = [
   'event.start',
   'event.duration',
   'event.end',
+  'error.message',
   'user.name',
   'kibana.server_uuid',
   'kibana.namespace',

diff --git a/x-pack/test/alerting_api_integration/common/config.ts b/x-pack/test/alerting_api_integration/common/config.ts
@@ -75,6 +75,7 @@ export function createTestConfig(name: string, options: CreateTestConfigOptions)
           ])}`,
           `--xpack.actions.enabledActionTypes=${JSON.stringify(enabledActionTypes)}`,
           '--xpack.alerting.enabled=true',
+          '--xpack.event_log.logEntries=true',
           ...disabledPlugins.map(key => `--xpack.${key}.enabled=false`),
           `--plugin-path=${path.join(__dirname, 'fixtures', 'plugins', 'alerts')}`,
           `--plugin-path=${path.join(__dirname, 'fixtures', 'plugins', 'actions')}`,

diff --git a/x-pack/test/alerting_api_integration/common/fixtures/plugins/alerts/index.ts b/x-pack/test/alerting_api_integration/common/fixtures/plugins/alerts/index.ts
@@ -63,7 +63,7 @@ export default function(kibana: any) {
           }),
         },
         async executor({ config, secrets, params, services }: ActionTypeExecutorOptions) {
-          return await services.callCluster('index', {
+          await services.callCluster('index', {
             index: params.index,
             refresh: 'wait_for',
             body: {
@@ -97,7 +97,7 @@ export default function(kibana: any) {
               source: 'action:test.failing',
             },
           });
-          throw new Error('Failed to execute action type');
+          throw new Error(`expected failure for ${params.index} ${params.reference}`);
         },
       };
       const rateLimitedActionType: ActionType = {

diff --git a/x-pack/test/alerting_api_integration/spaces_only/tests/actions/execute.ts b/x-pack/test/alerting_api_integration/spaces_only/tests/actions/execute.ts
@@ -88,6 +88,38 @@ export default function({ getService }: FtrProviderContext) {
       });
     });
 
+    it('should handle failed executions', async () => {
+      const { body: createdAction } = await supertest
+        .post(`${getUrlPrefix(Spaces.space1.id)}/api/action`)
+        .set('kbn-xsrf', 'foo')
+        .send({
+          name: 'failing action',
+          actionTypeId: 'test.failing',
+        })
+        .expect(200);
+      objectRemover.add(Spaces.space1.id, createdAction.id, 'action');
+
+      const reference = `actions-failure-1:${Spaces.space1.id}`;
+      const response = await supertest
+        .post(`${getUrlPrefix(Spaces.space1.id)}/api/action/${createdAction.id}/_execute`)
+        .set('kbn-xsrf', 'foo')
+        .send({
+          params: {
+            reference,
+            index: ES_TEST_INDEX_NAME,
+          },
+        });
+
+      expect(response.statusCode).to.eql(200);
+      expect(response.body).to.eql({
+        actionId: createdAction.id,
+        status: 'error',
+        message: 'an error occurred while running the action executor',
+        serviceMessage: `expected failure for ${ES_TEST_INDEX_NAME} ${reference}`,
+        retry: false,
+      });
+    });
+
     it(`shouldn't execute an action from another space`, async () => {
       const { body: createdAction } = await supertest
         .post(`${getUrlPrefix(Spaces.space1.id)}/api/action`)