[logging] Format new platform json logging to ECS (#71138)

* [logging] Format new platform json logging to ECS * update integration tests * merge instead of assign * add @timestamp override test * add partial merge test against log object * add object level override test * fix type error Co-authored-by: Elastic Machine <elasticmachine@users.noreply.github.com>
2020-07-15 08:45:20 -05:00 · 2020-07-15 08:45:20 -05:00 · 8bcecc0fb0
parent ed387dd15f
commit 8bcecc0fb0
6 changed files with 233 additions and 81 deletions
--- a/src/core/server/logging/snapshots/logging_system.test.ts.snap
+++ b/src/core/server/logging/snapshots/logging_system.test.ts.snap
@ -15,56 +15,72 @@ exports[`appends records via multiple appenders.: file logs 2`] = `
 exports[`asLoggerFactory() only allows to create new loggers. 1`] = `
 Object {
  "@timestamp": "2012-01-31T18:33:22.011-05:00",
-  "context": "test.context",
-  "level": "TRACE",
+  "log": Object {
+    "level": "TRACE",
+    "logger": "test.context",
+  },
  "message": "buffered trace message",
-  "pid": Any<Number>,
+  "process": Object {
+    "pid": Any<Number>,
+  },
 }
 `;

 exports[`asLoggerFactory() only allows to create new loggers. 2`] = `
 Object {
  "@timestamp": "2012-01-31T13:33:22.011-05:00",
-  "context": "test.context",
-  "level": "INFO",
-  "message": "buffered info message",
-  "meta": Object {
-    "some": "value",
+  "log": Object {
+    "level": "INFO",
+    "logger": "test.context",
  },
-  "pid": Any<Number>,
+  "message": "buffered info message",
+  "process": Object {
+    "pid": Any<Number>,
+  },
+  "some": "value",
 }
 `;

 exports[`asLoggerFactory() only allows to create new loggers. 3`] = `
 Object {
  "@timestamp": "2012-01-31T08:33:22.011-05:00",
-  "context": "test.context",
-  "level": "FATAL",
+  "log": Object {
+    "level": "FATAL",
+    "logger": "test.context",
+  },
  "message": "buffered fatal message",
-  "pid": Any<Number>,
+  "process": Object {
+    "pid": Any<Number>,
+  },
 }
 `;

 exports[`flushes memory buffer logger and switches to real logger once config is provided: buffered messages 1`] = `
 Object {
  "@timestamp": "2012-02-01T09:33:22.011-05:00",
-  "context": "test.context",
-  "level": "INFO",
-  "message": "buffered info message",
-  "meta": Object {
-    "some": "value",
+  "log": Object {
+    "level": "INFO",
+    "logger": "test.context",
  },
-  "pid": Any<Number>,
+  "message": "buffered info message",
+  "process": Object {
+    "pid": Any<Number>,
+  },
+  "some": "value",
 }
 `;

 exports[`flushes memory buffer logger and switches to real logger once config is provided: new messages 1`] = `
 Object {
  "@timestamp": "2012-01-31T23:33:22.011-05:00",
-  "context": "test.context",
-  "level": "INFO",
+  "log": Object {
+    "level": "INFO",
+    "logger": "test.context",
+  },
  "message": "some new info message",
-  "pid": Any<Number>,
+  "process": Object {
+    "pid": Any<Number>,
+  },
 }
 `;

--- a/src/core/server/logging/integration_tests/logging.test.ts
+++ b/src/core/server/logging/integration_tests/logging.test.ts
@ -198,13 +198,17 @@ describe('logging service', () => {
        JSON.parse(jsonString)
      );
      expect(firstCall).toMatchObject({
-        level: 'DEBUG',
-        context: 'plugins.myplugin.debug_json',
+        log: {
+          level: 'DEBUG',
+          logger: 'plugins.myplugin.debug_json',
+        },
        message: 'log1',
      });
      expect(secondCall).toMatchObject({
-        level: 'INFO',
-        context: 'plugins.myplugin.debug_json',
+        log: {
+          level: 'INFO',
+          logger: 'plugins.myplugin.debug_json',
+        },
        message: 'log2',
      });
    });
@ -217,8 +221,10 @@ describe('logging service', () => {

      expect(mockConsoleLog).toHaveBeenCalledTimes(1);
      expect(JSON.parse(mockConsoleLog.mock.calls[0][0])).toMatchObject({
-        level: 'INFO',
-        context: 'plugins.myplugin.info_json',
+        log: {
+          level: 'INFO',
+          logger: 'plugins.myplugin.info_json',
+        },
        message: 'log2',
      });
    });
@ -259,14 +265,18 @@ describe('logging service', () => {
      const logs = mockConsoleLog.mock.calls.map(([jsonString]) => jsonString);

      expect(JSON.parse(logs[0])).toMatchObject({
-        level: 'DEBUG',
-        context: 'plugins.myplugin.all',
+        log: {
+          level: 'DEBUG',
+          logger: 'plugins.myplugin.all',
+        },
        message: 'log1',
      });
      expect(logs[1]).toEqual('CUSTOM - PATTERN [plugins.myplugin.all][DEBUG] log1');
      expect(JSON.parse(logs[2])).toMatchObject({
-        level: 'INFO',
-        context: 'plugins.myplugin.all',
+        log: {
+          level: 'INFO',
+          logger: 'plugins.myplugin.all',
+        },
        message: 'log2',
      });
      expect(logs[3]).toEqual('CUSTOM - PATTERN [plugins.myplugin.all][INFO ] log2');
--- a/src/core/server/logging/layouts/snapshots/json_layout.test.ts.snap
+++ b/src/core/server/logging/layouts/snapshots/json_layout.test.ts.snap
@ -1,13 +1,13 @@
 // Jest Snapshot v1, https://goo.gl/fbAQLP

-exports[`\`format()\` correctly formats record. 1`] = `"{\\"@timestamp\\":\\"2012-02-01T09:30:22.011-05:00\\",\\"context\\":\\"context-1\\",\\"error\\":{\\"message\\":\\"Some error message\\",\\"name\\":\\"Some error name\\",\\"stack\\":\\"Some error stack\\"},\\"level\\":\\"FATAL\\",\\"message\\":\\"message-1\\",\\"pid\\":5355}"`;
+exports[`\`format()\` correctly formats record. 1`] = `"{\\"@timestamp\\":\\"2012-02-01T09:30:22.011-05:00\\",\\"message\\":\\"message-1\\",\\"error\\":{\\"message\\":\\"Some error message\\",\\"type\\":\\"Some error name\\",\\"stack_trace\\":\\"Some error stack\\"},\\"log\\":{\\"level\\":\\"FATAL\\",\\"logger\\":\\"context-1\\"},\\"process\\":{\\"pid\\":5355}}"`;

-exports[`\`format()\` correctly formats record. 2`] = `"{\\"@timestamp\\":\\"2012-02-01T09:30:22.011-05:00\\",\\"context\\":\\"context-2\\",\\"level\\":\\"ERROR\\",\\"message\\":\\"message-2\\",\\"pid\\":5355}"`;
+exports[`\`format()\` correctly formats record. 2`] = `"{\\"@timestamp\\":\\"2012-02-01T09:30:22.011-05:00\\",\\"message\\":\\"message-2\\",\\"log\\":{\\"level\\":\\"ERROR\\",\\"logger\\":\\"context-2\\"},\\"process\\":{\\"pid\\":5355}}"`;

-exports[`\`format()\` correctly formats record. 3`] = `"{\\"@timestamp\\":\\"2012-02-01T09:30:22.011-05:00\\",\\"context\\":\\"context-3\\",\\"level\\":\\"WARN\\",\\"message\\":\\"message-3\\",\\"pid\\":5355}"`;
+exports[`\`format()\` correctly formats record. 3`] = `"{\\"@timestamp\\":\\"2012-02-01T09:30:22.011-05:00\\",\\"message\\":\\"message-3\\",\\"log\\":{\\"level\\":\\"WARN\\",\\"logger\\":\\"context-3\\"},\\"process\\":{\\"pid\\":5355}}"`;

-exports[`\`format()\` correctly formats record. 4`] = `"{\\"@timestamp\\":\\"2012-02-01T09:30:22.011-05:00\\",\\"context\\":\\"context-4\\",\\"level\\":\\"DEBUG\\",\\"message\\":\\"message-4\\",\\"pid\\":5355}"`;
+exports[`\`format()\` correctly formats record. 4`] = `"{\\"@timestamp\\":\\"2012-02-01T09:30:22.011-05:00\\",\\"message\\":\\"message-4\\",\\"log\\":{\\"level\\":\\"DEBUG\\",\\"logger\\":\\"context-4\\"},\\"process\\":{\\"pid\\":5355}}"`;

-exports[`\`format()\` correctly formats record. 5`] = `"{\\"@timestamp\\":\\"2012-02-01T09:30:22.011-05:00\\",\\"context\\":\\"context-5\\",\\"level\\":\\"INFO\\",\\"message\\":\\"message-5\\",\\"pid\\":5355}"`;
+exports[`\`format()\` correctly formats record. 5`] = `"{\\"@timestamp\\":\\"2012-02-01T09:30:22.011-05:00\\",\\"message\\":\\"message-5\\",\\"log\\":{\\"level\\":\\"INFO\\",\\"logger\\":\\"context-5\\"},\\"process\\":{\\"pid\\":5355}}"`;

-exports[`\`format()\` correctly formats record. 6`] = `"{\\"@timestamp\\":\\"2012-02-01T09:30:22.011-05:00\\",\\"context\\":\\"context-6\\",\\"level\\":\\"TRACE\\",\\"message\\":\\"message-6\\",\\"pid\\":5355}"`;
+exports[`\`format()\` correctly formats record. 6`] = `"{\\"@timestamp\\":\\"2012-02-01T09:30:22.011-05:00\\",\\"message\\":\\"message-6\\",\\"log\\":{\\"level\\":\\"TRACE\\",\\"logger\\":\\"context-6\\"},\\"process\\":{\\"pid\\":5355}}"`;
--- a/src/core/server/logging/layouts/json_layout.test.ts
+++ b/src/core/server/logging/layouts/json_layout.test.ts
@ -98,21 +98,27 @@ test('`format()` correctly formats record with meta-data', () => {
        timestamp,
        pid: 5355,
        meta: {
-          from: 'v7',
-          to: 'v8',
+          version: {
+            from: 'v7',
+            to: 'v8',
+          },
        },
      })
    )
  ).toStrictEqual({
    '@timestamp': '2012-02-01T09:30:22.011-05:00',
-    context: 'context-with-meta',
-    level: 'DEBUG',
+    log: {
+      level: 'DEBUG',
+      logger: 'context-with-meta',
+    },
    message: 'message-with-meta',
-    meta: {
+    version: {
      from: 'v7',
      to: 'v8',
    },
-    pid: 5355,
+    process: {
+      pid: 5355,
+    },
  });
 });

