1 //
2 // Copyright 2022 The Abseil Authors.
3 //
4 // Licensed under the Apache License, Version 2.0 (the "License");
5 // you may not use this file except in compliance with the License.
6 // You may obtain a copy of the License at
7 //
8 // https://www.apache.org/licenses/LICENSE-2.0
9 //
10 // Unless required by applicable law or agreed to in writing, software
11 // distributed under the License is distributed on an "AS IS" BASIS,
12 // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 // See the License for the specific language governing permissions and
14 // limitations under the License.
15
16 #include "absl/log/log_sink.h"
17
18 #include "gmock/gmock.h"
19 #include "gtest/gtest.h"
20 #include "absl/base/attributes.h"
21 #include "absl/log/internal/test_actions.h"
22 #include "absl/log/internal/test_helpers.h"
23 #include "absl/log/internal/test_matchers.h"
24 #include "absl/log/log.h"
25 #include "absl/log/log_sink_registry.h"
26 #include "absl/log/scoped_mock_log.h"
27 #include "absl/strings/string_view.h"
28
29 namespace {
30
31 using ::absl::log_internal::DeathTestExpectedLogging;
32 using ::absl::log_internal::DeathTestUnexpectedLogging;
33 using ::absl::log_internal::DeathTestValidateExpectations;
34 using ::absl::log_internal::DiedOfFatal;
35 using ::testing::_;
36 using ::testing::AnyNumber;
37 using ::testing::HasSubstr;
38 using ::testing::InSequence;
39
40 auto* test_env ABSL_ATTRIBUTE_UNUSED = ::testing::AddGlobalTestEnvironment(
41 new absl::log_internal::LogTestEnvironment);
42
43 // Tests for global log sink registration.
44 // ---------------------------------------
45
TEST(LogSinkRegistryTest,AddLogSink)46 TEST(LogSinkRegistryTest, AddLogSink) {
47 absl::ScopedMockLog test_sink(absl::MockLogDefault::kDisallowUnexpected);
48
49 InSequence s;
50 EXPECT_CALL(test_sink, Log(_, _, "hello world")).Times(0);
51 EXPECT_CALL(test_sink, Log(absl::LogSeverity::kInfo, __FILE__, "Test : 42"));
52 EXPECT_CALL(test_sink,
53 Log(absl::LogSeverity::kWarning, __FILE__, "Danger ahead"));
54 EXPECT_CALL(test_sink,
55 Log(absl::LogSeverity::kError, __FILE__, "This is an error"));
56
57 LOG(INFO) << "hello world";
58 test_sink.StartCapturingLogs();
59
60 LOG(INFO) << "Test : " << 42;
61 LOG(WARNING) << "Danger" << ' ' << "ahead";
62 LOG(ERROR) << "This is an error";
63
64 test_sink.StopCapturingLogs();
65 LOG(INFO) << "Goodby world";
66 }
67
TEST(LogSinkRegistryTest,MultipleLogSinks)68 TEST(LogSinkRegistryTest, MultipleLogSinks) {
69 absl::ScopedMockLog test_sink1(absl::MockLogDefault::kDisallowUnexpected);
70 absl::ScopedMockLog test_sink2(absl::MockLogDefault::kDisallowUnexpected);
71
72 ::testing::InSequence seq;
73 EXPECT_CALL(test_sink1, Log(absl::LogSeverity::kInfo, _, "First")).Times(1);
74 EXPECT_CALL(test_sink2, Log(absl::LogSeverity::kInfo, _, "First")).Times(0);
75
76 EXPECT_CALL(test_sink1, Log(absl::LogSeverity::kInfo, _, "Second")).Times(1);
77 EXPECT_CALL(test_sink2, Log(absl::LogSeverity::kInfo, _, "Second")).Times(1);
78
79 EXPECT_CALL(test_sink1, Log(absl::LogSeverity::kInfo, _, "Third")).Times(0);
80 EXPECT_CALL(test_sink2, Log(absl::LogSeverity::kInfo, _, "Third")).Times(1);
81
82 LOG(INFO) << "Before first";
83
84 test_sink1.StartCapturingLogs();
85 LOG(INFO) << "First";
86
87 test_sink2.StartCapturingLogs();
88 LOG(INFO) << "Second";
89
90 test_sink1.StopCapturingLogs();
91 LOG(INFO) << "Third";
92
93 test_sink2.StopCapturingLogs();
94 LOG(INFO) << "Fourth";
95 }
96
TEST(LogSinkRegistrationDeathTest,DuplicateSinkRegistration)97 TEST(LogSinkRegistrationDeathTest, DuplicateSinkRegistration) {
98 ASSERT_DEATH_IF_SUPPORTED(
99 {
100 absl::ScopedMockLog sink;
101 sink.StartCapturingLogs();
102 absl::AddLogSink(&sink.UseAsLocalSink());
103 },
104 HasSubstr("Duplicate log sinks"));
105 }
106
TEST(LogSinkRegistrationDeathTest,MismatchSinkRemoval)107 TEST(LogSinkRegistrationDeathTest, MismatchSinkRemoval) {
108 ASSERT_DEATH_IF_SUPPORTED(
109 {
110 absl::ScopedMockLog sink;
111 absl::RemoveLogSink(&sink.UseAsLocalSink());
112 },
113 HasSubstr("Mismatched log sink"));
114 }
115
116 // Tests for log sink semantic.
117 // ---------------------------------------
118
TEST(LogSinkTest,FlushSinks)119 TEST(LogSinkTest, FlushSinks) {
120 absl::ScopedMockLog test_sink(absl::MockLogDefault::kDisallowUnexpected);
121
122 EXPECT_CALL(test_sink, Flush()).Times(2);
123
124 test_sink.StartCapturingLogs();
125
126 absl::FlushLogSinks();
127 absl::FlushLogSinks();
128 }
129
TEST(LogSinkDeathTest,DeathInSend)130 TEST(LogSinkDeathTest, DeathInSend) {
131 class FatalSendSink : public absl::LogSink {
132 public:
133 void Send(const absl::LogEntry&) override { LOG(FATAL) << "goodbye world"; }
134 };
135
136 FatalSendSink sink;
137 EXPECT_EXIT({ LOG(INFO).ToSinkAlso(&sink) << "hello world"; }, DiedOfFatal,
138 _);
139 }
140
141 // Tests for explicit log sink redirection.
142 // ---------------------------------------
143
TEST(LogSinkTest,ToSinkAlso)144 TEST(LogSinkTest, ToSinkAlso) {
145 absl::ScopedMockLog test_sink(absl::MockLogDefault::kDisallowUnexpected);
146 absl::ScopedMockLog another_sink(absl::MockLogDefault::kDisallowUnexpected);
147 EXPECT_CALL(test_sink, Log(_, _, "hello world"));
148 EXPECT_CALL(another_sink, Log(_, _, "hello world"));
149
150 test_sink.StartCapturingLogs();
151 LOG(INFO).ToSinkAlso(&another_sink.UseAsLocalSink()) << "hello world";
152 }
153
TEST(LogSinkTest,ToSinkOnly)154 TEST(LogSinkTest, ToSinkOnly) {
155 absl::ScopedMockLog another_sink(absl::MockLogDefault::kDisallowUnexpected);
156 EXPECT_CALL(another_sink, Log(_, _, "hello world"));
157 LOG(INFO).ToSinkOnly(&another_sink.UseAsLocalSink()) << "hello world";
158 }
159
TEST(LogSinkTest,ToManySinks)160 TEST(LogSinkTest, ToManySinks) {
161 absl::ScopedMockLog sink1(absl::MockLogDefault::kDisallowUnexpected);
162 absl::ScopedMockLog sink2(absl::MockLogDefault::kDisallowUnexpected);
163 absl::ScopedMockLog sink3(absl::MockLogDefault::kDisallowUnexpected);
164 absl::ScopedMockLog sink4(absl::MockLogDefault::kDisallowUnexpected);
165 absl::ScopedMockLog sink5(absl::MockLogDefault::kDisallowUnexpected);
166
167 EXPECT_CALL(sink3, Log(_, _, "hello world"));
168 EXPECT_CALL(sink4, Log(_, _, "hello world"));
169 EXPECT_CALL(sink5, Log(_, _, "hello world"));
170
171 LOG(INFO)
172 .ToSinkAlso(&sink1.UseAsLocalSink())
173 .ToSinkAlso(&sink2.UseAsLocalSink())
174 .ToSinkOnly(&sink3.UseAsLocalSink())
175 .ToSinkAlso(&sink4.UseAsLocalSink())
176 .ToSinkAlso(&sink5.UseAsLocalSink())
177 << "hello world";
178 }
179
180 class ReentrancyTest : public ::testing::Test {
181 protected:
182 ReentrancyTest() = default;
183 enum class LogMode : int { kNormal, kToSinkAlso, kToSinkOnly };
184
185 class ReentrantSendLogSink : public absl::LogSink {
186 public:
ReentrantSendLogSink(absl::LogSeverity severity,absl::LogSink * sink,LogMode mode)187 explicit ReentrantSendLogSink(absl::LogSeverity severity,
188 absl::LogSink* sink, LogMode mode)
189 : severity_(severity), sink_(sink), mode_(mode) {}
ReentrantSendLogSink(absl::LogSeverity severity)190 explicit ReentrantSendLogSink(absl::LogSeverity severity)
191 : ReentrantSendLogSink(severity, nullptr, LogMode::kNormal) {}
192
Send(const absl::LogEntry &)193 void Send(const absl::LogEntry&) override {
194 switch (mode_) {
195 case LogMode::kNormal:
196 LOG(LEVEL(severity_)) << "The log is coming from *inside the sink*.";
197 break;
198 case LogMode::kToSinkAlso:
199 LOG(LEVEL(severity_)).ToSinkAlso(sink_)
200 << "The log is coming from *inside the sink*.";
201 break;
202 case LogMode::kToSinkOnly:
203 LOG(LEVEL(severity_)).ToSinkOnly(sink_)
204 << "The log is coming from *inside the sink*.";
205 break;
206 default:
207 LOG(FATAL) << "Invalid mode " << static_cast<int>(mode_);
208 }
209 }
210
211 private:
212 absl::LogSeverity severity_;
213 absl::LogSink* sink_;
214 LogMode mode_;
215 };
216
LogAndReturn(absl::LogSeverity severity,absl::string_view to_log,absl::string_view to_return)217 static absl::string_view LogAndReturn(absl::LogSeverity severity,
218 absl::string_view to_log,
219 absl::string_view to_return) {
220 LOG(LEVEL(severity)) << to_log;
221 return to_return;
222 }
223 };
224
TEST_F(ReentrancyTest,LogFunctionThatLogs)225 TEST_F(ReentrancyTest, LogFunctionThatLogs) {
226 absl::ScopedMockLog test_sink(absl::MockLogDefault::kDisallowUnexpected);
227
228 InSequence seq;
229 EXPECT_CALL(test_sink, Log(absl::LogSeverity::kInfo, _, "hello"));
230 EXPECT_CALL(test_sink, Log(absl::LogSeverity::kInfo, _, "world"));
231 EXPECT_CALL(test_sink, Log(absl::LogSeverity::kWarning, _, "danger"));
232 EXPECT_CALL(test_sink, Log(absl::LogSeverity::kInfo, _, "here"));
233
234 test_sink.StartCapturingLogs();
235 LOG(INFO) << LogAndReturn(absl::LogSeverity::kInfo, "hello", "world");
236 LOG(INFO) << LogAndReturn(absl::LogSeverity::kWarning, "danger", "here");
237 }
238
TEST_F(ReentrancyTest,RegisteredLogSinkThatLogsInSend)239 TEST_F(ReentrancyTest, RegisteredLogSinkThatLogsInSend) {
240 absl::ScopedMockLog test_sink(absl::MockLogDefault::kDisallowUnexpected);
241 ReentrantSendLogSink renentrant_sink(absl::LogSeverity::kInfo);
242 EXPECT_CALL(test_sink, Log(_, _, "hello world"));
243
244 test_sink.StartCapturingLogs();
245 absl::AddLogSink(&renentrant_sink);
246 LOG(INFO) << "hello world";
247 absl::RemoveLogSink(&renentrant_sink);
248 }
249
TEST_F(ReentrancyTest,AlsoLogSinkThatLogsInSend)250 TEST_F(ReentrancyTest, AlsoLogSinkThatLogsInSend) {
251 absl::ScopedMockLog test_sink(absl::MockLogDefault::kDisallowUnexpected);
252 ReentrantSendLogSink reentrant_sink(absl::LogSeverity::kInfo);
253 EXPECT_CALL(test_sink, Log(_, _, "hello world"));
254 EXPECT_CALL(test_sink,
255 Log(_, _, "The log is coming from *inside the sink*."));
256
257 test_sink.StartCapturingLogs();
258 LOG(INFO).ToSinkAlso(&reentrant_sink) << "hello world";
259 }
260
TEST_F(ReentrancyTest,RegisteredAlsoLogSinkThatLogsInSend)261 TEST_F(ReentrancyTest, RegisteredAlsoLogSinkThatLogsInSend) {
262 absl::ScopedMockLog test_sink(absl::MockLogDefault::kDisallowUnexpected);
263 ReentrantSendLogSink reentrant_sink(absl::LogSeverity::kInfo);
264 EXPECT_CALL(test_sink, Log(_, _, "hello world"));
265 // We only call into the test_log sink once with this message, since the
266 // second time log statement is run we are in "ThreadIsLogging" mode and all
267 // the log statements are redirected into stderr.
268 EXPECT_CALL(test_sink,
269 Log(_, _, "The log is coming from *inside the sink*."));
270
271 test_sink.StartCapturingLogs();
272 absl::AddLogSink(&reentrant_sink);
273 LOG(INFO).ToSinkAlso(&reentrant_sink) << "hello world";
274 absl::RemoveLogSink(&reentrant_sink);
275 }
276
TEST_F(ReentrancyTest,OnlyLogSinkThatLogsInSend)277 TEST_F(ReentrancyTest, OnlyLogSinkThatLogsInSend) {
278 absl::ScopedMockLog test_sink(absl::MockLogDefault::kDisallowUnexpected);
279 ReentrantSendLogSink reentrant_sink(absl::LogSeverity::kInfo);
280 EXPECT_CALL(test_sink,
281 Log(_, _, "The log is coming from *inside the sink*."));
282
283 test_sink.StartCapturingLogs();
284 LOG(INFO).ToSinkOnly(&reentrant_sink) << "hello world";
285 }
286
TEST_F(ReentrancyTest,RegisteredOnlyLogSinkThatLogsInSend)287 TEST_F(ReentrancyTest, RegisteredOnlyLogSinkThatLogsInSend) {
288 absl::ScopedMockLog test_sink(absl::MockLogDefault::kDisallowUnexpected);
289 ReentrantSendLogSink reentrant_sink(absl::LogSeverity::kInfo);
290 EXPECT_CALL(test_sink,
291 Log(_, _, "The log is coming from *inside the sink*."));
292
293 test_sink.StartCapturingLogs();
294 absl::AddLogSink(&reentrant_sink);
295 LOG(INFO).ToSinkOnly(&reentrant_sink) << "hello world";
296 absl::RemoveLogSink(&reentrant_sink);
297 }
298
299 using ReentrancyDeathTest = ReentrancyTest;
300
TEST_F(ReentrancyDeathTest,LogFunctionThatLogsFatal)301 TEST_F(ReentrancyDeathTest, LogFunctionThatLogsFatal) {
302 EXPECT_EXIT(
303 {
304 absl::ScopedMockLog test_sink;
305
306 EXPECT_CALL(test_sink, Log)
307 .Times(AnyNumber())
308 .WillRepeatedly(DeathTestUnexpectedLogging());
309 EXPECT_CALL(test_sink, Log(_, _, "hello"))
310 .WillOnce(DeathTestExpectedLogging());
311
312 test_sink.StartCapturingLogs();
313 LOG(INFO) << LogAndReturn(absl::LogSeverity::kFatal, "hello", "world");
314 },
315 DiedOfFatal, DeathTestValidateExpectations());
316 }
317
TEST_F(ReentrancyDeathTest,RegisteredLogSinkThatLogsFatalInSend)318 TEST_F(ReentrancyDeathTest, RegisteredLogSinkThatLogsFatalInSend) {
319 EXPECT_EXIT(
320 {
321 absl::ScopedMockLog test_sink;
322 ReentrantSendLogSink reentrant_sink(absl::LogSeverity::kFatal);
323 EXPECT_CALL(test_sink, Log)
324 .Times(AnyNumber())
325 .WillRepeatedly(DeathTestUnexpectedLogging());
326 EXPECT_CALL(test_sink, Log(_, _, "hello world"))
327 .WillOnce(DeathTestExpectedLogging());
328
329 test_sink.StartCapturingLogs();
330 absl::AddLogSink(&reentrant_sink);
331 LOG(INFO) << "hello world";
332 // No need to call RemoveLogSink - process is dead at this point.
333 },
334 DiedOfFatal, DeathTestValidateExpectations());
335 }
336
TEST_F(ReentrancyDeathTest,AlsoLogSinkThatLogsFatalInSend)337 TEST_F(ReentrancyDeathTest, AlsoLogSinkThatLogsFatalInSend) {
338 EXPECT_EXIT(
339 {
340 absl::ScopedMockLog test_sink;
341 ReentrantSendLogSink reentrant_sink(absl::LogSeverity::kFatal);
342
343 EXPECT_CALL(test_sink, Log)
344 .Times(AnyNumber())
345 .WillRepeatedly(DeathTestUnexpectedLogging());
346 EXPECT_CALL(test_sink, Log(_, _, "hello world"))
347 .WillOnce(DeathTestExpectedLogging());
348 EXPECT_CALL(test_sink,
349 Log(_, _, "The log is coming from *inside the sink*."))
350 .WillOnce(DeathTestExpectedLogging());
351
352 test_sink.StartCapturingLogs();
353 LOG(INFO).ToSinkAlso(&reentrant_sink) << "hello world";
354 },
355 DiedOfFatal, DeathTestValidateExpectations());
356 }
357
TEST_F(ReentrancyDeathTest,RegisteredAlsoLogSinkThatLogsFatalInSend)358 TEST_F(ReentrancyDeathTest, RegisteredAlsoLogSinkThatLogsFatalInSend) {
359 EXPECT_EXIT(
360 {
361 absl::ScopedMockLog test_sink;
362 ReentrantSendLogSink reentrant_sink(absl::LogSeverity::kFatal);
363 EXPECT_CALL(test_sink, Log)
364 .Times(AnyNumber())
365 .WillRepeatedly(DeathTestUnexpectedLogging());
366 EXPECT_CALL(test_sink, Log(_, _, "hello world"))
367 .WillOnce(DeathTestExpectedLogging());
368 EXPECT_CALL(test_sink,
369 Log(_, _, "The log is coming from *inside the sink*."))
370 .WillOnce(DeathTestExpectedLogging());
371
372 test_sink.StartCapturingLogs();
373 absl::AddLogSink(&reentrant_sink);
374 LOG(INFO).ToSinkAlso(&reentrant_sink) << "hello world";
375 // No need to call RemoveLogSink - process is dead at this point.
376 },
377 DiedOfFatal, DeathTestValidateExpectations());
378 }
379
TEST_F(ReentrancyDeathTest,OnlyLogSinkThatLogsFatalInSend)380 TEST_F(ReentrancyDeathTest, OnlyLogSinkThatLogsFatalInSend) {
381 EXPECT_EXIT(
382 {
383 absl::ScopedMockLog test_sink;
384 ReentrantSendLogSink reentrant_sink(absl::LogSeverity::kFatal);
385 EXPECT_CALL(test_sink, Log)
386 .Times(AnyNumber())
387 .WillRepeatedly(DeathTestUnexpectedLogging());
388 EXPECT_CALL(test_sink,
389 Log(_, _, "The log is coming from *inside the sink*."))
390 .WillOnce(DeathTestExpectedLogging());
391
392 test_sink.StartCapturingLogs();
393 LOG(INFO).ToSinkOnly(&reentrant_sink) << "hello world";
394 },
395 DiedOfFatal, DeathTestValidateExpectations());
396 }
397
TEST_F(ReentrancyDeathTest,RegisteredOnlyLogSinkThatLogsFatalInSend)398 TEST_F(ReentrancyDeathTest, RegisteredOnlyLogSinkThatLogsFatalInSend) {
399 EXPECT_EXIT(
400 {
401 absl::ScopedMockLog test_sink;
402 ReentrantSendLogSink reentrant_sink(absl::LogSeverity::kFatal);
403 EXPECT_CALL(test_sink, Log)
404 .Times(AnyNumber())
405 .WillRepeatedly(DeathTestUnexpectedLogging());
406 EXPECT_CALL(test_sink,
407 Log(_, _, "The log is coming from *inside the sink*."))
408 .WillOnce(DeathTestExpectedLogging());
409
410 test_sink.StartCapturingLogs();
411 absl::AddLogSink(&reentrant_sink);
412 LOG(INFO).ToSinkOnly(&reentrant_sink) << "hello world";
413 // No need to call RemoveLogSink - process is dead at this point.
414 },
415 DiedOfFatal, DeathTestValidateExpectations());
416 }
417
418 } // namespace
419