From 7879757a92b6b62a16d278e31a65ff7f592824d2 Mon Sep 17 00:00:00 2001 From: "Christiane (Tina) Heiligers" Date: Wed, 10 Feb 2021 00:54:08 -0700 Subject: [PATCH] [7.x] [core.logging] Uses host timezone as default (#90368) (#90897) Co-authored-by: Kibana Machine <42973632+kibanamachine@users.noreply.github.com> # Conflicts: # docs/migration/migrate_8_0.asciidoc # src/core/server/config/deprecation/core_deprecations.ts --- docs/setup/settings.asciidoc | 3 +- .../deprecation/core_deprecations.test.ts | 20 ++++++++++++ .../config/deprecation/core_deprecations.ts | 13 +++++++- .../legacy/integration_tests/logging.test.ts | 20 ++++++------ src/core/server/logging/README.md | 31 ++++++++++--------- .../__snapshots__/logging_system.test.ts.snap | 14 ++++----- .../__snapshots__/pattern_layout.test.ts.snap | 24 +++++++------- .../logging/layouts/conversions/date.ts | 11 ++++--- .../logging/layouts/pattern_layout.test.ts | 12 ++++--- 9 files changed, 93 insertions(+), 55 deletions(-) diff --git a/docs/setup/settings.asciidoc b/docs/setup/settings.asciidoc index ecdb41c897b12..9b9c26fd0e1db 100644 --- a/docs/setup/settings.asciidoc +++ b/docs/setup/settings.asciidoc @@ -309,7 +309,8 @@ suppress all logging output. *Default: `false`* | Set to the canonical time zone ID (for example, `America/Los_Angeles`) to log events using that time zone. For possible values, refer to -https://en.wikipedia.org/wiki/List_of_tz_database_time_zones[database time zones]. *Default: `UTC`* +https://en.wikipedia.org/wiki/List_of_tz_database_time_zones[database time zones]. +When not set, log events use the host timezone | [[logging-verbose]] `logging.verbose:` {ess-icon} | Set to `true` to log all events, including system usage information and all diff --git a/src/core/server/config/deprecation/core_deprecations.test.ts b/src/core/server/config/deprecation/core_deprecations.test.ts index a64d4d562e082..5bb2ebf702aa7 100644 --- a/src/core/server/config/deprecation/core_deprecations.test.ts +++ b/src/core/server/config/deprecation/core_deprecations.test.ts @@ -318,4 +318,24 @@ describe('core deprecations', () => { expect(messages).toEqual([]); }); }); + + describe('logging.timezone', () => { + it('warns when ops events are used', () => { + const { messages } = applyCoreDeprecations({ + logging: { timezone: 'GMT' }, + }); + expect(messages).toMatchInlineSnapshot(` + Array [ + "\\"logging.timezone\\" has been deprecated and will be removed in 8.0. To set the timezone moving forward, please add a timezone date modifier to the log pattern in your logging configuration. For more details, see https://github.com/elastic/kibana/blob/master/src/core/server/logging/README.md", + ] + `); + }); + + it('does not warn when other events are configured', () => { + const { messages } = applyCoreDeprecations({ + logging: { events: { log: '*' } }, + }); + expect(messages).toEqual([]); + }); + }); }); diff --git a/src/core/server/config/deprecation/core_deprecations.ts b/src/core/server/config/deprecation/core_deprecations.ts index cd8c3183100f9..966dbaf282c46 100644 --- a/src/core/server/config/deprecation/core_deprecations.ts +++ b/src/core/server/config/deprecation/core_deprecations.ts @@ -136,7 +136,17 @@ const requestLoggingEventDeprecation: ConfigDeprecation = (settings, fromPath, l } return settings; }; - +const timezoneLoggingDeprecation: ConfigDeprecation = (settings, fromPath, log) => { + if (has(settings, 'logging.timezone')) { + log( + '"logging.timezone" has been deprecated and will be removed ' + + 'in 8.0. To set the timezone moving forward, please add a timezone date modifier to the log pattern ' + + 'in your logging configuration. For more details, see ' + + 'https://github.com/elastic/kibana/blob/master/src/core/server/logging/README.md' + ); + } + return settings; +}; export const coreDeprecationProvider: ConfigDeprecationProvider = ({ unusedFromRoot, renameFromRoot, @@ -185,4 +195,5 @@ export const coreDeprecationProvider: ConfigDeprecationProvider = ({ serverHostZeroDeprecation, opsLoggingEventDeprecation, requestLoggingEventDeprecation, + timezoneLoggingDeprecation, ]; diff --git a/src/core/server/legacy/integration_tests/logging.test.ts b/src/core/server/legacy/integration_tests/logging.test.ts index 6588f4270fe18..321eb81708f1e 100644 --- a/src/core/server/legacy/integration_tests/logging.test.ts +++ b/src/core/server/legacy/integration_tests/logging.test.ts @@ -87,7 +87,7 @@ describe('logging service', () => { const loggedString = getPlatformLogsFromMock(mockConsoleLog); expect(loggedString).toMatchInlineSnapshot(` Array [ - "[xxxx-xx-xxTxx:xx:xx.xxxZ][INFO ][test-file] handled by NP", + "[xxxx-xx-xxTxx:xx:xx.xxx-xx:xx][INFO ][test-file] handled by NP", ] `); }); @@ -131,9 +131,9 @@ describe('logging service', () => { expect(getPlatformLogsFromMock(mockConsoleLog)).toMatchInlineSnapshot(` Array [ - "[xxxx-xx-xxTxx:xx:xx.xxxZ][INFO ][test-file] info", - "[xxxx-xx-xxTxx:xx:xx.xxxZ][WARN ][test-file] warn", - "[xxxx-xx-xxTxx:xx:xx.xxxZ][ERROR][test-file] error", + "[xxxx-xx-xxTxx:xx:xx.xxx-xx:xx][INFO ][test-file] info", + "[xxxx-xx-xxTxx:xx:xx.xxx-xx:xx][WARN ][test-file] warn", + "[xxxx-xx-xxTxx:xx:xx.xxx-xx:xx][ERROR][test-file] error", ] `); @@ -162,9 +162,9 @@ describe('logging service', () => { expect(getPlatformLogsFromMock(mockConsoleLog)).toMatchInlineSnapshot(` Array [ - "[xxxx-xx-xxTxx:xx:xx.xxxZ][INFO ][test-file] info", - "[xxxx-xx-xxTxx:xx:xx.xxxZ][WARN ][test-file] warn", - "[xxxx-xx-xxTxx:xx:xx.xxxZ][ERROR][test-file] error", + "[xxxx-xx-xxTxx:xx:xx.xxx-xx:xx][INFO ][test-file] info", + "[xxxx-xx-xxTxx:xx:xx.xxx-xx:xx][WARN ][test-file] warn", + "[xxxx-xx-xxTxx:xx:xx.xxx-xx:xx][ERROR][test-file] error", ] `); @@ -199,9 +199,9 @@ describe('logging service', () => { expect(getPlatformLogsFromMock(mockConsoleLog)).toMatchInlineSnapshot(` Array [ - "[xxxx-xx-xxTxx:xx:xx.xxxZ][INFO ][test-file] info", - "[xxxx-xx-xxTxx:xx:xx.xxxZ][WARN ][test-file] warn", - "[xxxx-xx-xxTxx:xx:xx.xxxZ][ERROR][test-file] error", + "[xxxx-xx-xxTxx:xx:xx.xxx-xx:xx][INFO ][test-file] info", + "[xxxx-xx-xxTxx:xx:xx.xxx-xx:xx][WARN ][test-file] warn", + "[xxxx-xx-xxTxx:xx:xx.xxx-xx:xx][ERROR][test-file] error", ] `); diff --git a/src/core/server/logging/README.md b/src/core/server/logging/README.md index b0759defb8803..9e3da1f3e0d71 100644 --- a/src/core/server/logging/README.md +++ b/src/core/server/logging/README.md @@ -110,7 +110,8 @@ Example of `%meta` output: ##### date Outputs the date of the logging event. The date conversion specifier may be followed by a set of braces containing a name of predefined date format and canonical timezone name. -Timezone name is expected to be one from [TZ database name](https://en.wikipedia.org/wiki/List_of_tz_database_time_zones) +Timezone name is expected to be one from [TZ database name](https://en.wikipedia.org/wiki/List_of_tz_database_time_zones). +Timezone defaults to the host timezone when not explicitly specified. Example of `%date` output: | Conversion pattern | Example | @@ -410,22 +411,22 @@ loggerWithNestedContext.debug('Message with `debug` log level.'); And assuming logger for `server` context with `console` appender and `trace` level was used, console output will look like this: ```bash -[2017-07-25T18:54:41.639Z][TRACE][server] Message with `trace` log level. -[2017-07-25T18:54:41.639Z][DEBUG][server] Message with `debug` log level. -[2017-07-25T18:54:41.639Z][INFO ][server] Message with `info` log level. -[2017-07-25T18:54:41.639Z][WARN ][server] Message with `warn` log level. -[2017-07-25T18:54:41.639Z][ERROR][server] Message with `error` log level. -[2017-07-25T18:54:41.639Z][FATAL][server] Message with `fatal` log level. - -[2017-07-25T18:54:41.639Z][TRACE][server.http] Message with `trace` log level. -[2017-07-25T18:54:41.639Z][DEBUG][server.http] Message with `debug` log level. +[2017-07-25T11:54:41.639-07:00][TRACE][server] Message with `trace` log level. +[2017-07-25T11:54:41.639-07:00][DEBUG][server] Message with `debug` log level. +[2017-07-25T11:54:41.639-07:00][INFO ][server] Message with `info` log level. +[2017-07-25T11:54:41.639-07:00][WARN ][server] Message with `warn` log level. +[2017-07-25T11:54:41.639-07:00][ERROR][server] Message with `error` log level. +[2017-07-25T11:54:41.639-07:00][FATAL][server] Message with `fatal` log level. + +[2017-07-25T11:54:41.639-07:00][TRACE][server.http] Message with `trace` log level. +[2017-07-25T11:54:41.639-07:00][DEBUG][server.http] Message with `debug` log level. ``` The log will be less verbose with `warn` level for the `server` context: ```bash -[2017-07-25T18:54:41.639Z][WARN ][server] Message with `warn` log level. -[2017-07-25T18:54:41.639Z][ERROR][server] Message with `error` log level. -[2017-07-25T18:54:41.639Z][FATAL][server] Message with `fatal` log level. +[2017-07-25T11:54:41.639-07:00][WARN ][server] Message with `warn` log level. +[2017-07-25T11:54:41.639-07:00][ERROR][server] Message with `error` log level. +[2017-07-25T11:54:41.639-07:00][FATAL][server] Message with `fatal` log level. ``` ### Logging config migration @@ -488,7 +489,7 @@ logging.root.level: all #### logging.timezone Set to the canonical timezone id to log events using that timezone. New logging config allows -to [specify timezone](#date) for `layout: pattern`. +to [specify timezone](#date) for `layout: pattern`. Defaults to host timezone when not specified. ```yaml logging: appenders: @@ -530,7 +531,7 @@ TBD | Parameter | Platform log record in **pattern** format | Legacy Platform log record **text** format | | --------------- | ------------------------------------------ | ------------------------------------------ | -| @timestamp | ISO8601 `2012-01-31T23:33:22.011Z` | Absolute `23:33:22.011` | +| @timestamp | ISO8601_TZ `2012-01-31T23:33:22.011-05:00` | Absolute `23:33:22.011` | | context | `parent.child` | `['parent', 'child']` | | level | `DEBUG` | `['debug']` | | meta | stringified JSON object `{"to": "v8"}` | N/A | 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 cbe0e352a0f3a..8013aec4a06fd 100644 --- a/src/core/server/logging/__snapshots__/logging_system.test.ts.snap +++ b/src/core/server/logging/__snapshots__/logging_system.test.ts.snap @@ -1,20 +1,20 @@ // Jest Snapshot v1, https://goo.gl/fbAQLP -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.: console logs 1`] = `"[2012-01-31T18:33:22.011-05:00][INFO ][some-context] You know, just for your info."`; exports[`appends records via multiple appenders.: file logs 1`] = ` -"[2012-01-31T23:33:22.011Z][WARN ][tests] Config is not ready! +"[2012-01-31T13:33:22.011-05:00][WARN ][tests] Config is not ready! " `; exports[`appends records via multiple appenders.: file logs 2`] = ` -"[2012-01-31T23:33:22.011Z][ERROR][tests.child] Too bad that config is not ready :/ +"[2012-01-31T08:33:22.011-05:00][ERROR][tests.child] Too bad that config is not ready :/ " `; exports[`asLoggerFactory() only allows to create new loggers. 1`] = ` Object { - "@timestamp": "2012-01-31T18:33:22.011-05:00", + "@timestamp": "2012-01-30T22:33:22.011-05:00", "log": Object { "level": "TRACE", "logger": "test.context", @@ -28,7 +28,7 @@ Object { exports[`asLoggerFactory() only allows to create new loggers. 2`] = ` Object { - "@timestamp": "2012-01-31T13:33:22.011-05:00", + "@timestamp": "2012-01-30T17:33:22.011-05:00", "log": Object { "level": "INFO", "logger": "test.context", @@ -43,7 +43,7 @@ Object { exports[`asLoggerFactory() only allows to create new loggers. 3`] = ` Object { - "@timestamp": "2012-01-31T08:33:22.011-05:00", + "@timestamp": "2012-01-30T12:33:22.011-05:00", "log": Object { "level": "FATAL", "logger": "test.context", @@ -87,7 +87,7 @@ Object { exports[`uses \`root\` logger if context is not specified. 1`] = ` Array [ Array [ - "[2012-01-31T23:33:22.011Z][INFO ][root] This message goes to a root context.", + "[2012-01-31T03:33:22.011-05:00][INFO ][root] This message goes to a root context.", ], ] `; 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 8988f3019d509..54e46ca7f520e 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-01T14:30:22.011Z][FATAL][context-1] Some error stack"`; +exports[`\`format()\` correctly formats record with full pattern. 1`] = `"[2012-02-01T09:30:22.011-05:00][FATAL][context-1] Some error stack"`; -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. 2`] = `"[2012-02-01T09:30:22.011-05:00][ERROR][context-2] message-2"`; -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. 3`] = `"[2012-02-01T09:30:22.011-05:00][WARN ][context-3] message-3"`; -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. 4`] = `"[2012-02-01T09:30:22.011-05:00][DEBUG][context-4] message-4"`; -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. 5`] = `"[2012-02-01T09:30:22.011-05:00][INFO ][context-5] message-5"`; -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 full pattern. 6`] = `"[2012-02-01T09:30:22.011-05:00][TRACE][context-6] message-6"`; -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. 1`] = `[2012-02-01T09:30:22.011-05:00][FATAL][context-1] Some error stack`; -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. 2`] = `[2012-02-01T09:30:22.011-05:00][ERROR][context-2] message-2`; -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. 3`] = `[2012-02-01T09:30:22.011-05:00][WARN ][context-3] message-3`; -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. 4`] = `[2012-02-01T09:30:22.011-05:00][DEBUG][context-4] message-4`; -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. 5`] = `[2012-02-01T09:30:22.011-05:00][INFO ][context-5] message-5`; -exports[`\`format()\` correctly formats record with highlighting. 6`] = `[2012-02-01T14:30:22.011Z][TRACE][context-6] message-6`; +exports[`\`format()\` correctly formats record with highlighting. 6`] = `[2012-02-01T09:30:22.011-05:00][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/date.ts b/src/core/server/logging/layouts/conversions/date.ts index c1f871282c5de..66aad5b42354a 100644 --- a/src/core/server/logging/layouts/conversions/date.ts +++ b/src/core/server/logging/layouts/conversions/date.ts @@ -22,11 +22,14 @@ const formats = { UNIX_MILLIS: 'UNIX_MILLIS', }; -function formatDate(date: Date, dateFormat: string = formats.ISO8601, timezone?: string): string { +function formatDate( + date: Date, + dateFormat: string = formats.ISO8601_TZ, + timezone?: string +): string { const momentDate = moment(date); - if (timezone) { - momentDate.tz(timezone); - } + momentDate.tz(timezone ?? moment.tz.guess()); + switch (dateFormat) { case formats.ISO8601: return momentDate.toISOString(); diff --git a/src/core/server/logging/layouts/pattern_layout.test.ts b/src/core/server/logging/layouts/pattern_layout.test.ts index d291516524be0..7dd3c7c51f833 100644 --- a/src/core/server/logging/layouts/pattern_layout.test.ts +++ b/src/core/server/logging/layouts/pattern_layout.test.ts @@ -122,7 +122,9 @@ test('`format()` correctly formats record with meta data.', () => { to: 'v8', }, }) - ).toBe('[2012-02-01T14:30:22.011Z][DEBUG][context-meta]{"from":"v7","to":"v8"} message-meta'); + ).toBe( + '[2012-02-01T09:30:22.011-05:00][DEBUG][context-meta]{"from":"v7","to":"v8"} message-meta' + ); expect( layout.format({ @@ -133,7 +135,7 @@ test('`format()` correctly formats record with meta data.', () => { pid: 5355, meta: {}, }) - ).toBe('[2012-02-01T14:30:22.011Z][DEBUG][context-meta]{} message-meta'); + ).toBe('[2012-02-01T09:30:22.011-05:00][DEBUG][context-meta]{} message-meta'); expect( layout.format({ @@ -143,7 +145,7 @@ test('`format()` correctly formats record with meta data.', () => { timestamp, pid: 5355, }) - ).toBe('[2012-02-01T14:30:22.011Z][DEBUG][context-meta] message-meta'); + ).toBe('[2012-02-01T09:30:22.011-05:00][DEBUG][context-meta] message-meta'); }); test('`format()` correctly formats record with highlighting.', () => { @@ -187,10 +189,10 @@ describe('format', () => { timestamp, pid: 5355, }; - it('uses ISO8601 as default', () => { + it('uses ISO8601_TZ as default', () => { const layout = new PatternLayout(); - expect(layout.format(record)).toBe('[2012-02-01T14:30:22.011Z][DEBUG][context] message'); + expect(layout.format(record)).toBe('[2012-02-01T09:30:22.011-05:00][DEBUG][context] message'); }); describe('supports specifying a predefined format', () => {