Improve Envoy QUICHE logging by DavidSchinazi · Pull Request #15549 · envoyproxy/envoy

DavidSchinazi · 2021-03-18T00:57:30Z

Commit Message:

This PR makes a few small modifications to the Envoy platform
implementation of the QUICHE logging code.

Performance: conditions are no longer computed in QUICHE_LOG_IF
unless the logging level is enabled.

Debugging: logs now contain the file, line and function of the caller.
Also, it is now possible to control the QUICHE verbosity threshold
via an environment variable. Also, QUICHE_CHECH_GT and related macros
will print out the value of the compared variables.

Signed-off-by: David Schinazi dschinazi@google.com

Additional Description: None
Risk Level: Low
Testing: Manual
Docs Changes: None
Release Notes: None
Platform Specific Features: None
[Optional Runtime guard:]
[Optional Fixes #Issue]
[Optional Deprecated:]
[Optional API Considerations:]

This PR makes a few small modifications to the Envoy platform implementation of the QUICHE logging code. Performance: conditions are no longer computed in QUICHE_LOG_IF unless the logging level is enabled. Debugging: logs now contain the file, line and function of the caller. Also, it is now possible to control the QUICHE verbosity threshold via an environment variable. Also, QUICHE_CHECH_GT and related macros will print out the value of the compared variables. Signed-off-by: David Schinazi <dschinazi@google.com>

alyssawilk · 2021-03-18T13:18:17Z

Welcome to the Envoy project, and the joys of Envoy CI! While you passed the first hurdle of DCO, non-dictionary-words are as discouraged as enthusiastic spaces, so you'll want to check spelling and push an update.

As an aside, there's some way to make Envoy presubmits email you when they succeed or fail which I strongly encourage setting up and adding to our onboarding docs.

Signed-off-by: David Schinazi <dschinazi@google.com>

danzh2010

Thanks for working on logging improvement!

danzh2010 · 2021-03-18T18:48:14Z

source/extensions/quic_listeners/quiche/platform/quic_logging_impl.h

-  explicit QuicLogEmitter(QuicLogLevel level);
+  // |file_name| and |function_name| MUST be valid for the lifetime of the QuicLogEmitter. This is
+  // guaranteed when passing __FILE__ and __func__.
+  explicit QuicLogEmitter(QuicLogLevel level, const char* file_name, int line,


No need of explicit in this case.

Can we hard code __FILE__ and __func__ in ~QuicLogEmitter() instead? Then no need to worry about life time.

explicit is not required when there are multiple arguments, but it's still good practice because it prevents initializer-list construction. The Google style guide explicitly says it's OK either way in this case, and the Envoy one doesn't mention it. Is that OK with you?

__FILE__ and __func__ are expanded by the preprocessor from the caller of the macro that lead to them. We can't hard-code __FILE__ and __func__ in the .cc file because that'll give you that file name and function, as opposed to this macro usage which gives us the actual caller.

I see. Thanks for explanation!

danzh2010 · 2021-03-18T19:30:17Z

source/extensions/quic_listeners/quiche/platform/quic_logging_impl.h


 using QuicLogLevel = spdlog::level::level_enum;

+static const QuicLogLevel TRACE = spdlog::level::trace;


Do we have "QUIC_LOG(TRACE/DEBUG)"?

We don't, but our code calls GetLogger().set_level() with these values (see QuicPlatformTest for example) so we should cover all possible values.

danzh2010 · 2021-03-18T19:34:51Z

source/extensions/quic_listeners/quiche/platform/quic_logging_impl.h

+QUICHE_IS_LOG_LEVEL_ENABLED_IMPL(WARNING)
+QUICHE_IS_LOG_LEVEL_ENABLED_IMPL(ERROR)
+QUICHE_IS_LOG_LEVEL_ENABLED_IMPL(DFATAL)
+inline bool constexpr IsLogLevelEnabledFATAL() { return true; }


It's not obvious why IsLogLevelEnabledFATAL() can't be defined using the macro above?

Because that wouldn't be constexpr, there's a comment above to that effect - do you have a suggestion for how I could improve the comment?

danzh2010 · 2021-03-18T19:42:04Z

A side request, mind add document about ENVOY_QUICHE_VERBOSITY in source/docs/quiche_integration.md? Maybe add a debug section?

Signed-off-by: David Schinazi <dschinazi@google.com>

alyssawilk

Hurrah for logging improvements! Code LGTM, mind adding a unit test?
I'd hope TestEnvironment::setEnvVar would work for std::getenv but I'll admit I'm not 100% sure

DavidSchinazi · 2021-03-18T20:16:34Z

Unfortunately the std::getenv happens when the verbosity levels are first checked, and that happens before test instantiation. I could add a helper for tests but at that point it wouldn't exercise the code path we'd want to exercise. Thoughts?

alyssawilk

As discussed offline (and proven in your local client) doing a separate test file isn't going to work for this and given this is for debug logging and mainly for us, I'm fine with it as is. Throwing it over to @mattklein123 for non-google pass and in case he has other clever test ideas ;-)

mattklein123

Throwing it over to @mattklein123 for non-google pass and in case he has other clever test ideas ;-)

I can think of two ideas:

