1 //
2 //
3 // Copyright 2016 gRPC authors.
4 //
5 // Licensed under the Apache License, Version 2.0 (the "License");
6 // you may not use this file except in compliance with the License.
7 // You may obtain a copy of the License at
8 //
9 // http://www.apache.org/licenses/LICENSE-2.0
10 //
11 // Unless required by applicable law or agreed to in writing, software
12 // distributed under the License is distributed on an "AS IS" BASIS,
13 // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
14 // See the License for the specific language governing permissions and
15 // limitations under the License.
16 //
17 //
18
19 #include <grpc/grpc.h>
20 #include <grpc/status.h>
21
22 #include <atomic>
23 #include <map>
24 #include <regex>
25 #include <string>
26 #include <utility>
27
28 #include "absl/log/check.h"
29 #include "absl/log/globals.h"
30 #include "absl/log/log.h"
31 #include "absl/log/log_entry.h"
32 #include "absl/log/log_sink.h"
33 #include "absl/log/log_sink_registry.h"
34 #include "absl/strings/str_cat.h"
35 #include "absl/strings/string_view.h"
36 #include "absl/types/optional.h"
37 #include "gtest/gtest.h"
38 #include "src/core/lib/debug/trace.h"
39 #include "src/core/util/time.h"
40 #include "test/core/end2end/end2end_tests.h"
41
42 namespace grpc_core {
43
44 class VerifyLogNoiseLogSink : public absl::LogSink {
45 public:
VerifyLogNoiseLogSink(const absl::LogSeverityAtLeast severity,const int verbosity)46 explicit VerifyLogNoiseLogSink(const absl::LogSeverityAtLeast severity,
47 const int verbosity)
48 : log_noise_absent_(true) {
49 saved_absl_severity_ = absl::MinLogLevel();
50 absl::SetMinLogLevel(severity);
51 // SetGlobalVLogLevel sets verbosity and returns previous verbosity.
52 saved_absl_verbosity_ = absl::SetGlobalVLogLevel(verbosity);
53 grpc_tracer_set_enabled("all", false);
54 absl::AddLogSink(this);
55 }
56
~VerifyLogNoiseLogSink()57 ~VerifyLogNoiseLogSink() override {
58 CHECK(log_noise_absent_)
59 << "Unwanted logs present. This will cause log noise. Either user a "
60 "tracer (example GRPC_TRACE_LOG or GRPC_TRACE_VLOG) or convert the "
61 "statement to VLOG(2).";
62 // Reverse everything done in the constructor.
63 absl::RemoveLogSink(this);
64 saved_trace_flags_.Restore();
65 absl::SetGlobalVLogLevel(saved_absl_verbosity_);
66 absl::SetMinLogLevel(saved_absl_severity_);
67 }
68
69 // This function is called each time LOG or VLOG is called.
Send(const absl::LogEntry & entry)70 void Send(const absl::LogEntry& entry) override { CheckForNoisyLogs(entry); }
71
72 VerifyLogNoiseLogSink(const VerifyLogNoiseLogSink& other) = delete;
73 VerifyLogNoiseLogSink& operator=(const VerifyLogNoiseLogSink& other) = delete;
74
75 private:
IsVlogWithVerbosityMoreThan1(const absl::LogEntry & entry) const76 bool IsVlogWithVerbosityMoreThan1(const absl::LogEntry& entry) const {
77 return entry.log_severity() == absl::LogSeverity::kInfo &&
78 entry.verbosity() >= 1;
79 }
80
CheckForNoisyLogs(const absl::LogEntry & entry)81 void CheckForNoisyLogs(const absl::LogEntry& entry) {
82 // TODO(tjagtap) : Add a hard upper limit on number of times each log should
83 // appear. We can keep this number slightly higher to avoid our tests
84 // becoming flaky. Right now all entries in this list get a free pass to log
85 // infinitely - That may create log noise issues in the future.
86 //
87 // This list is an allow list of all LOG(INFO), LOG(WARNING), and LOG(ERROR)
88 // logs which will appear. For now we have decided to allow these instances.
89 // We should be very conservative while adding new entries to this list,
90 // because this has potential to cause massive log noise. Several users are
91 // using INFO log level setting for production.
92 static const auto* const allowed_logs_by_module =
93 new std::map<absl::string_view, std::regex>(
94 {{"cq_verifier.cc", std::regex("^Verify .* for [0-9]+ms")},
95 {"chaotic_good_server.cc",
96 std::regex("Failed to bind some addresses for.*")},
97 {"log.cc",
98 std::regex("Prefer WARNING or ERROR. However if you see this "
99 "message in a debug environment or test environment "
100 "it is safe to ignore this message.")}});
101
102 if (IsVlogWithVerbosityMoreThan1(entry)) {
103 return;
104 }
105
106 absl::string_view filename = entry.source_filename();
107 auto slash = filename.rfind('/');
108 if (slash != absl::string_view::npos) {
109 filename = filename.substr(slash + 1);
110 }
111 slash = filename.rfind('\\');
112 if (slash != absl::string_view::npos) {
113 filename = filename.substr(slash + 1);
114 }
115 auto it = allowed_logs_by_module->find(filename);
116 if (it != allowed_logs_by_module->end() &&
117 std::regex_search(std::string(entry.text_message()), it->second)) {
118 return;
119 }
120
121 // If we reach here means we have log noise. log_noise_absent_ will make the
122 // test fail.
123 log_noise_absent_ = false;
124 LOG(ERROR) << "�� Unwanted log at location : " << entry.source_filename()
125 << ":" << entry.source_line() << " " << entry.text_message();
126 }
127
128 absl::LogSeverityAtLeast saved_absl_severity_;
129 int saved_absl_verbosity_;
130 SavedTraceFlags saved_trace_flags_;
131 bool log_noise_absent_;
132 };
133
SimpleRequest(CoreEnd2endTest & test)134 void SimpleRequest(CoreEnd2endTest& test) {
135 auto c = test.NewClientCall("/foo").Timeout(Duration::Seconds(5)).Create();
136 EXPECT_NE(c.GetPeer(), absl::nullopt);
137 IncomingMetadata server_initial_metadata;
138 IncomingStatusOnClient server_status;
139 c.NewBatch(1)
140 .SendInitialMetadata({})
141 .SendCloseFromClient()
142 .RecvInitialMetadata(server_initial_metadata)
143 .RecvStatusOnClient(server_status);
144 auto s = test.RequestCall(101);
145 test.Expect(101, true);
146 test.Step();
147 EXPECT_NE(c.GetPeer(), absl::nullopt);
148 EXPECT_NE(s.GetPeer(), absl::nullopt);
149 IncomingCloseOnServer client_close;
150 s.NewBatch(102)
151 .SendInitialMetadata({})
152 .SendStatusFromServer(GRPC_STATUS_UNIMPLEMENTED, "xyz", {})
153 .RecvCloseOnServer(client_close);
154 test.Expect(102, true);
155 test.Expect(1, true);
156 test.Step();
157 EXPECT_EQ(server_status.status(), GRPC_STATUS_UNIMPLEMENTED);
158 EXPECT_EQ(server_status.message(), "xyz");
159 EXPECT_EQ(s.method(), "/foo");
160 EXPECT_FALSE(client_close.was_cancelled());
161 }
162
CORE_END2END_TEST(NoLoggingTest,NoLoggingTest)163 CORE_END2END_TEST(NoLoggingTest, NoLoggingTest) {
164 // This test makes sure that we don't get log noise when making an rpc
165 // especially when rpcs are successful.
166
167 // TODO(hork): remove when the listener flake is identified
168 #ifdef GPR_WINDOWS
169 if (IsEventEngineListenerEnabled()) {
170 GTEST_SKIP() << "not for windows + event engine listener";
171 }
172 #endif
173 VerifyLogNoiseLogSink nolog_verifier(absl::LogSeverityAtLeast::kInfo, 2);
174 for (int i = 0; i < 10; i++) {
175 SimpleRequest(*this);
176 }
177 }
178
179 } // namespace grpc_core
180