Convert event log's duration from number to string in Kibana (keep as "long" in Elasticsearch) (#130819)

* Convert event.duration to string in TypeScript, keep as long in Elasticsearch

* Fix jest test

* Fix functional tests

* Add ecsStringOrNumber to event log schema

* Fix jest test

* Add utility functions to event log plugin

* Use new event log utility functions

* PR fixes

Co-authored-by: Kibana Machine <42973632+kibanamachine@users.noreply.github.com>
This commit is contained in:
Mike Côté 2022-05-03 14:54:10 -04:00 committed by GitHub
parent 06b958d2a2
commit d3ac9aa8ce
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
28 changed files with 220 additions and 118 deletions

View file

@ -7,7 +7,7 @@
import { random, mean } from 'lodash';
import { SanitizedRule, AlertSummary } from '../types';
import { IValidatedEvent } from '@kbn/event-log-plugin/server';
import { IValidatedEvent, millisToNanos, nanosToMillis } from '@kbn/event-log-plugin/server';
import { EVENT_LOG_ACTIONS, EVENT_LOG_PROVIDER, LEGACY_EVENT_LOG_ACTIONS } from '../plugin';
import { alertSummaryFromEventLog } from './alert_summary_from_event_log';
@ -643,7 +643,7 @@ export class EventsFactory {
event: {
provider: EVENT_LOG_PROVIDER,
action: EVENT_LOG_ACTIONS.execute,
duration: random(2000, 180000) * 1000 * 1000,
duration: millisToNanos(random(2000, 180000)),
},
};
@ -710,7 +710,7 @@ export class EventsFactory {
return this.events
.filter((ev) => ev?.event?.action === 'execute' && ev?.event?.duration !== undefined)
.reduce((res: Record<string, number>, ev) => {
res[ev?.['@timestamp']!] = ev?.event?.duration! / (1000 * 1000);
res[ev?.['@timestamp']!] = nanosToMillis(ev?.event?.duration!);
return res;
}, {});
}

View file

@ -6,12 +6,10 @@
*/
import { mean } from 'lodash';
import { IEvent } from '@kbn/event-log-plugin/server';
import { IEvent, nanosToMillis } from '@kbn/event-log-plugin/server';
import { SanitizedRule, AlertSummary, AlertStatus } from '../types';
import { EVENT_LOG_ACTIONS, EVENT_LOG_PROVIDER, LEGACY_EVENT_LOG_ACTIONS } from '../plugin';
const Millis2Nanos = 1000 * 1000;
export interface AlertSummaryFromEventLogParams {
rule: SanitizedRule<{ bar: boolean }>;
events: IEvent[];
@ -111,7 +109,7 @@ export function alertSummaryFromEventLog(params: AlertSummaryFromEventLogParams)
}
if (event?.event?.duration) {
const eventDirationMillis = event.event.duration / Millis2Nanos;
const eventDirationMillis = nanosToMillis(event.event.duration);
eventDurations.push(eventDirationMillis);
eventDurationsWithTimestamp[event['@timestamp']!] = eventDirationMillis;
}

View file

