[NP] Add meta-data and timestamp formatting for Log Record #56982

mshustov · 2020-02-06T14:57:22Z

Summary

Timestamp

pattern: 'layout'

PR introduces additional config fields for timestamp: date format and timezone. Declared similarly to log4j format: {timestamp{FORMAT}{TIMEZONE}}.

I'm a bit hesitant to allow users to specify any custom date format since it introduces an implicit dependency on moment, so I added only 5 predefined formats for now:

ISO8601 : 2020-02-01T10:00:00.000
ISO801_WITH_TZ: 2020-02-01T10:00:00.000+01:00
ABSOLUTE: 10:00:00.000
UNIX: 1580899135
UNIX_MILLIS: 1580899154504

We can allow custom formats later if see that it's required.

Compat with legacy: LP provides timestamp configuration only and always logs in format of HH:mm:ss.SSS.

pattern: 'json'

The current format is identical to elasticsearch ESJsonLayout yyyy-MM-dd'T'HH:mm:ss,SSSZZ, but uses . separator to be closer to moment().toISOString()
https://github.com/elastic/elasticsearch/blob/a4a79670f85d5c135c1ad668c387808fffd733f7/server/src/main/java/org/elasticsearch/common/logging/ESJsonLayout.java#L91

{"type": "server", "timestamp": "2020-02-05T09:52:52,861+01:00",  ..... }

LP @timestamp format for json layout: YYYY-MM-DDTHH:mm:ssZZ

{ "@timestamp":"2020-02-09T12:46:42+01:00", ...}

users cannot specify a different format.

Checklist

Delete any items that are not applicable to this PR.

Unit or functional tests were updated or added to match the most common scenarios

For maintainers

This was checked for breaking API changes and was labeled appropriately

elasticmachine · 2020-02-06T14:57:26Z

Pinging @elastic/kibana-platform (Team:Platform)

elasticmachine · 2020-02-07T09:31:32Z

💚 Build Succeeded

continuous-integration/kibana-ci/pull-request
Commit: 63f8fa7

History

💚 Build #24925 succeeded ff134f6

To update your PR or re-run it, just comment with:
@elasticmachine merge upstream

elasticmachine · 2020-02-07T15:33:59Z

💔 Build Failed

continuous-integration/kibana-ci/pull-request
Commit: fcd7a03

Test Failures

Kibana Pipeline / kibana-intake-agent / Jest Tests.src/core/server/logging/layouts.format timestamp supports specifying a predefined format ABSOLUTE

Link to Jenkins

Standard Out

Failed Tests Reporter:
  - Test has not failed recently on tracked branches

Stack Trace

Error: expect(received).toBe(expected) // Object.is equality

Expected: "[01:00:00,000][context]"
Received: "[00:00:00,000][context]"
    at Object.it (/var/lib/jenkins/workspace/elastic+kibana+pipeline-pull-request/kibana/src/core/server/logging/layouts/pattern_layout.test.ts:226:39)
    at Object.asyncJestTest (/var/lib/jenkins/workspace/elastic+kibana+pipeline-pull-request/kibana/node_modules/jest-jasmine2/build/jasmineAsyncInstall.js:102:37)
    at resolve (/var/lib/jenkins/workspace/elastic+kibana+pipeline-pull-request/kibana/node_modules/jest-jasmine2/build/queueRunner.js:43:12)
    at new Promise (<anonymous>)
    at mapper (/var/lib/jenkins/workspace/elastic+kibana+pipeline-pull-request/kibana/node_modules/jest-jasmine2/build/queueRunner.js:26:19)
    at promise.then (/var/lib/jenkins/workspace/elastic+kibana+pipeline-pull-request/kibana/node_modules/jest-jasmine2/build/queueRunner.js:73:41)
    at process._tickCallback (internal/process/next_tick.js:68:7)

History

💚 Build #25171 succeeded 63f8fa7
💚 Build #24925 succeeded ff134f6

To update your PR or re-run it, just comment with:
@elasticmachine merge upstream

mshustov · 2020-02-10T08:22:24Z

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');


Unifying timezone across all the tests. Should be compatible with the guess result.

dgieselaar

APM changes LGTM! Thanks

kibanamachine · 2020-02-10T10:17:40Z

💚 Build Succeeded

continuous-integration/kibana-ci/pull-request
Commit: decc931

History

💔 Build #25250 failed fcd7a03
💚 Build #25171 succeeded 63f8fa7
💚 Build #24925 succeeded ff134f6

To update your PR or re-run it, just comment with:
@elasticmachine merge upstream

