Skip to content
Merged
Show file tree
Hide file tree
Changes from 7 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion bazel/external/quiche.BUILD
Original file line number Diff line number Diff line change
Expand Up @@ -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",
Expand All @@ -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",
Expand Down
9 changes: 8 additions & 1 deletion source/extensions/quic_listeners/quiche/platform/BUILD
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,7 @@ load(
"//bazel:envoy_build_system.bzl",
"envoy_cc_library",
"envoy_package",
"envoy_select_quiche",
)

envoy_package()
Expand Down Expand Up @@ -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",
Expand All @@ -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",
Expand All @@ -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(
Expand Down
Original file line number Diff line number Diff line change
@@ -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 <atomic>

namespace quic {

namespace {
std::atomic<int>& VerbosityLogThreshold() {
static std::atomic<int> 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_ << "]";

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

}
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
135 changes: 135 additions & 0 deletions source/extensions/quic_listeners/quiche/platform/quic_logging_impl.h
Original file line number Diff line number Diff line change
@@ -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 <cerrno>
#include <cstring>
#include <iostream>
#include <sstream>

#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)

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fair enough, SG


#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)

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

SG, added a TODO.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks

#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;

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LG, thanks

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Got it, thanks!


Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

should there be a TODO for DFATAL here?

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LG

// 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 <typename T> inline NullLogStream& operator<<(NullLogStream& s, const T&) { return s; }

inline spdlog::logger& GetLogger() {
return Envoy::Logger::Registry::getLog(Envoy::Logger::Id::misc);

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

}

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
141 changes: 141 additions & 0 deletions test/extensions/quic_listeners/quiche/platform/quic_platform_test.cc
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,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"
Expand Down Expand Up @@ -109,6 +110,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);

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

QUIC_LOG_IF(INFO, false) << i++;
QUIC_LOG_IF(INFO, true) << i++;
EXPECT_EQ(0, i);

QUIC_LOG(ERROR) << (i = 11);
EXPECT_EQ(11, i);

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

QUIC_LOG_IF(ERROR, true) << i++;

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

SG. Could you add a TODO comment for that?

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done, thanks!

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);

QUIC_VLOG(1) << (i = 1);
EXPECT_EQ(1, i);

errno = EINVAL;
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) {

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Cool, nice to have a test for this

#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.";

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ha! :-)

} 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;

Expand Down
Loading