|
|
|
@ -22,12 +22,6 @@ |
|
|
|
|
#include <string> |
|
|
|
|
#include <utility> |
|
|
|
|
|
|
|
|
|
#include "absl/log/check.h" |
|
|
|
|
#include "absl/log/globals.h" |
|
|
|
|
#include "absl/log/log.h" |
|
|
|
|
#include "absl/log/log_entry.h" |
|
|
|
|
#include "absl/log/log_sink.h" |
|
|
|
|
#include "absl/log/log_sink_registry.h" |
|
|
|
|
#include "absl/strings/str_cat.h" |
|
|
|
|
#include "absl/strings/string_view.h" |
|
|
|
|
#include "absl/types/optional.h" |
|
|
|
@ -35,66 +29,57 @@ |
|
|
|
|
|
|
|
|
|
#include <grpc/grpc.h> |
|
|
|
|
#include <grpc/status.h> |
|
|
|
|
#include <grpc/support/log.h> |
|
|
|
|
|
|
|
|
|
#include "src/core/lib/debug/trace.h" |
|
|
|
|
#include "src/core/lib/gprpp/time.h" |
|
|
|
|
#include "test/core/end2end/end2end_tests.h" |
|
|
|
|
|
|
|
|
|
namespace grpc_core { |
|
|
|
|
void gpr_default_log(gpr_log_func_args* args); |
|
|
|
|
|
|
|
|
|
class VerifyLogNoiseLogSink : public absl::LogSink { |
|
|
|
|
namespace grpc_core { |
|
|
|
|
// This test is currently broken.
|
|
|
|
|
// The whole test will be re-written as a part of gpr to absl log conversion.
|
|
|
|
|
class Verifier { |
|
|
|
|
public: |
|
|
|
|
explicit VerifyLogNoiseLogSink(const absl::LogSeverityAtLeast severity, |
|
|
|
|
const int verbosity) { |
|
|
|
|
saved_absl_severity_ = absl::MinLogLevel(); |
|
|
|
|
absl::SetMinLogLevel(severity); |
|
|
|
|
// SetGlobalVLogLevel sets verbosity and returns previous verbosity.
|
|
|
|
|
saved_absl_verbosity_ = absl::SetGlobalVLogLevel(verbosity); |
|
|
|
|
grpc_tracer_set_enabled("all", false); |
|
|
|
|
absl::AddLogSink(this); |
|
|
|
|
Verifier() { |
|
|
|
|
if (gpr_should_log(GPR_LOG_SEVERITY_DEBUG)) { |
|
|
|
|
saved_severity_ = GPR_LOG_SEVERITY_DEBUG; |
|
|
|
|
} else if (gpr_should_log(GPR_LOG_SEVERITY_INFO)) { |
|
|
|
|
saved_severity_ = GPR_LOG_SEVERITY_INFO; |
|
|
|
|
} else if (gpr_should_log(GPR_LOG_SEVERITY_ERROR)) { |
|
|
|
|
saved_severity_ = GPR_LOG_SEVERITY_ERROR; |
|
|
|
|
} else { |
|
|
|
|
saved_severity_ = |
|
|
|
|
static_cast<gpr_log_severity>(GPR_LOG_SEVERITY_ERROR + 1); |
|
|
|
|
} |
|
|
|
|
grpc_tracer_set_enabled("all", 0); |
|
|
|
|
grpc_set_absl_verbosity_debug(); |
|
|
|
|
// This is broken. Replace with an absl log sink.
|
|
|
|
|
gpr_set_log_function(DispatchLog); |
|
|
|
|
} |
|
|
|
|
|
|
|
|
|
~VerifyLogNoiseLogSink() override { |
|
|
|
|
// Reverse everything done in the constructor.
|
|
|
|
|
absl::RemoveLogSink(this); |
|
|
|
|
~Verifier() { |
|
|
|
|
// This is broken. Replace with an absl log sink.
|
|
|
|
|
gpr_set_log_function(gpr_default_log); |
|
|
|
|
saved_trace_flags_.Restore(); |
|
|
|
|
absl::SetGlobalVLogLevel(saved_absl_verbosity_); |
|
|
|
|
absl::SetMinLogLevel(saved_absl_severity_); |
|
|
|
|
gpr_set_log_verbosity(saved_severity_); |
|
|
|
|
} |
|
|
|
|
Verifier(const Verifier&) = delete; |
|
|
|
|
Verifier& operator=(const Verifier&) = delete; |
|
|
|
|
|
|
|
|
|
// This function is called each time LOG or VLOG is called.
|
|
|
|
|
void Send(const absl::LogEntry& entry) override { |
|
|
|
|
if (entry.log_severity() > absl::LogSeverity::kInfo || |
|
|
|
|
entry.verbosity() < 1) { |
|
|
|
|
// For LOG(INFO) severity is INFO and verbosity is 0.
|
|
|
|
|
// For VLOG(n) severity is INFO and verbosity is n.
|
|
|
|
|
// LOG(INFO) and VLOG(0) have identical severity and verbosity.
|
|
|
|
|
// We check log noise for LOG(INFO), LOG(WARNING) and LOG(ERROR).
|
|
|
|
|
// We ignore VLOG(n) if (n>0) because we dont expect (n>0) in
|
|
|
|
|
// production systems.
|
|
|
|
|
CheckForNoisyLogs(entry); |
|
|
|
|
} |
|
|
|
|
} |
|
|
|
|
|
|
|
|
|
VerifyLogNoiseLogSink(const VerifyLogNoiseLogSink& other) = delete; |
|
|
|
|
VerifyLogNoiseLogSink& operator=(const VerifyLogNoiseLogSink& other) = delete; |
|
|
|
|
void FailOnAnyLog() { g_log_func_.store(NoLog); } |
|
|
|
|
void FailOnNonErrorLog() { g_log_func_.store(NoErrorLog); } |
|
|
|
|
|
|
|
|
|
private: |
|
|
|
|
void CheckForNoisyLogs(const absl::LogEntry& entry) { |
|
|
|
|
static void DispatchLog(gpr_log_func_args* args) { g_log_func_.load()(args); } |
|
|
|
|
|
|
|
|
|
static void NoLog(gpr_log_func_args* args) { |
|
|
|
|
static const auto* const allowed_logs_by_module = |
|
|
|
|
new std::map<absl::string_view, std::regex>( |
|
|
|
|
{{"cq_verifier.cc", std::regex("^Verify .* for [0-9]+ms")}, |
|
|
|
|
{"chttp2_transport.cc", |
|
|
|
|
std::regex("Sending goaway.*Channel Destroyed")}, |
|
|
|
|
{"config.cc", std::regex("gRPC experiments.*")}, |
|
|
|
|
{"chaotic_good_server.cc", |
|
|
|
|
std::regex("Failed to bind some addresses for.*")}, |
|
|
|
|
{"log.cc", |
|
|
|
|
std::regex("Prefer WARNING or ERROR. However if you see this " |
|
|
|
|
"message in a debug environmenmt or test environmenmt " |
|
|
|
|
"it is safe to ignore this message.")}}); |
|
|
|
|
|
|
|
|
|
absl::string_view filename = entry.source_filename(); |
|
|
|
|
std::regex("Sending goaway.*Channel Destroyed")}}); |
|
|
|
|
absl::string_view filename = args->file; |
|
|
|
|
auto slash = filename.rfind('/'); |
|
|
|
|
if (slash != absl::string_view::npos) { |
|
|
|
|
filename = filename.substr(slash + 1); |
|
|
|
@ -105,23 +90,30 @@ class VerifyLogNoiseLogSink : public absl::LogSink { |
|
|
|
|
} |
|
|
|
|
auto it = allowed_logs_by_module->find(filename); |
|
|
|
|
if (it != allowed_logs_by_module->end() && |
|
|
|
|
std::regex_search(std::string(entry.text_message()), it->second)) { |
|
|
|
|
std::regex_search(args->message, it->second)) { |
|
|
|
|
gpr_default_log(args); |
|
|
|
|
return; |
|
|
|
|
} |
|
|
|
|
CHECK(false) << "Unwanted log: Either change to VLOG(2) or add it to " |
|
|
|
|
"allowed_logs_by_module " |
|
|
|
|
<< entry.source_filename() << ":" << entry.source_line() << " " |
|
|
|
|
<< entry.text_message(); |
|
|
|
|
std::string message = absl::StrCat("Unwanted log: ", args->message); |
|
|
|
|
args->message = message.c_str(); |
|
|
|
|
gpr_default_log(args); |
|
|
|
|
GTEST_FAIL(); |
|
|
|
|
} |
|
|
|
|
absl::LogSeverityAtLeast saved_absl_severity_; |
|
|
|
|
int saved_absl_verbosity_; |
|
|
|
|
|
|
|
|
|
static void NoErrorLog(gpr_log_func_args* args) { |
|
|
|
|
if (args->severity == GPR_LOG_SEVERITY_ERROR) { |
|
|
|
|
NoLog(args); |
|
|
|
|
} |
|
|
|
|
} |
|
|
|
|
|
|
|
|
|
gpr_log_severity saved_severity_; |
|
|
|
|
SavedTraceFlags saved_trace_flags_; |
|
|
|
|
static std::atomic<gpr_log_func> g_log_func_; |
|
|
|
|
}; |
|
|
|
|
|
|
|
|
|
void SimpleRequest(CoreEnd2endTest& test) { |
|
|
|
|
VLOG(1) << "If the test fails here, the test is broken because it is not " |
|
|
|
|
"able to differentiate between LOG(INFO) and VLOG(1)"; |
|
|
|
|
std::atomic<gpr_log_func> Verifier::g_log_func_(gpr_default_log); |
|
|
|
|
|
|
|
|
|
void SimpleRequest(CoreEnd2endTest& test) { |
|
|
|
|
auto c = test.NewClientCall("/foo").Timeout(Duration::Seconds(5)).Create(); |
|
|
|
|
EXPECT_NE(c.GetPeer(), absl::nullopt); |
|
|
|
|
IncomingMetadata server_initial_metadata; |
|
|
|
@ -151,7 +143,7 @@ void SimpleRequest(CoreEnd2endTest& test) { |
|
|
|
|
} |
|
|
|
|
|
|
|
|
|
CORE_END2END_TEST(NoLoggingTest, NoLoggingTest) { |
|
|
|
|
// This test makes sure that we don't get log noise when making an rpc
|
|
|
|
|
// This test makes sure that we dont get spammy logs when making an rpc
|
|
|
|
|
// especially when rpcs are successful.
|
|
|
|
|
|
|
|
|
|
// TODO(hork): remove when the listener flake is identified
|
|
|
|
@ -160,9 +152,13 @@ CORE_END2END_TEST(NoLoggingTest, NoLoggingTest) { |
|
|
|
|
GTEST_SKIP() << "not for windows + event engine listener"; |
|
|
|
|
} |
|
|
|
|
#endif |
|
|
|
|
VerifyLogNoiseLogSink nolog_verifier(absl::LogSeverityAtLeast::kInfo, 2); |
|
|
|
|
Verifier verifier; |
|
|
|
|
verifier.FailOnNonErrorLog(); |
|
|
|
|
for (int i = 0; i < 10; i++) { |
|
|
|
|
SimpleRequest(*this); |
|
|
|
|
} |
|
|
|
|
verifier.FailOnAnyLog(); |
|
|
|
|
SimpleRequest(*this); |
|
|
|
|
} |
|
|
|
|
|
|
|
|
|
} // namespace grpc_core
|
|
|
|
|