Add quic_logging_impl.(h|cc) to QUICHE platform implementation. by wu-bin · Pull Request #5758 · envoyproxy/envoy

wu-bin · 2019-01-29T19:52:33Z

Description:

Add quic_logging_impl.(h|cc) and unit tests to QUICHE platform implementation.

QUICHE code uses stream-style logging macros to do logging, e.g.:
QUIC_LOG(INFO) << "x = " << x;

The implementation in this PR uses a temporary std::ostringstream (one per macro invocation) to convert the stream into a std::string, then send the string to spdlog.

Risk Level: minimal: code not used yet
Testing:
[Unit test in release mode] bazel test --experimental_remap_main_repo -c opt test/extensions/quic_listeners/quiche/platform:quic_platform_test
[Unit test in debug mode] bazel test --experimental_remap_main_repo test/extensions/quic_listeners/quiche/platform:quic_platform_test

Docs Changes: none
Release Notes: none
[Optional Fixes #Issue]
[Optional Deprecated:]

Signed-off-by: Bin Wu <wub@google.com>

mpwarres · 2019-01-29T20:10:40Z

Tagging issue #2557

alyssawilk · 2019-01-30T16:23:17Z

Looks like you want to check CI on this one. FWIW you can also set up circle ci to email you on build failures - I don't think it does by default but it's super useful to get the reports

alyssawilk · 2019-01-31T14:39:46Z

/wait

wu-bin · 2019-01-31T14:45:40Z

@alyssawilk : This PR needs to wait for the resolution of #5767

alyssawilk · 2019-01-31T15:02:10Z

Totally fine - this just flags it on github dashboards as something I don't need to look at :-)
When the blocking issue is resolved and you push new code, it'll auto-remove the wait tag.

mpwarres

Looks awesome! I know this is blocked behind other things, but figured I'd give some comments in the meantime.

mpwarres · 2019-02-01T04:21:02Z

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

+  case 1:                                                                                          \
+    logstream
+
+#define QUIC_LOGGER() Envoy::Logger::Registry::getLog(Envoy::Logger::Id::misc)


nit: does QUIC_LOGGER have to be a macro? Wondering if you could instead just define a GetQuicLogger() function.

Replaced QUIC_LOGGER() by quic::GetLogger() function.

mpwarres · 2019-02-01T04:27:58Z

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

+
+#include "absl/base/optimization.h"
+
+#define QUIC_LOG_IMPL_INTERNAL(condition, logstream)                                               \


A brief comment explaining roughly how this works, and that it is done in order to instantiate logstream only if condition is true, would be nice.

Side question: I was noticing that base/logging.h does this slightly differently, placing the log stream expression in the default case of a switch(0), do you have any idea why that is? I agree your formulation seems simpler, just wondering if there's some reason behind the base/logging.h form.

Comment added.

I was following the style in go/onelog, not base/logging.h. But the style in go/onelog no longer compiles after I updated my clang to 7.0, so I've switched to the base/logging.h style.

About the switch(0):
If a macro is implemented in the form of "if (x) {} else {}", the switch(0) can be used to suppress a warning about ambiguous else blocks. Suppose there is

#define MACRO() if (x) {} else {}

And a call site:

if (y) MACRO();

Which expands to:

if (y) if (x) {} else {};

The "else" is bind to the second "if", but some compiler worries that the intent is to bind to the first "if", so they give warnings. The switch(0) trick eliminates this warning.

mpwarres · 2019-02-01T04:30:43Z

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

+  QUIC_LOG_IMPL_INTERNAL((condition) && quic::IsLogLevelEnabled(quic::severity),                   \
+                         quic::QuicLogEmitter(quic::severity).stream())
+
+#define QUIC_LOG_IMPL(severity) QUIC_LOG_IF_IMPL(severity, true)


(optional) slight preference for defining this directly in terms of QUIC_LOG_IMPL_INTERNAL, even though it's longer textually.

QUIC_LOG_IF_IMPL is easier to read and I think it compiles to the same code.

Fair enough, SG

mpwarres · 2019-02-01T04:32:50Z

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

+static const QuicLogLevel WARNING = spdlog::level::warn;
+static const QuicLogLevel ERROR = spdlog::level::err;
+static const QuicLogLevel FATAL = spdlog::level::critical;
+


should there be a TODO for DFATAL here?

Sorry, I forgot that, added to this PR, please take a look.

mpwarres · 2019-02-01T04:40:14Z

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

+static const QuicLogLevel INFO = spdlog::level::info;
+static const QuicLogLevel WARNING = spdlog::level::warn;
+static const QuicLogLevel ERROR = spdlog::level::err;
+static const QuicLogLevel FATAL = spdlog::level::critical;


does logging spdylog::level::critical kill the process? I couldn't find indication of that in spdlog documentation. If it does, perhaps this could be verified with a death test.

It doesn't, but I've updated this PR to kill the process when QUIC_LOG(FATAL) is hit.

mpwarres · 2019-02-01T04:48:04Z

test/extensions/quic_listeners/quiche/platform/quic_platform_test.cc

+  QUIC_LOG_IF(ERROR, false) << i++;
+  EXPECT_EQ(11, i);
+
+  QUIC_LOG_IF(ERROR, true) << i++;


would it be possible to have the test verify, for at least one of the log statements that actually executes, that the expected message actually makes it to spdlog? Might not be too bad if you mock spdlog::sinks::sink or base_sink.

If this ends up being more complicated, then maybe not worth the effort.

I plan to work on it in a follow up PR, in the context of quic_mock_log_impl.h.

SG. Could you add a TODO comment for that?

Done, thanks!

mpwarres · 2019-02-01T04:54:28Z

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

+#define QUIC_LOG_INFO_IS_ON_IMPL quic::IsLogLevelEnabled(quic::INFO)
+#define QUIC_LOG_WARNING_IS_ON_IMPL quic::IsLogLevelEnabled(quic::WARNING)
+#define QUIC_LOG_ERROR_IS_ON_IMPL quic::IsLogLevelEnabled(quic::ERROR)
+


I think we may need TODOs for CHECK and DCHECK macros (including the various (D)CHECK_ variants), since google3 quic_logging_impl.h implicitly provides those as well (by directly #including base/logging.h), and QUICHE code definitely uses them.

SG, added a TODO.

…ging Update the QUIC_LOG_IMPL_INTERNAL macro. Signed-off-by: Bin Wu <wub@google.com>

Signed-off-by: Bin Wu <wub@google.com>

mpwarres

LGTM, thanks for implementing this!

mpwarres · 2019-02-06T17:04:47Z

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

+  QUIC_LOG_IMPL_INTERNAL((condition) && quic::IsLogLevelEnabled(quic::severity),                   \
+                         quic::QuicLogEmitter(quic::severity).stream())
+
+#define QUIC_LOG_IMPL(severity) QUIC_LOG_IF_IMPL(severity, true)


Fair enough, SG

mpwarres · 2019-02-06T17:06:17Z

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

+#define QUIC_LOG_INFO_IS_ON_IMPL quic::IsLogLevelEnabled(quic::INFO)
+#define QUIC_LOG_WARNING_IS_ON_IMPL quic::IsLogLevelEnabled(quic::WARNING)
+#define QUIC_LOG_ERROR_IS_ON_IMPL quic::IsLogLevelEnabled(quic::ERROR)
+


mpwarres · 2019-02-06T17:12:13Z

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

+static const QuicLogLevel INFO = spdlog::level::info;
+static const QuicLogLevel WARNING = spdlog::level::warn;
+static const QuicLogLevel ERROR = spdlog::level::err;
+static const QuicLogLevel FATAL = spdlog::level::critical;


mpwarres · 2019-02-06T17:15:29Z

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

+static const QuicLogLevel WARNING = spdlog::level::warn;
+static const QuicLogLevel ERROR = spdlog::level::err;
+static const QuicLogLevel FATAL = spdlog::level::critical;
+


mpwarres · 2019-02-06T17:17:22Z

test/extensions/quic_listeners/quiche/platform/quic_platform_test.cc

+  QUIC_LOG_IF(ERROR, false) << i++;
+  EXPECT_EQ(11, i);
+
+  QUIC_LOG_IF(ERROR, true) << i++;


SG. Could you add a TODO comment for that?

mpwarres · 2019-02-06T17:18:14Z

test/extensions/quic_listeners/quiche/platform/quic_platform_test.cc

+// Test the behaviors of the cross products of
+//
+//   {QUIC_LOG, QUIC_DLOG} x {FATAL, DFATAL} x {debug, release}
+TEST(QuicPlatformTest, QuicFatalLog) {


Cool, nice to have a test for this

mpwarres · 2019-02-06T17:18:39Z

test/extensions/quic_listeners/quiche/platform/quic_platform_test.cc

+  quic::GetLogger().set_level(quic::INFO);
+
+  if (QUIC_PREDICT_FALSE(rand() % RAND_MAX == 123456789)) {
+    QUIC_LOG(INFO) << "Go buy some lottery tickets.";


Signed-off-by: Bin Wu <wub@google.com>

building it unless "--define quiche=enabled" is used. Signed-off-by: Bin Wu <wub@google.com>

Signed-off-by: Bin Wu <wub@google.com>

wu-bin · 2019-02-07T02:34:11Z

/retest

repokitteh-read-only · 2019-02-07T02:34:15Z

🔨 rebuilding ci/circleci: coverage (failed build)

🐱

Caused by: a #5758 (comment) was created by @wu-bin.

see: more, trace.

wu-bin · 2019-02-07T16:26:33Z

@alyssawilk : Can you take a look at this and (if no problem) merge it? Thanks!

alyssawilk

Very cool!

alyssawilk · 2019-02-07T18:20:39Z

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

+QuicLogEmitter::~QuicLogEmitter() {
+  if (is_perror_) {
+    // TODO(wub): Change to a thread-safe version of strerror.
+    stream_ << ": " << strerror(saved_errno_) << " [" << saved_errno_ << "]";


If this is as simple as switching to strerror_r might as well do it here

strerror is prevalent in Envoy code, I'd prefer to stick to it in this PR.
In the future, I can add a thread safe version of strerror to some Envoy utility class, and use that everywhere, but it will be in low priority.

alyssawilk · 2019-02-07T18:26:19Z

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

+template <typename T> inline NullLogStream& operator<<(NullLogStream& s, const T&) { return s; }
+
+inline spdlog::logger& GetLogger() {
+  return Envoy::Logger::Registry::getLog(Envoy::Logger::Id::misc);


I think we should probably declare a quic-specific logger in
source/common/common/logger.h
If it ends up being complicated a TODO is fine.

Done. (seems easier than I thought, hopefully ci won't complain:)

alyssawilk · 2019-02-07T18:32:01Z

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

+static const QuicLogLevel INFO = spdlog::level::info;
+static const QuicLogLevel WARNING = spdlog::level::warn;
+static const QuicLogLevel ERROR = spdlog::level::err;
+static const QuicLogLevel FATAL = spdlog::level::critical;


Just something to keep in mid as we code, in Envoy only critical logs flush immediately.
It won't cause problems and I think while we could set Enovy QUIC logs to flush at error it makes more sense to stick with the defaults, but worth being aware when we debug.

Got it, thanks!

alyssawilk · 2019-02-07T18:34:26Z

test/extensions/quic_listeners/quiche/platform/quic_platform_test.cc

+
+  int i = 0;
+
+  QUIC_LOG(INFO) << (i = 10);


Mind using EXPECT_LOG_[NOT_]ONTAINS macros instead of or in additon to the math checks?
It'll also verify we did the log mapping correctly.

I added some EXPECT_LOG_CONTAINS.
These macros forcefully set the log level to trace(example), so things like EXPECT_NO_LOGS do not work for the test where log is not emitted due to log level.

After this PR, I'll work on quic_mock_log_impl.h and add tests for the "no log expected" case.

Signed-off-by: Bin Wu <wub@google.com>

wu-bin

@alyssawilk Thanks for the review! PTAL.

wu-bin · 2019-02-07T19:49:25Z

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

+QuicLogEmitter::~QuicLogEmitter() {
+  if (is_perror_) {
+    // TODO(wub): Change to a thread-safe version of strerror.
+    stream_ << ": " << strerror(saved_errno_) << " [" << saved_errno_ << "]";


strerror is prevalent in Envoy code, I'd prefer to stick to it in this PR.
In the future, I can add a thread safe version of strerror to some Envoy utility class, and use that everywhere, but it will be in low priority.

wu-bin · 2019-02-07T19:50:11Z

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

+static const QuicLogLevel INFO = spdlog::level::info;
+static const QuicLogLevel WARNING = spdlog::level::warn;
+static const QuicLogLevel ERROR = spdlog::level::err;
+static const QuicLogLevel FATAL = spdlog::level::critical;


Got it, thanks!

wu-bin · 2019-02-07T20:02:21Z

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

+template <typename T> inline NullLogStream& operator<<(NullLogStream& s, const T&) { return s; }
+
+inline spdlog::logger& GetLogger() {
+  return Envoy::Logger::Registry::getLog(Envoy::Logger::Id::misc);


Done. (seems easier than I thought, hopefully ci won't complain:)

wu-bin · 2019-02-07T20:28:12Z

test/extensions/quic_listeners/quiche/platform/quic_platform_test.cc

+
+  int i = 0;
+
+  QUIC_LOG(INFO) << (i = 10);


I added some EXPECT_LOG_CONTAINS.
These macros forcefully set the log level to trace(example), so things like EXPECT_NO_LOGS do not work for the test where log is not emitted due to log level.

After this PR, I'll work on quic_mock_log_impl.h and add tests for the "no log expected" case.

…yproxy#5758) Add quic_logging_impl.(h|cc) and unit tests to QUICHE platform implementation. QUICHE code uses stream-style logging macros to do logging, e.g.: QUIC_LOG(INFO) << "x = " << x; The implementation in this PR uses a temporary std::ostringstream (one per macro invocation) to convert the stream into a std::string, then send the string to spdlog. Risk Level: minimal: code not used yet Testing: [Unit test in release mode] bazel test --experimental_remap_main_repo -c opt test/extensions/quic_listeners/quiche/platform:quic_platform_test [Unit test in debug mode] bazel test --experimental_remap_main_repo test/extensions/quic_listeners/quiche/platform:quic_platform_test Signed-off-by: Bin Wu <wub@google.com> Signed-off-by: Fred Douglas <fredlas@google.com>

Add quic_logging_impl.(h|cc) to QUICHE platform implementation.

e04c28c

Signed-off-by: Bin Wu <wub@google.com>

This was referenced Jan 29, 2019

For QUICHE integration, add --experimental_remap_main_repo to bazelrc. #5759

Closed

For QUICHE integration, add --experimental_remap_main_repo to bazelrc. #5767

Closed

alyssawilk assigned alyssawilk and mpwarres Jan 30, 2019

repokitteh-read-only bot added the waiting label Jan 31, 2019

mpwarres suggested changes Feb 1, 2019

View reviewed changes

wu-bin added 2 commits February 6, 2019 09:48

Merge remote-tracking branch 'upstream/master' into quic_platform_log…

75e7024

…ging Update the QUIC_LOG_IMPL_INTERNAL macro. Signed-off-by: Bin Wu <wub@google.com>

Update based on PR comments.

0ae37c0

Signed-off-by: Bin Wu <wub@google.com>

wu-bin requested review from alyssawilk and mattklein123 as code owners February 6, 2019 16:59

repokitteh-read-only bot removed the waiting label Feb 6, 2019

mpwarres previously approved these changes Feb 6, 2019

View reviewed changes

Add a TODO for implementing quic_mock_log_impl.h.

a2956eb

Signed-off-by: Bin Wu <wub@google.com>

wu-bin dismissed mpwarres’s stale review via a2956eb February 6, 2019 17:49

wu-bin added 3 commits February 6, 2019 14:48

Add envoy_select_quiche to "quic_platform_base_impl_lib" to skip

eefc0ac

building it unless "--define quiche=enabled" is used. Signed-off-by: Bin Wu <wub@google.com>

Make clang-tidy and spelling checker happy.

a470825

Signed-off-by: Bin Wu <wub@google.com>

Also make the pedantic spelling checker happy.

b9ed2f6

Signed-off-by: Bin Wu <wub@google.com>

alyssawilk reviewed Feb 7, 2019

View reviewed changes

Update based on PR comments.

d67cf0b

Signed-off-by: Bin Wu <wub@google.com>

wu-bin commented Feb 7, 2019

View reviewed changes

alyssawilk approved these changes Feb 7, 2019

View reviewed changes

htuch merged commit 2cf6524 into envoyproxy:master Feb 8, 2019


		#include "absl/base/optimization.h"

		#define QUIC_LOG_IMPL_INTERNAL(condition, logstream) \

Conversation

wu-bin commented Jan 29, 2019

Uh oh!

mpwarres commented Jan 29, 2019

Uh oh!

alyssawilk commented Jan 30, 2019

Uh oh!

alyssawilk commented Jan 31, 2019

Uh oh!

wu-bin commented Jan 31, 2019

Uh oh!

alyssawilk commented Jan 31, 2019

Uh oh!

mpwarres 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!

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!

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!

mpwarres 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!

wu-bin commented Feb 7, 2019

Uh oh!

repokitteh-read-only bot commented Feb 7, 2019

Uh oh!

wu-bin commented Feb 7, 2019

Uh oh!

alyssawilk left a comment