logger: Make log prefix configurable #10693

euroelessar · 2020-04-08T07:33:11Z

Description: Move [%g:%#] message prefix from compile-time macros to log format.
Please note that this change does not change behavior iff envoy is used with none logger formatting-related command line options.
Risk Level: medium (no-op but does increase cost of logging by default)
Testing: manual run of test & verifying output

$ envoy -l debug |& grep 'starting main dispatch loop'
[2020-04-08 01:45:33.537][46286404][info][main] [source/server/server.cc:554] starting main dispatch loop
$ envoy -l debug --log-format '[%Y-%m-%d %T.%e][%t][%l][%n] [%s:%#] %v' --log-format-prefix-with-location 0 |& grep 'starting main dispatch loop'
[2020-04-08 01:45:22.810][46285789][info][main] [server.cc:554] starting main dispatch loop

Docs Changes: TODO
Release Notes: TODO
Fixes #10688

Signed-off-by: Ruslan Nigmatullin <elessar@dropbox.com>

repokitteh-read-only · 2020-04-08T08:46:18Z

CC @envoyproxy/api-shepherds: Your approval is needed for changes made to api/.

🐱

Caused by: #10693 was synchronize by euroelessar.

see: more, trace.

ggreenway · 2020-04-08T17:19:43Z

I haven't looked at the code, but quick drive-by suggestion based on the description. The worst offender is .h files because they get a big spew of bazel-related prefix on their path. In many cases, there are duplicate file names, so I think the part of the path after source/ is probably still desired. But removing anything before _virtual_includes would be really helpful.

euroelessar · 2020-04-08T18:27:36Z

I haven't looked at the code, but quick drive-by suggestion based on the description. The worst offender is .h files because they get a big spew of bazel-related prefix on their path. In many cases, there are duplicate file names, so I think the part of the path after source/ is probably still desired. But removing anything before _virtual_includes would be really helpful.

This change's only goal is to remove file/line number from the compile-time prefixing to runtime format option. Fancy stripping can be done as a follow up.

htuch · 2020-04-08T22:48:17Z

/lgtm api

euroelessar · 2020-04-09T18:42:16Z

@dio Can you check if it is a right direction in terms of backward compatibility, please?
If it is - I'll update release notes and fix tests.

mattklein123 · 2020-04-10T00:21:31Z

@ggreenway @jmarantz can you also take a quick high level look at this and see if you like the direction?

ggreenway

It looks like spdlog has support for explicit format strings for source file, etc as %@, %#, %s, %g (https://github.com/gabime/spdlog/wiki/3.-Custom-formatting).

I'd like to see those used to get the full flexibility of the formatting. I'd be ok with changing the default format string to [%Y-%m-%d %T.%e][%t][%l][%n] [%g:%#] %v which would be the equivalent of what we have now, plumbing through whatever spdlog needs to make that work properly, and telling people with a custom log format that they'll need to update if they want to keep source file references in their logs.

Does anyone have a sense of how many people actually override the default log format?

ggreenway · 2020-04-10T16:44:53Z

api/envoy/admin/v3/server_info.proto

@@ -115,6 +115,9 @@ message CommandLineOptions {
  // See :option:`--log-format-escaped` for details.
  bool log_format_escaped = 27;

+  // See :option:`--log-format-prefix-with-location` for details.
+  bool log_format_prefix_with_location = 29;


Should this be inverted, so that the default unset value of false keeps the same behavior?

This is a temporary flag, I plan to invert the default in 1 release from now and delete in 2 releases from now (following the breaking change policy).

ggreenway · 2020-04-10T16:46:36Z

source/common/common/logger.cc

+  const spdlog::details::log_msg* msg = &msg_candidate;
+  // This memory buffer is used for compatibility and has to be in the scope of the function to
+  // avoid use-after-free.
+  // TODO(euroelessar): Delete this logic after after 0.16 release.


0.16 release of what? spdlog? Envoy 1.16? Also, what is expected to change at that time which makes it ok to delete this?

Two envoy releases from now, based on the breaking change policy). This logic can be deleted if it is acceptable to not preserve old behavior (and not provide an ability to revert to old behavior).

euroelessar

I'd like to see those used to get the full flexibility of the formatting. I'd be ok with changing the default format string to [%Y-%m-%d %T.%e][%t][%l][%n] [%g:%#] %v which would be the equivalent of what we have now, plumbing through whatever spdlog needs to make that work properly, and telling people with a custom log format that they'll need to update if they want to keep source file references in their logs.

This PR plumbs all the necessary information to spdlog to be able to use %g, %#, and friends. The concern is mostly around two points:

Users can override the format string
Users can pass --log-format-escaped

Combination of this two points assumes that users may have an automation which consumes envoy logs, so changing the format is a breaking change for them. The change is that file location is not part of %v anymore.

All the --log-format-prefix-with-location-related work in this PR is to provide some time for users to migrate to a new format.

euroelessar · 2020-04-10T17:32:30Z

source/common/common/logger.cc

+  const spdlog::details::log_msg* msg = &msg_candidate;
+  // This memory buffer is used for compatibility and has to be in the scope of the function to
+  // avoid use-after-free.
+  // TODO(euroelessar): Delete this logic after after 0.16 release.


Two envoy releases from now, based on the breaking change policy). This logic can be deleted if it is acceptable to not preserve old behavior (and not provide an ability to revert to old behavior).

ggreenway · 2020-04-10T18:18:45Z

Ok, I understand your plan now; that makes sense.

However, if we add a field to the protobufs, I think that it can't be removed immediately when it no longer applies, only deprecated. So the temporary part of this PR will live for a very long time. But that's probably fine.

As an alternate approach, we could consider a runtime override for this instead of config.

Also, instead of writing code to generate the source prefix, what if you scan the format string, and replace %v with [%g:%#] %v, and let spdlog still do all the actual formatting?

ggreenway · 2020-04-10T18:20:03Z

@alyssawilk or @htuch can you comment on the best way to add the needed knob/config to migrate from the current behavior to the new behavior?

euroelessar · 2020-04-10T19:22:02Z

However, if we add a field to the protobufs, I think that it can't be removed immediately when it no longer applies, only deprecated. So the temporary part of this PR will live for a very long time. But that's probably fine.

We potentially can not include it into protobuf definition if it's transient, thoughts?

As an alternate approach, we could consider a runtime override for this instead of config.

Isn't runtime a bit too late from initialization order point of view?

Also, instead of writing code to generate the source prefix, what if you scan the format string, and replace %v with [%g:%#] %v, and let spdlog still do all the actual formatting?

This doesn't work well with --log-format-escaped, the output in logs would be different.

ggreenway · 2020-04-10T21:01:59Z

This doesn't work well with --log-format-escaped, the output in logs would be different.

Can you post an example of how they'd be different. I looked at it and thought I determined they would be the same, but I'm probably missing something.

euroelessar · 2020-04-10T21:33:08Z

This doesn't work well with --log-format-escaped, the output in logs would be different.

Can you post an example of how they'd be different. I looked at it and thought I determined they would be the same, but I'm probably missing something.

Oh, you're right. For some reason I've thought it also wraps the message in quotes.

This leaves us with two approaches:

Change default logging format and document in release notes.
Add new flag with default value as on, replace all %v in the logging format by [%g:%#] %v iff it's on, change the default value to off in one envoy release, delete in two releases.

What do you prefer?

htuch · 2020-04-13T14:29:57Z

I'm in favor of adding a new CLI flag to handle this. This isn't a breaking xDS API consideration, since this is the CLI API, but I think we should treat this similar to runtime deprecations and provide advanced notice that this is going to happen.

Signed-off-by: Ruslan Nigmatullin <elessar@dropbox.com>

euroelessar · 2020-04-14T00:23:59Z

Updated, please have another look and tell if this direction is better.

ggreenway

I like the direction this is going. This will be great.

source/server/options_impl.cc

Signed-off-by: Ruslan Nigmatullin <elessar@dropbox.com>

…igurable Signed-off-by: Ruslan Nigmatullin <elessar@dropbox.com>

Signed-off-by: Ruslan Nigmatullin <elessar@dropbox.com>

ggreenway · 2020-04-16T16:04:50Z

docs/root/operations/cli.rst

+.. option:: --log-format-prefix-with-location <1|0>
+
+   *(optional)* This temporary flag allows replacing all entries of ``"%v"`` in the log format by
+   ``"[%g:%#] "``. This flag is provided for migration purposes only. If this is not set, a


replaces with [%g:%#] %v (you forgot the %v)

ggreenway · 2020-04-16T16:10:11Z

source/server/options_impl.cc

@@ -92,6 +93,10 @@ OptionsImpl::OptionsImpl(std::vector<std::string> args,
  TCLAP::SwitchArg log_format_escaped("", "log-format-escaped",
                                      "Escape c-style escape sequences in the application logs",
                                      cmd, false);
+  TCLAP::ValueArg<bool> log_format_prefix_with_location(
+      "", "log-format-prefix-with-location",
+      "Prefix all entrancies of '%v' in log format with with '[%g:%#] ' ('[path/to/file.cc:99] ').",


I liked "occurrences" better than "entrancies"

Signed-off-by: Ruslan Nigmatullin <elessar@dropbox.com>

ggreenway

Looks good. Thanks!

mattklein123 · 2020-04-16T22:25:42Z

Can you merge master? I'm not sure what stats integration test is failing.

/wait

…igurable Signed-off-by: Ruslan Nigmatullin <elessar@dropbox.com>

mattklein123 · 2020-04-18T22:05:07Z

Hmm. I don't understand it, but this seems to be changing the stats mem test numbers. cc @jmarantz

(Also sorry but please merge maser again to fix coverage and OSX).

/wait

…igurable Signed-off-by: Ruslan Nigmatullin <elessar@dropbox.com>

euroelessar · 2020-04-19T00:39:12Z

@mattklein123 Stats memory failure is gone after rebase.
There is a concerning redis asan failure, but it looks unrelated to this pr.

euroelessar · 2020-04-19T00:56:07Z

Sent a fix for the redis failure as a separate pr: #10840

mattklein123

Thanks!

…igurable Signed-off-by: Ruslan Nigmatullin <elessar@dropbox.com>

euroelessar · 2020-04-21T01:18:03Z

clang-tidy failure is not caused by this PR:

/build/tmp/_bazel_bazel/b570b5ccd0454dc9af9f65ab1833764d/execroot/envoy/source/common/http/utility.h:106:21: error: invalid case style for function 'host_and_port' [readability-identifier-naming,-warnings-as-errors]
  absl::string_view host_and_port() { return host_and_port_; }
                    ^~~~~~~~~~~~~
                    hostAndPort
/build/tmp/_bazel_bazel/b570b5ccd0454dc9af9f65ab1833764d/execroot/envoy/source/common/http/utility.h:107:21: error: invalid case style for function 'path_and_query_params' [readability-identifier-naming,-warnings-as-errors]
  absl::string_view path_and_query_params() { return path_and_query_params_; }
                    ^~~~~~~~~~~~~~~~~~~~~
                    pathAndQueryParams


73135 warnings generated.

/build/tmp/_bazel_bazel/b570b5ccd0454dc9af9f65ab1833764d/execroot/envoy/test/common/http/utility_test.cc:1082:6: error: invalid case style for function 'ValidateUrl' [readability-identifier-naming,-warnings-as-errors]
void ValidateUrl(absl::string_view raw_url, absl::string_view expected_scheme,
     ^~~~~~~~~~~
     validateUrl

…igurable Signed-off-by: Ruslan Nigmatullin <elessar@dropbox.com>

mattklein123

Thanks!

Signed-off-by: Ruslan Nigmatullin <elessar@dropbox.com> Signed-off-by: pengg <pengg@google.com>

Ruslan Nigmatullin added 3 commits April 8, 2020 00:29

logger: Make log prefix configurable

0216fd8

Signed-off-by: Ruslan Nigmatullin <elessar@dropbox.com>

add cli option

b868adb

Signed-off-by: Ruslan Nigmatullin <elessar@dropbox.com>

safe but expensive rollout

8b15eb6

Signed-off-by: Ruslan Nigmatullin <elessar@dropbox.com>

repokitteh-read-only bot added the api label Apr 8, 2020

asraa assigned dio Apr 8, 2020

repokitteh-read-only bot removed the api label Apr 8, 2020

ggreenway requested changes Apr 10, 2020

View reviewed changes

euroelessar commented Apr 10, 2020

View reviewed changes

Ruslan Nigmatullin added 3 commits April 13, 2020 15:57

revert complexity

4231460

Signed-off-by: Ruslan Nigmatullin <elessar@dropbox.com>

alter log-format

d377f95

Signed-off-by: Ruslan Nigmatullin <elessar@dropbox.com>

test

a6adf91

Signed-off-by: Ruslan Nigmatullin <elessar@dropbox.com>

ggreenway requested changes Apr 14, 2020

View reviewed changes

source/server/options_impl.cc Outdated Show resolved Hide resolved

source/server/options_impl.cc Show resolved Hide resolved

source/server/options_impl.cc Outdated Show resolved Hide resolved

Ruslan Nigmatullin added 4 commits April 15, 2020 18:32

cr

eae658a

Signed-off-by: Ruslan Nigmatullin <elessar@dropbox.com>

Merge branch 'master' of github.com:envoyproxy/envoy into logger-conf…

8db544f

…igurable Signed-off-by: Ruslan Nigmatullin <elessar@dropbox.com>

docs

db22fff

Signed-off-by: Ruslan Nigmatullin <elessar@dropbox.com>

style

0c1145e

Signed-off-by: Ruslan Nigmatullin <elessar@dropbox.com>

ggreenway requested changes Apr 16, 2020

View reviewed changes

ggreenway added the waiting label Apr 16, 2020

cr

4a687ea

Signed-off-by: Ruslan Nigmatullin <elessar@dropbox.com>

repokitteh-read-only bot removed the waiting label Apr 16, 2020

ggreenway previously approved these changes Apr 16, 2020

View reviewed changes

repokitteh-read-only bot added the waiting label Apr 16, 2020

Merge branch 'master' of github.com:envoyproxy/envoy into logger-conf…

ad8d42b

…igurable Signed-off-by: Ruslan Nigmatullin <elessar@dropbox.com>

repokitteh-read-only bot removed the waiting label Apr 16, 2020

ggreenway self-assigned this Apr 17, 2020

repokitteh-read-only bot added the waiting label Apr 18, 2020

Merge branch 'master' of github.com:envoyproxy/envoy into logger-conf…

59f4b75

…igurable Signed-off-by: Ruslan Nigmatullin <elessar@dropbox.com>

repokitteh-read-only bot removed the waiting label Apr 18, 2020

mattklein123 previously approved these changes Apr 20, 2020

View reviewed changes

Merge branch 'master' of github.com:envoyproxy/envoy into logger-conf…

cf502d7

…igurable Signed-off-by: Ruslan Nigmatullin <elessar@dropbox.com>

euroelessar dismissed stale reviews from mattklein123 and ggreenway via cf502d7 April 20, 2020 18:08

Merge branch 'master' of github.com:envoyproxy/envoy into logger-conf…

0155c11

…igurable Signed-off-by: Ruslan Nigmatullin <elessar@dropbox.com>

mattklein123 approved these changes Apr 21, 2020

View reviewed changes

mattklein123 merged commit 0fd0b94 into envoyproxy:master Apr 21, 2020

howardjohn mentioned this pull request Apr 21, 2020

Trim Envoy log file prefix istio/istio#23125

Closed

rgs1 mentioned this pull request Apr 22, 2020

Crash regression from #10362 #10901

Closed

penguingao pushed a commit to penguingao/envoy that referenced this pull request Apr 22, 2020

logger: Make log prefix configurable (envoyproxy#10693)

386107b

Signed-off-by: Ruslan Nigmatullin <elessar@dropbox.com> Signed-off-by: pengg <pengg@google.com>

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

logger: Make log prefix configurable #10693

logger: Make log prefix configurable #10693

euroelessar commented Apr 8, 2020 •

edited

Loading

repokitteh-read-only bot commented Apr 8, 2020

ggreenway commented Apr 8, 2020

euroelessar commented Apr 8, 2020

htuch commented Apr 8, 2020

euroelessar commented Apr 9, 2020

mattklein123 commented Apr 10, 2020

ggreenway left a comment

ggreenway Apr 10, 2020

euroelessar Apr 10, 2020

ggreenway Apr 10, 2020

euroelessar Apr 10, 2020

euroelessar left a comment

euroelessar Apr 10, 2020

ggreenway commented Apr 10, 2020

ggreenway commented Apr 10, 2020

euroelessar commented Apr 10, 2020

ggreenway commented Apr 10, 2020

euroelessar commented Apr 10, 2020 •

edited

Loading

htuch commented Apr 13, 2020

euroelessar commented Apr 14, 2020

ggreenway left a comment

ggreenway Apr 16, 2020

ggreenway Apr 16, 2020

ggreenway left a comment

mattklein123 commented Apr 16, 2020

mattklein123 commented Apr 18, 2020

euroelessar commented Apr 19, 2020

euroelessar commented Apr 19, 2020

mattklein123 left a comment

euroelessar commented Apr 21, 2020

mattklein123 left a comment

logger: Make log prefix configurable #10693

logger: Make log prefix configurable #10693

Conversation

euroelessar commented Apr 8, 2020 • edited Loading

repokitteh-read-only bot commented Apr 8, 2020

ggreenway commented Apr 8, 2020

euroelessar commented Apr 8, 2020

htuch commented Apr 8, 2020

euroelessar commented Apr 9, 2020

mattklein123 commented Apr 10, 2020

ggreenway left a comment

Choose a reason for hiding this comment

ggreenway Apr 10, 2020

Choose a reason for hiding this comment

euroelessar Apr 10, 2020

Choose a reason for hiding this comment

ggreenway Apr 10, 2020

Choose a reason for hiding this comment

euroelessar Apr 10, 2020

Choose a reason for hiding this comment

euroelessar left a comment

Choose a reason for hiding this comment

euroelessar Apr 10, 2020

Choose a reason for hiding this comment

ggreenway commented Apr 10, 2020

ggreenway commented Apr 10, 2020

euroelessar commented Apr 10, 2020

ggreenway commented Apr 10, 2020

euroelessar commented Apr 10, 2020 • edited Loading

htuch commented Apr 13, 2020

euroelessar commented Apr 14, 2020

ggreenway left a comment

Choose a reason for hiding this comment

ggreenway Apr 16, 2020

Choose a reason for hiding this comment

ggreenway Apr 16, 2020

Choose a reason for hiding this comment

ggreenway left a comment

Choose a reason for hiding this comment

mattklein123 commented Apr 16, 2020

mattklein123 commented Apr 18, 2020

euroelessar commented Apr 19, 2020

euroelessar commented Apr 19, 2020

mattklein123 left a comment

Choose a reason for hiding this comment

euroelessar commented Apr 21, 2020

mattklein123 left a comment

Choose a reason for hiding this comment

euroelessar commented Apr 8, 2020 •

edited

Loading

euroelessar commented Apr 10, 2020 •

edited

Loading