adds the Kibana server uuid to eventLog events (#56004)

resolves https://github.com/elastic/kibana/issues/55631

Also beefed up the event_logger test cases.

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,

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<string, Set<string>>;
 
-  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<string, Set<string>>();
   }

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<IEvent> {
+  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<string> {
+  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<string | IEvent> {
+  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`);
+}

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)}`);
   });
 }
 

x-pack/plugins/event_log/server/plugin.ts

@@ -57,6 +57,7 @@ export class Plugin implements CorePlugin<IEventLogService> {
       config,
       esContext: this.esContext,
       systemLogger: this.systemLogger,
+      kibanaUUID: core.uuid.getInstanceUuid(),
     });
 
     this.eventLogService.registerProviderActions(PROVIDER, Object.values(ACTIONS));