From e5a0992c9399f16d568964be61b011215a215c62 Mon Sep 17 00:00:00 2001 From: Jonathan Budzenski Date: Wed, 8 Jul 2020 12:30:16 -0500 Subject: [PATCH] [logging] Format new platform json logging to ECS --- .../__snapshots__/logging_system.test.ts.snap | 54 ++++++++++++------- .../__snapshots__/json_layout.test.ts.snap | 12 ++--- .../logging/layouts/json_layout.test.ts | 44 +++++++++------ .../server/logging/layouts/json_layout.ts | 18 ++++--- .../server/logging/logging_system.test.ts | 50 +++++++++++------ 5 files changed, 113 insertions(+), 65 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/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..4ec826639a0fe 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,42 @@ 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, + }, }); }); diff --git a/src/core/server/logging/layouts/json_layout.ts b/src/core/server/logging/layouts/json_layout.ts index ad8c33d7cb023..acd24d763740c 100644 --- a/src/core/server/logging/layouts/json_layout.ts +++ b/src/core/server/logging/layouts/json_layout.ts @@ -46,20 +46,24 @@ 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, + 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', + }, }); });