log_sink_test.cc (14857B)
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 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 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 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 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 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 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 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 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 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: 187 explicit ReentrantSendLogSink(absl::LogSeverity severity, 188 absl::LogSink* sink, LogMode mode) 189 : severity_(severity), sink_(sink), mode_(mode) {} 190 explicit ReentrantSendLogSink(absl::LogSeverity severity) 191 : ReentrantSendLogSink(severity, nullptr, LogMode::kNormal) {} 192 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 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 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 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 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 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 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 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 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 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 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 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 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 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