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