From 7b1378db97930ec33fb1c0ef5d64136b0faadf64 Mon Sep 17 00:00:00 2001 From: Patrick Mueller Date: Thu, 12 Nov 2020 09:32:22 -0500 Subject: [PATCH] [alerts] add executionStatus to event log doc for action execute (#82401) resolves https://github.com/elastic/kibana/issues/79785 Until now, the execution status was available in the the event log document for the execute action. In this PR we add it. The event log is extended to add the following fields: - `kibana.alerting.status` - from executionStatus.status - `event.reason` - from executionStatus.error.reason The date from the executionStatus and start date in the event log will be set to the same value. Previously, errors encountered while trying to execute an alert executor, eg decrypting the alert, would not end up with an event doc generated. Now they will. In addition, there were a few places where events that could have had the action group in them did not, and one where the instance id was undefined - those were fixed up. --- .../server/alert_instance/alert_instance.ts | 4 + .../create_execution_handler.test.ts | 1 + .../task_runner/create_execution_handler.ts | 1 + .../server/task_runner/task_runner.test.ts | 231 ++++++++++++++---- .../alerts/server/task_runner/task_runner.ts | 115 ++++++--- .../plugins/event_log/generated/mappings.json | 8 + x-pack/plugins/event_log/generated/schemas.ts | 4 +- x-pack/plugins/event_log/scripts/mappings.js | 6 + .../event_log/server/event_logger.test.ts | 6 +- .../plugins/event_log/server/event_logger.ts | 7 +- .../tests/alerting/event_log.ts | 84 +++++++ .../tests/alerting/index.ts | 1 + .../spaces_only/tests/alerting/event_log.ts | 106 +++++--- 13 files changed, 442 insertions(+), 132 deletions(-) create mode 100644 x-pack/test/alerting_api_integration/security_and_spaces/tests/alerting/event_log.ts diff --git a/x-pack/plugins/alerts/server/alert_instance/alert_instance.ts b/x-pack/plugins/alerts/server/alert_instance/alert_instance.ts index 661fb75f81c007..01790b2a4a0c08 100644 --- a/x-pack/plugins/alerts/server/alert_instance/alert_instance.ts +++ b/x-pack/plugins/alerts/server/alert_instance/alert_instance.ts @@ -51,6 +51,10 @@ export class AlertInstance< return false; } + getLastScheduledActions() { + return this.meta.lastScheduledActions; + } + getScheduledActionOptions() { return this.scheduledExecutionOptions; } diff --git a/x-pack/plugins/alerts/server/task_runner/create_execution_handler.test.ts b/x-pack/plugins/alerts/server/task_runner/create_execution_handler.test.ts index 2f0754d34492fb..ed73fec24db261 100644 --- a/x-pack/plugins/alerts/server/task_runner/create_execution_handler.test.ts +++ b/x-pack/plugins/alerts/server/task_runner/create_execution_handler.test.ts @@ -113,6 +113,7 @@ test('enqueues execution per selected action', async () => { }, "kibana": Object { "alerting": Object { + "action_group_id": "default", "instance_id": "2", }, "saved_objects": Array [ diff --git a/x-pack/plugins/alerts/server/task_runner/create_execution_handler.ts b/x-pack/plugins/alerts/server/task_runner/create_execution_handler.ts index 21e642d228b4dc..f49310c42c247a 100644 --- a/x-pack/plugins/alerts/server/task_runner/create_execution_handler.ts +++ b/x-pack/plugins/alerts/server/task_runner/create_execution_handler.ts @@ -116,6 +116,7 @@ export function createExecutionHandler({ kibana: { alerting: { instance_id: alertInstanceId, + action_group_id: actionGroup, }, saved_objects: [ { rel: SAVED_OBJECT_REL_PRIMARY, type: 'alert', id: alertId, ...namespace }, diff --git a/x-pack/plugins/alerts/server/task_runner/task_runner.test.ts b/x-pack/plugins/alerts/server/task_runner/task_runner.test.ts index 4d0d69010914e2..859b6ec4362cef 100644 --- a/x-pack/plugins/alerts/server/task_runner/task_runner.test.ts +++ b/x-pack/plugins/alerts/server/task_runner/task_runner.test.ts @@ -184,11 +184,15 @@ describe('Task Runner', () => { expect(eventLogger.logEvent).toHaveBeenCalledTimes(1); expect(eventLogger.logEvent.mock.calls[0][0]).toMatchInlineSnapshot(` Object { + "@timestamp": "1970-01-01T00:00:00.000Z", "event": Object { "action": "execute", "outcome": "success", }, "kibana": Object { + "alerting": Object { + "status": "ok", + }, "saved_objects": Array [ Object { "id": "1", @@ -249,29 +253,13 @@ describe('Task Runner', () => { const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; expect(eventLogger.logEvent).toHaveBeenCalledTimes(4); - expect(eventLogger.logEvent).toHaveBeenCalledWith({ - event: { - action: 'execute', - outcome: 'success', - }, - kibana: { - saved_objects: [ - { - id: '1', - namespace: undefined, - rel: 'primary', - type: 'alert', - }, - ], - }, - message: "alert executed: test:1: 'alert-name'", - }); - expect(eventLogger.logEvent).toHaveBeenCalledWith({ + expect(eventLogger.logEvent).toHaveBeenNthCalledWith(1, { event: { action: 'new-instance', }, kibana: { alerting: { + action_group_id: 'default', instance_id: '1', }, saved_objects: [ @@ -285,7 +273,7 @@ describe('Task Runner', () => { }, message: "test:1: 'alert-name' created new instance: '1'", }); - expect(eventLogger.logEvent).toHaveBeenCalledWith({ + expect(eventLogger.logEvent).toHaveBeenNthCalledWith(2, { event: { action: 'active-instance', }, @@ -305,13 +293,14 @@ describe('Task Runner', () => { }, message: "test:1: 'alert-name' active instance: '1' in actionGroup: 'default'", }); - expect(eventLogger.logEvent).toHaveBeenCalledWith({ + expect(eventLogger.logEvent).toHaveBeenNthCalledWith(3, { event: { action: 'execute-action', }, kibana: { alerting: { instance_id: '1', + action_group_id: 'default', }, saved_objects: [ { @@ -330,6 +319,27 @@ describe('Task Runner', () => { message: "alert: test:1: 'alert-name' instanceId: '1' scheduled actionGroup: 'default' action: action:1", }); + expect(eventLogger.logEvent).toHaveBeenNthCalledWith(4, { + '@timestamp': '1970-01-01T00:00:00.000Z', + event: { + action: 'execute', + outcome: 'success', + }, + kibana: { + alerting: { + status: 'active', + }, + saved_objects: [ + { + id: '1', + namespace: undefined, + rel: 'primary', + type: 'alert', + }, + ], + }, + message: "alert executed: test:1: 'alert-name'", + }); }); test('includes the apiKey in the request used to initialize the actionsClient', async () => { @@ -402,10 +412,13 @@ describe('Task Runner', () => { Array [ Object { "event": Object { - "action": "execute", - "outcome": "success", + "action": "new-instance", }, "kibana": Object { + "alerting": Object { + "action_group_id": "default", + "instance_id": "1", + }, "saved_objects": Array [ Object { "id": "1", @@ -415,17 +428,17 @@ describe('Task Runner', () => { }, ], }, - "message": "alert executed: test:1: 'alert-name'", + "message": "test:1: 'alert-name' created new instance: '1'", }, ], Array [ Object { "event": Object { - "action": "new-instance", + "action": "active-instance", }, "kibana": Object { "alerting": Object { - "action_group_id": undefined, + "action_group_id": "default", "instance_id": "1", }, "saved_objects": Array [ @@ -437,13 +450,13 @@ describe('Task Runner', () => { }, ], }, - "message": "test:1: 'alert-name' created new instance: '1'", + "message": "test:1: 'alert-name' active instance: '1' in actionGroup: 'default'", }, ], Array [ Object { "event": Object { - "action": "active-instance", + "action": "execute-action", }, "kibana": Object { "alerting": Object { @@ -457,19 +470,26 @@ describe('Task Runner', () => { "rel": "primary", "type": "alert", }, + Object { + "id": "1", + "namespace": undefined, + "type": "action", + }, ], }, - "message": "test:1: 'alert-name' active instance: '1' in actionGroup: 'default'", + "message": "alert: test:1: 'alert-name' instanceId: '1' scheduled actionGroup: 'default' action: action:1", }, ], Array [ Object { + "@timestamp": "1970-01-01T00:00:00.000Z", "event": Object { - "action": "execute-action", + "action": "execute", + "outcome": "success", }, "kibana": Object { "alerting": Object { - "instance_id": "1", + "status": "active", }, "saved_objects": Array [ Object { @@ -478,14 +498,9 @@ describe('Task Runner', () => { "rel": "primary", "type": "alert", }, - Object { - "id": "1", - "namespace": undefined, - "type": "action", - }, ], }, - "message": "alert: test:1: 'alert-name' instanceId: '1' scheduled actionGroup: 'default' action: action:1", + "message": "alert executed: test:1: 'alert-name'", }, ], ] @@ -498,6 +513,7 @@ describe('Task Runner', () => { executorServices.alertInstanceFactory('1').scheduleActions('default'); } ); + const date = new Date().toISOString(); const taskRunner = new TaskRunner( alertType, { @@ -505,8 +521,14 @@ describe('Task Runner', () => { state: { ...mockedTaskInstance.state, alertInstances: { - '1': { meta: {}, state: { bar: false } }, - '2': { meta: {}, state: { bar: false } }, + '1': { + meta: { lastScheduledActions: { group: 'default', date } }, + state: { bar: false }, + }, + '2': { + meta: { lastScheduledActions: { group: 'default', date } }, + state: { bar: false }, + }, }, }, }, @@ -545,10 +567,13 @@ describe('Task Runner', () => { Array [ Object { "event": Object { - "action": "execute", - "outcome": "success", + "action": "resolved-instance", }, "kibana": Object { + "alerting": Object { + "action_group_id": "default", + "instance_id": "2", + }, "saved_objects": Array [ Object { "id": "1", @@ -558,18 +583,18 @@ describe('Task Runner', () => { }, ], }, - "message": "alert executed: test:1: 'alert-name'", + "message": "test:1: 'alert-name' resolved instance: '2'", }, ], Array [ Object { "event": Object { - "action": "resolved-instance", + "action": "active-instance", }, "kibana": Object { "alerting": Object { - "action_group_id": undefined, - "instance_id": "2", + "action_group_id": "default", + "instance_id": "1", }, "saved_objects": Array [ Object { @@ -580,18 +605,19 @@ describe('Task Runner', () => { }, ], }, - "message": "test:1: 'alert-name' resolved instance: '2'", + "message": "test:1: 'alert-name' active instance: '1' in actionGroup: 'default'", }, ], Array [ Object { + "@timestamp": "1970-01-01T00:00:00.000Z", "event": Object { - "action": "active-instance", + "action": "execute", + "outcome": "success", }, "kibana": Object { "alerting": Object { - "action_group_id": "default", - "instance_id": "1", + "status": "active", }, "saved_objects": Array [ Object { @@ -602,7 +628,7 @@ describe('Task Runner', () => { }, ], }, - "message": "test:1: 'alert-name' active instance: '1' in actionGroup: 'default'", + "message": "alert executed: test:1: 'alert-name'", }, ], ] @@ -787,14 +813,19 @@ describe('Task Runner', () => { Array [ Array [ Object { + "@timestamp": "1970-01-01T00:00:00.000Z", "error": Object { "message": "OMG", }, "event": Object { "action": "execute", "outcome": "failure", + "reason": "execute", }, "kibana": Object { + "alerting": Object { + "status": "error", + }, "saved_objects": Array [ Object { "id": "1", @@ -834,6 +865,40 @@ describe('Task Runner', () => { "state": Object {}, } `); + + const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; + expect(eventLogger.logEvent).toHaveBeenCalledTimes(1); + expect(eventLogger.logEvent.mock.calls).toMatchInlineSnapshot(` + Array [ + Array [ + Object { + "@timestamp": "1970-01-01T00:00:00.000Z", + "error": Object { + "message": "OMG", + }, + "event": Object { + "action": "execute", + "outcome": "failure", + "reason": "decrypt", + }, + "kibana": Object { + "alerting": Object { + "status": "error", + }, + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + }, + ], + }, + "message": "test:1: execution failed", + }, + ], + ] + `); }); test('recovers gracefully when the Alert Task Runner throws an exception when getting internal Services', async () => { @@ -867,6 +932,40 @@ describe('Task Runner', () => { "state": Object {}, } `); + + const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; + expect(eventLogger.logEvent).toHaveBeenCalledTimes(1); + expect(eventLogger.logEvent.mock.calls).toMatchInlineSnapshot(` + Array [ + Array [ + Object { + "@timestamp": "1970-01-01T00:00:00.000Z", + "error": Object { + "message": "OMG", + }, + "event": Object { + "action": "execute", + "outcome": "failure", + "reason": "unknown", + }, + "kibana": Object { + "alerting": Object { + "status": "error", + }, + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + }, + ], + }, + "message": "test:1: execution failed", + }, + ], + ] + `); }); test('recovers gracefully when the Alert Task Runner throws an exception when fetching attributes', async () => { @@ -899,6 +998,40 @@ describe('Task Runner', () => { "state": Object {}, } `); + + const eventLogger = taskRunnerFactoryInitializerParams.eventLogger; + expect(eventLogger.logEvent).toHaveBeenCalledTimes(1); + expect(eventLogger.logEvent.mock.calls).toMatchInlineSnapshot(` + Array [ + Array [ + Object { + "@timestamp": "1970-01-01T00:00:00.000Z", + "error": Object { + "message": "OMG", + }, + "event": Object { + "action": "execute", + "outcome": "failure", + "reason": "read", + }, + "kibana": Object { + "alerting": Object { + "status": "error", + }, + "saved_objects": Array [ + Object { + "id": "1", + "namespace": undefined, + "rel": "primary", + "type": "alert", + }, + ], + }, + "message": "test:1: execution failed", + }, + ], + ] + `); }); test('recovers gracefully when the Runner of a legacy Alert task which has no schedule throws an exception when fetching attributes', async () => { diff --git a/x-pack/plugins/alerts/server/task_runner/task_runner.ts b/x-pack/plugins/alerts/server/task_runner/task_runner.ts index 86bf7006e8d09e..5bccf5c497a60c 100644 --- a/x-pack/plugins/alerts/server/task_runner/task_runner.ts +++ b/x-pack/plugins/alerts/server/task_runner/task_runner.ts @@ -4,7 +4,7 @@ * you may not use this file except in compliance with the Elastic License. */ import type { PublicMethodsOf } from '@kbn/utility-types'; -import { Dictionary, pickBy, mapValues, without } from 'lodash'; +import { Dictionary, pickBy, mapValues, without, cloneDeep } from 'lodash'; import { Logger, KibanaRequest } from '../../../../../src/core/server'; import { TaskRunnerContext } from './task_runner_factory'; import { ConcreteTaskInstance, throwUnrecoverableError } from '../../../task_manager/server'; @@ -40,6 +40,8 @@ import { partiallyUpdateAlert } from '../saved_objects'; const FALLBACK_RETRY_INTERVAL = '5m'; +type Event = Exclude; + interface AlertTaskRunResult { state: AlertTaskState; schedule: IntervalSchedule | undefined; @@ -153,7 +155,8 @@ export class TaskRunner { alert: SanitizedAlert, params: AlertExecutorOptions['params'], executionHandler: ReturnType, - spaceId: string + spaceId: string, + event: Event ): Promise { const { throttle, muteAll, mutedInstanceIds, name, tags, createdBy, updatedBy } = alert; const { @@ -166,24 +169,10 @@ export class TaskRunner { alertRawInstances, (rawAlertInstance) => new AlertInstance(rawAlertInstance) ); + const originalAlertInstances = cloneDeep(alertInstances); - const originalAlertInstanceIds = Object.keys(alertInstances); const eventLogger = this.context.eventLogger; const alertLabel = `${this.alertType.id}:${alertId}: '${name}'`; - const event: IEvent = { - event: { action: EVENT_LOG_ACTIONS.execute }, - kibana: { - saved_objects: [ - { - rel: SAVED_OBJECT_REL_PRIMARY, - type: 'alert', - id: alertId, - namespace, - }, - ], - }, - }; - eventLogger.startTiming(event); let updatedAlertTypeState: void | Record; try { @@ -205,21 +194,17 @@ export class TaskRunner { updatedBy, }); } catch (err) { - eventLogger.stopTiming(event); event.message = `alert execution failure: ${alertLabel}`; event.error = event.error || {}; event.error.message = err.message; event.event = event.event || {}; event.event.outcome = 'failure'; - eventLogger.logEvent(event); throw new ErrorWithReason(AlertExecutionStatusErrorReasons.Execute, err); } - eventLogger.stopTiming(event); event.message = `alert executed: ${alertLabel}`; event.event = event.event || {}; event.event.outcome = 'success'; - eventLogger.logEvent(event); // Cleanup alert instances that are no longer scheduling actions to avoid over populating the alertInstances object const instancesWithScheduledActions = pickBy(alertInstances, (alertInstance: AlertInstance) => @@ -227,7 +212,7 @@ export class TaskRunner { ); generateNewAndResolvedInstanceEvents({ eventLogger, - originalAlertInstanceIds, + originalAlertInstances, currentAlertInstances: instancesWithScheduledActions, alertId, alertLabel, @@ -261,7 +246,8 @@ export class TaskRunner { async validateAndExecuteAlert( services: Services, apiKey: RawAlert['apiKey'], - alert: SanitizedAlert + alert: SanitizedAlert, + event: Event ) { const { params: { alertId, spaceId }, @@ -278,10 +264,17 @@ export class TaskRunner { alert.actions, alert.params ); - return this.executeAlertInstances(services, alert, validatedParams, executionHandler, spaceId); + return this.executeAlertInstances( + services, + alert, + validatedParams, + executionHandler, + spaceId, + event + ); } - async loadAlertAttributesAndRun(): Promise> { + async loadAlertAttributesAndRun(event: Event): Promise> { const { params: { alertId, spaceId }, } = this.taskInstance; @@ -304,7 +297,7 @@ export class TaskRunner { return { state: await promiseResult( - this.validateAndExecuteAlert(services, apiKey, alert) + this.validateAndExecuteAlert(services, apiKey, alert, event) ), schedule: asOk( // fetch the alert again to ensure we return the correct schedule as it may have @@ -322,18 +315,65 @@ export class TaskRunner { schedule: taskSchedule, } = this.taskInstance; - const { state, schedule } = await errorAsAlertTaskRunResult(this.loadAlertAttributesAndRun()); - const namespace = spaceId === 'default' ? undefined : spaceId; + const namespace = this.context.spaceIdToNamespace(spaceId); + const eventLogger = this.context.eventLogger; + const event: IEvent = { + // explicitly set execute timestamp so it will be before other events + // generated here (new-instance, schedule-action, etc) + '@timestamp': new Date().toISOString(), + event: { action: EVENT_LOG_ACTIONS.execute }, + kibana: { + saved_objects: [ + { + rel: SAVED_OBJECT_REL_PRIMARY, + type: 'alert', + id: alertId, + namespace, + }, + ], + }, + }; + eventLogger.startTiming(event); + + const { state, schedule } = await errorAsAlertTaskRunResult( + this.loadAlertAttributesAndRun(event) + ); const executionStatus: AlertExecutionStatus = map( state, (alertTaskState: AlertTaskState) => executionStatusFromState(alertTaskState), (err: Error) => executionStatusFromError(err) ); + + // set the executionStatus date to same as event, if it's set + if (event.event?.start) { + executionStatus.lastExecutionDate = new Date(event.event.start); + } + this.logger.debug( `alertExecutionStatus for ${this.alertType.id}:${alertId}: ${JSON.stringify(executionStatus)}` ); + eventLogger.stopTiming(event); + event.kibana = event.kibana || {}; + event.kibana.alerting = event.kibana.alerting || {}; + event.kibana.alerting.status = executionStatus.status; + + // if executionStatus indicates an error, fill in fields in + // event from it + if (executionStatus.error) { + event.event = event.event || {}; + event.event.reason = executionStatus.error?.reason || 'unknown'; + event.event.outcome = 'failure'; + event.error = event.error || {}; + event.error.message = event.error.message || executionStatus.error.message; + if (!event.message) { + event.message = `${this.alertType.id}:${alertId}: execution failed`; + } + } + + eventLogger.logEvent(event); + const client = this.context.internalSavedObjectsRepository; const attributes = { executionStatus: alertExecutionStatusToRaw(executionStatus), @@ -381,7 +421,7 @@ export class TaskRunner { interface GenerateNewAndResolvedInstanceEventsParams { eventLogger: IEventLogger; - originalAlertInstanceIds: string[]; + originalAlertInstances: Dictionary; currentAlertInstances: Dictionary; alertId: string; alertLabel: string; @@ -389,26 +429,23 @@ interface GenerateNewAndResolvedInstanceEventsParams { } function generateNewAndResolvedInstanceEvents(params: GenerateNewAndResolvedInstanceEventsParams) { - const { - eventLogger, - alertId, - namespace, - currentAlertInstances, - originalAlertInstanceIds, - } = params; + const { eventLogger, alertId, namespace, currentAlertInstances, originalAlertInstances } = params; + const originalAlertInstanceIds = Object.keys(originalAlertInstances); const currentAlertInstanceIds = Object.keys(currentAlertInstances); const newIds = without(currentAlertInstanceIds, ...originalAlertInstanceIds); const resolvedIds = without(originalAlertInstanceIds, ...currentAlertInstanceIds); for (const id of resolvedIds) { + const actionGroup = originalAlertInstances[id].getLastScheduledActions()?.group; const message = `${params.alertLabel} resolved instance: '${id}'`; - logInstanceEvent(id, EVENT_LOG_ACTIONS.resolvedInstance, message); + logInstanceEvent(id, EVENT_LOG_ACTIONS.resolvedInstance, message, actionGroup); } for (const id of newIds) { + const actionGroup = currentAlertInstances[id].getScheduledActionOptions()?.actionGroup; const message = `${params.alertLabel} created new instance: '${id}'`; - logInstanceEvent(id, EVENT_LOG_ACTIONS.newInstance, message); + logInstanceEvent(id, EVENT_LOG_ACTIONS.newInstance, message, actionGroup); } for (const id of currentAlertInstanceIds) { @@ -425,7 +462,7 @@ function generateNewAndResolvedInstanceEvents(params: GenerateNewAndResolvedInst kibana: { alerting: { instance_id: instanceId, - action_group_id: group, + ...(group ? { action_group_id: group } : {}), }, saved_objects: [ { diff --git a/x-pack/plugins/event_log/generated/mappings.json b/x-pack/plugins/event_log/generated/mappings.json index 5c7eb50117d9b1..3131235ebcfbeb 100644 --- a/x-pack/plugins/event_log/generated/mappings.json +++ b/x-pack/plugins/event_log/generated/mappings.json @@ -45,6 +45,10 @@ "outcome": { "ignore_above": 1024, "type": "keyword" + }, + "reason": { + "ignore_above": 1024, + "type": "keyword" } } }, @@ -85,6 +89,10 @@ "action_group_id": { "type": "keyword", "ignore_above": 1024 + }, + "status": { + "type": "keyword", + "ignore_above": 1024 } } }, diff --git a/x-pack/plugins/event_log/generated/schemas.ts b/x-pack/plugins/event_log/generated/schemas.ts index 3dbb43b15350f6..d2024ea8ed14a3 100644 --- a/x-pack/plugins/event_log/generated/schemas.ts +++ b/x-pack/plugins/event_log/generated/schemas.ts @@ -18,7 +18,7 @@ type DeepPartial = { [P in keyof T]?: T[P] extends Array ? Array> : DeepPartial; }; -export const ECS_VERSION = '1.5.0'; +export const ECS_VERSION = '1.6.0'; // types and config-schema describing the es structures export type IValidatedEvent = TypeOf; @@ -42,6 +42,7 @@ export const EventSchema = schema.maybe( duration: ecsNumber(), end: ecsDate(), outcome: ecsString(), + reason: ecsString(), }) ), error: schema.maybe( @@ -61,6 +62,7 @@ export const EventSchema = schema.maybe( schema.object({ instance_id: ecsString(), action_group_id: ecsString(), + status: ecsString(), }) ), saved_objects: schema.maybe( diff --git a/x-pack/plugins/event_log/scripts/mappings.js b/x-pack/plugins/event_log/scripts/mappings.js index c9af2b0aa57fb4..bd05f84d4e2b84 100644 --- a/x-pack/plugins/event_log/scripts/mappings.js +++ b/x-pack/plugins/event_log/scripts/mappings.js @@ -22,6 +22,10 @@ exports.EcsKibanaExtensionsMappings = { type: 'keyword', ignore_above: 1024, }, + status: { + type: 'keyword', + ignore_above: 1024, + }, }, }, // array of saved object references, for "linking" via search @@ -63,11 +67,13 @@ exports.EcsEventLogProperties = [ 'event.duration', 'event.end', 'event.outcome', // optional, but one of failure, success, unknown + 'event.reason', 'error.message', 'user.name', 'kibana.server_uuid', 'kibana.alerting.instance_id', 'kibana.alerting.action_group_id', + 'kibana.alerting.status', 'kibana.saved_objects.rel', 'kibana.saved_objects.namespace', 'kibana.saved_objects.id', diff --git a/x-pack/plugins/event_log/server/event_logger.test.ts b/x-pack/plugins/event_log/server/event_logger.test.ts index 0ab3071f70efaa..ea699af45ccd2f 100644 --- a/x-pack/plugins/event_log/server/event_logger.test.ts +++ b/x-pack/plugins/event_log/server/event_logger.test.ts @@ -102,16 +102,16 @@ describe('EventLogger', () => { event: { provider: 'test-provider', action: 'a' }, }); - const ignoredTimestamp = '1999-01-01T00:00:00Z'; + const respectedTimestamp = '2999-01-01T00:00:00.000Z'; eventLogger.logEvent({ - '@timestamp': ignoredTimestamp, + '@timestamp': respectedTimestamp, event: { action: 'b', }, }); const event = await waitForLogEvent(systemLogger); - expect(event!['@timestamp']).not.toEqual(ignoredTimestamp); + expect(event!['@timestamp']).toEqual(respectedTimestamp); expect(event?.event?.action).toEqual('b'); }); diff --git a/x-pack/plugins/event_log/server/event_logger.ts b/x-pack/plugins/event_log/server/event_logger.ts index 8730870f9620b4..658d90d8096525 100644 --- a/x-pack/plugins/event_log/server/event_logger.ts +++ b/x-pack/plugins/event_log/server/event_logger.ts @@ -72,7 +72,6 @@ export class EventLogger implements IEventLogger { const event: IEvent = {}; const fixedProperties = { - '@timestamp': new Date().toISOString(), ecs: { version: ECS_VERSION, }, @@ -81,8 +80,12 @@ export class EventLogger implements IEventLogger { }, }; + const defaultProperties = { + '@timestamp': new Date().toISOString(), + }; + // merge the initial properties and event properties - merge(event, this.initialProperties, eventProperties, fixedProperties); + merge(event, defaultProperties, this.initialProperties, eventProperties, fixedProperties); let validatedEvent: IValidatedEvent; try { diff --git a/x-pack/test/alerting_api_integration/security_and_spaces/tests/alerting/event_log.ts b/x-pack/test/alerting_api_integration/security_and_spaces/tests/alerting/event_log.ts new file mode 100644 index 00000000000000..385d8bfca4a9a3 --- /dev/null +++ b/x-pack/test/alerting_api_integration/security_and_spaces/tests/alerting/event_log.ts @@ -0,0 +1,84 @@ +/* + * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one + * or more contributor license agreements. Licensed under the Elastic License; + * you may not use this file except in compliance with the Elastic License. + */ + +import expect from '@kbn/expect'; +import { Spaces } from '../../scenarios'; +import { getUrlPrefix, getTestAlertData, ObjectRemover, getEventLog } from '../../../common/lib'; +import { FtrProviderContext } from '../../../common/ftr_provider_context'; +import { validateEvent } from '../../../spaces_only/tests/alerting/event_log'; + +// eslint-disable-next-line import/no-default-export +export default function eventLogTests({ getService }: FtrProviderContext) { + const supertest = getService('supertest'); + const retry = getService('retry'); + + describe('eventLog', () => { + const objectRemover = new ObjectRemover(supertest); + + after(() => objectRemover.removeAll()); + + it('should generate events for alert decrypt errors', async () => { + const spaceId = Spaces[0].id; + const response = await supertest + .post(`${getUrlPrefix(spaceId)}/api/alerts/alert`) + .set('kbn-xsrf', 'foo') + .send( + getTestAlertData({ + alertTypeId: 'test.noop', + schedule: { interval: '1s' }, + throttle: null, + }) + ); + + expect(response.status).to.eql(200); + const alertId = response.body.id; + objectRemover.add(spaceId, alertId, 'alert', 'alerts'); + + // break AAD + await supertest + .put(`${getUrlPrefix(spaceId)}/api/alerts_fixture/saved_object/alert/${alertId}`) + .set('kbn-xsrf', 'foo') + .send({ + attributes: { + name: 'bar', + }, + }) + .expect(200); + + const events = await retry.try(async () => { + // there can be a successful execute before the error one + const someEvents = await getEventLog({ + getService, + spaceId, + type: 'alert', + id: alertId, + provider: 'alerting', + actions: ['execute'], + }); + const errorEvents = someEvents.filter( + (event) => event?.kibana?.alerting?.status === 'error' + ); + if (errorEvents.length === 0) { + throw new Error('no execute/error events yet'); + } + return errorEvents; + }); + + const event = events[0]; + expect(event).to.be.ok(); + + validateEvent(event, { + spaceId, + savedObjects: [{ type: 'alert', id: alertId, rel: 'primary' }], + outcome: 'failure', + message: `test.noop:${alertId}: execution failed`, + errorMessage: 'Unable to decrypt attribute "apiKey"', + status: 'error', + reason: 'decrypt', + }); + }); + }); +} diff --git a/x-pack/test/alerting_api_integration/security_and_spaces/tests/alerting/index.ts b/x-pack/test/alerting_api_integration/security_and_spaces/tests/alerting/index.ts index 1fbee9e18fdaa2..4f8525cfcf683c 100644 --- a/x-pack/test/alerting_api_integration/security_and_spaces/tests/alerting/index.ts +++ b/x-pack/test/alerting_api_integration/security_and_spaces/tests/alerting/index.ts @@ -26,6 +26,7 @@ export default function alertingTests({ loadTestFile }: FtrProviderContext) { loadTestFile(require.resolve('./update')); loadTestFile(require.resolve('./update_api_key')); loadTestFile(require.resolve('./alerts')); + loadTestFile(require.resolve('./event_log')); // note that this test will destroy existing spaces loadTestFile(require.resolve('./rbac_legacy')); diff --git a/x-pack/test/alerting_api_integration/spaces_only/tests/alerting/event_log.ts b/x-pack/test/alerting_api_integration/spaces_only/tests/alerting/event_log.ts index dbf8eb162fca71..937045b6218c6d 100644 --- a/x-pack/test/alerting_api_integration/spaces_only/tests/alerting/event_log.ts +++ b/x-pack/test/alerting_api_integration/spaces_only/tests/alerting/event_log.ts @@ -107,6 +107,8 @@ export default function eventLogTests({ getService }: FtrProviderContext) { expect(resolvedInstanceTimes[0] > newInstanceTimes[0]).to.be(true); // validate each event + let executeCount = 0; + const executeStatuses = ['ok', 'active', 'active']; for (const event of events) { switch (event?.event?.action) { case 'execute': @@ -115,6 +117,7 @@ export default function eventLogTests({ getService }: FtrProviderContext) { savedObjects: [{ type: 'alert', id: alertId, rel: 'primary' }], outcome: 'success', message: `alert executed: test.patternFiring:${alertId}: 'abc'`, + status: executeStatuses[executeCount++], }); break; case 'execute-action': @@ -125,6 +128,8 @@ export default function eventLogTests({ getService }: FtrProviderContext) { { type: 'action', id: createdAction.id }, ], message: `alert: test.patternFiring:${alertId}: 'abc' instanceId: 'instance' scheduled actionGroup: 'default' action: test.noop:${createdAction.id}`, + instanceId: 'instance', + actionGroupId: 'default', }); break; case 'new-instance': @@ -147,6 +152,8 @@ export default function eventLogTests({ getService }: FtrProviderContext) { spaceId: Spaces.space1.id, savedObjects: [{ type: 'alert', id: alertId, rel: 'primary' }], message: `test.patternFiring:${alertId}: 'abc' ${subMessage}`, + instanceId: 'instance', + actionGroupId: 'default', }); } }); @@ -187,60 +194,83 @@ export default function eventLogTests({ getService }: FtrProviderContext) { outcome: 'failure', message: `alert execution failure: test.throw:${alertId}: 'abc'`, errorMessage: 'this alert is intended to fail', + status: 'error', + reason: 'execute', }); }); }); +} + +interface SavedObject { + type: string; + id: string; + rel?: string; +} + +interface ValidateEventLogParams { + spaceId: string; + savedObjects: SavedObject[]; + outcome?: string; + message: string; + errorMessage?: string; + status?: string; + actionGroupId?: string; + instanceId?: string; + reason?: string; +} + +export function validateEvent(event: IValidatedEvent, params: ValidateEventLogParams): void { + const { spaceId, savedObjects, outcome, message, errorMessage } = params; + const { status, actionGroupId, instanceId, reason } = params; - interface SavedObject { - type: string; - id: string; - rel?: string; + if (status) { + expect(event?.kibana?.alerting?.status).to.be(status); } - interface ValidateEventLogParams { - spaceId: string; - savedObjects: SavedObject[]; - outcome?: string; - message: string; - errorMessage?: string; + if (actionGroupId) { + expect(event?.kibana?.alerting?.action_group_id).to.be(actionGroupId); } - function validateEvent(event: IValidatedEvent, params: ValidateEventLogParams): void { - const { spaceId, savedObjects, outcome, message, errorMessage } = params; + if (instanceId) { + expect(event?.kibana?.alerting?.instance_id).to.be(instanceId); + } - const duration = event?.event?.duration; - const eventStart = Date.parse(event?.event?.start || 'undefined'); - const eventEnd = Date.parse(event?.event?.end || 'undefined'); - const dateNow = Date.now(); + if (reason) { + expect(event?.event?.reason).to.be(reason); + } - if (duration !== undefined) { - expect(typeof duration).to.be('number'); - expect(eventStart).to.be.ok(); - expect(eventEnd).to.be.ok(); + const duration = event?.event?.duration; + const eventStart = Date.parse(event?.event?.start || 'undefined'); + const eventEnd = Date.parse(event?.event?.end || 'undefined'); + const dateNow = Date.now(); - const durationDiff = Math.abs( - Math.round(duration! / NANOS_IN_MILLIS) - (eventEnd - eventStart) - ); + if (duration !== undefined) { + expect(typeof duration).to.be('number'); + expect(eventStart).to.be.ok(); + expect(eventEnd).to.be.ok(); - // account for rounding errors - expect(durationDiff < 1).to.equal(true); - expect(eventStart <= eventEnd).to.equal(true); - expect(eventEnd <= dateNow).to.equal(true); - } + const durationDiff = Math.abs( + Math.round(duration! / NANOS_IN_MILLIS) - (eventEnd - eventStart) + ); - expect(event?.event?.outcome).to.equal(outcome); + // account for rounding errors + expect(durationDiff < 1).to.equal(true); + expect(eventStart <= eventEnd).to.equal(true); + expect(eventEnd <= dateNow).to.equal(true); + } - for (const savedObject of savedObjects) { - expect( - isSavedObjectInEvent(event, spaceId, savedObject.type, savedObject.id, savedObject.rel) - ).to.be(true); - } + expect(event?.event?.outcome).to.equal(outcome); - expect(event?.message).to.eql(message); + for (const savedObject of savedObjects) { + expect( + isSavedObjectInEvent(event, spaceId, savedObject.type, savedObject.id, savedObject.rel) + ).to.be(true); + } - if (errorMessage) { - expect(event?.error?.message).to.eql(errorMessage); - } + expect(event?.message).to.eql(message); + + if (errorMessage) { + expect(event?.error?.message).to.eql(errorMessage); } }