@ -122,36 +128,131 @@ test('`format()` correctly formats error record with meta-data', () => {
  expect(
    JSON.parse(
      layout.format({
-        context: 'error-with-meta',
        level: LogLevel.Debug,
+        context: 'error-with-meta',
        error: {
          message: 'Some error message',
-          name: 'Some error name',
+          name: 'Some error type',
          stack: 'Some error stack',
        },
        message: 'Some error message',
        timestamp,
        pid: 5355,
        meta: {
-          from: 'v7',
-          to: 'v8',
+          version: {
+            from: 'v7',
+            to: 'v8',
+          },
        },
      })
    )
  ).toStrictEqual({
    '@timestamp': '2012-02-01T09:30:22.011-05:00',
-    context: 'error-with-meta',
-    level: 'DEBUG',
+    log: {
+      level: 'DEBUG',
+      logger: 'error-with-meta',
+    },
    error: {
      message: 'Some error message',
-      name: 'Some error name',
-      stack: 'Some error stack',
+      type: 'Some error type',
+      stack_trace: 'Some error stack',
    },
    message: 'Some error message',
-    meta: {
+    version: {
      from: 'v7',
      to: 'v8',
    },
-    pid: 5355,
+    process: {
+      pid: 5355,
+    },
+  });
+});
+
+test('format() meta can override @timestamp', () => {
+  const layout = new JsonLayout();
+  expect(
+    JSON.parse(
+      layout.format({
+        message: 'foo',
+        timestamp,
+        level: LogLevel.Debug,
+        context: 'bar',
+        pid: 3,
+        meta: {
+          '@timestamp': '2099-05-01T09:30:22.011-05:00',
+        },
+      })
+    )
+  ).toStrictEqual({
+    '@timestamp': '2099-05-01T09:30:22.011-05:00',
+    message: 'foo',
+    log: {
+      level: 'DEBUG',
+      logger: 'bar',
+    },
+    process: {
+      pid: 3,
+    },
+  });
+});
+
+test('format() meta can merge override logs', () => {
+  const layout = new JsonLayout();
+  expect(
+    JSON.parse(
+      layout.format({
+        timestamp,
+        message: 'foo',
+        level: LogLevel.Error,
+        context: 'bar',
+        pid: 3,
+        meta: {
+          log: {
+            kbn_custom_field: 'hello',
+          },
+        },
+      })
+    )
+  ).toStrictEqual({
+    '@timestamp': '2012-02-01T09:30:22.011-05:00',
+    message: 'foo',
+    log: {
+      level: 'ERROR',
+      logger: 'bar',
+      kbn_custom_field: 'hello',
+    },
+    process: {
+      pid: 3,
+    },
+  });
+});
+
+test('format() meta can override log level objects', () => {
+  const layout = new JsonLayout();
+  expect(
+    JSON.parse(
+      layout.format({
+        timestamp,
+        context: '123',
+        message: 'foo',
+        level: LogLevel.Error,
+        pid: 3,
+        meta: {
+          log: {
+            level: 'FATAL',
+          },
+        },
+      })
+    )
+  ).toStrictEqual({
+    '@timestamp': '2012-02-01T09:30:22.011-05:00',
+    message: 'foo',
+    log: {
+      level: 'FATAL',
+      logger: '123',
+    },
+    process: {
+      pid: 3,
+    },
  });
 });
--- a/src/core/server/logging/layouts/json_layout.ts
+++ b/src/core/server/logging/layouts/json_layout.ts
@ -18,6 +18,7 @@
 */

 import moment from 'moment-timezone';
+import { merge } from 'lodash';
 import { schema, TypeOf } from '@kbn/config-schema';

 import { LogRecord } from '../log_record';
@ -46,20 +47,28 @@ export class JsonLayout implements Layout {

    return {
      message: error.message,
-      name: error.name,
-      stack: error.stack,
+      type: error.name,
+      stack_trace: error.stack,
    };
  }

  public format(record: LogRecord): string {
-    return JSON.stringify({
-      '@timestamp': moment(record.timestamp).format('YYYY-MM-DDTHH:mm:ss.SSSZ'),
-      context: record.context,
-      error: JsonLayout.errorToSerializableObject(record.error),
-      level: record.level.id.toUpperCase(),
-      message: record.message,
-      meta: record.meta,
-      pid: record.pid,
-    });
+    return JSON.stringify(
+      merge(
+        {
+          '@timestamp': moment(record.timestamp).format('YYYY-MM-DDTHH:mm:ss.SSSZ'),
+          message: record.message,
+          error: JsonLayout.errorToSerializableObject(record.error),
+          log: {
+            level: record.level.id.toUpperCase(),
+            logger: record.context,
+          },
+          process: {
+            pid: record.pid,
+          },
+        },
+        record.meta
+      )
+    );
  }
 }