Use bazel to explicitly run a test setting the env var. I don't know off hand whether this would force recompilation or if you can just run the test binary with a new action_env var that wouldn't effect compilation.
If we think we will never use this in the release build, the other option would be to do what nghttp2 does and just compile all of this out on release, and then on debug you could do something like read the env var for every log line. https://nghttp2.org/documentation/nghttp2_set_debug_vprintf_callback.html

No strong preference but throwing that out there in case either of them appeal to you.

mattklein123 · 2021-03-19T00:07:59Z

source/docs/quiche_integration.md

 * In Google QUIC, encodeHeaders()/encodeTrailers() check the buffer size increase on header stream before and after writing headers/trailers. In QuicSession::OnCanWrite(), may drain header stream send buffer, so there we also check send buffer size decrease on header stream.
 * In IETF QUIC, encodeHeaders()/encodeTrailers() check the buffer size increase on the corresponding data stream which is similar to encodeData(). The buffered headers/trailers are only drained via QuicStream::OnCanWrite() so there is no need to check QuicSession::OnCanWrite.
+
+### Debugging


While you are in here do you mind also documenting the nghttp2 env var? https://github.com/envoyproxy/envoy/blob/main/source/common/http/http2/nghttp2.cc (edit never mind this isn't where you would document nghttp2, but see cross linking comment below)

Would it be worth it to standardize the names a bit also? I don't feel strongly but might be nice.

And finally, if you search fro ENVOY_NGHTTP2_TRACE you will see it's documented a few different places. Might be nice to consolidate and/or cross reference.

I intentionally picked a slightly different name because ENVOY_NGHTTP2_TRACE is a bool whereas ENVOY_QUICHE_VERBOSITY is an int. What do you think?

I just modified the documentation that referenced ENVOY_NGHTTP2_TRACE to also reference ENVOY_QUICHE_VERBOSITY.

Sure sounds good.

Signed-off-by: David Schinazi <dschinazi@google.com>

DavidSchinazi · 2021-03-19T00:42:58Z

Thanks @mattklein123 ! I think there's value in enabling ENVOY_QUICHE_VERBOSITY even on release builds, our internal equivalent has helped me debug QUIC issues that were only happening in release builds in the past.

I'm happy to do what you mentioned:

Use bazel to explicitly run a test setting the env var. I don't know off hand whether this would force recompilation or if you can just run the test binary with a new action_env var that wouldn't effect compilation.

but I'm not knowledgeable enough in bazel to know how to do this. Do you have another example I can use as inspiration? Alternatively we can say that this debugging feature doesn't need a test given the overhead?

mattklein123 · 2021-03-19T00:58:13Z

but I'm not knowledgeable enough in bazel to know how to do this. Do you have another example I can use as inspiration? Alternatively we can say that this debugging feature doesn't need a test given the overhead?

I'm fine with whatever you and @danzh2010 @alyssawilk decide, but if you want to try with bazel you would use --action_env to pass an env variable. The thing I don't know off the top of my head is whether setting this will recompile. If it does it's not worth it IMO. If it doesn't, up to you.

mattklein123

Let's merge this and if you want to circle back with a test feel free.

DavidSchinazi requested review from alyssawilk, ggreenway and mattklein123 as code owners March 18, 2021 00:57

jmarantz assigned danzh2010 Mar 18, 2021

alyssawilk self-assigned this Mar 18, 2021

fix spelling

3b91b6c

Signed-off-by: David Schinazi <dschinazi@google.com>

danzh2010 reviewed Mar 18, 2021

View reviewed changes

fix clang-tidy and add documentation

a38c91a

Signed-off-by: David Schinazi <dschinazi@google.com>

alyssawilk reviewed Mar 18, 2021

View reviewed changes

alyssawilk previously approved these changes Mar 18, 2021

View reviewed changes

alyssawilk assigned mattklein123 Mar 18, 2021

danzh2010 previously approved these changes Mar 18, 2021

View reviewed changes

mattklein123 reviewed Mar 19, 2021

View reviewed changes

moar docs

040a437

Signed-off-by: David Schinazi <dschinazi@google.com>

DavidSchinazi dismissed stale reviews from danzh2010 and alyssawilk via 040a437 March 19, 2021 00:39

mattklein123 approved these changes Mar 19, 2021

View reviewed changes

mattklein123 merged commit 1bd965e into envoyproxy:main Mar 19, 2021

qinggniq mentioned this pull request Mar 23, 2021

build: can not build quiche at latest commit #15620

Closed


		using QuicLogLevel = spdlog::level::level_enum;

		static const QuicLogLevel TRACE = spdlog::level::trace;

Conversation

DavidSchinazi commented Mar 18, 2021

Uh oh!

alyssawilk commented Mar 18, 2021

Uh oh!

danzh2010 left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

danzh2010 commented Mar 18, 2021

Uh oh!

alyssawilk left a comment

Choose a reason for hiding this comment

Uh oh!

DavidSchinazi commented Mar 18, 2021

Uh oh!

alyssawilk left a comment

Choose a reason for hiding this comment

Uh oh!

mattklein123 left a comment

Choose a reason for hiding this comment

Uh oh!

mattklein123 Mar 19, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

DavidSchinazi commented Mar 19, 2021

Uh oh!

mattklein123 commented Mar 19, 2021

Uh oh!

mattklein123 left a comment

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

mattklein123 Mar 19, 2021 •

edited

Loading