From 41569d9443d54bc67d652f2d2fcb1bc0ea360a5d Mon Sep 17 00:00:00 2001 From: Mikhail Shustov Date: Wed, 12 Feb 2020 10:37:05 +0100 Subject: [PATCH] [NP] Add meta-data and timestamp formatting for Log Record (#56982) (#57419) * log meta in pattern layout * address pgayvallet comment * add conversion patterns for timestamp * use comparison instead of inline snapshots * logs. use elasticsearch and LP compatible timezone format in json layout * use regexp groups and dot separator for ms. as in default iso format * use America/New_York timezone as default as it set in guess anyway * fix APM tests. they need to reset timezone locally and restore it after * fix logging tests --- .../logging_service.test.ts.snap | 22 +- .../__snapshots__/json_layout.test.ts.snap | 16 +- .../__snapshots__/pattern_layout.test.ts.snap | 24 +- .../logging/layouts/conversions/context.ts | 34 +++ .../logging/layouts/conversions/level.ts | 44 ++++ .../logging/layouts/conversions/message.ts | 29 +++ .../logging/layouts/conversions/meta.ts | 27 +++ .../server/logging/layouts/conversions/pid.ts | 28 +++ .../logging/layouts/conversions/timestamp.ts | 90 ++++++++ .../logging/layouts/conversions/type.ts | 25 +++ .../logging/layouts/json_layout.test.ts | 49 +++- .../server/logging/layouts/json_layout.ts | 3 +- .../logging/layouts/pattern_layout.test.ts | 211 +++++++++++++++++- .../server/logging/layouts/pattern_layout.ts | 92 +++----- .../server/logging/logging_service.test.ts | 2 +- src/dev/jest/setup/mocks.js | 1 + .../CustomPlot/getTimezoneOffsetInMs.test.ts | 26 ++- 17 files changed, 606 insertions(+), 117 deletions(-) create mode 100644 src/core/server/logging/layouts/conversions/context.ts create mode 100644 src/core/server/logging/layouts/conversions/level.ts create mode 100644 src/core/server/logging/layouts/conversions/message.ts create mode 100644 src/core/server/logging/layouts/conversions/meta.ts create mode 100644 src/core/server/logging/layouts/conversions/pid.ts create mode 100644 src/core/server/logging/layouts/conversions/timestamp.ts create mode 100644 src/core/server/logging/layouts/conversions/type.ts diff --git a/src/core/server/logging/__snapshots__/logging_service.test.ts.snap b/src/core/server/logging/__snapshots__/logging_service.test.ts.snap index 54c170f523299d..2add00457b2ed5 100644 --- a/src/core/server/logging/__snapshots__/logging_service.test.ts.snap +++ b/src/core/server/logging/__snapshots__/logging_service.test.ts.snap @@ -1,20 +1,20 @@ // Jest Snapshot v1, https://goo.gl/fbAQLP -exports[`appends records via multiple appenders.: console logs 1`] = `"[2012-02-01T00:00:00.000Z][INFO ][some-context] You know, just for your info."`; +exports[`appends records via multiple appenders.: console logs 1`] = `"[2012-01-31T23:33:22.011Z][INFO ][some-context] You know, just for your info."`; exports[`appends records via multiple appenders.: file logs 1`] = ` -"[2012-02-01T00:00:00.000Z][WARN ][tests] Config is not ready! +"[2012-01-31T23:33:22.011Z][WARN ][tests] Config is not ready! " `; exports[`appends records via multiple appenders.: file logs 2`] = ` -"[2012-02-01T00:00:00.000Z][ERROR][tests.child] Too bad that config is not ready :/ +"[2012-01-31T23:33:22.011Z][ERROR][tests.child] Too bad that config is not ready :/ " `; exports[`asLoggerFactory() only allows to create new loggers. 1`] = ` Object { - "@timestamp": "2012-02-01T00:00:00.000Z", + "@timestamp": "2012-01-31T18:33:22.011-05:00", "context": "test.context", "level": "TRACE", "message": "buffered trace message", @@ -24,7 +24,7 @@ Object { exports[`asLoggerFactory() only allows to create new loggers. 2`] = ` Object { - "@timestamp": "2012-02-01T00:00:00.000Z", + "@timestamp": "2012-01-31T13:33:22.011-05:00", "context": "test.context", "level": "INFO", "message": "buffered info message", @@ -37,7 +37,7 @@ Object { exports[`asLoggerFactory() only allows to create new loggers. 3`] = ` Object { - "@timestamp": "2012-02-01T00:00:00.000Z", + "@timestamp": "2012-01-31T08:33:22.011-05:00", "context": "test.context", "level": "FATAL", "message": "buffered fatal message", @@ -47,7 +47,7 @@ Object { exports[`flushes memory buffer logger and switches to real logger once config is provided: buffered messages 1`] = ` Object { - "@timestamp": "2012-02-01T00:00:00.000Z", + "@timestamp": "2012-02-01T09:33:22.011-05:00", "context": "test.context", "level": "INFO", "message": "buffered info message", @@ -60,7 +60,7 @@ Object { exports[`flushes memory buffer logger and switches to real logger once config is provided: new messages 1`] = ` Object { - "@timestamp": "2012-02-01T00:00:00.000Z", + "@timestamp": "2012-01-31T23:33:22.011-05:00", "context": "test.context", "level": "INFO", "message": "some new info message", @@ -71,7 +71,7 @@ Object { exports[`uses \`root\` logger if context is not specified. 1`] = ` Array [ Array [ - "[2012-02-01T00:00:00.000Z][INFO ][root] This message goes to a root context.", + "[2012-01-31T23:33:22.011Z][INFO ][root] This message goes to a root context.", ], ] `; @@ -86,7 +86,7 @@ Object { "message": "trace message", "meta": undefined, "pid": Any, - "timestamp": 2012-02-01T00:00:00.000Z, + "timestamp": 2012-02-01T14:33:22.011Z, } `; @@ -102,6 +102,6 @@ Object { "some": "value", }, "pid": Any, - "timestamp": 2012-02-01T00:00:00.000Z, + "timestamp": 2012-02-01T14:33:22.011Z, } `; 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 21cf4302c49dc3..da57023c942866 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,17 @@ // Jest Snapshot v1, https://goo.gl/fbAQLP -exports[`\`format()\` correctly formats record. 1`] = `"{\\"@timestamp\\":\\"2012-02-01T00:00:00.000Z\\",\\"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 error record with meta-data 1`] = `"{\\"@timestamp\\":\\"2012-02-01T09:30:22.011-05:00\\",\\"context\\":\\"context-with-meta\\",\\"level\\":\\"DEBUG\\",\\"message\\":\\"message-with-meta\\",\\"meta\\":{\\"from\\":\\"v7\\",\\"to\\":\\"v8\\"},\\"pid\\":5355}"`; -exports[`\`format()\` correctly formats record. 2`] = `"{\\"@timestamp\\":\\"2012-02-01T00:00:00.000Z\\",\\"context\\":\\"context-2\\",\\"level\\":\\"ERROR\\",\\"message\\":\\"message-2\\",\\"pid\\":5355}"`; +exports[`\`format()\` correctly formats record with meta-data 1`] = `"{\\"@timestamp\\":\\"2012-02-01T09:30:22.011-05:00\\",\\"context\\":\\"context-with-meta\\",\\"level\\":\\"DEBUG\\",\\"message\\":\\"message-with-meta\\",\\"meta\\":{\\"from\\":\\"v7\\",\\"to\\":\\"v8\\"},\\"pid\\":5355}"`; -exports[`\`format()\` correctly formats record. 3`] = `"{\\"@timestamp\\":\\"2012-02-01T00:00:00.000Z\\",\\"context\\":\\"context-3\\",\\"level\\":\\"WARN\\",\\"message\\":\\"message-3\\",\\"pid\\":5355}"`; +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. 4`] = `"{\\"@timestamp\\":\\"2012-02-01T00:00:00.000Z\\",\\"context\\":\\"context-4\\",\\"level\\":\\"DEBUG\\",\\"message\\":\\"message-4\\",\\"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. 5`] = `"{\\"@timestamp\\":\\"2012-02-01T00:00:00.000Z\\",\\"context\\":\\"context-5\\",\\"level\\":\\"INFO\\",\\"message\\":\\"message-5\\",\\"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. 6`] = `"{\\"@timestamp\\":\\"2012-02-01T00:00:00.000Z\\",\\"context\\":\\"context-6\\",\\"level\\":\\"TRACE\\",\\"message\\":\\"message-6\\",\\"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. 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. 6`] = `"{\\"@timestamp\\":\\"2012-02-01T09:30:22.011-05:00\\",\\"context\\":\\"context-6\\",\\"level\\":\\"TRACE\\",\\"message\\":\\"message-6\\",\\"pid\\":5355}"`; diff --git a/src/core/server/logging/layouts/__snapshots__/pattern_layout.test.ts.snap b/src/core/server/logging/layouts/__snapshots__/pattern_layout.test.ts.snap index 9ff4f7445d0433..1bf13204873a65 100644 --- a/src/core/server/logging/layouts/__snapshots__/pattern_layout.test.ts.snap +++ b/src/core/server/logging/layouts/__snapshots__/pattern_layout.test.ts.snap @@ -12,29 +12,29 @@ exports[`\`format()\` correctly formats record with custom pattern. 5`] = `"mock exports[`\`format()\` correctly formats record with custom pattern. 6`] = `"mock-message-6-context-6-message-6"`; -exports[`\`format()\` correctly formats record with full pattern. 1`] = `"[2012-02-01T00:00:00.000Z][FATAL][context-1] Some error stack"`; +exports[`\`format()\` correctly formats record with full pattern. 1`] = `"[2012-02-01T14:30:22.011Z][FATAL][context-1] Some error stack"`; -exports[`\`format()\` correctly formats record with full pattern. 2`] = `"[2012-02-01T00:00:00.000Z][ERROR][context-2] message-2"`; +exports[`\`format()\` correctly formats record with full pattern. 2`] = `"[2012-02-01T14:30:22.011Z][ERROR][context-2] message-2"`; -exports[`\`format()\` correctly formats record with full pattern. 3`] = `"[2012-02-01T00:00:00.000Z][WARN ][context-3] message-3"`; +exports[`\`format()\` correctly formats record with full pattern. 3`] = `"[2012-02-01T14:30:22.011Z][WARN ][context-3] message-3"`; -exports[`\`format()\` correctly formats record with full pattern. 4`] = `"[2012-02-01T00:00:00.000Z][DEBUG][context-4] message-4"`; +exports[`\`format()\` correctly formats record with full pattern. 4`] = `"[2012-02-01T14:30:22.011Z][DEBUG][context-4] message-4"`; -exports[`\`format()\` correctly formats record with full pattern. 5`] = `"[2012-02-01T00:00:00.000Z][INFO ][context-5] message-5"`; +exports[`\`format()\` correctly formats record with full pattern. 5`] = `"[2012-02-01T14:30:22.011Z][INFO ][context-5] message-5"`; -exports[`\`format()\` correctly formats record with full pattern. 6`] = `"[2012-02-01T00:00:00.000Z][TRACE][context-6] message-6"`; +exports[`\`format()\` correctly formats record with full pattern. 6`] = `"[2012-02-01T14:30:22.011Z][TRACE][context-6] message-6"`; -exports[`\`format()\` correctly formats record with highlighting. 1`] = `"[2012-02-01T00:00:00.000Z][FATAL][context-1] Some error stack"`; +exports[`\`format()\` correctly formats record with highlighting. 1`] = `"[2012-02-01T14:30:22.011Z][FATAL][context-1] Some error stack"`; -exports[`\`format()\` correctly formats record with highlighting. 2`] = `"[2012-02-01T00:00:00.000Z][ERROR][context-2] message-2"`; +exports[`\`format()\` correctly formats record with highlighting. 2`] = `"[2012-02-01T14:30:22.011Z][ERROR][context-2] message-2"`; -exports[`\`format()\` correctly formats record with highlighting. 3`] = `"[2012-02-01T00:00:00.000Z][WARN ][context-3] message-3"`; +exports[`\`format()\` correctly formats record with highlighting. 3`] = `"[2012-02-01T14:30:22.011Z][WARN ][context-3] message-3"`; -exports[`\`format()\` correctly formats record with highlighting. 4`] = `"[2012-02-01T00:00:00.000Z][DEBUG][context-4] message-4"`; +exports[`\`format()\` correctly formats record with highlighting. 4`] = `"[2012-02-01T14:30:22.011Z][DEBUG][context-4] message-4"`; -exports[`\`format()\` correctly formats record with highlighting. 5`] = `"[2012-02-01T00:00:00.000Z][INFO ][context-5] message-5"`; +exports[`\`format()\` correctly formats record with highlighting. 5`] = `"[2012-02-01T14:30:22.011Z][INFO ][context-5] message-5"`; -exports[`\`format()\` correctly formats record with highlighting. 6`] = `"[2012-02-01T00:00:00.000Z][TRACE][context-6] message-6"`; +exports[`\`format()\` correctly formats record with highlighting. 6`] = `"[2012-02-01T14:30:22.011Z][TRACE][context-6] message-6"`; exports[`allows specifying the PID in custom pattern 1`] = `"5355-context-1-Some error stack"`; diff --git a/src/core/server/logging/layouts/conversions/context.ts b/src/core/server/logging/layouts/conversions/context.ts new file mode 100644 index 00000000000000..d1fa9ca84f5553 --- /dev/null +++ b/src/core/server/logging/layouts/conversions/context.ts @@ -0,0 +1,34 @@ +/* + * Licensed to Elasticsearch B.V. under one or more contributor + * license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright + * ownership. Elasticsearch B.V. licenses this file to you under + * the Apache License, Version 2.0 (the "License"); you may + * not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +import chalk from 'chalk'; + +import { Conversion } from './type'; +import { LogRecord } from '../../log_record'; + +export const ContextConversion: Conversion = { + pattern: /{context}/gi, + formatter(record: LogRecord, highlight: boolean) { + let message = record.context; + if (highlight) { + message = chalk.magenta(message); + } + return message; + }, +}; diff --git a/src/core/server/logging/layouts/conversions/level.ts b/src/core/server/logging/layouts/conversions/level.ts new file mode 100644 index 00000000000000..02ed86dd2c24fb --- /dev/null +++ b/src/core/server/logging/layouts/conversions/level.ts @@ -0,0 +1,44 @@ +/* + * Licensed to Elasticsearch B.V. under one or more contributor + * license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright + * ownership. Elasticsearch B.V. licenses this file to you under + * the Apache License, Version 2.0 (the "License"); you may + * not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +import chalk from 'chalk'; + +import { Conversion } from './type'; +import { LogLevel } from '../../log_level'; +import { LogRecord } from '../../log_record'; + +const LEVEL_COLORS = new Map([ + [LogLevel.Fatal, chalk.red], + [LogLevel.Error, chalk.red], + [LogLevel.Warn, chalk.yellow], + [LogLevel.Debug, chalk.green], + [LogLevel.Trace, chalk.blue], +]); + +export const LevelConversion: Conversion = { + pattern: /{level}/gi, + formatter(record: LogRecord, highlight: boolean) { + let message = record.level.id.toUpperCase().padEnd(5); + if (highlight && LEVEL_COLORS.has(record.level)) { + const color = LEVEL_COLORS.get(record.level)!; + message = color(message); + } + return message; + }, +}; diff --git a/src/core/server/logging/layouts/conversions/message.ts b/src/core/server/logging/layouts/conversions/message.ts new file mode 100644 index 00000000000000..b95a89b12b7808 --- /dev/null +++ b/src/core/server/logging/layouts/conversions/message.ts @@ -0,0 +1,29 @@ +/* + * Licensed to Elasticsearch B.V. under one or more contributor + * license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright + * ownership. Elasticsearch B.V. licenses this file to you under + * the Apache License, Version 2.0 (the "License"); you may + * not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +import { Conversion } from './type'; +import { LogRecord } from '../../log_record'; + +export const MessageConversion: Conversion = { + pattern: /{message}/gi, + formatter(record: LogRecord) { + // Error stack is much more useful than just the message. + return (record.error && record.error.stack) || record.message; + }, +}; diff --git a/src/core/server/logging/layouts/conversions/meta.ts b/src/core/server/logging/layouts/conversions/meta.ts new file mode 100644 index 00000000000000..f6d4557e0db53c --- /dev/null +++ b/src/core/server/logging/layouts/conversions/meta.ts @@ -0,0 +1,27 @@ +/* + * Licensed to Elasticsearch B.V. under one or more contributor + * license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright + * ownership. Elasticsearch B.V. licenses this file to you under + * the Apache License, Version 2.0 (the "License"); you may + * not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ +import { Conversion } from './type'; +import { LogRecord } from '../../log_record'; + +export const MetaConversion: Conversion = { + pattern: /{meta}/gi, + formatter(record: LogRecord) { + return record.meta ? `[${JSON.stringify(record.meta)}]` : ''; + }, +}; diff --git a/src/core/server/logging/layouts/conversions/pid.ts b/src/core/server/logging/layouts/conversions/pid.ts new file mode 100644 index 00000000000000..0fcdd93fcda0c7 --- /dev/null +++ b/src/core/server/logging/layouts/conversions/pid.ts @@ -0,0 +1,28 @@ +/* + * Licensed to Elasticsearch B.V. under one or more contributor + * license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright + * ownership. Elasticsearch B.V. licenses this file to you under + * the Apache License, Version 2.0 (the "License"); you may + * not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +import { Conversion } from './type'; +import { LogRecord } from '../../log_record'; + +export const PidConversion: Conversion = { + pattern: /{pid}/gi, + formatter(record: LogRecord) { + return String(record.pid); + }, +}; diff --git a/src/core/server/logging/layouts/conversions/timestamp.ts b/src/core/server/logging/layouts/conversions/timestamp.ts new file mode 100644 index 00000000000000..6db6fc6eeb6bfe --- /dev/null +++ b/src/core/server/logging/layouts/conversions/timestamp.ts @@ -0,0 +1,90 @@ +/* + * Licensed to Elasticsearch B.V. under one or more contributor + * license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright + * ownership. Elasticsearch B.V. licenses this file to you under + * the Apache License, Version 2.0 (the "License"); you may + * not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ +import moment from 'moment-timezone'; +import { last } from 'lodash'; + +import { Conversion } from './type'; +import { LogRecord } from '../../log_record'; + +const timestampRegExp = /{timestamp({(?[^}]+)})?({(?[^}]+)})?}/gi; + +const formats = { + ISO8601: 'ISO8601', + ISO8601_TZ: 'ISO8601_TZ', + ABSOLUTE: 'ABSOLUTE', + UNIX: 'UNIX', + UNIX_MILLIS: 'UNIX_MILLIS', +}; + +function formatDate(date: Date, dateFormat: string = formats.ISO8601, timezone?: string): string { + const momentDate = moment(date); + if (timezone) { + momentDate.tz(timezone); + } + switch (dateFormat) { + case formats.ISO8601: + return momentDate.toISOString(); + case formats.ISO8601_TZ: + return momentDate.format('YYYY-MM-DDTHH:mm:ss.SSSZ'); + case formats.ABSOLUTE: + return momentDate.format('HH:mm:ss.SSS'); + case formats.UNIX: + return momentDate.format('X'); + case formats.UNIX_MILLIS: + return momentDate.format('x'); + default: + throw new Error(`Unknown format: ${dateFormat}`); + } +} + +function validateDateFormat(input: string) { + if (Reflect.has(formats, input)) return; + throw new Error( + `Date format expected one of ${Reflect.ownKeys(formats).join(', ')}, but given: ${input}` + ); +} + +function validateTimezone(timezone: string) { + if (moment.tz.zone(timezone)) return; + throw new Error(`Unknown timezone: ${timezone}`); +} + +function validate(rawString: string) { + for (const matched of rawString.matchAll(timestampRegExp)) { + const { format, timezone } = matched.groups!; + + if (format) { + validateDateFormat(format); + } + if (timezone) { + validateTimezone(timezone); + } + } +} + +export const TimestampConversion: Conversion = { + pattern: timestampRegExp, + formatter(record: LogRecord, highlight: boolean, ...matched: any[]) { + const groups: Record = last(matched); + const { format, timezone } = groups; + + return formatDate(record.timestamp, format, timezone); + }, + validate, +}; diff --git a/src/core/server/logging/layouts/conversions/type.ts b/src/core/server/logging/layouts/conversions/type.ts new file mode 100644 index 00000000000000..34a64751388149 --- /dev/null +++ b/src/core/server/logging/layouts/conversions/type.ts @@ -0,0 +1,25 @@ +/* + * Licensed to Elasticsearch B.V. under one or more contributor + * license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright + * ownership. Elasticsearch B.V. licenses this file to you under + * the Apache License, Version 2.0 (the "License"); you may + * not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ +import { LogRecord } from 'kibana/server'; + +export interface Conversion { + pattern: RegExp; + formatter: (record: LogRecord, highlight: boolean) => string; + validate?: (input: string) => void; +} diff --git a/src/core/server/logging/layouts/json_layout.test.ts b/src/core/server/logging/layouts/json_layout.test.ts index 2e4c5af80dd2e3..ec8c44ec62a227 100644 --- a/src/core/server/logging/layouts/json_layout.test.ts +++ b/src/core/server/logging/layouts/json_layout.test.ts @@ -21,6 +21,7 @@ import { LogLevel } from '../log_level'; import { LogRecord } from '../log_record'; import { JsonLayout } from './json_layout'; +const timestamp = new Date(Date.UTC(2012, 1, 1, 14, 30, 22, 11)); const records: LogRecord[] = [ { context: 'context-1', @@ -31,42 +32,42 @@ const records: LogRecord[] = [ }, level: LogLevel.Fatal, message: 'message-1', - timestamp: new Date(Date.UTC(2012, 1, 1)), + timestamp, pid: 5355, }, { context: 'context-2', level: LogLevel.Error, message: 'message-2', - timestamp: new Date(Date.UTC(2012, 1, 1)), + timestamp, pid: 5355, }, { context: 'context-3', level: LogLevel.Warn, message: 'message-3', - timestamp: new Date(Date.UTC(2012, 1, 1)), + timestamp, pid: 5355, }, { context: 'context-4', level: LogLevel.Debug, message: 'message-4', - timestamp: new Date(Date.UTC(2012, 1, 1)), + timestamp, pid: 5355, }, { context: 'context-5', level: LogLevel.Info, message: 'message-5', - timestamp: new Date(Date.UTC(2012, 1, 1)), + timestamp, pid: 5355, }, { context: 'context-6', level: LogLevel.Trace, message: 'message-6', - timestamp: new Date(Date.UTC(2012, 1, 1)), + timestamp, pid: 5355, }, ]; @@ -84,3 +85,39 @@ test('`format()` correctly formats record.', () => { expect(layout.format(record)).toMatchSnapshot(); } }); + +test('`format()` correctly formats record with meta-data', () => { + const layout = new JsonLayout(); + + expect( + layout.format({ + context: 'context-with-meta', + level: LogLevel.Debug, + message: 'message-with-meta', + timestamp, + pid: 5355, + meta: { + from: 'v7', + to: 'v8', + }, + }) + ).toMatchSnapshot(); +}); + +test('`format()` correctly formats error record with meta-data', () => { + const layout = new JsonLayout(); + + expect( + layout.format({ + context: 'context-with-meta', + level: LogLevel.Debug, + message: 'message-with-meta', + timestamp, + pid: 5355, + meta: { + from: 'v7', + to: 'v8', + }, + }) + ).toMatchSnapshot(); +}); diff --git a/src/core/server/logging/layouts/json_layout.ts b/src/core/server/logging/layouts/json_layout.ts index 8e90b2f7eb7828..ad8c33d7cb0231 100644 --- a/src/core/server/logging/layouts/json_layout.ts +++ b/src/core/server/logging/layouts/json_layout.ts @@ -17,6 +17,7 @@ * under the License. */ +import moment from 'moment-timezone'; import { schema, TypeOf } from '@kbn/config-schema'; import { LogRecord } from '../log_record'; @@ -52,7 +53,7 @@ export class JsonLayout implements Layout { public format(record: LogRecord): string { return JSON.stringify({ - '@timestamp': record.timestamp.toISOString(), + '@timestamp': moment(record.timestamp).format('YYYY-MM-DDTHH:mm:ss.SSSZ'), context: record.context, error: JsonLayout.errorToSerializableObject(record.error), level: record.level.id.toUpperCase(), diff --git a/src/core/server/logging/layouts/pattern_layout.test.ts b/src/core/server/logging/layouts/pattern_layout.test.ts index 23656c5d20510d..2d948ea59c6d16 100644 --- a/src/core/server/logging/layouts/pattern_layout.test.ts +++ b/src/core/server/logging/layouts/pattern_layout.test.ts @@ -20,8 +20,9 @@ import { stripAnsiSnapshotSerializer } from '../../../test_helpers/strip_ansi_snapshot_serializer'; import { LogLevel } from '../log_level'; import { LogRecord } from '../log_record'; -import { PatternLayout } from './pattern_layout'; +import { PatternLayout, patternSchema } from './pattern_layout'; +const timestamp = new Date(Date.UTC(2012, 1, 1, 14, 30, 22, 11)); const records: LogRecord[] = [ { context: 'context-1', @@ -32,42 +33,42 @@ const records: LogRecord[] = [ }, level: LogLevel.Fatal, message: 'message-1', - timestamp: new Date(Date.UTC(2012, 1, 1)), + timestamp, pid: 5355, }, { context: 'context-2', level: LogLevel.Error, message: 'message-2', - timestamp: new Date(Date.UTC(2012, 1, 1)), + timestamp, pid: 5355, }, { context: 'context-3', level: LogLevel.Warn, message: 'message-3', - timestamp: new Date(Date.UTC(2012, 1, 1)), + timestamp, pid: 5355, }, { context: 'context-4', level: LogLevel.Debug, message: 'message-4', - timestamp: new Date(Date.UTC(2012, 1, 1)), + timestamp, pid: 5355, }, { context: 'context-5', level: LogLevel.Info, message: 'message-5', - timestamp: new Date(Date.UTC(2012, 1, 1)), + timestamp, pid: 5355, }, { context: 'context-6', level: LogLevel.Trace, message: 'message-6', - timestamp: new Date(Date.UTC(2012, 1, 1)), + timestamp, pid: 5355, }, ]; @@ -118,6 +119,45 @@ test('`format()` correctly formats record with custom pattern.', () => { } }); +test('`format()` correctly formats record with meta data.', () => { + const layout = new PatternLayout(); + + expect( + layout.format({ + context: 'context-meta', + level: LogLevel.Debug, + message: 'message-meta', + timestamp, + pid: 5355, + meta: { + from: 'v7', + to: 'v8', + }, + }) + ).toBe('[2012-02-01T14:30:22.011Z][DEBUG][context-meta][{"from":"v7","to":"v8"}] message-meta'); + + expect( + layout.format({ + context: 'context-meta', + level: LogLevel.Debug, + message: 'message-meta', + timestamp, + pid: 5355, + meta: {}, + }) + ).toBe('[2012-02-01T14:30:22.011Z][DEBUG][context-meta][{}] message-meta'); + + expect( + layout.format({ + context: 'context-meta', + level: LogLevel.Debug, + message: 'message-meta', + timestamp, + pid: 5355, + }) + ).toBe('[2012-02-01T14:30:22.011Z][DEBUG][context-meta] message-meta'); +}); + test('`format()` correctly formats record with highlighting.', () => { const layout = new PatternLayout(undefined, true); @@ -133,3 +173,160 @@ test('allows specifying the PID in custom pattern', () => { expect(layout.format(record)).toMatchSnapshot(); } }); + +test('`format()` allows specifying pattern with meta.', () => { + const layout = new PatternLayout('{context}-{meta}-{message}'); + const record = { + context: 'context', + level: LogLevel.Debug, + message: 'message', + timestamp, + pid: 5355, + meta: { + from: 'v7', + to: 'v8', + }, + }; + expect(layout.format(record)).toBe('context-[{"from":"v7","to":"v8"}]-message'); +}); + +describe('format', () => { + describe('timestamp', () => { + const record = { + context: 'context', + level: LogLevel.Debug, + message: 'message', + timestamp, + pid: 5355, + }; + it('uses ISO8601 as default', () => { + const layout = new PatternLayout(); + + expect(layout.format(record)).toBe('[2012-02-01T14:30:22.011Z][DEBUG][context] message'); + }); + + describe('supports specifying a predefined format', () => { + it('ISO8601', () => { + const layout = new PatternLayout('[{timestamp{ISO8601}}][{context}]'); + + expect(layout.format(record)).toBe('[2012-02-01T14:30:22.011Z][context]'); + }); + + it('ISO8601_TZ', () => { + const layout = new PatternLayout('[{timestamp{ISO8601_TZ}}][{context}]'); + + expect(layout.format(record)).toBe('[2012-02-01T09:30:22.011-05:00][context]'); + }); + + it('ABSOLUTE', () => { + const layout = new PatternLayout('[{timestamp{ABSOLUTE}}][{context}]'); + + expect(layout.format(record)).toBe('[09:30:22.011][context]'); + }); + + it('UNIX', () => { + const layout = new PatternLayout('[{timestamp{UNIX}}][{context}]'); + + expect(layout.format(record)).toBe('[1328106622][context]'); + }); + + it('UNIX_MILLIS', () => { + const layout = new PatternLayout('[{timestamp{UNIX_MILLIS}}][{context}]'); + + expect(layout.format(record)).toBe('[1328106622011][context]'); + }); + }); + + describe('supports specifying a predefined format and timezone', () => { + it('ISO8601', () => { + const layout = new PatternLayout('[{timestamp{ISO8601}{America/Los_Angeles}}][{context}]'); + + expect(layout.format(record)).toBe('[2012-02-01T14:30:22.011Z][context]'); + }); + + it('ISO8601_TZ', () => { + const layout = new PatternLayout( + '[{timestamp{ISO8601_TZ}{America/Los_Angeles}}][{context}]' + ); + + expect(layout.format(record)).toBe('[2012-02-01T06:30:22.011-08:00][context]'); + }); + + it('ABSOLUTE', () => { + const layout = new PatternLayout('[{timestamp{ABSOLUTE}{America/Los_Angeles}}][{context}]'); + + expect(layout.format(record)).toBe('[06:30:22.011][context]'); + }); + + it('UNIX', () => { + const layout = new PatternLayout('[{timestamp{UNIX}{America/Los_Angeles}}][{context}]'); + + expect(layout.format(record)).toBe('[1328106622][context]'); + }); + + it('UNIX_MILLIS', () => { + const layout = new PatternLayout( + '[{timestamp{UNIX_MILLIS}{America/Los_Angeles}}][{context}]' + ); + + expect(layout.format(record)).toBe('[1328106622011][context]'); + }); + }); + it('formats several conversions patterns correctly', () => { + const layout = new PatternLayout( + '[{timestamp{ABSOLUTE}{America/Los_Angeles}}][{context}][{timestamp{UNIX}}]' + ); + + expect(layout.format(record)).toBe('[06:30:22.011][context][1328106622]'); + }); + }); +}); + +describe('schema', () => { + describe('pattern', () => { + describe('{timestamp}', () => { + it('does not fail when {timestamp} not present', () => { + expect(patternSchema.validate('')).toBe(''); + expect(patternSchema.validate('{pid}')).toBe('{pid}'); + }); + + it('does not fail on {timestamp} without params', () => { + expect(patternSchema.validate('{timestamp}')).toBe('{timestamp}'); + expect(patternSchema.validate('{timestamp}}')).toBe('{timestamp}}'); + expect(patternSchema.validate('{{timestamp}}')).toBe('{{timestamp}}'); + }); + + it('does not fail on {timestamp} with predefined date format', () => { + expect(patternSchema.validate('{timestamp{ISO8601}}')).toBe('{timestamp{ISO8601}}'); + }); + + it('does not fail on {timestamp} with predefined date format and valid timezone', () => { + expect(patternSchema.validate('{timestamp{ISO8601_TZ}{Europe/Berlin}}')).toBe( + '{timestamp{ISO8601_TZ}{Europe/Berlin}}' + ); + }); + + it('fails on {timestamp} with unknown date format', () => { + expect(() => + patternSchema.validate('{timestamp{HH:MM:SS}}') + ).toThrowErrorMatchingInlineSnapshot( + `"Date format expected one of ISO8601, ISO8601_TZ, ABSOLUTE, UNIX, UNIX_MILLIS, but given: HH:MM:SS"` + ); + }); + + it('fails on {timestamp} with predefined date format and invalid timezone', () => { + expect(() => + patternSchema.validate('{timestamp{ISO8601_TZ}{Europe/Kibana}}') + ).toThrowErrorMatchingInlineSnapshot(`"Unknown timezone: Europe/Kibana"`); + }); + + it('validates several {timestamp} in pattern', () => { + expect(() => + patternSchema.validate('{timestamp{ISO8601_TZ}{Europe/Berlin}}{message}{timestamp{HH}}') + ).toThrowErrorMatchingInlineSnapshot( + `"Date format expected one of ISO8601, ISO8601_TZ, ABSOLUTE, UNIX, UNIX_MILLIS, but given: HH"` + ); + }); + }); + }); +}); diff --git a/src/core/server/logging/layouts/pattern_layout.ts b/src/core/server/logging/layouts/pattern_layout.ts index 64424c02268ff5..0a2a25a1350692 100644 --- a/src/core/server/logging/layouts/pattern_layout.ts +++ b/src/core/server/logging/layouts/pattern_layout.ts @@ -18,55 +18,44 @@ */ import { schema, TypeOf } from '@kbn/config-schema'; -import chalk from 'chalk'; -import { LogLevel } from '../log_level'; import { LogRecord } from '../log_record'; import { Layout } from './layouts'; -/** - * A set of static constants describing supported parameters in the log message pattern. - */ -const Parameters = Object.freeze({ - Context: '{context}', - Level: '{level}', - Message: '{message}', - Timestamp: '{timestamp}', - Pid: '{pid}', -}); - -/** - * Regular expression used to parse log message pattern and fill in placeholders - * with the actual data. - */ -const PATTERN_REGEX = new RegExp( - `${Parameters.Timestamp}|${Parameters.Level}|${Parameters.Context}|${Parameters.Message}|${Parameters.Pid}`, - 'gi' -); - -/** - * Mapping between `LogLevel` and color that is used to highlight `level` part of - * the log message. - */ -const LEVEL_COLORS = new Map([ - [LogLevel.Fatal, chalk.red], - [LogLevel.Error, chalk.red], - [LogLevel.Warn, chalk.yellow], - [LogLevel.Debug, chalk.green], - [LogLevel.Trace, chalk.blue], -]); +import { Conversion } from './conversions/type'; +import { ContextConversion } from './conversions/context'; +import { LevelConversion } from './conversions/level'; +import { MetaConversion } from './conversions/meta'; +import { MessageConversion } from './conversions/message'; +import { PidConversion } from './conversions/pid'; +import { TimestampConversion } from './conversions/timestamp'; /** * Default pattern used by PatternLayout if it's not overridden in the configuration. */ -const DEFAULT_PATTERN = `[${Parameters.Timestamp}][${Parameters.Level}][${Parameters.Context}] ${Parameters.Message}`; +const DEFAULT_PATTERN = `[{timestamp}][{level}][{context}]{meta} {message}`; + +export const patternSchema = schema.string({ + validate: string => { + TimestampConversion.validate!(string); + }, +}); const patternLayoutSchema = schema.object({ highlight: schema.maybe(schema.boolean()), kind: schema.literal('pattern'), - pattern: schema.maybe(schema.string()), + pattern: schema.maybe(patternSchema), }); +const conversions: Conversion[] = [ + ContextConversion, + MessageConversion, + LevelConversion, + MetaConversion, + PidConversion, + TimestampConversion, +]; + /** @internal */ export type PatternLayoutConfigType = TypeOf; @@ -77,19 +66,6 @@ export type PatternLayoutConfigType = TypeOf; */ export class PatternLayout implements Layout { public static configSchema = patternLayoutSchema; - - private static highlightRecord(record: LogRecord, formattedRecord: Map) { - if (LEVEL_COLORS.has(record.level)) { - const color = LEVEL_COLORS.get(record.level)!; - formattedRecord.set(Parameters.Level, color(formattedRecord.get(Parameters.Level)!)); - } - - formattedRecord.set( - Parameters.Context, - chalk.magenta(formattedRecord.get(Parameters.Context)!) - ); - } - constructor(private readonly pattern = DEFAULT_PATTERN, private readonly highlight = false) {} /** @@ -97,20 +73,14 @@ export class PatternLayout implements Layout { * @param record Instance of `LogRecord` to format into string. */ public format(record: LogRecord): string { - // Error stack is much more useful than just the message. - const message = (record.error && record.error.stack) || record.message; - const formattedRecord = new Map([ - [Parameters.Timestamp, record.timestamp.toISOString()], - [Parameters.Level, record.level.id.toUpperCase().padEnd(5)], - [Parameters.Context, record.context], - [Parameters.Message, message], - [Parameters.Pid, String(record.pid)], - ]); - - if (this.highlight) { - PatternLayout.highlightRecord(record, formattedRecord); + let recordString = this.pattern; + for (const conversion of conversions) { + recordString = recordString.replace( + conversion.pattern, + conversion.formatter.bind(null, record, this.highlight) + ); } - return this.pattern.replace(PATTERN_REGEX, match => formattedRecord.get(match)!); + return recordString; } } diff --git a/src/core/server/logging/logging_service.test.ts b/src/core/server/logging/logging_service.test.ts index 51697fd15bebea..1e6c253c56c7b1 100644 --- a/src/core/server/logging/logging_service.test.ts +++ b/src/core/server/logging/logging_service.test.ts @@ -29,7 +29,7 @@ jest.mock('../../../legacy/server/logging/rotate', () => ({ setupLoggingRotate: jest.fn().mockImplementation(() => Promise.resolve({})), })); -const timestamp = new Date(Date.UTC(2012, 1, 1)); +const timestamp = new Date(Date.UTC(2012, 1, 1, 14, 33, 22, 11)); let mockConsoleLog: jest.SpyInstance; import { createWriteStream } from 'fs'; diff --git a/src/dev/jest/setup/mocks.js b/src/dev/jest/setup/mocks.js index 19c88d3cc35e42..095c82bd50fbd8 100644 --- a/src/dev/jest/setup/mocks.js +++ b/src/dev/jest/setup/mocks.js @@ -45,6 +45,7 @@ jest.mock('moment-timezone', () => { // timezone in all tests. const moment = jest.requireActual('moment-timezone'); moment.tz.guess = () => 'America/New_York'; + moment.tz.setDefault('America/New_York'); return moment; }); diff --git a/x-pack/legacy/plugins/apm/public/components/shared/charts/CustomPlot/getTimezoneOffsetInMs.test.ts b/x-pack/legacy/plugins/apm/public/components/shared/charts/CustomPlot/getTimezoneOffsetInMs.test.ts index d99cb5cb9f1f13..7081286ecf3f2d 100644 --- a/x-pack/legacy/plugins/apm/public/components/shared/charts/CustomPlot/getTimezoneOffsetInMs.test.ts +++ b/x-pack/legacy/plugins/apm/public/components/shared/charts/CustomPlot/getTimezoneOffsetInMs.test.ts @@ -9,8 +9,21 @@ import moment from 'moment-timezone'; // FAILING: https://github.com/elastic/kibana/issues/50005 describe('getTimezoneOffsetInMs', () => { + let originalTimezone: moment.MomentZone | null; + + beforeAll(() => { + // @ts-ignore moment types do not define defaultZone but it's there + originalTimezone = moment.defaultZone; + }); + + afterAll(() => { + moment.tz.setDefault(originalTimezone ? originalTimezone.name : ''); + }); + describe('when no default timezone is set', () => { it('guesses the timezone', () => { + moment.tz.setDefault(); + const guess = jest.fn(() => 'Etc/UTC'); jest.spyOn(moment.tz, 'guess').mockImplementationOnce(guess); @@ -21,19 +34,8 @@ describe('getTimezoneOffsetInMs', () => { }); describe('when a default timezone is set', () => { - let originalTimezone: moment.MomentZone | null; - - beforeAll(() => { - // @ts-ignore moment types do not define defaultZone but it's there - originalTimezone = moment.defaultZone; - moment.tz.setDefault('America/Denver'); - }); - - afterAll(() => { - moment.tz.setDefault(originalTimezone ? originalTimezone.name : ''); - }); - it('returns the time in milliseconds', () => { + moment.tz.setDefault('America/Denver'); const now = Date.now(); // get the expected offset from moment to prevent any issues with DST const expectedOffset =