--- a/src/core/server/logging/logging_system.test.ts
+++ b/src/core/server/logging/logging_system.test.ts
@ -23,7 +23,7 @@ jest.mock('fs', () => ({
  createWriteStream: jest.fn(() => ({ write: mockStreamWrite })),
 }));

-const dynamicProps = { pid: expect.any(Number) };
+const dynamicProps = { process: { pid: expect.any(Number) } };

 jest.mock('../../../legacy/server/logging/rotate', () => ({
  setupLoggingRotate: jest.fn().mockImplementation(() => Promise.resolve({})),
@ -61,8 +61,10 @@ test('uses default memory buffer logger until config is provided', () => {
  anotherLogger.fatal('fatal message', { some: 'value' });

  expect(bufferAppendSpy).toHaveBeenCalledTimes(2);
-  expect(bufferAppendSpy.mock.calls[0][0]).toMatchSnapshot(dynamicProps);
-  expect(bufferAppendSpy.mock.calls[1][0]).toMatchSnapshot(dynamicProps);
+
+  // pid at args level, nested under process for ECS writes
+  expect(bufferAppendSpy.mock.calls[0][0]).toMatchSnapshot({ pid: expect.any(Number) });
+  expect(bufferAppendSpy.mock.calls[1][0]).toMatchSnapshot({ pid: expect.any(Number) });
 });

 test('flushes memory buffer logger and switches to real logger once config is provided', () => {
@ -210,20 +212,26 @@ test('setContextConfig() updates config with relative contexts', () => {
  expect(mockConsoleLog).toHaveBeenCalledTimes(4);
  // Parent contexts are unaffected
  expect(JSON.parse(mockConsoleLog.mock.calls[0][0])).toMatchObject({
-    context: 'tests',
    message: 'tests log to default!',
-    level: 'WARN',
+    log: {
+      level: 'WARN',
+      logger: 'tests',
+    },
  });
  expect(JSON.parse(mockConsoleLog.mock.calls[1][0])).toMatchObject({
-    context: 'tests.child',
    message: 'tests.child log to default!',
-    level: 'ERROR',
+    log: {
+      level: 'ERROR',
+      logger: 'tests.child',
+    },
  });
  // Customized context is logged in both appender formats
  expect(JSON.parse(mockConsoleLog.mock.calls[2][0])).toMatchObject({
-    context: 'tests.child.grandchild',
    message: 'tests.child.grandchild log to default and custom!',
-    level: 'DEBUG',
+    log: {
+      level: 'DEBUG',
+      logger: 'tests.child.grandchild',
+    },
  });
  expect(mockConsoleLog.mock.calls[3][0]).toMatchInlineSnapshot(
    `"[DEBUG][tests.child.grandchild] tests.child.grandchild log to default and custom!"`
@ -259,9 +267,11 @@ test('setContextConfig() updates config for a root context', () => {
  expect(mockConsoleLog).toHaveBeenCalledTimes(3);
  // Parent context is unaffected
  expect(JSON.parse(mockConsoleLog.mock.calls[0][0])).toMatchObject({
-    context: 'tests',
    message: 'tests log to default!',
-    level: 'WARN',
+    log: {
+      level: 'WARN',
+      logger: 'tests',
+    },
  });
  // Customized contexts
  expect(mockConsoleLog.mock.calls[1][0]).toMatchInlineSnapshot(
@ -299,9 +309,11 @@ test('custom context configs are applied on subsequent calls to update()', () =>
  // Customized context is logged in both appender formats still
  expect(mockConsoleLog).toHaveBeenCalledTimes(2);
  expect(JSON.parse(mockConsoleLog.mock.calls[0][0])).toMatchObject({
-    context: 'tests.child.grandchild',
    message: 'tests.child.grandchild log to default and custom!',
-    level: 'DEBUG',
+    log: {
+      level: 'DEBUG',
+      logger: 'tests.child.grandchild',
+    },
  });
  expect(mockConsoleLog.mock.calls[1][0]).toMatchInlineSnapshot(
    `"[DEBUG][tests.child.grandchild] tests.child.grandchild log to default and custom!"`
@ -347,9 +359,11 @@ test('subsequent calls to setContextConfig() for the same context override the p
  // Only the warn log should have been logged
  expect(mockConsoleLog).toHaveBeenCalledTimes(2);
  expect(JSON.parse(mockConsoleLog.mock.calls[0][0])).toMatchObject({
-    context: 'tests.child.grandchild',
    message: 'tests.child.grandchild log to default and custom!',
-    level: 'WARN',
+    log: {
+      level: 'WARN',
+      logger: 'tests.child.grandchild',
+    },
  });
  expect(mockConsoleLog.mock.calls[1][0]).toMatchInlineSnapshot(
    `"[WARN ][tests.child.grandchild] second pattern! tests.child.grandchild log to default and custom!"`
@ -384,8 +398,10 @@ test('subsequent calls to setContextConfig() for the same context can disable th
  // Only the warn log should have been logged once on the default appender
  expect(mockConsoleLog).toHaveBeenCalledTimes(1);
  expect(JSON.parse(mockConsoleLog.mock.calls[0][0])).toMatchObject({
-    context: 'tests.child.grandchild',
    message: 'tests.child.grandchild log to default!',
-    level: 'WARN',
+    log: {
+      level: 'WARN',
+      logger: 'tests.child.grandchild',
+    },
  });
 });