Make rule execute events @timestamp represent the end of the event rather than the start (#119761)

* Fix event log timestamp for execute events

* commit using @elastic.co

* Fix failing jest tests

* Fix typo

* Fix failing jest tests

Co-authored-by: Kibana Machine <42973632+kibanamachine@users.noreply.github.com>
This commit is contained in:
Mike Côté 2021-12-07 15:07:12 -05:00 committed by GitHub
parent 80dc3b64f2
commit d955835a2c
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
4 changed files with 4 additions and 63 deletions

View file

@ -299,7 +299,6 @@ describe('Task Runner', () => {
expect(eventLogger.startTiming).toHaveBeenCalledTimes(1);
expect(eventLogger.logEvent.mock.calls[0][0]).toMatchInlineSnapshot(`
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"event": Object {
"action": "execute-start",
"category": Array [
@ -450,7 +449,6 @@ describe('Task Runner', () => {
const eventLogger = customTaskRunnerFactoryInitializerParams.eventLogger;
expect(eventLogger.logEvent).toHaveBeenCalledTimes(5);
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(1, {
'@timestamp': '1970-01-01T00:00:00.000Z',
event: {
action: 'execute-start',
category: ['alerts'],
@ -582,7 +580,6 @@ describe('Task Runner', () => {
},
});
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(5, {
'@timestamp': '1970-01-01T00:00:00.000Z',
event: { action: 'execute', category: ['alerts'], kind: 'alert', outcome: 'success' },
kibana: {
alerting: {
@ -671,7 +668,6 @@ describe('Task Runner', () => {
expect(eventLogger.startTiming).toHaveBeenCalledTimes(1);
expect(eventLogger.logEvent).toHaveBeenCalledTimes(4);
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(1, {
'@timestamp': '1970-01-01T00:00:00.000Z',
event: {
action: 'execute-start',
category: ['alerts'],
@ -767,7 +763,6 @@ describe('Task Runner', () => {
},
});
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(4, {
'@timestamp': '1970-01-01T00:00:00.000Z',
event: {
action: 'execute',
category: ['alerts'],
@ -931,7 +926,6 @@ describe('Task Runner', () => {
Array [
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"event": Object {
"action": "execute-start",
"category": Array [
@ -1001,7 +995,6 @@ describe('Task Runner', () => {
],
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"event": Object {
"action": "execute",
"category": Array [
@ -1272,7 +1265,6 @@ describe('Task Runner', () => {
Array [
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"event": Object {
"action": "execute-start",
"category": Array [
@ -1418,7 +1410,6 @@ describe('Task Runner', () => {
],
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"event": Object {
"action": "execute",
"category": Array [
@ -1569,7 +1560,6 @@ describe('Task Runner', () => {
Array [
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"event": Object {
"action": "execute-start",
"category": Array [
@ -1755,7 +1745,6 @@ describe('Task Runner', () => {
],
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"event": Object {
"action": "execute",
"category": Array [
@ -2139,7 +2128,6 @@ describe('Task Runner', () => {
Array [
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"event": Object {
"action": "execute-start",
"category": Array [
@ -2246,7 +2234,6 @@ describe('Task Runner', () => {
],
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"event": Object {
"action": "execute",
"category": Array [
@ -2481,7 +2468,6 @@ describe('Task Runner', () => {
Array [
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"event": Object {
"action": "execute-start",
"category": Array [
@ -2515,7 +2501,6 @@ describe('Task Runner', () => {
],
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"error": Object {
"message": "OMG",
},
@ -2590,7 +2575,6 @@ describe('Task Runner', () => {
Array [
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"event": Object {
"action": "execute-start",
"category": Array [
@ -2624,7 +2608,6 @@ describe('Task Runner', () => {
],
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"error": Object {
"message": "OMG",
},
@ -2708,7 +2691,6 @@ describe('Task Runner', () => {
Array [
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"event": Object {
"action": "execute-start",
"category": Array [
@ -2742,7 +2724,6 @@ describe('Task Runner', () => {
],
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"error": Object {
"message": "OMG",
},
@ -2826,7 +2807,6 @@ describe('Task Runner', () => {
Array [
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"event": Object {
"action": "execute-start",
"category": Array [
@ -2860,7 +2840,6 @@ describe('Task Runner', () => {
],
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"error": Object {
"message": "OMG",
},
@ -2943,7 +2922,6 @@ describe('Task Runner', () => {
Array [
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"event": Object {
"action": "execute-start",
"category": Array [
@ -2977,7 +2955,6 @@ describe('Task Runner', () => {
],
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"error": Object {
"message": "OMG",
},
@ -3238,7 +3215,6 @@ describe('Task Runner', () => {
Array [
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"event": Object {
"action": "execute-start",
"category": Array [
@ -3416,7 +3392,6 @@ describe('Task Runner', () => {
],
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"event": Object {
"action": "execute",
"category": Array [
@ -3525,7 +3500,6 @@ describe('Task Runner', () => {
Array [
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"event": Object {
"action": "execute-start",
"category": Array [
@ -3631,7 +3605,6 @@ describe('Task Runner', () => {
],
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"event": Object {
"action": "execute",
"category": Array [
@ -3732,7 +3705,6 @@ describe('Task Runner', () => {
Array [
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"event": Object {
"action": "execute-start",
"category": Array [
@ -3834,7 +3806,6 @@ describe('Task Runner', () => {
],
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"event": Object {
"action": "execute",
"category": Array [
@ -3930,7 +3901,6 @@ describe('Task Runner', () => {
Array [
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"event": Object {
"action": "execute-start",
"category": Array [
@ -4036,7 +4006,6 @@ describe('Task Runner', () => {
],
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"event": Object {
"action": "execute",
"category": Array [
@ -4134,7 +4103,6 @@ describe('Task Runner', () => {
Array [
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"event": Object {
"action": "execute-start",
"category": Array [
@ -4234,7 +4202,6 @@ describe('Task Runner', () => {
],
Array [
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"event": Object {
"action": "execute",
"category": Array [
@ -4383,7 +4350,6 @@ describe('Task Runner', () => {
expect(eventLogger.startTiming).toHaveBeenCalledTimes(1);
expect(eventLogger.logEvent.mock.calls[0][0]).toMatchInlineSnapshot(`
Object {
"@timestamp": "1970-01-01T00:00:00.000Z",
"event": Object {
"action": "execute-start",
"category": Array [
@ -4463,7 +4429,6 @@ describe('Task Runner', () => {
const eventLogger = taskRunnerFactoryInitializerParams.eventLogger;
expect(eventLogger.logEvent).toHaveBeenCalledTimes(2);
expect(eventLogger.logEvent.mock.calls[0][0]).toStrictEqual({
'@timestamp': '1970-01-01T00:00:00.000Z',
event: {
action: 'execute-start',
kind: 'alert',
@ -4484,7 +4449,6 @@ describe('Task Runner', () => {
message: 'alert execution start: "1"',
});
expect(eventLogger.logEvent.mock.calls[1][0]).toStrictEqual({
'@timestamp': '1970-01-01T00:00:00.000Z',
event: {
action: 'execute',
kind: 'alert',

View file

@ -602,7 +602,6 @@ export class TaskRunner<
const scheduleDelay = runDate.getTime() - this.taskInstance.runAt.getTime();
const event = createAlertEventLogRecordObject({
timestamp: runDateString,
ruleId: alertId,
ruleType: this.alertType as UntypedNormalizedAlertType,
action: EVENT_LOG_ACTIONS.execute,
@ -747,7 +746,6 @@ export class TaskRunner<
const eventLogger = this.context.eventLogger;
const event: IEvent = {
'@timestamp': new Date().toISOString(),
event: {
action: EVENT_LOG_ACTIONS.executeTimeout,
kind: 'alert',

View file

@ -196,7 +196,6 @@ describe('Task Runner Cancel', () => {
expect(eventLogger.logEvent).toHaveBeenCalledTimes(3);
expect(eventLogger.startTiming).toHaveBeenCalledTimes(1);
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(1, {
'@timestamp': '1970-01-01T00:00:00.000Z',
event: {
action: 'execute-start',
category: ['alerts'],
@ -225,7 +224,6 @@ describe('Task Runner Cancel', () => {
},
});
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(2, {
'@timestamp': '1970-01-01T00:00:00.000Z',
event: {
action: 'execute-timeout',
category: ['alerts'],
@ -250,7 +248,6 @@ describe('Task Runner Cancel', () => {
},
});
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(3, {
'@timestamp': '1970-01-01T00:00:00.000Z',
event: {
action: 'execute',
category: ['alerts'],
@ -424,7 +421,6 @@ describe('Task Runner Cancel', () => {
expect(eventLogger.startTiming).toHaveBeenCalledTimes(1);
expect(eventLogger.logEvent).toHaveBeenCalledTimes(3);
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(1, {
'@timestamp': '1970-01-01T00:00:00.000Z',
event: {
action: 'execute-start',
category: ['alerts'],
@ -453,7 +449,6 @@ describe('Task Runner Cancel', () => {
},
});
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(2, {
'@timestamp': '1970-01-01T00:00:00.000Z',
event: {
action: 'execute-timeout',
category: ['alerts'],
@ -479,7 +474,6 @@ describe('Task Runner Cancel', () => {
},
});
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(3, {
'@timestamp': '1970-01-01T00:00:00.000Z',
event: {
action: 'execute',
category: ['alerts'],
@ -539,7 +533,6 @@ describe('Task Runner Cancel', () => {
const eventLogger = taskRunnerFactoryInitializerParams.eventLogger;
expect(eventLogger.logEvent).toHaveBeenCalledTimes(6);
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(1, {
'@timestamp': '1970-01-01T00:00:00.000Z',
event: {
action: 'execute-start',
category: ['alerts'],
@ -569,7 +562,6 @@ describe('Task Runner Cancel', () => {
},
});
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(2, {
'@timestamp': '1970-01-01T00:00:00.000Z',
event: {
action: 'execute-timeout',
category: ['alerts'],
@ -689,7 +681,6 @@ describe('Task Runner Cancel', () => {
},
});
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(6, {
'@timestamp': '1970-01-01T00:00:00.000Z',
event: { action: 'execute', category: ['alerts'], kind: 'alert', outcome: 'success' },
kibana: {
alerting: {

View file

@ -107,26 +107,19 @@ export default function eventLogTests({ getService }: FtrProviderContext) {
const executeEvents = getEventsByAction(events, 'execute');
const executeStartEvents = getEventsByAction(events, 'execute-start');
const executeActionEvents = getEventsByAction(events, 'execute-action');
const newInstanceEvents = getEventsByAction(events, 'new-instance');
const recoveredInstanceEvents = getEventsByAction(events, 'recovered-instance');
// make sure the events are in the right temporal order
const executeTimes = getTimestamps(executeEvents);
const executeStartTimes = getTimestamps(executeStartEvents);
const executeActionTimes = getTimestamps(executeActionEvents);
const newInstanceTimes = getTimestamps(newInstanceEvents);
const recoveredInstanceTimes = getTimestamps(recoveredInstanceEvents);
expect(executeTimes[0] < newInstanceTimes[0]).to.be(true);
expect(executeTimes[1] <= newInstanceTimes[0]).to.be(true);
expect(executeTimes[1] >= newInstanceTimes[0]).to.be(true);
expect(executeTimes[2] > newInstanceTimes[0]).to.be(true);
expect(executeTimes[1] <= executeActionTimes[0]).to.be(true);
expect(executeTimes[2] > executeActionTimes[0]).to.be(true);
expect(executeStartTimes.length === executeTimes.length).to.be(true);
executeStartTimes.forEach((est, index) =>
expect(est === executeTimes[index]).to.be(true)
);
expect(recoveredInstanceTimes[0] > newInstanceTimes[0]).to.be(true);
// validate each event
@ -325,26 +318,19 @@ export default function eventLogTests({ getService }: FtrProviderContext) {
const executeEvents = getEventsByAction(events, 'execute');
const executeStartEvents = getEventsByAction(events, 'execute-start');
const executeActionEvents = getEventsByAction(events, 'execute-action');
const newInstanceEvents = getEventsByAction(events, 'new-instance');
const recoveredInstanceEvents = getEventsByAction(events, 'recovered-instance');
// make sure the events are in the right temporal order
const executeTimes = getTimestamps(executeEvents);
const executeStartTimes = getTimestamps(executeStartEvents);
const executeActionTimes = getTimestamps(executeActionEvents);
const newInstanceTimes = getTimestamps(newInstanceEvents);
const recoveredInstanceTimes = getTimestamps(recoveredInstanceEvents);
expect(executeTimes[0] < newInstanceTimes[0]).to.be(true);
expect(executeTimes[1] <= newInstanceTimes[0]).to.be(true);
expect(executeTimes[1] >= newInstanceTimes[0]).to.be(true);
expect(executeTimes[2] > newInstanceTimes[0]).to.be(true);
expect(executeTimes[1] <= executeActionTimes[0]).to.be(true);
expect(executeTimes[2] > executeActionTimes[0]).to.be(true);
expect(executeStartTimes.length === executeTimes.length).to.be(true);
executeStartTimes.forEach((est, index) =>
expect(est === executeTimes[index]).to.be(true)
);
expect(recoveredInstanceTimes[0] > newInstanceTimes[0]).to.be(true);
// validate each event
@ -589,6 +575,7 @@ export function validateEvent(event: IValidatedEvent, params: ValidateEventLogPa
}
const duration = event?.event?.duration;
const timestamp = Date.parse(event?.['@timestamp'] || 'undefined');
const eventStart = Date.parse(event?.event?.start || 'undefined');
const eventEnd = Date.parse(event?.event?.end || 'undefined');
const dateNow = Date.now();
@ -608,6 +595,7 @@ export function validateEvent(event: IValidatedEvent, params: ValidateEventLogPa
expect(durationDiff < 1).to.equal(true);
expect(eventStart <= eventEnd).to.equal(true);
expect(eventEnd <= dateNow).to.equal(true);
expect(eventEnd <= timestamp).to.equal(true);
}
if (shouldHaveEventEnd === false) {