diff --git a/bazel/external/quiche.BUILD b/bazel/external/quiche.BUILD index 788441bf40533..9a3a6d9a46465 100644 --- a/bazel/external/quiche.BUILD +++ b/bazel/external/quiche.BUILD @@ -122,6 +122,7 @@ cc_library( "quiche/quic/platform/api/quic_fallthrough.h", "quiche/quic/platform/api/quic_flag_utils.h", "quiche/quic/platform/api/quic_iovec.h", + "quiche/quic/platform/api/quic_logging.h", "quiche/quic/platform/api/quic_prefetch.h", "quiche/quic/platform/api/quic_ptr_util.h", "quiche/quic/platform/api/quic_str_cat.h", @@ -142,7 +143,6 @@ cc_library( # "quiche/quic/platform/api/quic_interval.h", # "quiche/quic/platform/api/quic_ip_address_family.h", # "quiche/quic/platform/api/quic_ip_address.h", - # "quiche/quic/platform/api/quic_logging.h", # "quiche/quic/platform/api/quic_lru_cache.h", # "quiche/quic/platform/api/quic_map_util.h", # "quiche/quic/platform/api/quic_mem_slice.h", diff --git a/source/common/common/logger.h b/source/common/common/logger.h index 5b627ea4eef97..ce4da1ab9493b 100644 --- a/source/common/common/logger.h +++ b/source/common/common/logger.h @@ -40,6 +40,7 @@ namespace Logger { FUNCTION(main) \ FUNCTION(misc) \ FUNCTION(mongo) \ + FUNCTION(quic) \ FUNCTION(pool) \ FUNCTION(rbac) \ FUNCTION(redis) \ diff --git a/source/extensions/quic_listeners/quiche/platform/BUILD b/source/extensions/quic_listeners/quiche/platform/BUILD index fb8ffa1ccfeac..d163699de1b93 100644 --- a/source/extensions/quic_listeners/quiche/platform/BUILD +++ b/source/extensions/quic_listeners/quiche/platform/BUILD @@ -4,6 +4,7 @@ load( "//bazel:envoy_build_system.bzl", "envoy_cc_library", "envoy_package", + "envoy_select_quiche", ) envoy_package() @@ -39,6 +40,9 @@ envoy_cc_library( envoy_cc_library( name = "quic_platform_base_impl_lib", + srcs = envoy_select_quiche([ + "quic_logging_impl.cc", + ]), hdrs = [ "quic_aligned_impl.h", "quic_arraysize_impl.h", @@ -55,7 +59,7 @@ envoy_cc_library( "quic_string_impl.h", "quic_string_piece_impl.h", "quic_uint128_impl.h", - ], + ] + envoy_select_quiche(["quic_logging_impl.h"]), external_deps = [ "abseil_base", "abseil_hash", @@ -65,6 +69,9 @@ envoy_cc_library( "abseil_node_hash_set", ], visibility = ["//visibility:public"], + deps = envoy_select_quiche([ + "//source/common/common:assert_lib", + ]), ) envoy_cc_library( diff --git a/source/extensions/quic_listeners/quiche/platform/quic_logging_impl.cc b/source/extensions/quic_listeners/quiche/platform/quic_logging_impl.cc new file mode 100644 index 0000000000000..5f6b16d6fde57 --- /dev/null +++ b/source/extensions/quic_listeners/quiche/platform/quic_logging_impl.cc @@ -0,0 +1,39 @@ +// NOLINT(namespace-envoy) + +// This file is part of the QUICHE platform implementation, and is not to be +// consumed or referenced directly by other Envoy code. It serves purely as a +// porting layer for QUICHE. + +#include "extensions/quic_listeners/quiche/platform/quic_logging_impl.h" + +#include + +namespace quic { + +namespace { +std::atomic& VerbosityLogThreshold() { + static std::atomic threshold(0); + return threshold; +} +} // namespace + +QuicLogEmitter::QuicLogEmitter(QuicLogLevel level) : level_(level), saved_errno_(errno) {} + +QuicLogEmitter::~QuicLogEmitter() { + if (is_perror_) { + // TODO(wub): Change to a thread-safe version of strerror. + stream_ << ": " << strerror(saved_errno_) << " [" << saved_errno_ << "]"; + } + GetLogger().log(level_, "quic: {}", stream_.str().c_str()); + if (level_ == FATAL) { + abort(); + } +} + +int GetVerbosityLogThreshold() { return VerbosityLogThreshold().load(std::memory_order_relaxed); } + +void SetVerbosityLogThreshold(int new_verbosity) { + VerbosityLogThreshold().store(new_verbosity, std::memory_order_relaxed); +} + +} // namespace quic \ No newline at end of file diff --git a/source/extensions/quic_listeners/quiche/platform/quic_logging_impl.h b/source/extensions/quic_listeners/quiche/platform/quic_logging_impl.h new file mode 100644 index 0000000000000..ff577f0d341c8 --- /dev/null +++ b/source/extensions/quic_listeners/quiche/platform/quic_logging_impl.h @@ -0,0 +1,135 @@ +#pragma once + +// NOLINT(namespace-envoy) + +// This file is part of the QUICHE platform implementation, and is not to be +// consumed or referenced directly by other Envoy code. It serves purely as a +// porting layer for QUICHE. + +#include +#include +#include +#include + +#include "common/common/assert.h" +#include "common/common/logger.h" + +#include "absl/base/optimization.h" + +// TODO(wub): Add CHECK/DCHECK and variants, which are not explicitly exposed by quic_logging.h. +// TODO(wub): Implement quic_mock_log_impl.h for testing. + +// If |condition| is true, use |logstream| to stream the log message and send it to spdlog. +// If |condition| is false, |logstream| will not be instantiated. +// The switch(0) is used to suppress a compiler warning on ambiguous "else". +#define QUIC_LOG_IMPL_INTERNAL(condition, logstream) \ + switch (0) \ + default: \ + if (!(condition)) { \ + } else \ + logstream + +#define QUIC_LOG_IF_IMPL(severity, condition) \ + 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) + +#define QUIC_VLOG_IF_IMPL(verbosity, condition) \ + QUIC_LOG_IMPL_INTERNAL((condition) && quic::IsVerboseLogEnabled(verbosity), \ + quic::QuicLogEmitter(quic::INFO).stream()) + +#define QUIC_VLOG_IMPL(verbosity) QUIC_VLOG_IF_IMPL(verbosity, true) + +// TODO(wub): Implement QUIC_LOG_FIRST_N_IMPL. +#define QUIC_LOG_FIRST_N_IMPL(severity, n) QUIC_LOG_IMPL(severity) + +// TODO(wub): Implement QUIC_LOG_EVERY_N_SEC_IMPL. +#define QUIC_LOG_EVERY_N_SEC_IMPL(severity, seconds) QUIC_LOG_IMPL(severity) + +#define QUIC_PLOG_IMPL(severity) \ + QUIC_LOG_IMPL_INTERNAL(quic::IsLogLevelEnabled(quic::severity), \ + quic::QuicLogEmitter(quic::severity).SetPerror().stream()) + +#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) + +#ifdef NDEBUG +// Release build +#define QUIC_COMPILED_OUT_LOG() QUIC_LOG_IMPL_INTERNAL(false, quic::NullLogStream().stream()) +#define QUIC_DVLOG_IMPL(verbosity) QUIC_COMPILED_OUT_LOG() +#define QUIC_DVLOG_IF_IMPL(verbosity, condition) QUIC_COMPILED_OUT_LOG() +#define QUIC_DLOG_IMPL(severity) QUIC_COMPILED_OUT_LOG() +#define QUIC_DLOG_IF_IMPL(severity, condition) QUIC_COMPILED_OUT_LOG() +#define QUIC_DLOG_INFO_IS_ON_IMPL 0 +#define QUIC_NOTREACHED_IMPL() +#else +// Debug build +#define QUIC_DVLOG_IMPL(verbosity) QUIC_VLOG_IMPL(verbosity) +#define QUIC_DVLOG_IF_IMPL(verbosity, condition) QUIC_VLOG_IF_IMPL(verbosity, condition) +#define QUIC_DLOG_IMPL(severity) QUIC_LOG_IMPL(severity) +#define QUIC_DLOG_IF_IMPL(severity, condition) QUIC_LOG_IF_IMPL(severity, condition) +#define QUIC_DLOG_INFO_IS_ON_IMPL QUIC_LOG_INFO_IS_ON_IMPL +#define QUIC_NOTREACHED_IMPL() NOT_REACHED_GCOVR_EXCL_LINE +#endif + +#define QUIC_PREDICT_FALSE_IMPL(x) ABSL_PREDICT_FALSE(x) + +namespace quic { + +using QuicLogLevel = spdlog::level::level_enum; + +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; + +// DFATAL is FATAL in debug mode, ERROR in release mode. +#ifdef NDEBUG +static const QuicLogLevel DFATAL = ERROR; +#else +static const QuicLogLevel DFATAL = FATAL; +#endif + +class QuicLogEmitter { +public: + explicit QuicLogEmitter(QuicLogLevel level); + + ~QuicLogEmitter(); + + QuicLogEmitter& SetPerror() { + is_perror_ = true; + return *this; + } + + std::ostringstream& stream() { return stream_; } + +private: + const QuicLogLevel level_; + const int saved_errno_; + bool is_perror_ = false; + std::ostringstream stream_; +}; + +class NullLogStream { +public: + NullLogStream& stream() { return *this; } +}; + +template inline NullLogStream& operator<<(NullLogStream& s, const T&) { return s; } + +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(); +} + +} // namespace quic diff --git a/test/extensions/quic_listeners/quiche/platform/BUILD b/test/extensions/quic_listeners/quiche/platform/BUILD index 59fcc209a9ab6..bb0dce1ce507e 100644 --- a/test/extensions/quic_listeners/quiche/platform/BUILD +++ b/test/extensions/quic_listeners/quiche/platform/BUILD @@ -27,6 +27,7 @@ envoy_cc_test( srcs = envoy_select_quiche(["quic_platform_test.cc"]), external_deps = ["quiche_quic_platform"], deps = [ + "//test/test_common:logging_lib", "//test/test_common:utility_lib", ], ) diff --git a/test/extensions/quic_listeners/quiche/platform/quic_platform_test.cc b/test/extensions/quic_listeners/quiche/platform/quic_platform_test.cc index 44b343af8efd7..10ff12d307d2a 100644 --- a/test/extensions/quic_listeners/quiche/platform/quic_platform_test.cc +++ b/test/extensions/quic_listeners/quiche/platform/quic_platform_test.cc @@ -1,3 +1,4 @@ +#include "test/test_common/logging.h" #include "test/test_common/test_base.h" #include "quiche/quic/platform/api/quic_aligned.h" @@ -6,6 +7,7 @@ #include "quiche/quic/platform/api/quic_containers.h" #include "quiche/quic/platform/api/quic_endian.h" #include "quiche/quic/platform/api/quic_estimate_memory_usage.h" +#include "quiche/quic/platform/api/quic_logging.h" #include "quiche/quic/platform/api/quic_mutex.h" #include "quiche/quic/platform/api/quic_ptr_util.h" #include "quiche/quic/platform/api/quic_string.h" @@ -109,6 +111,146 @@ TEST(QuicPlatformTest, QuicPtrUtil) { EXPECT_EQ("aaa", *p); } +namespace { +class QuicLogThresholdSaver { +public: + QuicLogThresholdSaver() + : level_(quic::GetLogger().level()), verbosity_threshold_(quic::GetVerbosityLogThreshold()) {} + + ~QuicLogThresholdSaver() { + quic::SetVerbosityLogThreshold(verbosity_threshold_); + quic::GetLogger().set_level(level_); + } + +private: + const quic::QuicLogLevel level_; + const int verbosity_threshold_; +}; +} // namespace + +TEST(QuicPlatformTest, QuicLog) { + QuicLogThresholdSaver saver; + + // By default, tests emit logs at level ERROR or higher. + ASSERT_EQ(quic::ERROR, quic::GetLogger().level()); + + int i = 0; + + QUIC_LOG(INFO) << (i = 10); + QUIC_LOG_IF(INFO, false) << i++; + QUIC_LOG_IF(INFO, true) << i++; + EXPECT_EQ(0, i); + + EXPECT_LOG_CONTAINS("error", ": 11", QUIC_LOG(ERROR) << (i = 11)); + EXPECT_EQ(11, i); + + QUIC_LOG_IF(ERROR, false) << i++; + EXPECT_EQ(11, i); + + EXPECT_LOG_CONTAINS("error", ": 11", QUIC_LOG_IF(ERROR, true) << i++); + EXPECT_EQ(12, i); + + // Set QUIC log level to INFO, since VLOG is emitted at the INFO level. + quic::GetLogger().set_level(quic::INFO); + + ASSERT_EQ(0, quic::GetVerbosityLogThreshold()); + + QUIC_VLOG(1) << (i = 1); + EXPECT_EQ(12, i); + + quic::SetVerbosityLogThreshold(1); + + EXPECT_LOG_CONTAINS("info", ": 1", QUIC_VLOG(1) << (i = 1)); + EXPECT_EQ(1, i); + + errno = EINVAL; + EXPECT_LOG_CONTAINS("info", ": 3:", QUIC_PLOG(INFO) << (i = 3)); + EXPECT_EQ(3, i); +} + +#ifdef NDEBUG +#define VALUE_BY_COMPILE_MODE(debug_mode_value, release_mode_value) release_mode_value +#else +#define VALUE_BY_COMPILE_MODE(debug_mode_value, release_mode_value) debug_mode_value +#endif + +TEST(QuicPlatformTest, QuicDLog) { + QuicLogThresholdSaver saver; + + int i = 0; + + quic::GetLogger().set_level(quic::ERROR); + + QUIC_DLOG(INFO) << (i = 10); + QUIC_DLOG_IF(INFO, false) << i++; + QUIC_DLOG_IF(INFO, true) << i++; + EXPECT_EQ(0, i); + + quic::GetLogger().set_level(quic::INFO); + + QUIC_DLOG(INFO) << (i = 10); + QUIC_DLOG_IF(INFO, false) << i++; + EXPECT_EQ(VALUE_BY_COMPILE_MODE(10, 0), i); + + QUIC_DLOG_IF(INFO, true) << (i = 11); + EXPECT_EQ(VALUE_BY_COMPILE_MODE(11, 0), i); + + ASSERT_EQ(0, quic::GetVerbosityLogThreshold()); + + QUIC_DVLOG(1) << (i = 1); + EXPECT_EQ(VALUE_BY_COMPILE_MODE(11, 0), i); + + quic::SetVerbosityLogThreshold(1); + + QUIC_DVLOG(1) << (i = 1); + EXPECT_EQ(VALUE_BY_COMPILE_MODE(1, 0), i); + + QUIC_DVLOG_IF(1, false) << (i = 2); + EXPECT_EQ(VALUE_BY_COMPILE_MODE(1, 0), i); + + QUIC_DVLOG_IF(1, true) << (i = 2); + EXPECT_EQ(VALUE_BY_COMPILE_MODE(2, 0), i); +} + +#undef VALUE_BY_COMPILE_MODE + +// Test the behaviors of the cross products of +// +// {QUIC_LOG, QUIC_DLOG} x {FATAL, DFATAL} x {debug, release} +TEST(QuicPlatformTest, QuicFatalLog) { +#ifdef NDEBUG + // Release build + EXPECT_DEATH(QUIC_LOG(FATAL) << "Should abort 0", "Should abort 0"); + QUIC_LOG(DFATAL) << "Should not abort"; + QUIC_DLOG(FATAL) << "Should compile out"; + QUIC_DLOG(DFATAL) << "Should compile out"; +#else + // Debug build + EXPECT_DEATH(QUIC_LOG(FATAL) << "Should abort 1", "Should abort 1"); + EXPECT_DEATH(QUIC_LOG(DFATAL) << "Should abort 2", "Should abort 2"); + EXPECT_DEATH(QUIC_DLOG(FATAL) << "Should abort 3", "Should abort 3"); + EXPECT_DEATH(QUIC_DLOG(DFATAL) << "Should abort 4", "Should abort 4"); +#endif +} + +TEST(QuicPlatformTest, QuicBranchPrediction) { + quic::GetLogger().set_level(quic::INFO); + + if (QUIC_PREDICT_FALSE(rand() % RAND_MAX == 123456789)) { + QUIC_LOG(INFO) << "Go buy some lottery tickets."; + } else { + QUIC_LOG(INFO) << "As predicted."; + } +} + +TEST(QuicPlatformTest, QuicNotReached) { +#ifdef NDEBUG + QUIC_NOTREACHED(); // Expect no-op. +#else + EXPECT_DEATH(QUIC_NOTREACHED(), "not reached"); +#endif +} + TEST(QuicPlatformTest, QuicMutex) { quic::QuicMutex mu; diff --git a/tools/spelling_dictionary.txt b/tools/spelling_dictionary.txt index f7a4911917f8a..c7e23dce1c860 100644 --- a/tools/spelling_dictionary.txt +++ b/tools/spelling_dictionary.txt @@ -38,9 +38,12 @@ CTX CTXs CVC CX +DCHECK DER DESC +DFATAL DGRAM +DLOG DNS DRYs DS @@ -242,6 +245,7 @@ UTF UUID UUIDs VH +VLOG WKT WRR WS