From f5e3148efffeb2b43f563aac26b299c85bd002f0 Mon Sep 17 00:00:00 2001 From: Patrick Mueller Date: Fri, 17 Jan 2020 16:45:08 -0500 Subject: [PATCH] fix action execution event logging --- .../actions/server/lib/action_executor.ts | 85 +++++++++++-------- x-pack/legacy/plugins/actions/server/types.ts | 2 +- .../plugins/event_log/generated/mappings.json | 9 ++ x-pack/plugins/event_log/generated/schemas.ts | 5 ++ x-pack/plugins/event_log/scripts/mappings.js | 1 + .../alerting_api_integration/common/config.ts | 1 + .../common/fixtures/plugins/alerts/index.ts | 4 +- .../spaces_only/tests/actions/execute.ts | 32 +++++++ 8 files changed, 100 insertions(+), 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 index eaace606298a47..401470cf0b995b 100644 --- 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; + let validatedConfig: Record; + let validatedSecrets: Record; 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 index 6a6fb7d660cbbd..b11a0db7f333d6 100644 --- 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; +) => Promise; interface ValidatorType { validate(value: any): any; diff --git a/x-pack/plugins/event_log/generated/mappings.json b/x-pack/plugins/event_log/generated/mappings.json index 6d802997327051..fc1fdb71b0c372 100644 --- 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 index e64fdb3e6b0e31..a040ede891bfdc 100644 --- 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 index de79d26588fd66..43fd0c78183a10 100644 --- 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 index f322945e236b8c..d23bd2ac4646d5 100644 --- 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 index b5d201c1682bd4..9babed9799b928 100644 --- 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 index a0eac43d06c667..c2e5aa041055d8 100644 --- 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`)