diff --git a/x-pack/plugins/event_log/server/event_log_service.test.ts b/x-pack/plugins/event_log/server/event_log_service.test.ts index 5ab019e533dae..c7e752d1a652b 100644 --- a/x-pack/plugins/event_log/server/event_log_service.test.ts +++ b/x-pack/plugins/event_log/server/event_log_service.test.ts @@ -24,6 +24,7 @@ describe('EventLogService', () => { return new EventLogService({ esContext, systemLogger, + kibanaUUID: '42', config: { enabled, logEntries, @@ -67,6 +68,7 @@ describe('EventLogService', () => { const params = { esContext, systemLogger, + kibanaUUID: '42', config: { enabled: true, logEntries: true, @@ -103,6 +105,7 @@ describe('EventLogService', () => { const params = { esContext, systemLogger, + kibanaUUID: '42', config: { enabled: true, logEntries: true, diff --git a/x-pack/plugins/event_log/server/event_log_service.ts b/x-pack/plugins/event_log/server/event_log_service.ts index 2746d86b8b2cb..fc72de6e47356 100644 --- a/x-pack/plugins/event_log/server/event_log_service.ts +++ b/x-pack/plugins/event_log/server/event_log_service.ts @@ -20,19 +20,23 @@ type SystemLogger = Plugin['systemLogger']; interface EventLogServiceCtorParams { config: IEventLogConfig; esContext: EsContext; + kibanaUUID: string; systemLogger: SystemLogger; } // note that clusterClient may be null, indicating we can't write to ES export class EventLogService implements IEventLogService { private config: IEventLogConfig; - private systemLogger: SystemLogger; private esContext: EsContext; + private systemLogger: SystemLogger; private registeredProviderActions: Map>; - constructor({ config, systemLogger, esContext }: EventLogServiceCtorParams) { + public readonly kibanaUUID: string; + + constructor({ config, esContext, kibanaUUID, systemLogger }: EventLogServiceCtorParams) { this.config = config; this.esContext = esContext; + this.kibanaUUID = kibanaUUID; this.systemLogger = systemLogger; this.registeredProviderActions = new Map>(); } 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 0b06515c00bf3..c2de8d4dfd12b 100644 --- a/x-pack/plugins/event_log/server/event_logger.test.ts +++ b/x-pack/plugins/event_log/server/event_logger.test.ts @@ -4,64 +4,122 @@ * you may not use this file except in compliance with the Elastic License. */ -import { IEvent, IEventLogger } from './index'; +import { IEvent, IEventLogger, IEventLogService } from './index'; +import { ECS_VERSION } from './types'; import { EventLogService } from './event_log_service'; import { getEsNames } from './es/names'; +import { EsContext } from './es/context'; import { createMockEsContext } from './es/context.mock'; -import { loggingServiceMock } from '../../../../src/core/server/logging/logging_service.mock'; +import { loggerMock, MockedLogger } from '../../../../src/core/server/logging/logger.mock'; import { delay } from './lib/delay'; +import { EVENT_LOGGED_PREFIX } from './event_logger'; -const loggingService = loggingServiceMock.create(); -const systemLogger = loggingService.get(); +const KIBANA_SERVER_UUID = '424-24-2424'; describe('EventLogger', () => { - const esContext = createMockEsContext({ esNames: getEsNames('ABC'), logger: systemLogger }); - const config = { enabled: true, logEntries: true, indexEntries: true }; - const service = new EventLogService({ esContext, systemLogger, config }); + let systemLogger: MockedLogger; + let esContext: EsContext; + let service: IEventLogService; let eventLogger: IEventLogger; beforeEach(() => { + systemLogger = loggerMock.create(); + esContext = createMockEsContext({ esNames: getEsNames('ABC'), logger: systemLogger }); + service = new EventLogService({ + esContext, + systemLogger, + config: { enabled: true, logEntries: true, indexEntries: false }, + kibanaUUID: KIBANA_SERVER_UUID, + }); eventLogger = service.getLogger({}); }); - test('logEvent()', () => { + test('method logEvent() writes expected default values', async () => { service.registerProviderActions('test-provider', ['test-action-1']); - const initialProperties = { - event: { provider: 'test-provider' }, - }; - eventLogger = service.getLogger(initialProperties); + eventLogger = service.getLogger({ + event: { provider: 'test-provider', action: 'test-action-1' }, + }); - // ATM, just make sure it doesn't blow up + const dateStart = new Date().valueOf(); eventLogger.logEvent({}); + const event = await waitForLogEvent(systemLogger); + const dateEnd = new Date().valueOf(); + + expect(event).toMatchObject({ + event: { + provider: 'test-provider', + action: 'test-action-1', + }, + '@timestamp': expect.stringMatching(/.*/), + ecs: { + version: ECS_VERSION, + }, + kibana: { + server_uuid: '424-24-2424', + }, + error: {}, + user: {}, + }); + + const $timeStamp = event!['@timestamp']!; + const timeStamp = new Date($timeStamp); + expect(timeStamp).not.toBeNaN(); + + const timeStampValue = timeStamp.valueOf(); + expect(timeStampValue).toBeGreaterThanOrEqual(dateStart); + expect(timeStampValue).toBeLessThanOrEqual(dateEnd); }); - test('timing', async () => { + test('method logEvent() merges event data', async () => { + service.registerProviderActions('test-provider', ['a', 'b']); + eventLogger = service.getLogger({ + event: { provider: 'test-provider', action: 'a' }, + }); + + const ignoredTimestamp = '1999-01-01T00:00:00Z'; + eventLogger.logEvent({ + '@timestamp': ignoredTimestamp, + event: { + action: 'b', + }, + }); + const event = await waitForLogEvent(systemLogger); + + expect(event!['@timestamp']).not.toEqual(ignoredTimestamp); + expect(event?.event?.action).toEqual('b'); + }); + + test('timing methods work', async () => { + const delayMS = 100; const event: IEvent = {}; eventLogger.startTiming(event); const timeStart = event.event!.start!; expect(timeStart).toBeTruthy(); - expect(new Date(timeStart)).toBeTruthy(); + const timeStartValue = new Date(timeStart).valueOf(); - await delay(100); + await delay(delayMS); eventLogger.stopTiming(event); const timeStop = event.event!.end!; expect(timeStop).toBeTruthy(); - expect(new Date(timeStop)).toBeTruthy(); + const timeStopValue = new Date(timeStop).valueOf(); + + expect(timeStopValue).toBeGreaterThanOrEqual(timeStartValue); const duration = event.event!.duration!; - expect(duration).toBeGreaterThan(90 * 1000 * 1000); + expect(duration).toBeGreaterThan(0.95 * delayMS * 1000 * 1000); + expect(duration / (1000 * 1000)).toBeCloseTo(timeStopValue - timeStartValue); }); - test('timing - no start', async () => { + test('timing method endTiming() method works when startTiming() is not called', async () => { const event: IEvent = {}; eventLogger.stopTiming(event); expect(event.event).toBeUndefined(); }); - test('timing - bad start', async () => { + test('timing method endTiming() method works event contains bad data', async () => { const event: IEvent = { event: { start: 'not a date that can be parsed', @@ -72,4 +130,76 @@ describe('EventLogger', () => { expect(event.event!.end).toBeUndefined(); expect(event.event!.duration).toBeUndefined(); }); + + test('logs warnings when using unregistered actions and providers', async () => { + service.registerProviderActions('provider', ['action-a', 'action-b']); + eventLogger = service.getLogger({}); + + let message: string; + + eventLogger.logEvent({ event: { provider: 'provider-X', action: 'action-a' } }); + message = await waitForLogMessage(systemLogger); + expect(message).toMatch(/invalid event logged.*provider-X.*action-a.*/); + + eventLogger.logEvent({ event: { action: 'action-a' } }); + message = await waitForLogMessage(systemLogger); + expect(message).toMatch(/invalid event logged.*provider.*undefined.*/); + + eventLogger.logEvent({ event: { provider: 'provider', action: 'action-c' } }); + message = await waitForLogMessage(systemLogger); + expect(message).toMatch(/invalid event logged.*provider.*action-c.*/); + + eventLogger.logEvent({ event: { provider: 'provider' } }); + message = await waitForLogMessage(systemLogger); + expect(message).toMatch(/invalid event logged.*action.*undefined.*/); + }); }); + +// return the next logged event; throw if not an event +async function waitForLogEvent(mockLogger: MockedLogger, waitSeconds: number = 1): Promise { + const result = await waitForLog(mockLogger, waitSeconds); + if (typeof result === 'string') throw new Error('expecting an event'); + return result; +} + +// return the next logged message; throw if it is an event +async function waitForLogMessage( + mockLogger: MockedLogger, + waitSeconds: number = 1 +): Promise { + const result = await waitForLog(mockLogger, waitSeconds); + if (typeof result !== 'string') throw new Error('expecting a message'); + return result; +} + +// return the next logged message, if it's an event log entry, parse it +async function waitForLog( + mockLogger: MockedLogger, + waitSeconds: number = 1 +): Promise { + const intervals = 4; + const interval = (waitSeconds * 1000) / intervals; + + // break the waiting time into some intervals + for (let i = 0; i <= intervals; i++) { + await delay(interval); + + const calls = mockLogger.warn.mock.calls.concat(mockLogger.info.mock.calls); + if (calls.length === 0) continue; + + const call = calls[0][0]; + mockLogger.info.mockReset(); + mockLogger.warn.mockReset(); + + if (typeof call !== 'string') throw new Error(`expecting a string: ${call}`); + if (!call.startsWith(EVENT_LOGGED_PREFIX)) { + return call; + } else { + return JSON.parse(call.substr(EVENT_LOGGED_PREFIX.length)); + } + } + + mockLogger.info.mockReset(); + mockLogger.warn.mockReset(); + throw new Error(`expecting a log message in ${waitSeconds} seconds, but did not get it`); +} diff --git a/x-pack/plugins/event_log/server/event_logger.ts b/x-pack/plugins/event_log/server/event_logger.ts index 50cf83f55730b..891abda947fc8 100644 --- a/x-pack/plugins/event_log/server/event_logger.ts +++ b/x-pack/plugins/event_log/server/event_logger.ts @@ -10,6 +10,7 @@ import { merge } from 'lodash'; import { Plugin } from './plugin'; import { EsContext } from './es'; +import { EventLogService } from './event_log_service'; import { IEvent, IValidatedEvent, @@ -28,14 +29,14 @@ interface Doc { interface IEventLoggerCtorParams { esContext: EsContext; - eventLogService: IEventLogService; + eventLogService: EventLogService; initialProperties: IEvent; systemLogger: SystemLogger; } export class EventLogger implements IEventLogger { private esContext: EsContext; - private eventLogService: IEventLogService; + private eventLogService: EventLogService; private initialProperties: IEvent; private systemLogger: SystemLogger; @@ -69,17 +70,18 @@ export class EventLogger implements IEventLogger { if (!this.eventLogService.isEnabled()) return; const event: IEvent = {}; + const fixedProperties = { + '@timestamp': new Date().toISOString(), + ecs: { + version: ECS_VERSION, + }, + kibana: { + server_uuid: this.eventLogService.kibanaUUID, + }, + }; // merge the initial properties and event properties - merge(event, this.initialProperties, eventProperties); - - // add fixed properties - event['@timestamp'] = new Date().toISOString(); - event.ecs = event.ecs || {}; - event.ecs.version = ECS_VERSION; - - // TODO add kibana server uuid - // event.kibana.server_uuid = NP version of config.get('server.uuid'); + merge(event, this.initialProperties, eventProperties, fixedProperties); let validatedEvent: IValidatedEvent; try { @@ -138,9 +140,11 @@ function validateEvent(eventLogService: IEventLogService, event: IEvent): IValid return EventSchema.validate(event); } +export const EVENT_LOGGED_PREFIX = `event logged: `; + function logEventDoc(logger: Logger, doc: Doc): void { setImmediate(() => { - logger.info(`event logged ${JSON.stringify(doc.body)}`); + logger.info(`${EVENT_LOGGED_PREFIX}${JSON.stringify(doc.body)}`); }); } diff --git a/x-pack/plugins/event_log/server/plugin.ts b/x-pack/plugins/event_log/server/plugin.ts index 5bc0bcd4287b4..e32d4ff6f7acc 100644 --- a/x-pack/plugins/event_log/server/plugin.ts +++ b/x-pack/plugins/event_log/server/plugin.ts @@ -57,6 +57,7 @@ export class Plugin implements CorePlugin { config, esContext: this.esContext, systemLogger: this.systemLogger, + kibanaUUID: core.uuid.getInstanceUuid(), }); this.eventLogService.registerProviderActions(PROVIDER, Object.values(ACTIONS));