From 8bcecc0fb01edbb6a64fad239c29ccd4d2555083 Mon Sep 17 00:00:00 2001 From: Jonathan Budzenski Date: Wed, 15 Jul 2020 08:45:20 -0500 Subject: [PATCH] [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 --- .../__snapshots__/logging_system.test.ts.snap | 54 ++++--- .../logging/integration_tests/logging.test.ts | 30 ++-- .../__snapshots__/json_layout.test.ts.snap | 12 +- .../logging/layouts/json_layout.test.ts | 133 +++++++++++++++--- .../server/logging/layouts/json_layout.ts | 31 ++-- .../server/logging/logging_system.test.ts | 50 ++++--- 6 files changed, 231 insertions(+), 79 deletions(-) diff --git a/src/core/server/logging/__snapshots__/logging_system.test.ts.snap b/src/core/server/logging/__snapshots__/logging_system.test.ts.snap index 2add00457b2ed..cbe0e352a0f3a 100644 --- 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, + "process": Object { + "pid": Any, + }, } `; exports[`asLoggerFactory() only allows to create new loggers. 2`] = ` Object { "@timestamp": "2012-01-31T13:33:22.011-05:00", - "context": "test.context", - "level": "INFO", + "log": Object { + "level": "INFO", + "logger": "test.context", + }, "message": "buffered info message", - "meta": Object { - "some": "value", + "process": Object { + "pid": Any, }, - "pid": Any, + "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, + "process": Object { + "pid": Any, + }, } `; 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", + "log": Object { + "level": "INFO", + "logger": "test.context", + }, "message": "buffered info message", - "meta": Object { - "some": "value", + "process": Object { + "pid": Any, }, - "pid": Any, + "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, + "process": Object { + "pid": Any, + }, } `; diff --git a/src/core/server/logging/integration_tests/logging.test.ts b/src/core/server/logging/integration_tests/logging.test.ts index a80939a25ae65..841c1ce15af47 100644 --- 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'); diff --git a/src/core/server/logging/layouts/__snapshots__/json_layout.test.ts.snap b/src/core/server/logging/layouts/__snapshots__/json_layout.test.ts.snap index 14c071b40ad7a..0e7ce8d0b2f3c 100644 --- 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}}"`; diff --git a/src/core/server/logging/layouts/json_layout.test.ts b/src/core/server/logging/layouts/json_layout.test.ts index 77e2876c143da..6cda1e4806aa8 100644 --- 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, + }, }); }); diff --git a/src/core/server/logging/layouts/json_layout.ts b/src/core/server/logging/layouts/json_layout.ts index ad8c33d7cb023..04416184a5957 100644 --- 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 + ) + ); } } diff --git a/src/core/server/logging/logging_system.test.ts b/src/core/server/logging/logging_system.test.ts index ac52973081106..afe58ddff92aa 100644 --- 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', + }, }); });