Skip to content

Commit

Permalink
[logging] Format new platform json logging to ECS
Browse files Browse the repository at this point in the history
  • Loading branch information
jbudz committed Jul 8, 2020
1 parent 93ac059 commit e5a0992
Show file tree
Hide file tree
Showing 5 changed files with 113 additions and 65 deletions.
54 changes: 35 additions & 19 deletions src/core/server/logging/__snapshots__/logging_system.test.ts.snap

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

44 changes: 28 additions & 16 deletions src/core/server/logging/layouts/json_layout.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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,
},
});
});

Expand All @@ -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,
},
});
});
18 changes: 11 additions & 7 deletions src/core/server/logging/layouts/json_layout.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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,
});
}
}
50 changes: 33 additions & 17 deletions src/core/server/logging/logging_system.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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({})),
Expand Down Expand Up @@ -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', () => {
Expand Down Expand Up @@ -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!"`
Expand Down Expand Up @@ -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(
Expand Down Expand Up @@ -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!"`
Expand Down Expand Up @@ -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!"`
Expand Down Expand Up @@ -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',
},
});
});

0 comments on commit e5a0992

Please sign in to comment.