Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Reduce log spam of load shed points if not configured. #28753

Merged
merged 2 commits into from
Aug 1, 2023
Merged
Show file tree
Hide file tree
Changes from all 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
25 changes: 25 additions & 0 deletions source/common/common/logger.h
Original file line number Diff line number Diff line change
Expand Up @@ -674,20 +674,45 @@ class ExtractedMessage : public spdlog::custom_flag_formatter {
} \
} while (0)

#define ENVOY_LOG_FIRST_N_TO_LOGGER_IF(LOGGER, LEVEL, N, CONDITION, ...) \
do { \
if (ENVOY_LOG_COMP_LEVEL(LOGGER, LEVEL) && (CONDITION)) { \
static auto* countdown = new std::atomic<uint64_t>(); \
if (countdown->fetch_add(1) < N) { \
ENVOY_LOG_TO_LOGGER(LOGGER, LEVEL, ##__VA_ARGS__); \
} \
} \
} while (0)

#define ENVOY_LOG_FIRST_N(LEVEL, N, ...) \
ENVOY_LOG_FIRST_N_TO_LOGGER(ENVOY_LOGGER(), LEVEL, N, ##__VA_ARGS__)

#define ENVOY_LOG_FIRST_N_IF(LEVEL, N, CONDITION, ...) \
ENVOY_LOG_FIRST_N_TO_LOGGER_IF(ENVOY_LOGGER(), LEVEL, N, (CONDITION), ##__VA_ARGS__)

#define ENVOY_LOG_FIRST_N_MISC(LEVEL, N, ...) \
ENVOY_LOG_FIRST_N_TO_LOGGER(GET_MISC_LOGGER(), LEVEL, N, ##__VA_ARGS__)

#define ENVOY_LOG_FIRST_N_MISC_IF(LEVEL, N, CONDITION, ...) \
ENVOY_LOG_FIRST_N_TO_LOGGER_IF(GET_MISC_LOGGER(), LEVEL, N, (CONDITION), ##__VA_ARGS__)

#define ENVOY_LOG_ONCE_TO_LOGGER(LOGGER, LEVEL, ...) \
ENVOY_LOG_FIRST_N_TO_LOGGER(LOGGER, LEVEL, 1, ##__VA_ARGS__)

#define ENVOY_LOG_ONCE_TO_LOGGER_IF(LOGGER, LEVEL, CONDITION, ...) \
ENVOY_LOG_FIRST_N_TO_LOGGER_IF(LOGGER, LEVEL, 1, (CONDITION), ##__VA_ARGS__)

#define ENVOY_LOG_ONCE(LEVEL, ...) ENVOY_LOG_ONCE_TO_LOGGER(ENVOY_LOGGER(), LEVEL, ##__VA_ARGS__)

#define ENVOY_LOG_ONCE_IF(LEVEL, CONDITION, ...) \
ENVOY_LOG_ONCE_TO_LOGGER_IF(ENVOY_LOGGER(), LEVEL, (CONDITION), ##__VA_ARGS__)

#define ENVOY_LOG_ONCE_MISC(LEVEL, ...) \
ENVOY_LOG_ONCE_TO_LOGGER(GET_MISC_LOGGER(), LEVEL, ##__VA_ARGS__)

#define ENVOY_LOG_ONCE_MISC_IF(LEVEL, CONDITION, ...) \
ENVOY_LOG_ONCE_TO_LOGGER_IF(GET_MISC_LOGGER(), LEVEL, (CONDITION), ##__VA_ARGS__)

#define ENVOY_LOG_EVERY_NTH_TO_LOGGER(LOGGER, LEVEL, N, ...) \
do { \
if (ENVOY_LOG_COMP_LEVEL(LOGGER, LEVEL)) { \
Expand Down
7 changes: 6 additions & 1 deletion source/common/http/conn_manager_impl.cc
Original file line number Diff line number Diff line change
Expand Up @@ -111,7 +111,12 @@ ConnectionManagerImpl::ConnectionManagerImpl(ConnectionManagerConfig& config,
/*server_name=*/config_.serverName(),
/*proxy_status_config=*/config_.proxyStatusConfig())),
refresh_rtt_after_request_(
Runtime::runtimeFeatureEnabled("envoy.reloadable_features.refresh_rtt_after_request")) {}
Runtime::runtimeFeatureEnabled("envoy.reloadable_features.refresh_rtt_after_request")) {
ENVOY_LOG_ONCE_IF(
trace, accept_new_http_stream_ == nullptr,
"LoadShedPoint envoy.load_shed_points.http_connection_manager_decode_headers is not "
"found. Is it configured?");
}

const ResponseHeaderMap& ConnectionManagerImpl::continueHeader() {
static const auto headers = createHeaderMap<ResponseHeaderMapImpl>(
Expand Down
3 changes: 3 additions & 0 deletions source/common/http/http1/codec_impl.cc
Original file line number Diff line number Diff line change
Expand Up @@ -1071,6 +1071,9 @@ ServerConnectionImpl::ServerConnectionImpl(
headers_with_underscores_action_(headers_with_underscores_action),
abort_dispatch_(
overload_manager.getLoadShedPoint("envoy.load_shed_points.http1_server_abort_dispatch")) {
ENVOY_LOG_ONCE_IF(trace, abort_dispatch_ == nullptr,
"LoadShedPoint envoy.load_shed_points.http1_server_abort_dispatch is not "
"found. Is it configured?");
owned_output_buffer_->setWatermarks(connection.bufferLimit());
// Inform parent
output_buffer_ = owned_output_buffer_.get();
Expand Down
3 changes: 3 additions & 0 deletions source/common/http/http2/codec_impl.cc
Original file line number Diff line number Diff line change
Expand Up @@ -2056,6 +2056,9 @@ ServerConnectionImpl::ServerConnectionImpl(
callbacks_(callbacks), headers_with_underscores_action_(headers_with_underscores_action),
should_send_go_away_on_dispatch_(overload_manager.getLoadShedPoint(
"envoy.load_shed_points.http2_server_go_away_on_dispatch")) {
ENVOY_LOG_ONCE_IF(trace, should_send_go_away_on_dispatch_ == nullptr,
"LoadShedPoint envoy.load_shed_points.http2_server_go_away_on_dispatch is not "
"found. Is it configured?");
Http2Options h2_options(http2_options, max_request_headers_kb);

auto visitor = std::make_unique<http2::adapter::CallbackVisitor>(
Expand Down
3 changes: 3 additions & 0 deletions source/common/network/tcp_listener_impl.cc
Original file line number Diff line number Diff line change
Expand Up @@ -140,6 +140,9 @@ void TcpListenerImpl::configureLoadShedPoints(
Server::LoadShedPointProvider& load_shed_point_provider) {
listener_accept_ =
load_shed_point_provider.getLoadShedPoint("envoy.load_shed_points.tcp_listener_accept");
ENVOY_LOG_ONCE_MISC_IF(
trace, listener_accept_ == nullptr,
"LoadShedPoint envoy.load_shed_points.tcp_listener_accept is not found. Is it configured?");
}

} // namespace Network
Expand Down
1 change: 0 additions & 1 deletion source/server/overload_manager_impl.cc
Original file line number Diff line number Diff line change
Expand Up @@ -565,7 +565,6 @@ LoadShedPoint* OverloadManagerImpl::getLoadShedPoint(absl::string_view point_nam
if (auto it = loadshed_points_.find(point_name); it != loadshed_points_.end()) {
return it->second.get();
}
ENVOY_LOG(trace, "LoadShedPoint {} is not found. Is it configured?", point_name);
return nullptr;
}

Expand Down
37 changes: 37 additions & 0 deletions test/common/common/log_macros_test.cc
Original file line number Diff line number Diff line change
Expand Up @@ -213,6 +213,23 @@ class SparseLogMacrosTest : public testing::TestWithParam<bool>,
ENVOY_LOG_PERIODIC(error, 1s, "foo7 '{}'", evaluations()++);
}
}

void logOnceIf(bool condition) {
if (use_misc_macros_) {
ENVOY_LOG_ONCE_MISC_IF(error, condition, "foo8 '{}'", evaluations()++);
} else {
ENVOY_LOG_ONCE_IF(error, condition, "foo8 '{}'", evaluations()++);
}
}

void logSomethingThriceIf(bool condition) {
if (use_misc_macros_) {
ENVOY_LOG_FIRST_N_MISC_IF(error, 3, condition, "foo9 '{}'", evaluations()++);
} else {
ENVOY_LOG_FIRST_N_IF(error, 3, condition, "foo9 '{}'", evaluations()++);
}
}

std::atomic<int32_t>& evaluations() { MUTABLE_CONSTRUCT_ON_FIRST_USE(std::atomic<int32_t>); };

const bool use_misc_macros_;
Expand Down Expand Up @@ -271,6 +288,26 @@ TEST_P(SparseLogMacrosTest, All) {
// We shouldn't observe additional argument evaluations for log lines below the configured
// log level.
EXPECT_EQ(29, evaluations());

spamCall([this]() { logSomethingThriceIf(false); }, kNumThreads);
// As the condition was false the logs didn't evaluate.
EXPECT_EQ(29, evaluations());
spamCall([this]() { logOnceIf(false); }, kNumThreads);
// As the condition was false the logs didn't evaluate.
EXPECT_EQ(29, evaluations());

spamCall([this]() { logOnceIf(true); }, kNumThreads);
// First call evaluates.
EXPECT_EQ(30, evaluations());

// First and last call evaluates as the condition holds.
logSomethingThriceIf(true);
logSomethingThriceIf(false);
logSomethingThriceIf(true);
EXPECT_EQ(32, evaluations());
spamCall([this]() { logSomethingThriceIf(true); }, kNumThreads);
// Only one remaining log was left.
EXPECT_EQ(33, evaluations());
}

TEST(RegistryTest, LoggerWithName) {
Expand Down
8 changes: 3 additions & 5 deletions test/server/overload_manager_impl_test.cc
Original file line number Diff line number Diff line change
Expand Up @@ -955,7 +955,7 @@ TEST_F(OverloadManagerLoadShedPointImplTest, ThrowsIfDuplicateTrigger) {
"Duplicate trigger resource for LoadShedPoint .*");
}

TEST_F(OverloadManagerLoadShedPointImplTest, ShouldLogIfNonExistentLoadShedPointRequested) {
TEST_F(OverloadManagerLoadShedPointImplTest, ReturnsNullIfNonExistentLoadShedPointRequested) {
setDispatcherExpectation();
const std::string config = R"EOF(
resource_monitors:
Expand All @@ -970,10 +970,8 @@ TEST_F(OverloadManagerLoadShedPointImplTest, ShouldLogIfNonExistentLoadShedPoint

auto manager{createOverloadManager(config)};
manager->start();
EXPECT_LOG_CONTAINS("trace", "LoadShedPoint non_existent_point is not found", {
LoadShedPoint* point = manager->getLoadShedPoint("non_existent_point");
EXPECT_EQ(point, nullptr);
});
LoadShedPoint* point = manager->getLoadShedPoint("non_existent_point");
EXPECT_EQ(point, nullptr);
}

TEST_F(OverloadManagerLoadShedPointImplTest, PointUsesTriggerToDetermineWhetherToLoadShed) {
Expand Down