Improve Envoy QUICHE logging (envoyproxy#15549)

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 <[email protected]>

Author: DavidSchinazi

bazel/EXTERNAL_DEPS.md

@@ -109,6 +109,9 @@ dependencies:
 
 * `nghttp2`: set `ENVOY_NGHTTP2_TRACE` in the environment and run at `-l trace`.
 
+* `QUICHE`: set `ENVOY_QUICHE_VERBOSITY=n` in the environment to display
+  verbose logs up to level `n`.
+
 # Distdir - prefetching dependencies
 
 Usually Bazel downloads all dependencies during build time. But there is a

bazel/README.md

@@ -619,6 +619,10 @@ bazel test //test/integration:protocol_integration_test --test_output=streamed \
   --test_arg="-l trace" --test_env="ENVOY_NGHTTP2_TRACE="
 ```
 
+Similarly, `QUICHE` verbose logs can be enabled by setting `ENVOY_QUICHE_VERBOSITY=n` in the
+environment where `n` is the desired verbosity level (e.g.
+`--test_env="ENVOY_QUICHE_VERBOSITY=2"`.
+
 ## Disabling optional features
 
 The following optional features can be disabled on the Bazel build command-line:

source/docs/quiche_integration.md

@@ -35,3 +35,8 @@ When the aggregated buffered bytes goes above high watermark, its registered net
 As to Http::StreamEncoder::encodeHeaders()/encodeTrailers(), the accounting is done differently between Google QUIC and IETF QUIC:
  * 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
+
+QUICHE verbose logs (such as `QUICHE_VLOG(2)` for example) can be enabled by setting the `ENVOY_QUICHE_VERBOSITY` environment variable. For example, pass `--test_env="ENVOY_QUICHE_VERBOSITY=2"` to `bazel test`.
+

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

@@ -7,13 +7,45 @@
 #include "extensions/quic_listeners/quiche/platform/quic_logging_impl.h"
 
 #include <atomic>
+#include <cstdlib>
 
 #include "common/common/utility.h"
 
 namespace quic {
 
 namespace {
-std::atomic<int> g_verbosity_threshold;
+
+// Helper class that allows getting and setting QUICHE log verbosity threshold.
+class QuicLogVerbosityManager {
+public:
+  // Gets QUICHE log verbosity threshold.
+  static int getThreshold() {
+    return getSingleton()->verbosity_threshold_.load(std::memory_order_relaxed);
+  }
+
+  // Sets QUICHE log verbosity threshold.
+  static void setThreshold(int new_verbosity) {
+    getSingleton()->verbosity_threshold_.store(new_verbosity, std::memory_order_relaxed);
+  }
+
+private:
+  static QuicLogVerbosityManager* getSingleton() {
+    static QuicLogVerbosityManager manager = QuicLogVerbosityManager();
+    return &manager;
+  }
+
+  explicit QuicLogVerbosityManager() {
+    int verbosity = 0;
+    const char* verbosity_str = std::getenv("ENVOY_QUICHE_VERBOSITY");
+    if (verbosity_str != nullptr) {
+      verbosity = atoi(verbosity_str);
+    }
+    verbosity_threshold_.store(verbosity, std::memory_order_relaxed);
+  }
+
+  std::atomic<int> verbosity_threshold_;
+};
+
 std::atomic<bool> g_dfatal_exit_disabled;
 
 // Pointer to the global log sink, usually it is nullptr.
@@ -23,7 +55,16 @@ std::atomic<QuicLogSink*> g_quic_log_sink;
 absl::Mutex g_quic_log_sink_mutex;
 } // namespace
 
-QuicLogEmitter::QuicLogEmitter(QuicLogLevel level) : level_(level), saved_errno_(errno) {}
+int getVerbosityLogThreshold() { return QuicLogVerbosityManager::getThreshold(); }
+
+void setVerbosityLogThreshold(int new_verbosity) {
+  QuicLogVerbosityManager::setThreshold(new_verbosity);
+}
+
+QuicLogEmitter::QuicLogEmitter(QuicLogLevel level, const char* file_name, int line,
+                               const char* function_name)
+    : level_(level), file_name_(file_name), line_(line), function_name_(function_name),
+      saved_errno_(errno) {}
 
 QuicLogEmitter::~QuicLogEmitter() {
   if (is_perror_) {
@@ -36,7 +77,8 @@ QuicLogEmitter::~QuicLogEmitter() {
     // the output.
     content.back() = '\0';
   }
-  GetLogger().log(level_, "{}", content.c_str());
+  GetLogger().log(::spdlog::source_loc(file_name_, line_, function_name_), level_, "{}",
+                  content.c_str());
 
   // Normally there is no log sink and we can avoid acquiring the lock.
   if (g_quic_log_sink.load(std::memory_order_relaxed) != nullptr) {
@@ -61,15 +103,9 @@ QuicLogEmitter::~QuicLogEmitter() {
   }
 }
 
-int GetVerbosityLogThreshold() { return g_verbosity_threshold.load(std::memory_order_relaxed); }
-
-void SetVerbosityLogThreshold(int new_verbosity) {
-  g_verbosity_threshold.store(new_verbosity, std::memory_order_relaxed);
-}
-
-bool IsDFatalExitDisabled() { return g_dfatal_exit_disabled.load(std::memory_order_relaxed); }
+bool isDFatalExitDisabled() { return g_dfatal_exit_disabled.load(std::memory_order_relaxed); }
 
-void SetDFatalExitDisabled(bool is_disabled) {
+void setDFatalExitDisabled(bool is_disabled) {
   g_dfatal_exit_disabled.store(is_disabled, std::memory_order_relaxed);
 }
 

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

@@ -37,14 +37,16 @@
       logstream
 
 #define QUICHE_LOG_IF_IMPL(severity, condition)                                                    \
-  QUICHE_LOG_IMPL_INTERNAL((condition) && quic::IsLogLevelEnabled(quic::severity),                 \
-                           quic::QuicLogEmitter(quic::severity).stream())
+  QUICHE_LOG_IMPL_INTERNAL(                                                                        \
+      QUICHE_IS_LOG_LEVEL_ENABLED(severity) && (condition),                                        \
+      quic::QuicLogEmitter(quic::severity, __FILE__, __LINE__, __func__).stream())
 
 #define QUICHE_LOG_IMPL(severity) QUICHE_LOG_IF_IMPL(severity, true)
 
 #define QUICHE_VLOG_IF_IMPL(verbosity, condition)                                                  \
-  QUICHE_LOG_IMPL_INTERNAL((condition) && quic::IsVerboseLogEnabled(verbosity),                    \
-                           quic::QuicLogEmitter(quic::INFO).stream())
+  QUICHE_LOG_IMPL_INTERNAL(                                                                        \
+      quic::isVerboseLogEnabled(verbosity) && (condition),                                         \
+      quic::QuicLogEmitter(quic::INFO, __FILE__, __LINE__, __func__).stream())
 
 #define QUICHE_VLOG_IMPL(verbosity) QUICHE_VLOG_IF_IMPL(verbosity, true)
 
@@ -58,22 +60,29 @@
 #define QUICHE_LOG_EVERY_N_SEC_IMPL(severity, seconds) QUICHE_LOG_IMPL(severity)
 
 #define QUICHE_PLOG_IMPL(severity)                                                                 \
-  QUICHE_LOG_IMPL_INTERNAL(quic::IsLogLevelEnabled(quic::severity),                                \
-                           quic::QuicLogEmitter(quic::severity).SetPerror().stream())
+  QUICHE_LOG_IMPL_INTERNAL(                                                                        \
+      QUICHE_IS_LOG_LEVEL_ENABLED(severity),                                                       \
+      quic::QuicLogEmitter(quic::severity, __FILE__, __LINE__, __func__).SetPerror().stream())
 
-#define QUICHE_LOG_INFO_IS_ON_IMPL() quic::IsLogLevelEnabled(quic::INFO)
-#define QUICHE_LOG_WARNING_IS_ON_IMPL() quic::IsLogLevelEnabled(quic::WARNING)
-#define QUICHE_LOG_ERROR_IS_ON_IMPL() quic::IsLogLevelEnabled(quic::ERROR)
+#define QUICHE_LOG_INFO_IS_ON_IMPL() QUICHE_IS_LOG_LEVEL_ENABLED(INFO)
+#define QUICHE_LOG_WARNING_IS_ON_IMPL() QUICHE_IS_LOG_LEVEL_ENABLED(WARNING)
+#define QUICHE_LOG_ERROR_IS_ON_IMPL() QUICHE_IS_LOG_LEVEL_ENABLED(ERROR)
 
-#define QUICHE_CHECK_IMPL(condition)                                                               \
-  QUICHE_LOG_IF_IMPL(FATAL, ABSL_PREDICT_FALSE(!(condition))) << "CHECK failed: " #condition "."
+#define QUICHE_CHECK_INNER_IMPL(condition, details)                                                \
+  QUICHE_LOG_IF_IMPL(FATAL, ABSL_PREDICT_FALSE(!(condition))) << details << ". "
 
-#define QUICHE_CHECK_GT_IMPL(a, b) QUICHE_CHECK_IMPL((a) > (b))
-#define QUICHE_CHECK_GE_IMPL(a, b) QUICHE_CHECK_IMPL((a) >= (b))
-#define QUICHE_CHECK_LT_IMPL(a, b) QUICHE_CHECK_IMPL((a) < (b))
-#define QUICHE_CHECK_LE_IMPL(a, b) QUICHE_CHECK_IMPL((a) <= (b))
-#define QUICHE_CHECK_NE_IMPL(a, b) QUICHE_CHECK_IMPL((a) != (b))
-#define QUICHE_CHECK_EQ_IMPL(a, b) QUICHE_CHECK_IMPL((a) == (b))
+#define QUICHE_CHECK_IMPL(condition) QUICHE_CHECK_INNER_IMPL(condition, "CHECK failed: " #condition)
+
+#define QUICHE_CHECK_INNER_IMPL_OP(op, a, b)                                                       \
+  QUICHE_CHECK_INNER_IMPL((a)op(b),                                                                \
+                          "CHECK failed: " #a " (=" << (a) << ") " #op " " #b " (=" << (b) << ")")
+
+#define QUICHE_CHECK_GT_IMPL(a, b) QUICHE_CHECK_INNER_IMPL_OP(>, a, b)
+#define QUICHE_CHECK_GE_IMPL(a, b) QUICHE_CHECK_INNER_IMPL_OP(>=, a, b)
+#define QUICHE_CHECK_LT_IMPL(a, b) QUICHE_CHECK_INNER_IMPL_OP(<, a, b)
+#define QUICHE_CHECK_LE_IMPL(a, b) QUICHE_CHECK_INNER_IMPL_OP(<=, a, b)
+#define QUICHE_CHECK_NE_IMPL(a, b) QUICHE_CHECK_INNER_IMPL_OP(!=, a, b)
+#define QUICHE_CHECK_EQ_IMPL(a, b) QUICHE_CHECK_INNER_IMPL_OP(==, a, b)
 
 #ifdef NDEBUG
 // Release build
@@ -87,6 +96,12 @@
 #define QUICHE_DLOG_INFO_IS_ON_IMPL() 0
 #define QUICHE_DLOG_EVERY_N_IMPL(severity, n) QUICHE_COMPILED_OUT_LOG(false)
 #define QUICHE_NOTREACHED_IMPL()
+#define QUICHE_DCHECK_GT_IMPL(a, b) QUICHE_COMPILED_OUT_LOG((a) > (b))
+#define QUICHE_DCHECK_GE_IMPL(a, b) QUICHE_COMPILED_OUT_LOG((a) >= (b))
+#define QUICHE_DCHECK_LT_IMPL(a, b) QUICHE_COMPILED_OUT_LOG((a) < (b))
+#define QUICHE_DCHECK_LE_IMPL(a, b) QUICHE_COMPILED_OUT_LOG((a) <= (b))
+#define QUICHE_DCHECK_NE_IMPL(a, b) QUICHE_COMPILED_OUT_LOG((a) != (b))
+#define QUICHE_DCHECK_EQ_IMPL(a, b) QUICHE_COMPILED_OUT_LOG((a) == (b))
 #else
 // Debug build
 #define QUICHE_DCHECK_IMPL(condition) QUICHE_CHECK_IMPL(condition)
@@ -97,21 +112,22 @@
 #define QUICHE_DLOG_INFO_IS_ON_IMPL() QUICHE_LOG_INFO_IS_ON_IMPL()
 #define QUICHE_DLOG_EVERY_N_IMPL(severity, n) QUICHE_LOG_EVERY_N_IMPL(severity, n)
 #define QUICHE_NOTREACHED_IMPL() NOT_REACHED_GCOVR_EXCL_LINE
+#define QUICHE_DCHECK_GT_IMPL(a, b) QUICHE_CHECK_GT_IMPL(a, b)
+#define QUICHE_DCHECK_GE_IMPL(a, b) QUICHE_CHECK_GE_IMPL(a, b)
+#define QUICHE_DCHECK_LT_IMPL(a, b) QUICHE_CHECK_LT_IMPL(a, b)
+#define QUICHE_DCHECK_LE_IMPL(a, b) QUICHE_CHECK_LE_IMPL(a, b)
+#define QUICHE_DCHECK_NE_IMPL(a, b) QUICHE_CHECK_NE_IMPL(a, b)
+#define QUICHE_DCHECK_EQ_IMPL(a, b) QUICHE_CHECK_EQ_IMPL(a, b)
 #endif
 
-#define QUICHE_DCHECK_GE_IMPL(a, b) QUICHE_DCHECK_IMPL((a) >= (b))
-#define QUICHE_DCHECK_GT_IMPL(a, b) QUICHE_DCHECK_IMPL((a) > (b))
-#define QUICHE_DCHECK_LT_IMPL(a, b) QUICHE_DCHECK_IMPL((a) < (b))
-#define QUICHE_DCHECK_LE_IMPL(a, b) QUICHE_DCHECK_IMPL((a) <= (b))
-#define QUICHE_DCHECK_NE_IMPL(a, b) QUICHE_DCHECK_IMPL((a) != (b))
-#define QUICHE_DCHECK_EQ_IMPL(a, b) QUICHE_DCHECK_IMPL((a) == (b))
-
 #define QUICHE_PREDICT_FALSE_IMPL(x) ABSL_PREDICT_FALSE(x)
 
 namespace quic {
 
 using QuicLogLevel = spdlog::level::level_enum;
 
+static const QuicLogLevel TRACE = spdlog::level::trace;
+static const QuicLogLevel DEBUG = spdlog::level::debug;
 static const QuicLogLevel INFO = spdlog::level::info;
 static const QuicLogLevel WARNING = spdlog::level::warn;
 static const QuicLogLevel ERROR = spdlog::level::err;
@@ -126,7 +142,10 @@ static const QuicLogLevel DFATAL = FATAL;
 
 class QuicLogEmitter {
 public:
-  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,
+                          const char* function_name);
 
   ~QuicLogEmitter();
 
@@ -139,6 +158,9 @@ class QuicLogEmitter {
 
 private:
   const QuicLogLevel level_;
+  const char* file_name_;
+  int line_;
+  const char* function_name_;
   const int saved_errno_;
   bool is_perror_ = false;
   std::ostringstream stream_;
@@ -157,17 +179,27 @@ inline spdlog::logger& GetLogger() {
   return Envoy::Logger::Registry::getLog(Envoy::Logger::Id::quic);
 }
 
-inline bool IsLogLevelEnabled(QuicLogLevel level) { return level >= GetLogger().level(); }
-
-int GetVerbosityLogThreshold();
-void SetVerbosityLogThreshold(int new_verbosity);
-
-inline bool IsVerboseLogEnabled(int verbosity) {
-  return IsLogLevelEnabled(INFO) && verbosity <= GetVerbosityLogThreshold();
+// This allows us to use QUICHE_CHECK(condition) from constexpr functions.
+#define QUICHE_IS_LOG_LEVEL_ENABLED(severity) quic::isLogLevelEnabled##severity()
+#define QUICHE_IS_LOG_LEVEL_ENABLED_IMPL(severity)                                                 \
+  inline bool isLogLevelEnabled##severity() { return quic::severity >= GetLogger().level(); }
+QUICHE_IS_LOG_LEVEL_ENABLED_IMPL(TRACE)
+QUICHE_IS_LOG_LEVEL_ENABLED_IMPL(DEBUG)
+QUICHE_IS_LOG_LEVEL_ENABLED_IMPL(INFO)
+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; }
+
+int getVerbosityLogThreshold();
+void setVerbosityLogThreshold(int new_verbosity);
+
+inline bool isVerboseLogEnabled(int verbosity) {
+  return QUICHE_IS_LOG_LEVEL_ENABLED(INFO) && verbosity <= getVerbosityLogThreshold();
 }
 
-bool IsDFatalExitDisabled();
-void SetDFatalExitDisabled(bool is_disabled);
+bool isDFatalExitDisabled();
+void setDFatalExitDisabled(bool is_disabled);
 
 // QuicLogSink is used to capture logs emitted from the QUICHE_LOG... macros.
 class QuicLogSink {

test/extensions/quic_listeners/quiche/platform/quic_mock_log_impl.h

@@ -51,14 +51,14 @@ class QuicEnvoyMockLog : public QuicLogSink {
 // behavior is restored.
 class ScopedDisableExitOnDFatal {
 public:
-  ScopedDisableExitOnDFatal() : previous_value_(IsDFatalExitDisabled()) {
-    SetDFatalExitDisabled(true);
+  ScopedDisableExitOnDFatal() : previous_value_(isDFatalExitDisabled()) {
+    setDFatalExitDisabled(true);
   }
 
   ScopedDisableExitOnDFatal(const ScopedDisableExitOnDFatal&) = delete;
   ScopedDisableExitOnDFatal& operator=(const ScopedDisableExitOnDFatal&) = delete;
 
-  ~ScopedDisableExitOnDFatal() { SetDFatalExitDisabled(previous_value_); }
+  ~ScopedDisableExitOnDFatal() { setDFatalExitDisabled(previous_value_); }
 
 private:
   const bool previous_value_;

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

@@ -74,13 +74,13 @@ namespace {
 class QuicPlatformTest : public testing::Test {
 protected:
   QuicPlatformTest()
-      : log_level_(GetLogger().level()), verbosity_log_threshold_(GetVerbosityLogThreshold()) {
-    SetVerbosityLogThreshold(0);
+      : log_level_(GetLogger().level()), verbosity_log_threshold_(getVerbosityLogThreshold()) {
+    setVerbosityLogThreshold(0);
     GetLogger().set_level(ERROR);
   }
 
   ~QuicPlatformTest() override {
-    SetVerbosityLogThreshold(verbosity_log_threshold_);
+    setVerbosityLogThreshold(verbosity_log_threshold_);
     GetLogger().set_level(log_level_);
   }
 
@@ -312,12 +312,12 @@ TEST_F(QuicPlatformTest, QuicLog) {
   // Set QUIC log level to INFO, since VLOG is emitted at the INFO level.
   GetLogger().set_level(INFO);
 
-  ASSERT_EQ(0, GetVerbosityLogThreshold());
+  ASSERT_EQ(0, getVerbosityLogThreshold());
 
   QUIC_VLOG(1) << (i = 1);
   EXPECT_EQ(12, i);
 
-  SetVerbosityLogThreshold(1);
+  setVerbosityLogThreshold(1);
 
   EXPECT_LOG_CONTAINS("info", "i=1", QUIC_VLOG(1) << "i=" << (i = 1));
   EXPECT_EQ(1, i);
@@ -364,12 +364,12 @@ TEST_F(QuicPlatformTest, QuicDLog) {
   QUIC_DLOG_IF(INFO, true) << (i = 11);
   EXPECT_EQ(VALUE_BY_COMPILE_MODE(11, 0), i);
 
-  ASSERT_EQ(0, GetVerbosityLogThreshold());
+  ASSERT_EQ(0, getVerbosityLogThreshold());
 
   QUIC_DVLOG(1) << (i = 1);
   EXPECT_EQ(VALUE_BY_COMPILE_MODE(11, 0), i);
 
-  SetVerbosityLogThreshold(1);
+  setVerbosityLogThreshold(1);
 
   QUIC_DVLOG(1) << (i = 1);
   EXPECT_EQ(VALUE_BY_COMPILE_MODE(1, 0), i);
@@ -383,17 +383,20 @@ TEST_F(QuicPlatformTest, QuicDLog) {
 
 #undef VALUE_BY_COMPILE_MODE
 
-TEST_F(QuicPlatformTest, QuicCHECK) {
-  CHECK(1 == 1);
-  CHECK(1 == 1) << " 1 == 1 is forever true.";
+TEST_F(QuicPlatformTest, QuicheCheck) {
+  QUICHE_CHECK(1 == 1);
+  QUICHE_CHECK(1 == 1) << " 1 == 1 is forever true.";
 
-  EXPECT_DEBUG_DEATH({ DCHECK(false) << " Supposed to fail in debug mode."; },
+  EXPECT_DEBUG_DEATH({ QUICHE_DCHECK(false) << " Supposed to fail in debug mode."; },
                      "CHECK failed:.* Supposed to fail in debug mode.");
-  EXPECT_DEBUG_DEATH({ DCHECK(false); }, "CHECK failed");
+  EXPECT_DEBUG_DEATH({ QUICHE_DCHECK(false); }, "CHECK failed");
 
-  EXPECT_DEATH({ CHECK(false) << " Supposed to fail in all modes."; },
+  EXPECT_DEATH({ QUICHE_CHECK(false) << " Supposed to fail in all modes."; },
                "CHECK failed:.* Supposed to fail in all modes.");
-  EXPECT_DEATH({ CHECK(false); }, "CHECK failed");
+  EXPECT_DEATH({ QUICHE_CHECK(false); }, "CHECK failed");
+  EXPECT_DEATH({ QUICHE_CHECK_LT(1 + 1, 2); }, "CHECK failed: 1 \\+ 1 \\(=2\\) < 2 \\(=2\\)");
+  EXPECT_DEBUG_DEATH({ QUICHE_DCHECK_NE(1 + 1, 2); },
+                     "CHECK failed: 1 \\+ 1 \\(=2\\) != 2 \\(=2\\)");
 }
 
 // Test the behaviors of the cross products of