joshdover · 2020-02-10T22:08:38Z

Just to be clear, these differences only affect appenders configured with the new logging config, correct? The legacy logging functionality is untouched?

joshdover · 2020-02-10T22:13:11Z

src/core/server/logging/layouts/conversions/timestamp.ts

+import { Conversion } from './type';
+import { LogRecord } from '../../log_record';
+
+const timestampRegExp = /{timestamp({(?<format>[^}]+)})?({(?<timezone>[^}]+)})?}/gi;


I think maybe my last comment here was missed: #41956 (comment)

Is there a reason we can't support the same syntax as log4j? Eg. %timestamp{options} instead of {timestamp{options}}?

my bad, I forgot to answer: agree, we can switch to log4h-like syntax, but I will do it in a separate PR since it affects all the tests. added to #41956

pgayvallet

Please ignore the personal NIT if you feel like it.

The only (minor) thing that bothers me is regarding colorization. With current implementation, level/context will not colorize their outer []. This make sense technically, as the [] are manually specified around the {level} parts in the format, but I wonder if we should find a way to allow to colorize that.

My point being that with, say
pattern = "[{timestamp}][{level}][{context}]{meta} {message}";, I think the user might want to be able to have the whole [WARN] colorized instead of uncolorized('[')colorized('WARN')uncolorized(']') ?

src/core/server/logging/layouts/conversions/context.ts

pgayvallet · 2020-02-11T07:46:14Z

src/core/server/logging/layouts/conversions/message.ts

+  pattern: /{message}/gi,
+  formatter(record: LogRecord) {
+    // Error stack is much more useful than just the message.
+    return (record.error && record.error.stack) || record.message;


In case of errors, can we have both error and message on the record?

yes, but record.message === record.error.message. I suspect it was done in this way to simplify typings

kibana/src/core/server/logging/logger.ts

Line 162 in 5abca85

message: errorOrMessage.message,

src/core/server/logging/layouts/conversions/meta.ts

src/core/server/logging/layouts/conversions/timestamp.ts

src/core/server/logging/layouts/json_layout.test.ts

src/core/server/logging/layouts/pattern_layout.ts

mshustov · 2020-02-11T13:17:09Z

Just to be clear, these differences only affect appenders configured with the new logging config, correct? The legacy logging functionality is untouched?

The LP logging shouldn't be affected.

The only (minor) thing that bothers me is regarding colorization. With current implementation, level/context will not colorize their outer []. This make sense technically, as the [] are manually specified around the {level} parts in the format, but I wonder if we should find a way to allow to colorize that.

[ and ] are part of a template. We shouldn't make assumptions about the conversion position in the template, nor should we affect any user-defined template by our colorization.
Elasticsearch output, for comparison:

Probably in the future we add log4j colorization conversion support to allow users to specify a custom color for any parts of layout pattern %blue{[%level]}.

joshdover

Tested locally, worked as expected 👍

joshdover · 2020-02-11T22:13:12Z

src/core/server/logging/layouts/pattern_layout.test.ts

+      pid: 5355,
+      meta: {},
+    })
+  ).toBe('[2012-02-01T14:30:22.011Z][DEBUG][context-meta][{}] message-meta');


Is it useful to include meta in the layout if it's an empty object?

an object could be empty or stringified to an empty object. In this case, I'd rather show it explicitly in logs. Otherwise, we will have complaints on
meta-object disappearing from the logs.

let something = undefined; // .... log('message', { something }); // absence from the log since stringified to an empty object

joshdover · 2020-02-11T22:17:20Z

src/core/server/logging/layouts/conversions/level.ts

