Skip to content

Commit

Permalink
[Alerting] Add event log entry when an action starts executing (elast…
Browse files Browse the repository at this point in the history 
…ic#102370)

* First steps for adding action execution to event log

* Fix tests

* Move the event to the actions plugin

* Update functional tests

* Fix tests

* Fix types
  • Loading branch information
@chrisronline
chrisronline authored Jun 22, 2021
1 parent b386ce1 commit dec77cf
Show file tree
Hide file tree
Showing 5 changed files with 156 additions and 32 deletions.
1 change: 1 addition & 0 deletions x-pack/plugins/actions/server/constants/event_log.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -8,5 +8,6 @@
export const EVENT_LOG_PROVIDER = 'actions';
export const EVENT_LOG_ACTIONS = {
execute: 'execute',
executeStart: 'execute-start',
executeViaHttp: 'execute-via-http',
};
47 changes: 46 additions & 1 deletion x-pack/plugins/actions/server/lib/action_executor.test.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,7 @@ const services = actionsMock.createServices();
const actionsClient = actionsClientMock.create();
const encryptedSavedObjectsClient = encryptedSavedObjectsMock.createClient();
const actionTypeRegistry = actionTypeRegistryMock.create();
const eventLogger = eventLoggerMock.create();

const executeParams = {
actionId: '1',
Expand All @@ -42,7 +43,7 @@ actionExecutor.initialize({
getActionsClientWithRequest,
actionTypeRegistry,
encryptedSavedObjectsClient,
eventLogger: eventLoggerMock.create(),
eventLogger,
preconfiguredActions: [],
});

Expand Down Expand Up @@ -379,6 +380,50 @@ test('logs a warning when alert executor returns invalid status', async () => {
);
});

test('writes to event log for execute and execute start', async () => {
const executorMock = setupActionExecutorMock();
executorMock.mockResolvedValue({
actionId: '1',
status: 'ok',
});
await actionExecutor.execute(executeParams);
expect(eventLogger.logEvent).toHaveBeenCalledTimes(2);
expect(eventLogger.logEvent.mock.calls[0][0]).toMatchObject({
event: {
action: 'execute-start',
},
kibana: {
saved_objects: [
{
rel: 'primary',
type: 'action',
id: '1',
type_id: 'test',
namespace: 'some-namespace',
},
],
},
message: 'action started: test:1: action-1',
});
expect(eventLogger.logEvent.mock.calls[1][0]).toMatchObject({
event: {
action: 'execute',
},
kibana: {
saved_objects: [
{
rel: 'primary',
type: 'action',
id: '1',
type_id: 'test',
namespace: 'some-namespace',
},
],
},
message: 'action executed: test:1: action-1',
});
});

function setupActionExecutorMock() {
const actionType: jest.Mocked<ActionType> = {
id: 'test',
Expand Down
12 changes: 12 additions & 0 deletions x-pack/plugins/actions/server/lib/action_executor.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@

import type { PublicMethodsOf } from '@kbn/utility-types';
import { Logger, KibanaRequest } from 'src/core/server';
import { cloneDeep } from 'lodash';
import { withSpan } from '@kbn/apm-utils';
import { validateParams, validateConfig, validateSecrets } from './validate_with_schema';
import {
Expand Down Expand Up @@ -168,6 +169,17 @@ export class ActionExecutor {
}

eventLogger.startTiming(event);

const startEvent = cloneDeep({
...event,
event: {
...event.event,
action: EVENT_LOG_ACTIONS.executeStart,
},
message: `action started: ${actionLabel}`,
});
eventLogger.logEvent(startEvent);

let rawResult: ActionTypeExecutorResult<unknown>;
try {
rawResult = await actionType.executor({
Expand Down
78 changes: 62 additions & 16 deletions x-pack/test/alerting_api_integration/security_and_spaces/tests/actions/execute.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -519,47 +519,93 @@ export default function ({ getService }: FtrProviderContext) {
type: 'action',
id: connectorId,
provider: 'actions',
actions: new Map([['execute', { equal: 1 }]]),
filter: 'event.action:(execute)',
actions: new Map([
['execute-start', { equal: 1 }],
['execute', { equal: 1 }],
]),
// filter: 'event.action:(execute)',
});
});

const event = events[0];
const startExecuteEvent = events[0];
const executeEvent = events[1];

const duration = event?.event?.duration;
const eventStart = Date.parse(event?.event?.start || 'undefined');
const eventEnd = Date.parse(event?.event?.end || 'undefined');
const duration = executeEvent?.event?.duration;
const executeEventStart = Date.parse(executeEvent?.event?.start || 'undefined');
const startExecuteEventStart = Date.parse(startExecuteEvent?.event?.start || 'undefined');
const executeEventEnd = Date.parse(executeEvent?.event?.end || 'undefined');
const dateNow = Date.now();

expect(typeof duration).to.be('number');
expect(eventStart).to.be.ok();
expect(eventEnd).to.be.ok();
expect(executeEventStart).to.be.ok();
expect(startExecuteEventStart).to.equal(executeEventStart);
expect(executeEventEnd).to.be.ok();

const durationDiff = Math.abs(
Math.round(duration! / NANOS_IN_MILLIS) - (eventEnd - eventStart)
Math.round(duration! / NANOS_IN_MILLIS) - (executeEventEnd - executeEventStart)
);

// account for rounding errors
expect(durationDiff < 1).to.equal(true);
expect(eventStart <= eventEnd).to.equal(true);
expect(eventEnd <= dateNow).to.equal(true);
expect(executeEventStart <= executeEventEnd).to.equal(true);
expect(executeEventEnd <= dateNow).to.equal(true);

expect(event?.event?.outcome).to.equal(outcome);
expect(executeEvent?.event?.outcome).to.equal(outcome);

expect(event?.kibana?.saved_objects).to.eql([
expect(executeEvent?.kibana?.saved_objects).to.eql([
{
rel: 'primary',
type: 'action',
id: connectorId,
namespace: 'space1',
type_id: actionTypeId,
namespace: spaceId,
},
]);
expect(startExecuteEvent?.kibana?.saved_objects).to.eql(executeEvent?.kibana?.saved_objects);

expect(event?.message).to.eql(message);
expect(executeEvent?.message).to.eql(message);
expect(startExecuteEvent?.message).to.eql(message.replace('executed', 'started'));

if (errorMessage) {
expect(event?.error?.message).to.eql(errorMessage);
expect(executeEvent?.error?.message).to.eql(errorMessage);
}

// const event = events[0];

// 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();

// expect(typeof duration).to.be('number');
// expect(eventStart).to.be.ok();
// expect(eventEnd).to.be.ok();

// const durationDiff = Math.abs(
// Math.round(duration! / NANOS_IN_MILLIS) - (eventEnd - eventStart)
// );

// // account for rounding errors
// expect(durationDiff < 1).to.equal(true);
// expect(eventStart <= eventEnd).to.equal(true);
// expect(eventEnd <= dateNow).to.equal(true);

// expect(event?.event?.outcome).to.equal(outcome);

// expect(event?.kibana?.saved_objects).to.eql([
// {
// rel: 'primary',
// type: 'action',
// id: connectorId,
// type_id: actionTypeId,
// namespace: spaceId,
// },
// ]);

// expect(event?.message).to.eql(message);

// if (errorMessage) {
// expect(event?.error?.message).to.eql(errorMessage);
// }
}
}
50 changes: 35 additions & 15 deletions x-pack/test/alerting_api_integration/spaces_only/tests/actions/execute.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -100,6 +100,7 @@ export default function ({ getService }: FtrProviderContext) {
actionTypeId: 'test.index-record',
outcome: 'success',
message: `action executed: test.index-record:${createdAction.id}: My action`,
startMessage: `action started: test.index-record:${createdAction.id}: My action`,
});
});

Expand Down Expand Up @@ -336,10 +337,19 @@ export default function ({ getService }: FtrProviderContext) {
outcome: string;
message: string;
errorMessage?: string;
startMessage?: string;
}

async function validateEventLog(params: ValidateEventLogParams): Promise<void> {
const { spaceId, actionId, actionTypeId, outcome, message, errorMessage } = params;
const {
spaceId,
actionId,
actionTypeId,
outcome,
message,
startMessage,
errorMessage,
} = params;

const events: IValidatedEvent[] = await retry.try(async () => {
return await getEventLog({
Expand All @@ -348,33 +358,39 @@ export default function ({ getService }: FtrProviderContext) {
type: 'action',
id: actionId,
provider: 'actions',
actions: new Map([['execute', { equal: 1 }]]),
actions: new Map([
['execute-start', { equal: 1 }],
['execute', { equal: 1 }],
]),
});
});

const event = events[0];
const startExecuteEvent = events[0];
const executeEvent = events[1];

const duration = event?.event?.duration;
const eventStart = Date.parse(event?.event?.start || 'undefined');
const eventEnd = Date.parse(event?.event?.end || 'undefined');
const duration = executeEvent?.event?.duration;
const executeEventStart = Date.parse(executeEvent?.event?.start || 'undefined');
const startExecuteEventStart = Date.parse(startExecuteEvent?.event?.start || 'undefined');
const executeEventEnd = Date.parse(executeEvent?.event?.end || 'undefined');
const dateNow = Date.now();

expect(typeof duration).to.be('number');
expect(eventStart).to.be.ok();
expect(eventEnd).to.be.ok();
expect(executeEventStart).to.be.ok();
expect(startExecuteEventStart).to.equal(executeEventStart);
expect(executeEventEnd).to.be.ok();

const durationDiff = Math.abs(
Math.round(duration! / NANOS_IN_MILLIS) - (eventEnd - eventStart)
Math.round(duration! / NANOS_IN_MILLIS) - (executeEventEnd - executeEventStart)
);

// account for rounding errors
expect(durationDiff < 1).to.equal(true);
expect(eventStart <= eventEnd).to.equal(true);
expect(eventEnd <= dateNow).to.equal(true);
expect(executeEventStart <= executeEventEnd).to.equal(true);
expect(executeEventEnd <= dateNow).to.equal(true);

expect(event?.event?.outcome).to.equal(outcome);
expect(executeEvent?.event?.outcome).to.equal(outcome);

expect(event?.kibana?.saved_objects).to.eql([
expect(executeEvent?.kibana?.saved_objects).to.eql([
{
rel: 'primary',
type: 'action',
Expand All @@ -383,11 +399,15 @@ export default function ({ getService }: FtrProviderContext) {
type_id: actionTypeId,
},
]);
expect(startExecuteEvent?.kibana?.saved_objects).to.eql(executeEvent?.kibana?.saved_objects);

expect(event?.message).to.eql(message);
expect(executeEvent?.message).to.eql(message);
if (startMessage) {
expect(startExecuteEvent?.message).to.eql(startMessage);
}

if (errorMessage) {
expect(event?.error?.message).to.eql(errorMessage);
expect(executeEvent?.error?.message).to.eql(errorMessage);
}
}
}

0 comments on commit dec77cf

Please sign in to comment.