diff --git a/src/core/lib/iomgr/ev_posix.cc b/src/core/lib/iomgr/ev_posix.cc index 06551a93cb7..d7206d421cf 100644 --- a/src/core/lib/iomgr/ev_posix.cc +++ b/src/core/lib/iomgr/ev_posix.cc @@ -104,7 +104,8 @@ static void try_engine(absl::string_view engine) { if (g_vtables[i] != nullptr && is(engine, g_vtables[i]->name) && g_vtables[i]->check_engine_available(engine == g_vtables[i]->name)) { g_event_engine = g_vtables[i]; - VLOG(2) << "Using polling engine: " << g_event_engine->name; + GRPC_TRACE_VLOG(polling_api, 2) + << "Using polling engine: " << g_event_engine->name; return; } } diff --git a/src/core/util/log.cc b/src/core/util/log.cc index ca89ba97a99..b7c437a87fa 100644 --- a/src/core/util/log.cc +++ b/src/core/util/log.cc @@ -98,7 +98,6 @@ void gpr_log_verbosity_init(void) { // This setting will change things for other libraries/code that is unrelated // to grpc. absl::string_view verbosity = grpc_core::ConfigVars::Get().Verbosity(); - DVLOG(2) << "Log verbosity: " << verbosity; if (absl::EqualsIgnoreCase(verbosity, "INFO")) { LOG_FIRST_N(WARNING, 1) << "Log level INFO is not suitable for production. Prefer WARNING or " diff --git a/test/core/end2end/tests/no_logging.cc b/test/core/end2end/tests/no_logging.cc index faf53c2e1c7..3091c5dfd69 100644 --- a/test/core/end2end/tests/no_logging.cc +++ b/test/core/end2end/tests/no_logging.cc @@ -22,6 +22,12 @@ #include #include +#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" @@ -29,53 +35,79 @@ #include #include -#include #include "src/core/lib/debug/trace.h" #include "src/core/lib/gprpp/time.h" #include "test/core/end2end/end2end_tests.h" 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 { + +class VerifyLogNoiseLogSink : public absl::LogSink { public: - 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_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); + explicit VerifyLogNoiseLogSink(const absl::LogSeverityAtLeast severity, + const int verbosity) + : log_noise_absent_(true) { + 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() { - // This is broken. Replace with an absl log sink. + + ~VerifyLogNoiseLogSink() override { + CHECK(log_noise_absent_) + << "Unwanted logs present. This will cause log noise. Either user a " + "tracer (example GRPC_TRACE_LOG or GRPC_TRACE_VLOG) or convert the " + "statement to VLOG(2)."; + // Reverse everything done in the constructor. + absl::RemoveLogSink(this); saved_trace_flags_.Restore(); + absl::SetGlobalVLogLevel(saved_absl_verbosity_); + absl::SetMinLogLevel(saved_absl_severity_); } - Verifier(const Verifier&) = delete; - Verifier& operator=(const Verifier&) = delete; - void FailOnAnyLog() { g_log_func_.store(NoLog); } - void FailOnNonErrorLog() { g_log_func_.store(NoErrorLog); } + // This function is called each time LOG or VLOG is called. + void Send(const absl::LogEntry& entry) override { CheckForNoisyLogs(entry); } + + VerifyLogNoiseLogSink(const VerifyLogNoiseLogSink& other) = delete; + VerifyLogNoiseLogSink& operator=(const VerifyLogNoiseLogSink& other) = delete; private: - static void DispatchLog(gpr_log_func_args* args) { g_log_func_.load()(args); } + bool IsVlogWithVerbosityMoreThan1(const absl::LogEntry& entry) const { + return entry.log_severity() == absl::LogSeverity::kInfo && + entry.verbosity() >= 1; + } - static void NoLog(gpr_log_func_args* args) { + void CheckForNoisyLogs(const absl::LogEntry& entry) { + // TODO(tjagtap) : Add a hard upper limit on number of times each log should + // appear. We can keep this number slightly higher to avoid our tests + // becoming flaky. Right now all entries in this list get a free pass to log + // infinitely - That may create log noise issues in the future. + // + // This list is an allow list of all LOG(INFO), LOG(WARNING), and LOG(ERROR) + // logs which will appear. For now we have decided to allow these instances. + // We should be very conservative while adding new entries to this list, + // because this has potential to cause massive log noise. Several users are + // using INFO log level setting for production. static const auto* const allowed_logs_by_module = new std::map( {{"cq_verifier.cc", std::regex("^Verify .* for [0-9]+ms")}, {"chttp2_transport.cc", - std::regex("Sending goaway.*Channel Destroyed")}}); - absl::string_view filename = args->file; + 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.")}}); + + if (IsVlogWithVerbosityMoreThan1(entry)) { + return; + } + + absl::string_view filename = entry.source_filename(); auto slash = filename.rfind('/'); if (slash != absl::string_view::npos) { filename = filename.substr(slash + 1); @@ -86,27 +118,23 @@ class Verifier { } auto it = allowed_logs_by_module->find(filename); if (it != allowed_logs_by_module->end() && - std::regex_search(args->message, it->second)) { + std::regex_search(std::string(entry.text_message()), it->second)) { return; } - std::string message = absl::StrCat("Unwanted log: ", args->message); - args->message = message.c_str(); - GTEST_FAIL(); - } - static void NoErrorLog(gpr_log_func_args* args) { - if (args->severity == GPR_LOG_SEVERITY_ERROR) { - NoLog(args); - } + // If we reach here means we have log noise. log_noise_absent_ will make the + // test fail. + log_noise_absent_ = false; + LOG(ERROR) << "Unwanted log at location : " << entry.source_filename() + << ":" << entry.source_line() << " " << entry.text_message(); } - gpr_log_severity saved_severity_; + absl::LogSeverityAtLeast saved_absl_severity_; + int saved_absl_verbosity_; SavedTraceFlags saved_trace_flags_; - static std::atomic g_log_func_; + bool log_noise_absent_; }; -std::atomic Verifier::g_log_func_(NoErrorLog); - void SimpleRequest(CoreEnd2endTest& test) { auto c = test.NewClientCall("/foo").Timeout(Duration::Seconds(5)).Create(); EXPECT_NE(c.GetPeer(), absl::nullopt); @@ -137,7 +165,7 @@ void SimpleRequest(CoreEnd2endTest& test) { } CORE_END2END_TEST(NoLoggingTest, NoLoggingTest) { -// This test makes sure that we dont get spammy logs when making an rpc +// This test makes sure that we don't get log noise when making an rpc // especially when rpcs are successful. // TODO(hork): remove when the listener flake is identified @@ -146,13 +174,10 @@ CORE_END2END_TEST(NoLoggingTest, NoLoggingTest) { GTEST_SKIP() << "not for windows + event engine listener"; } #endif - Verifier verifier; - verifier.FailOnNonErrorLog(); + VerifyLogNoiseLogSink nolog_verifier(absl::LogSeverityAtLeast::kInfo, 2); for (int i = 0; i < 10; i++) { SimpleRequest(*this); } - verifier.FailOnAnyLog(); - SimpleRequest(*this); } } // namespace grpc_core