+export const LevelConversion: Conversion = {
+  pattern: /{level}/gi,
+  formatter(record: LogRecord, highlight: boolean) {
+    let message = record.level.id.toUpperCase().padEnd(5);


TIL about the padEnd and padStart methods.

joshdover · 2020-02-11T22:20:19Z

src/core/server/logging/layouts/conversions/timestamp.ts

+}
+
+export const TimestampConversion: Conversion = {
+  pattern: timestampRegExp,


For some of the more complex regexes, what do you think about testing them directly? It's sort of covered in the tests on PatternLayout, but it could be useful to test the edge cases of the regex explicitly. Maybe would make sense to do after changing to the log4j syntax.

I could move tests here, but I think it's more important to test conversion compatibility. That would be especially important when we introduce nested patterns (like from example with colorization) %blue{[%level]}

…6982) * 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

mshustov · 2020-02-12T08:23:22Z

@pgayvallet I fixed your nits, but didn't push changes. will do in the following PR

…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

mshustov added 2 commits February 6, 2020 15:55

log meta in pattern layout

ef00c6a

address pgayvallet comment

ff134f6

mshustov added Team:Core Core services & architecture: plugins, logging, config, saved objects, http, ES client, i18n, etc Feature:New Platform v8.0.0 release_note:skip Skip the PR/issue when compiling release notes v7.7.0 labels Feb 6, 2020

Merge branch 'master' into log-record-meta

63f8fa7

elastic deleted a comment from kibanamachine Feb 7, 2020

mshustov added 2 commits February 7, 2020 14:56

add conversion patterns for timestamp

36ec899

use comparison instead of inline snapshots

fcd7a03

mshustov changed the title ~~[NP] Log record meta data~~ [NP] Add meta-data and timestamp formatting for Log Record Feb 7, 2020

mshustov added 5 commits February 9, 2020 15:59

logs. use elasticsearch and LP compatible timezone format in json layout

cdfcf2f

use regexp groups and dot separator for ms. as in default iso format

ff01b02

use America/New_York timezone as default as it set in guess anyway

54e07b9

fix APM tests. they need to reset timezone locally and restore it after

295c724

fix logging tests

a40e52c

mshustov commented Feb 10, 2020

View reviewed changes

mshustov marked this pull request as ready for review February 10, 2020 08:52

mshustov requested review from a team as code owners February 10, 2020 08:52

Merge branch 'master' into log-record-meta

decc931

dgieselaar approved these changes Feb 10, 2020

View reviewed changes

jbudz approved these changes Feb 10, 2020

View reviewed changes

joshdover reviewed Feb 10, 2020

View reviewed changes

pgayvallet reviewed Feb 11, 2020

View reviewed changes

mshustov requested review from joshdover and pgayvallet February 11, 2020 13:57

mshustov mentioned this pull request Feb 11, 2020

Logging service uses new config format #41956

Closed

17 tasks

joshdover approved these changes Feb 11, 2020

View reviewed changes

mshustov merged commit 2abc3f5 into elastic:master Feb 12, 2020

mshustov deleted the log-record-meta branch February 12, 2020 08:04

mshustov mentioned this pull request Feb 12, 2020

[7.x] [NP] Add meta-data and timestamp formatting for Log Record (#56982) #57419

Merged

mshustov added the backported label Feb 21, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[NP] Add meta-data and timestamp formatting for Log Record #56982

[NP] Add meta-data and timestamp formatting for Log Record #56982

mshustov commented Feb 6, 2020 •

edited

Loading

elasticmachine commented Feb 6, 2020

elasticmachine commented Feb 7, 2020

elasticmachine commented Feb 7, 2020

Standard Out

Stack Trace

mshustov Feb 10, 2020

dgieselaar left a comment

kibanamachine commented Feb 10, 2020

joshdover commented Feb 10, 2020

joshdover Feb 10, 2020

mshustov Feb 11, 2020 •

edited

Loading

pgayvallet left a comment

pgayvallet Feb 11, 2020

mshustov Feb 11, 2020

mshustov commented Feb 11, 2020

joshdover left a comment

joshdover Feb 11, 2020

mshustov Feb 12, 2020

joshdover Feb 11, 2020

joshdover Feb 11, 2020

mshustov Feb 12, 2020

mshustov commented Feb 12, 2020

[NP] Add meta-data and timestamp formatting for Log Record #56982

[NP] Add meta-data and timestamp formatting for Log Record #56982

Conversation

mshustov commented Feb 6, 2020 • edited Loading

Summary

Meta

pattern: 'layout':

pattern: 'json'

Timestamp

pattern: 'layout'

pattern: 'json'

Checklist

For maintainers

elasticmachine commented Feb 6, 2020

elasticmachine commented Feb 7, 2020

💚 Build Succeeded

History

elasticmachine commented Feb 7, 2020

💔 Build Failed

Standard Out

Stack Trace

History

Choose a reason for hiding this comment

dgieselaar left a comment

Choose a reason for hiding this comment

kibanamachine commented Feb 10, 2020

💚 Build Succeeded

History

joshdover commented Feb 10, 2020

Choose a reason for hiding this comment

mshustov Feb 11, 2020 • edited Loading

Choose a reason for hiding this comment

pgayvallet left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mshustov commented Feb 11, 2020

joshdover left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mshustov commented Feb 12, 2020

mshustov commented Feb 6, 2020 •

edited

Loading

mshustov Feb 11, 2020 •

edited

Loading