@ -71,7 +71,7 @@ export function createAlertEventLogRecordObject(params: CreateAlertEventLogRecor
category: [ruleType.producer],
...(state?.start ? { start: state.start as string } : {}),
...(state?.end ? { end: state.end as string } : {}),
...(state?.duration !== undefined ? { duration: state.duration as number } : {}),
...(state?.duration !== undefined ? { duration: state.duration as string } : {}),
},
kibana: {
alert: {

View file

@ -296,7 +296,7 @@ const findResults = {
kind: 'action',
start: '2022-03-23T17:37:07.105Z',
end: '2022-03-23T17:37:07.105Z',
duration: 0,
duration: '0',
outcome: 'failure',
},
kibana: {
@ -345,7 +345,7 @@ const findResults = {
kind: 'action',
start: '2022-03-23T17:37:07.101Z',
end: '2022-03-23T17:37:07.102Z',
duration: 1000000,
duration: '1000000',
outcome: 'failure',
},
kibana: {
@ -394,7 +394,7 @@ const findResults = {
kind: 'action',
start: '2022-03-23T17:37:07.098Z',
end: '2022-03-23T17:37:07.098Z',
duration: 0,
duration: '0',
outcome: 'failure',
},
kibana: {
@ -443,7 +443,7 @@ const findResults = {
kind: 'action',
start: '2022-03-23T17:37:07.095Z',
end: '2022-03-23T17:37:07.096Z',
duration: 1000000,
duration: '1000000',
outcome: 'failure',
},
kibana: {
@ -492,7 +492,7 @@ const findResults = {
kind: 'action',
start: '2022-03-23T17:37:07.084Z',
end: '2022-03-23T17:37:07.086Z',
duration: 2000000,
duration: '2000000',
outcome: 'failure',
},
kibana: {
@ -543,7 +543,7 @@ const findResults = {
start: '2022-03-23T17:23:05.131Z',
outcome: 'failure',
end: '2022-03-23T17:23:05.248Z',
duration: 117000000,
duration: '117000000',
reason: 'execute',
},
kibana: {

View file

@ -28,7 +28,7 @@ export const DATE_1969 = '1969-12-31T00:00:00.000Z';
export const DATE_1970 = '1970-01-01T00:00:00.000Z';
export const DATE_1970_5_MIN = '1969-12-31T23:55:00.000Z';
export const DATE_9999 = '9999-12-31T12:34:56.789Z';
export const MOCK_DURATION = 86400000000000;
export const MOCK_DURATION = '86400000000000';
export const SAVED_OBJECT = {
id: '1',

View file

@ -344,7 +344,7 @@ describe('Task Runner', () => {
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(
2,
generateEventLog({
duration: 0,
duration: '0',
start: DATE_1970,
action: EVENT_LOG_ACTIONS.newInstance,
actionSubgroup: 'subDefault',
@ -356,7 +356,7 @@ describe('Task Runner', () => {
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(
3,
generateEventLog({
duration: 0,
duration: '0',
start: DATE_1970,
action: EVENT_LOG_ACTIONS.activeInstance,
actionGroupId: 'default',
@ -459,7 +459,7 @@ describe('Task Runner', () => {
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(
2,
generateEventLog({
duration: 0,
duration: '0',
start: DATE_1970,
action: EVENT_LOG_ACTIONS.newInstance,
actionGroupId: 'default',
@ -470,7 +470,7 @@ describe('Task Runner', () => {
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(
3,
generateEventLog({
duration: 0,
duration: '0',
start: DATE_1970,
action: EVENT_LOG_ACTIONS.activeInstance,
actionGroupId: 'default',
@ -1025,7 +1025,7 @@ describe('Task Runner', () => {
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(
2,
generateEventLog({
duration: 0,
duration: '0',
start: DATE_1970,
action: EVENT_LOG_ACTIONS.newInstance,
actionGroupId: 'default',
@ -1036,7 +1036,7 @@ describe('Task Runner', () => {
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(
3,
generateEventLog({
duration: 0,
duration: '0',
start: DATE_1970,
action: EVENT_LOG_ACTIONS.activeInstance,
actionGroupId: 'default',
@ -1109,7 +1109,7 @@ describe('Task Runner', () => {
state: {
bar: false,
start: DATE_1969,
duration: 80000000000,
duration: '80000000000',
},
},
'2': {
@ -1117,7 +1117,7 @@ describe('Task Runner', () => {
state: {
bar: false,
start: '1969-12-31T06:00:00.000Z',
duration: 70000000000,
duration: '70000000000',
},
},
},
@ -1169,7 +1169,7 @@ describe('Task Runner', () => {
2,
generateEventLog({
action: EVENT_LOG_ACTIONS.recoveredInstance,
duration: 64800000000000,
duration: '64800000000000',
instanceId: '2',
start: '1969-12-31T06:00:00.000Z',
end: DATE_1970,
@ -1419,7 +1419,7 @@ describe('Task Runner', () => {
state: {
bar: false,
start: DATE_1969,
duration: 80000000000,
duration: '80000000000',
},
},
'2': {
@ -1427,7 +1427,7 @@ describe('Task Runner', () => {
state: {
bar: false,
start: '1969-12-31T06:00:00.000Z',
duration: 70000000000,
duration: '70000000000',
},
},
},
@ -1459,7 +1459,7 @@ describe('Task Runner', () => {
generateEventLog({
action: EVENT_LOG_ACTIONS.recoveredInstance,
actionGroupId: 'default',
duration: 64800000000000,
duration: '64800000000000',
instanceId: '2',
start: '1969-12-31T06:00:00.000Z',
end: DATE_1970,
@ -2045,7 +2045,7 @@ describe('Task Runner', () => {
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(
2,
generateEventLog({
duration: 0,
duration: '0',
start: DATE_1970,
action: EVENT_LOG_ACTIONS.newInstance,
actionGroupId: 'default',
@ -2056,7 +2056,7 @@ describe('Task Runner', () => {
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(
3,
generateEventLog({
duration: 0,
duration: '0',
start: DATE_1970,
action: EVENT_LOG_ACTIONS.newInstance,
actionGroupId: 'default',
@ -2067,7 +2067,7 @@ describe('Task Runner', () => {
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(
4,
generateEventLog({
duration: 0,
duration: '0',
start: DATE_1970,
action: EVENT_LOG_ACTIONS.activeInstance,
actionGroupId: 'default',
@ -2078,7 +2078,7 @@ describe('Task Runner', () => {
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(
5,
generateEventLog({
duration: 0,
duration: '0',
start: DATE_1970,
action: EVENT_LOG_ACTIONS.activeInstance,
actionGroupId: 'default',
@ -2132,7 +2132,7 @@ describe('Task Runner', () => {
state: {
bar: false,
start: DATE_1969,
duration: 80000000000,
duration: '80000000000',
},
},
'2': {
@ -2140,7 +2140,7 @@ describe('Task Runner', () => {
state: {
bar: false,
start: '1969-12-31T06:00:00.000Z',
duration: 70000000000,
duration: '70000000000',
},
},
},
@ -2185,7 +2185,7 @@ describe('Task Runner', () => {
generateEventLog({
action: EVENT_LOG_ACTIONS.activeInstance,
actionGroupId: 'default',
duration: 64800000000000,
duration: '64800000000000',
start: '1969-12-31T06:00:00.000Z',
instanceId: '2',
consumer: 'bar',
@ -2315,7 +2315,7 @@ describe('Task Runner', () => {
state: {
bar: false,
start: DATE_1969,
duration: 80000000000,
duration: '80000000000',
},
},
'2': {
@ -2323,7 +2323,7 @@ describe('Task Runner', () => {
state: {
bar: false,
start: '1969-12-31T06:00:00.000Z',
duration: 70000000000,
duration: '70000000000',
},
},
},
@ -2366,7 +2366,7 @@ describe('Task Runner', () => {
3,
generateEventLog({
action: EVENT_LOG_ACTIONS.recoveredInstance,
duration: 64800000000000,
duration: '64800000000000',
start: '1969-12-31T06:00:00.000Z',
end: DATE_1970,
consumer: 'bar',
@ -2789,7 +2789,7 @@ describe('Task Runner', () => {
},
},
state: {
duration: 0,
duration: '0',
start: '1970-01-01T00:00:00.000Z',
},
},
@ -2819,7 +2819,7 @@ describe('Task Runner', () => {
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(
2,
generateEventLog({
duration: 0,
duration: '0',
start: DATE_1970,
action: EVENT_LOG_ACTIONS.newInstance,
actionGroupId: 'default',
@ -2830,7 +2830,7 @@ describe('Task Runner', () => {
expect(eventLogger.logEvent).toHaveBeenNthCalledWith(
3,
generateEventLog({
duration: 0,
duration: '0',
start: DATE_1970,
action: EVENT_LOG_ACTIONS.activeInstance,
actionGroupId: 'default',
@ -2989,7 +2989,7 @@ describe('Task Runner', () => {
},
},
state: {
duration: 0,
duration: '0',
start: '1970-01-01T00:00:00.000Z',
},
},
@ -3001,7 +3001,7 @@ describe('Task Runner', () => {
},
},
state: {
duration: 0,
duration: '0',
start: '1970-01-01T00:00:00.000Z',
},
},

View file

@ -12,7 +12,12 @@ import uuid from 'uuid';
import { addSpaceIdToPath } from '@kbn/spaces-plugin/server';
import { KibanaRequest, Logger } from '@kbn/core/server';
import { ConcreteTaskInstance, throwUnrecoverableError } from '@kbn/task-manager-plugin/server';
import { IEvent, SAVED_OBJECT_REL_PRIMARY } from '@kbn/event-log-plugin/server';
import {
IEvent,
SAVED_OBJECT_REL_PRIMARY,
millisToNanos,
nanosToMillis,
} from '@kbn/event-log-plugin/server';
import { TaskRunnerContext } from './task_runner_factory';
import { createExecutionHandler, ExecutionHandler } from './create_execution_handler';
import { Alert, createAlertFactory } from '../alert';
@ -803,7 +808,7 @@ export class TaskRunner<
// Copy duration into execution status if available
if (null != event.event?.duration) {
executionStatus.lastDuration = Math.round(event.event?.duration / Millis2Nanos);
executionStatus.lastDuration = nanosToMillis(event.event?.duration);
monitoringHistory.duration = executionStatus.lastDuration;
}
@ -1062,9 +1067,9 @@ function trackAlertDurations<
const state = originalAlertIds.includes(id)
? originalAlerts[id].getState()
: currentAlerts[id].getState();
const duration = state.start
? (new Date(currentTime).valueOf() - new Date(state.start as string).valueOf()) * 1000 * 1000 // nanoseconds
: undefined;
const durationInMs =
new Date(currentTime).valueOf() - new Date(state.start as string).valueOf();
const duration = state.start ? millisToNanos(durationInMs) : undefined;
currentAlerts[id].replaceState({
...state,
...(state.start ? { start: state.start } : {}),
@ -1075,9 +1080,9 @@ function trackAlertDurations<
// Inject end time into alert state of recovered alerts
for (const id of recoveredAlertIds) {
const state = recoveredAlerts[id].getState();
const duration = state.start
? (new Date(currentTime).valueOf() - new Date(state.start as string).valueOf()) * 1000 * 1000 // nanoseconds
: undefined;
const durationInMs =
new Date(currentTime).valueOf() - new Date(state.start as string).valueOf();
const duration = state.start ? millisToNanos(durationInMs) : undefined;
recoveredAlerts[id].replaceState({
...state,
...(duration ? { duration } : {}),
@ -1175,7 +1180,7 @@ function generateNewAndRecoveredAlertEvents<
category: [ruleType.producer],
...(state?.start ? { start: state.start as string } : {}),
...(state?.end ? { end: state.end as string } : {}),
...(state?.duration !== undefined ? { duration: state.duration as number } : {}),
...(state?.duration !== undefined ? { duration: state.duration as string } : {}),
},
kibana: {
alert: {

View file

@ -783,7 +783,7 @@ describe('Task Runner Cancel', () => {
action: 'new-instance',
category: ['alerts'],
kind: 'alert',
duration: 0,
duration: '0',
start: '1970-01-01T00:00:00.000Z',
},
kibana: {
@ -825,7 +825,7 @@ describe('Task Runner Cancel', () => {
event: {
action: 'active-instance',
category: ['alerts'],
duration: 0,
duration: '0',
kind: 'alert',
start: '1970-01-01T00:00:00.000Z',
},

View file

@ -6,3 +6,4 @@
*/
export const BASE_EVENT_LOG_API_PATH = '/internal/event_log';
export { millisToNanos, nanosToMillis } from './lib';

View file

@ -0,0 +1,9 @@
/*
* Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
* or more contributor license agreements. Licensed under the Elastic License
* 2.0; you may not use this file except in compliance with the Elastic License
* 2.0.
*/
export { millisToNanos } from './millis_to_nanos';
export { nanosToMillis } from './nanos_to_millis';

View file

@ -0,0 +1,26 @@
/*
* Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
* or more contributor license agreements. Licensed under the Elastic License
* 2.0; you may not use this file except in compliance with the Elastic License
* 2.0.
*/
import { millisToNanos } from './millis_to_nanos';
describe('millisToNanos', () => {
test('should return "0" when passing 0 millis', () => {
expect(millisToNanos(0)).toEqual('0');
});
test('should return "1000000" when passing in 1 millis', () => {
expect(millisToNanos(1)).toEqual('1000000');
});
test('should return "9007199254740991000000" when passing in 9007199254740991 (Number.MAX_SAFE_INTEGER)', () => {
expect(millisToNanos(9007199254740991)).toEqual('9007199254740991000000');
});
test('should round to "1000000" wheen passing in 0.75 millis', () => {
expect(millisToNanos(0.75)).toEqual('1000000');
});
});

View file

@ -0,0 +1,14 @@
/*
* Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
* or more contributor license agreements. Licensed under the Elastic License
* 2.0; you may not use this file except in compliance with the Elastic License
* 2.0.
*/
export function millisToNanos(millis: number): string {
const roundedMillis = Math.round(millis);
if (roundedMillis === 0) {
return '0';
}
return `${roundedMillis}000000`;
}

View file

@ -0,0 +1,32 @@
/*
* Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
* or more contributor license agreements. Licensed under the Elastic License
* 2.0; you may not use this file except in compliance with the Elastic License
* 2.0.
*/
import { nanosToMillis } from './nanos_to_millis';
describe('nanosToMillis', () => {
test('should return 0 when passing in "0" nanos', () => {
expect(nanosToMillis('0')).toEqual(0);
});
test('should drop decimals when passing in "1" nanos', () => {
expect(nanosToMillis('1')).toEqual(0);
});
test('should drop decimals when passing in "1000001" nanos', () => {
expect(nanosToMillis('1000001')).toEqual(1);
});
test('should return 9007199254740991 (Number.MAX_SAFE_INTEGER) when passing in "9007199254740991000000" nanos', () => {
expect(nanosToMillis('9007199254740991000000')).toEqual(9007199254740991);
});
test('should work when numbers are passed in', () => {
expect(nanosToMillis(0)).toEqual(0);
expect(nanosToMillis(1)).toEqual(0);
expect(nanosToMillis(1000001)).toEqual(1);
});
});

View file

@ -0,0 +1,12 @@
/*
* Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
* or more contributor license agreements. Licensed under the Elastic License
* 2.0; you may not use this file except in compliance with the Elastic License
* 2.0.
*/
const ONE_MILLION = BigInt(1000 * 1000);
export function nanosToMillis(nanos: string | number): number {
return Number(BigInt(nanos) / ONE_MILLION);
}

View file

@ -376,4 +376,4 @@
}
}
}
}
}

View file

@ -52,7 +52,7 @@ export const EventSchema = schema.maybe(
code: ecsString(),
created: ecsDate(),
dataset: ecsString(),
duration: ecsNumber(),
duration: ecsStringOrNumber(),
end: ecsDate(),
hash: ecsString(),
id: ecsString(),
@ -66,8 +66,8 @@ export const EventSchema = schema.maybe(
reference: ecsString(),
risk_score: ecsNumber(),
risk_score_norm: ecsNumber(),
sequence: ecsNumber(),
severity: ecsNumber(),
sequence: ecsStringOrNumber(),
severity: ecsStringOrNumber(),
start: ecsDate(),
timezone: ecsString(),
type: ecsStringMulti(),
@ -106,7 +106,7 @@ export const EventSchema = schema.maybe(
schema.object({
id: ecsString(),
scheduled: ecsDate(),
schedule_delay: ecsNumber(),
schedule_delay: ecsStringOrNumber(),
})
),
alerting: schema.maybe(
@ -126,20 +126,20 @@ export const EventSchema = schema.maybe(
schema.object({
uuid: ecsString(),
status: ecsString(),
status_order: ecsNumber(),
status_order: ecsStringOrNumber(),
metrics: schema.maybe(
schema.object({
number_of_triggered_actions: ecsNumber(),
number_of_generated_actions: ecsNumber(),
number_of_new_alerts: ecsNumber(),
number_of_active_alerts: ecsNumber(),
number_of_recovered_alerts: ecsNumber(),
total_number_of_alerts: ecsNumber(),
number_of_searches: ecsNumber(),
total_indexing_duration_ms: ecsNumber(),
es_search_duration_ms: ecsNumber(),
total_search_duration_ms: ecsNumber(),
execution_gap_duration_s: ecsNumber(),
number_of_triggered_actions: ecsStringOrNumber(),
number_of_generated_actions: ecsStringOrNumber(),
number_of_new_alerts: ecsStringOrNumber(),
number_of_active_alerts: ecsStringOrNumber(),
number_of_recovered_alerts: ecsStringOrNumber(),
total_number_of_alerts: ecsStringOrNumber(),
number_of_searches: ecsStringOrNumber(),
total_indexing_duration_ms: ecsStringOrNumber(),
es_search_duration_ms: ecsStringOrNumber(),
total_search_duration_ms: ecsStringOrNumber(),
execution_gap_duration_s: ecsStringOrNumber(),
})
),
})
@ -179,6 +179,10 @@ function ecsNumber() {
return schema.maybe(schema.number());
}
function ecsStringOrNumber() {
return schema.maybe(schema.oneOf([schema.string(), schema.number()]));
}
function ecsDate() {
return schema.maybe(schema.string({ validate: validateDate }));
}

View file

@ -115,7 +115,8 @@ function writeEventLogConfigSchema(elSchema, ecsVersion) {
}
const StringTypes = new Set(['string', 'keyword', 'text', 'ip']);
const NumberTypes = new Set(['long', 'integer', 'float']);
const NumberTypes = new Set(['integer', 'float']);
const StringOrNumberTypes = new Set(['long']);
function augmentMappings(mappings, multiValuedProperties) {
for (const prop of multiValuedProperties) {
@ -145,6 +146,11 @@ function generateSchemaLines(lineWriter, prop, mappings) {
return;
}
if (StringOrNumberTypes.has(mappings.type)) {
lineWriter.addLine(`${propKey}: ecsStringOrNumber(),`);
return;
}
if (mappings.type === 'date') {
lineWriter.addLine(`${propKey}: ecsDate(),`);
return;
@ -310,6 +316,10 @@ function ecsNumber() {
return schema.maybe(schema.number());
}
function ecsStringOrNumber() {
return schema.maybe(schema.oneOf([schema.string(), schema.number()]));
}
function ecsDate() {
return schema.maybe(schema.string({ validate: validateDate }));
}

View file

@ -250,7 +250,7 @@ function fakeEvent(overrides = {}) {
action: 'execute',
start: '2020-03-30T14:55:47.054Z',
end: '2020-03-30T14:55:47.055Z',
duration: 1000000,
duration: '1000000',
},
kibana: {
namespace: 'default',

View file

@ -5,6 +5,7 @@
* 2.0.
*/
import { nanosToMillis } from '../common';
import { IEvent, IEventLogger, IEventLogService } from '.';
import { ECS_VERSION } from './types';
import { EventLogService } from './event_log_service';
@ -137,9 +138,9 @@ describe('EventLogger', () => {
expect(timeStopValue).toBeGreaterThanOrEqual(timeStartValue);
const duration = event.event!.duration!;
const duration = Number(event.event!.duration!);
expect(duration).toBeGreaterThan(0.95 * delayMS * 1000 * 1000);
expect(duration / (1000 * 1000)).toBeCloseTo(timeStopValue - timeStartValue);
expect(nanosToMillis(duration)).toBeCloseTo(timeStopValue - timeStartValue);
});
test('timing method endTiming() method works when startTiming() is not called', async () => {

View file

@ -13,6 +13,7 @@ import { coerce } from 'semver';
import { Plugin } from './plugin';
import { EsContext } from './es';
import { EventLogService } from './event_log_service';
import { millisToNanos } from '../common';
import {
IEvent,
IValidatedEvent,
@ -61,7 +62,7 @@ export class EventLogger implements IEventLogger {
const end = Date.now();
event.event.end = new Date(end).toISOString();
event.event.duration = (end - start) * 1000 * 1000; // nanoseconds
event.event.duration = millisToNanos(end - start);
}
// non-blocking, but spawns an async task to do the work

View file

@ -9,6 +9,8 @@ import { PluginInitializerContext, PluginConfigDescriptor } from '@kbn/core/serv
import { ConfigSchema, IEventLogConfig } from './types';
import { Plugin } from './plugin';
export { millisToNanos, nanosToMillis } from '../common';
export type {
IEventLogService,
IEventLogger,

View file

@ -50,7 +50,7 @@ export function fakeEvent(overrides = {}) {
action: 'execute',
start: '2020-03-30T14:55:47.054Z',
end: '2020-03-30T14:55:47.055Z',
duration: 1000000,
duration: '1000000',
},
kibana: {
saved_objects: [

View file

@ -12,7 +12,7 @@
"generated/*",
// have to declare *.json explicitly due to https://github.com/microsoft/TypeScript/issues/25636
"generated/*.json",
"common/*"
"common/**/*"
],
"references": [
{ "path": "../../../src/core/tsconfig.json" },

View file

@ -6,7 +6,7 @@
*/
import expect from '@kbn/expect';
import { IValidatedEvent } from '@kbn/event-log-plugin/server';
import { IValidatedEvent, nanosToMillis } from '@kbn/event-log-plugin/server';
import { UserAtSpaceScenarios } from '../../scenarios';
import {
ESTestIndexTool,
@ -17,8 +17,6 @@ import {
} from '../../../common/lib';
import { FtrProviderContext } from '../../../common/ftr_provider_context';
const NANOS_IN_MILLIS = 1000 * 1000;
// eslint-disable-next-line import/no-default-export
export default function ({ getService }: FtrProviderContext) {
const supertest = getService('supertest');
@ -538,14 +536,12 @@ export default function ({ getService }: FtrProviderContext) {
const executeEventEnd = Date.parse(executeEvent?.event?.end || 'undefined');
const dateNow = Date.now();
expect(typeof duration).to.be('number');
expect(typeof duration).to.be('string');
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) - (executeEventEnd - executeEventStart)
);
const durationDiff = Math.abs(nanosToMillis(duration!) - (executeEventEnd - executeEventStart));
// account for rounding errors
expect(durationDiff < 1).to.equal(true);

View file

@ -8,7 +8,7 @@
import expect from '@kbn/expect';
import { omit } from 'lodash';
import type * as estypes from '@elastic/elasticsearch/lib/api/typesWithBodyKey';
import { IValidatedEvent } from '@kbn/event-log-plugin/server';
import { IValidatedEvent, nanosToMillis } from '@kbn/event-log-plugin/server';
import { TaskRunning, TaskRunningStage } from '@kbn/task-manager-plugin/server/task_running';
import { ConcreteTaskInstance } from '@kbn/task-manager-plugin/server';
import { UserAtSpaceScenarios, Superuser } from '../../scenarios';
@ -25,8 +25,6 @@ import {
getEventLog,
} from '../../../common/lib';
const NANOS_IN_MILLIS = 1000 * 1000;
// eslint-disable-next-line import/no-default-export
export default function alertTests({ getService }: FtrProviderContext) {
const supertest = getService('supertest');
@ -1303,13 +1301,11 @@ instanceStateValue: true
const eventEnd = Date.parse(event?.event?.end || 'undefined');
const dateNow = Date.now();
expect(typeof duration).to.be('number');
expect(typeof duration).to.be('string');
expect(eventStart).to.be.ok();
expect(eventEnd).to.be.ok();
const durationDiff = Math.abs(
Math.round(duration! / NANOS_IN_MILLIS) - (eventEnd - eventStart)
);
const durationDiff = Math.abs(nanosToMillis(duration!) - (eventEnd - eventStart));
// account for rounding errors
expect(durationDiff < 1).to.equal(true);

View file

@ -6,7 +6,7 @@
*/
import type { Client } from '@elastic/elasticsearch';
import expect from '@kbn/expect';
import { IValidatedEvent } from '@kbn/event-log-plugin/server';
import { IValidatedEvent, nanosToMillis } from '@kbn/event-log-plugin/server';
import { Spaces } from '../../scenarios';
import {
ESTestIndexTool,
@ -17,8 +17,6 @@ import {
} from '../../../common/lib';
import { FtrProviderContext } from '../../../common/ftr_provider_context';
const NANOS_IN_MILLIS = 1000 * 1000;
// eslint-disable-next-line import/no-default-export
export default function ({ getService }: FtrProviderContext) {
const supertest = getService('supertest');
@ -372,14 +370,12 @@ export default function ({ getService }: FtrProviderContext) {
const executeEventEnd = Date.parse(executeEvent?.event?.end || 'undefined');
const dateNow = Date.now();
expect(typeof duration).to.be('number');
expect(typeof duration).to.be('string');
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) - (executeEventEnd - executeEventStart)
);
const durationDiff = Math.abs(nanosToMillis(duration!) - (executeEventEnd - executeEventStart));
// account for rounding errors
expect(durationDiff < 1).to.equal(true);

View file

@ -7,7 +7,7 @@
import expect from '@kbn/expect';
import uuid from 'uuid';
import { IValidatedEvent } from '@kbn/event-log-plugin/server';
import { IValidatedEvent, nanosToMillis } from '@kbn/event-log-plugin/server';
import { Spaces } from '../../scenarios';
import {
getUrlPrefix,
@ -18,8 +18,6 @@ import {
} from '../../../common/lib';
import { FtrProviderContext } from '../../../common/ftr_provider_context';
const NANOS_IN_MILLIS = 1000 * 1000;
// eslint-disable-next-line import/no-default-export
export default function eventLogTests({ getService }: FtrProviderContext) {
const supertest = getService('supertest');
@ -403,10 +401,12 @@ export default function eventLogTests({ getService }: FtrProviderContext) {
expect(event?.kibana?.alert?.rule?.execution?.metrics?.number_of_searches).to.be(
numSearches
);
const esSearchDuration =
event?.kibana?.alert?.rule?.execution?.metrics?.es_search_duration_ms;
const totalSearchDuration =
event?.kibana?.alert?.rule?.execution?.metrics?.total_search_duration_ms;
const esSearchDuration = Number(
event?.kibana?.alert?.rule?.execution?.metrics?.es_search_duration_ms
);
const totalSearchDuration = Number(
event?.kibana?.alert?.rule?.execution?.metrics?.total_search_duration_ms
);
expect(esSearchDuration).not.to.be(undefined);
expect(totalSearchDuration).not.to.be(undefined);
@ -861,15 +861,13 @@ export function validateEvent(event: IValidatedEvent, params: ValidateEventLogPa
const dateNow = Date.now();
if (duration !== undefined) {
expect(typeof duration).to.be('number');
expect(typeof duration).to.be('string');
expect(eventStart).to.be.ok();
if (shouldHaveEventEnd !== false) {
expect(eventEnd).to.be.ok();
const durationDiff = Math.abs(
Math.round(duration! / NANOS_IN_MILLIS) - (eventEnd - eventStart)
);
const durationDiff = Math.abs(nanosToMillis(duration!) - (eventEnd - eventStart));
// account for rounding errors
expect(durationDiff < 1).to.equal(true);

View file

@ -6,7 +6,7 @@
*/
import expect from '@kbn/expect';
import { IValidatedEvent } from '@kbn/event-log-plugin/server';
import { IValidatedEvent, nanosToMillis } from '@kbn/event-log-plugin/server';
import { Spaces } from '../../scenarios';
import { getUrlPrefix, getTestRuleData, ObjectRemover, getEventLog } from '../../../common/lib';
import { FtrProviderContext } from '../../../common/ftr_provider_context';
@ -91,7 +91,7 @@ export default function eventLogAlertTests({ getService }: FtrProviderContext) {
const currentAlertSpan: {
alertId?: string;
start?: string;
durationToDate?: number;
durationToDate?: string;
} = {};
for (let i = 0; i < instanceEvents.length; ++i) {
switch (instanceEvents[i]?.event?.action) {
@ -102,7 +102,7 @@ export default function eventLogAlertTests({ getService }: FtrProviderContext) {
currentAlertSpan.alertId = instanceEvents[i]?.kibana?.alerting?.instance_id;
currentAlertSpan.start = instanceEvents[i]?.event?.start;
currentAlertSpan.durationToDate = instanceEvents[i]?.event?.duration;
currentAlertSpan.durationToDate = `${instanceEvents[i]?.event?.duration}`;
break;
case 'active-instance':
@ -110,12 +110,13 @@ export default function eventLogAlertTests({ getService }: FtrProviderContext) {
expect(instanceEvents[i]?.event?.start).to.equal(currentAlertSpan.start);
expect(instanceEvents[i]?.event?.end).to.be(undefined);
if (instanceEvents[i]?.event?.duration! !== 0) {
expect(instanceEvents[i]?.event?.duration! > currentAlertSpan.durationToDate!).to.be(
true
);
if (instanceEvents[i]?.event?.duration! !== '0') {
expect(
BigInt(instanceEvents[i]?.event?.duration!) >
BigInt(currentAlertSpan.durationToDate!)
).to.be(true);
}
currentAlertSpan.durationToDate = instanceEvents[i]?.event?.duration;
currentAlertSpan.durationToDate = `${instanceEvents[i]?.event?.duration}`;
break;
case 'recovered-instance':
@ -125,7 +126,7 @@ export default function eventLogAlertTests({ getService }: FtrProviderContext) {
expect(
new Date(instanceEvents[i]?.event?.end!).valueOf() -
new Date(instanceEvents[i]?.event?.start!).valueOf()
).to.equal(instanceEvents[i]?.event?.duration! / 1000 / 1000);
).to.equal(nanosToMillis(instanceEvents[i]?.event?.duration!));
break;
}
}