base/logging_unittest.cc

   1 // Copyright 2011 The Chromium Authors
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #include <sstream>
   6 #include <string>
   7
   8 #include "base/bind.h"
   9 #include "base/callback.h"
  10 #include "base/command_line.h"
  11 #include "base/files/file_util.h"
  12 #include "base/files/scoped_temp_dir.h"
  13 #include "base/logging.h"
  14 #include "base/no_destructor.h"
  15 #include "base/process/process.h"
  16 #include "base/run_loop.h"
  17 #include "base/sanitizer_buildflags.h"
  18 #include "base/strings/string_piece.h"
  19 #include "base/strings/utf_string_conversions.h"
  20 #include "base/test/bind.h"
  21 #include "base/test/scoped_logging_settings.h"
  22 #include "base/test/task_environment.h"
  23 #include "build/build_config.h"
  24 #include "build/chromeos_buildflags.h"
  25
  26 #include "testing/gmock/include/gmock/gmock.h"
  27 #include "testing/gtest/include/gtest/gtest.h"
  28
  29 #if BUILDFLAG(IS_POSIX)
  30 #include <signal.h>
  31 #include <unistd.h>
  32 #include "base/posix/eintr_wrapper.h"
  33 #endif  // BUILDFLAG(IS_POSIX)
  34
  35 #if BUILDFLAG(IS_LINUX) || BUILDFLAG(IS_CHROMEOS) || BUILDFLAG(IS_ANDROID)
  36 #include <ucontext.h>
  37 #endif
  38
  39 #if BUILDFLAG(IS_WIN)
  40 #include <windows.h>
  41 #include <excpt.h>
  42 #endif  // BUILDFLAG(IS_WIN)
  43
  44 #if BUILDFLAG(IS_FUCHSIA)
  45 #include <lib/zx/channel.h>
  46 #include <lib/zx/event.h>
  47 #include <lib/zx/exception.h>
  48 #include <lib/zx/thread.h>
  49 #include <zircon/syscalls/debug.h>
  50 #include <zircon/syscalls/exception.h>
  51 #include <zircon/types.h>
  52 #endif  // BUILDFLAG(IS_FUCHSIA)
  53
  54 #include "third_party/abseil-cpp/absl/types/optional.h"
  55
  56 namespace logging {
  57
  58 namespace {
  59
  60 using ::testing::Return;
  61 using ::testing::_;
  62
  63 class LoggingTest : public testing::Test {
  64  protected:
  65   const ScopedLoggingSettings& scoped_logging_settings() {
  66     return scoped_logging_settings_;
  67   }
  68
  69  private:
  70   base::test::SingleThreadTaskEnvironment task_environment_{
  71       base::test::SingleThreadTaskEnvironment::MainThreadType::IO};
  72   ScopedLoggingSettings scoped_logging_settings_;
  73 };
  74
  75 class MockLogSource {
  76  public:
  77   MOCK_METHOD0(Log, const char*());
  78 };
  79
  80 class MockLogAssertHandler {
  81  public:
  82   MOCK_METHOD4(
  83       HandleLogAssert,
  84       void(const char*, int, const base::StringPiece, const base::StringPiece));
  85 };
  86
  87 TEST_F(LoggingTest, BasicLogging) {
  88   MockLogSource mock_log_source;
  89
  90   // 4 base logs: LOG, LOG_IF, PLOG, and PLOG_IF
  91   int expected_logs = 4;
  92
  93   // 4 verbose logs: VLOG, VLOG_IF, PVLOG, PVLOG_IF.
  94   if (VLOG_IS_ON(0))
  95     expected_logs += 4;
  96
  97   // 4 debug logs: DLOG, DLOG_IF, DPLOG, DPLOG_IF.
  98   if (DCHECK_IS_ON())
  99     expected_logs += 4;
 100
 101   // 4 verbose debug logs: DVLOG, DVLOG_IF, DVPLOG, DVPLOG_IF
 102   if (VLOG_IS_ON(0) && DCHECK_IS_ON())
 103     expected_logs += 4;
 104
 105   EXPECT_CALL(mock_log_source, Log())
 106       .Times(expected_logs)
 107       .WillRepeatedly(Return("log message"));
 108
 109   SetMinLogLevel(LOGGING_INFO);
 110
 111   EXPECT_TRUE(LOG_IS_ON(INFO));
 112   EXPECT_EQ(DCHECK_IS_ON(), DLOG_IS_ON(INFO));
 113
 114 #if BUILDFLAG(USE_RUNTIME_VLOG)
 115   EXPECT_TRUE(VLOG_IS_ON(0));
 116 #else
 117   // VLOG defaults to off when not USE_RUNTIME_VLOG.
 118   EXPECT_FALSE(VLOG_IS_ON(0));
 119 #endif  // BUILDFLAG(USE_RUNTIME_VLOG)
 120
 121   LOG(INFO) << mock_log_source.Log();
 122   LOG_IF(INFO, true) << mock_log_source.Log();
 123   PLOG(INFO) << mock_log_source.Log();
 124   PLOG_IF(INFO, true) << mock_log_source.Log();
 125   VLOG(0) << mock_log_source.Log();
 126   VLOG_IF(0, true) << mock_log_source.Log();
 127   VPLOG(0) << mock_log_source.Log();
 128   VPLOG_IF(0, true) << mock_log_source.Log();
 129
 130   DLOG(INFO) << mock_log_source.Log();
 131   DLOG_IF(INFO, true) << mock_log_source.Log();
 132   DPLOG(INFO) << mock_log_source.Log();
 133   DPLOG_IF(INFO, true) << mock_log_source.Log();
 134   DVLOG(0) << mock_log_source.Log();
 135   DVLOG_IF(0, true) << mock_log_source.Log();
 136   DVPLOG(0) << mock_log_source.Log();
 137   DVPLOG_IF(0, true) << mock_log_source.Log();
 138 }
 139
 140 TEST_F(LoggingTest, LogIsOn) {
 141   SetMinLogLevel(LOGGING_INFO);
 142   EXPECT_TRUE(LOG_IS_ON(INFO));
 143   EXPECT_TRUE(LOG_IS_ON(WARNING));
 144   EXPECT_TRUE(LOG_IS_ON(ERROR));
 145   EXPECT_TRUE(LOG_IS_ON(FATAL));
 146   EXPECT_TRUE(LOG_IS_ON(DFATAL));
 147
 148   SetMinLogLevel(LOGGING_WARNING);
 149   EXPECT_FALSE(LOG_IS_ON(INFO));
 150   EXPECT_TRUE(LOG_IS_ON(WARNING));
 151   EXPECT_TRUE(LOG_IS_ON(ERROR));
 152   EXPECT_TRUE(LOG_IS_ON(FATAL));
 153   EXPECT_TRUE(LOG_IS_ON(DFATAL));
 154
 155   SetMinLogLevel(LOGGING_ERROR);
 156   EXPECT_FALSE(LOG_IS_ON(INFO));
 157   EXPECT_FALSE(LOG_IS_ON(WARNING));
 158   EXPECT_TRUE(LOG_IS_ON(ERROR));
 159   EXPECT_TRUE(LOG_IS_ON(FATAL));
 160   EXPECT_TRUE(LOG_IS_ON(DFATAL));
 161
 162   SetMinLogLevel(LOGGING_FATAL + 1);
 163   EXPECT_FALSE(LOG_IS_ON(INFO));
 164   EXPECT_FALSE(LOG_IS_ON(WARNING));
 165   EXPECT_FALSE(LOG_IS_ON(ERROR));
 166   // LOG_IS_ON(FATAL) should always be true.
 167   EXPECT_TRUE(LOG_IS_ON(FATAL));
 168   // If DCHECK_IS_ON() then DFATAL is FATAL.
 169   EXPECT_EQ(DCHECK_IS_ON(), LOG_IS_ON(DFATAL));
 170 }
 171
 172 TEST_F(LoggingTest, LoggingIsLazyBySeverity) {
 173   MockLogSource mock_log_source;
 174   EXPECT_CALL(mock_log_source, Log()).Times(0);
 175
 176   SetMinLogLevel(LOGGING_WARNING);
 177
 178   EXPECT_FALSE(LOG_IS_ON(INFO));
 179   EXPECT_FALSE(DLOG_IS_ON(INFO));
 180   EXPECT_FALSE(VLOG_IS_ON(1));
 181
 182   LOG(INFO) << mock_log_source.Log();
 183   LOG_IF(INFO, false) << mock_log_source.Log();
 184   PLOG(INFO) << mock_log_source.Log();
 185   PLOG_IF(INFO, false) << mock_log_source.Log();
 186   VLOG(1) << mock_log_source.Log();
 187   VLOG_IF(1, true) << mock_log_source.Log();
 188   VPLOG(1) << mock_log_source.Log();
 189   VPLOG_IF(1, true) << mock_log_source.Log();
 190
 191   DLOG(INFO) << mock_log_source.Log();
 192   DLOG_IF(INFO, true) << mock_log_source.Log();
 193   DPLOG(INFO) << mock_log_source.Log();
 194   DPLOG_IF(INFO, true) << mock_log_source.Log();
 195   DVLOG(1) << mock_log_source.Log();
 196   DVLOG_IF(1, true) << mock_log_source.Log();
 197   DVPLOG(1) << mock_log_source.Log();
 198   DVPLOG_IF(1, true) << mock_log_source.Log();
 199 }
 200
 201 TEST_F(LoggingTest, LoggingIsLazyByDestination) {
 202   MockLogSource mock_log_source;
 203   MockLogSource mock_log_source_error;
 204   EXPECT_CALL(mock_log_source, Log()).Times(0);
 205
 206   // Severity >= ERROR is always printed to stderr.
 207   EXPECT_CALL(mock_log_source_error, Log()).Times(1).
 208       WillRepeatedly(Return("log message"));
 209
 210   LoggingSettings settings;
 211   settings.logging_dest = LOG_NONE;
 212   InitLogging(settings);
 213
 214   LOG(INFO) << mock_log_source.Log();
 215   LOG(WARNING) << mock_log_source.Log();
 216   LOG(ERROR) << mock_log_source_error.Log();
 217 }
 218
 219 // Check that logging to stderr is gated on LOG_TO_STDERR.
 220 TEST_F(LoggingTest, LogToStdErrFlag) {
 221   LoggingSettings settings;
 222   settings.logging_dest = LOG_NONE;
 223   InitLogging(settings);
 224   MockLogSource mock_log_source;
 225   EXPECT_CALL(mock_log_source, Log()).Times(0);
 226   LOG(INFO) << mock_log_source.Log();
 227
 228   settings.logging_dest = LOG_TO_STDERR;
 229   MockLogSource mock_log_source_stderr;
 230   InitLogging(settings);
 231   EXPECT_CALL(mock_log_source_stderr, Log()).Times(1).WillOnce(Return("foo"));
 232   LOG(INFO) << mock_log_source_stderr.Log();
 233 }
 234
 235 // Check that messages with severity ERROR or higher are always logged to
 236 // stderr if no log-destinations are set, other than LOG_TO_FILE.
 237 // This test is currently only POSIX-compatible.
 238 #if BUILDFLAG(IS_POSIX) || BUILDFLAG(IS_FUCHSIA)
 239 namespace {
 240 void TestForLogToStderr(int log_destinations,
 241                         bool* did_log_info,
 242                         bool* did_log_error) {
 243   const char kInfoLogMessage[] = "This is an INFO level message";
 244   const char kErrorLogMessage[] = "Here we have a message of level ERROR";
 245   base::ScopedTempDir temp_dir;
 246   ASSERT_TRUE(temp_dir.CreateUniqueTempDir());
 247
 248   // Set up logging.
 249   LoggingSettings settings;
 250   settings.logging_dest = log_destinations;
 251   base::FilePath file_logs_path;
 252   if (log_destinations & LOG_TO_FILE) {
 253     file_logs_path = temp_dir.GetPath().Append("file.log");
 254     settings.log_file_path = file_logs_path.value().c_str();
 255   }
 256   InitLogging(settings);
 257
 258   // Create a file and change stderr to write to that file, to easily check
 259   // contents.
 260   base::FilePath stderr_logs_path = temp_dir.GetPath().Append("stderr.log");
 261   base::File stderr_logs = base::File(
 262       stderr_logs_path,
 263       base::File::FLAG_CREATE | base::File::FLAG_WRITE | base::File::FLAG_READ);
 264   base::ScopedFD stderr_backup = base::ScopedFD(dup(STDERR_FILENO));
 265   int dup_result = dup2(stderr_logs.GetPlatformFile(), STDERR_FILENO);
 266   ASSERT_EQ(dup_result, STDERR_FILENO);
 267
 268   LOG(INFO) << kInfoLogMessage;
 269   LOG(ERROR) << kErrorLogMessage;
 270
 271   // Restore the original stderr logging destination.
 272   dup_result = dup2(stderr_backup.get(), STDERR_FILENO);
 273   ASSERT_EQ(dup_result, STDERR_FILENO);
 274
 275   // Check which of the messages were written to stderr.
 276   std::string written_logs;
 277   ASSERT_TRUE(base::ReadFileToString(stderr_logs_path, &written_logs));
 278   *did_log_info = written_logs.find(kInfoLogMessage) != std::string::npos;
 279   *did_log_error = written_logs.find(kErrorLogMessage) != std::string::npos;
 280 }
 281 }  // namespace
 282
 283 TEST_F(LoggingTest, AlwaysLogErrorsToStderr) {
 284   bool did_log_info = false;
 285   bool did_log_error = false;
 286
 287   // Fuchsia only logs to stderr when explicitly specified.
 288 #if !BUILDFLAG(IS_FUCHSIA)
 289   // When no destinations are specified, ERRORs should still log to stderr.
 290   TestForLogToStderr(LOG_NONE, &did_log_info, &did_log_error);
 291   EXPECT_FALSE(did_log_info);
 292   EXPECT_TRUE(did_log_error);
 293
 294   // Logging only to a file should also log ERRORs to stderr as well.
 295   TestForLogToStderr(LOG_TO_FILE, &did_log_info, &did_log_error);
 296   EXPECT_FALSE(did_log_info);
 297   EXPECT_TRUE(did_log_error);
 298 #endif
 299
 300   // ERRORs should not be logged to stderr if any destination besides FILE is
 301   // set.
 302   TestForLogToStderr(LOG_TO_SYSTEM_DEBUG_LOG, &did_log_info, &did_log_error);
 303   EXPECT_FALSE(did_log_info);
 304   EXPECT_FALSE(did_log_error);
 305
 306   // Both ERRORs and INFO should be logged if LOG_TO_STDERR is set.
 307   TestForLogToStderr(LOG_TO_STDERR, &did_log_info, &did_log_error);
 308   EXPECT_TRUE(did_log_info);
 309   EXPECT_TRUE(did_log_error);
 310 }
 311 #endif  // BUILDFLAG(IS_POSIX) || BUILDFLAG(IS_FUCHSIA)
 312
 313 #if BUILDFLAG(IS_CHROMEOS_ASH)
 314 TEST_F(LoggingTest, InitWithFileDescriptor) {
 315   const char kErrorLogMessage[] = "something bad happened";
 316
 317   // Open a file to pass to the InitLogging.
 318   base::ScopedTempDir temp_dir;
 319   ASSERT_TRUE(temp_dir.CreateUniqueTempDir());
 320   base::FilePath file_log_path = temp_dir.GetPath().Append("file.log");
 321   FILE* log_file = fopen(file_log_path.value().c_str(), "w");
 322   CHECK(log_file);
 323
 324   // Set up logging.
 325   LoggingSettings settings;
 326   settings.logging_dest = LOG_TO_FILE;
 327   settings.log_file = log_file;
 328   InitLogging(settings);
 329
 330   LOG(ERROR) << kErrorLogMessage;
 331
 332   // Check the message was written to the log file.
 333   std::string written_logs;
 334   ASSERT_TRUE(base::ReadFileToString(file_log_path, &written_logs));
 335   ASSERT_NE(written_logs.find(kErrorLogMessage), std::string::npos);
 336 }
 337
 338 TEST_F(LoggingTest, DuplicateLogFile) {
 339   const char kErrorLogMessage1[] = "something really bad happened";
 340   const char kErrorLogMessage2[] = "some other bad thing happened";
 341
 342   base::ScopedTempDir temp_dir;
 343   ASSERT_TRUE(temp_dir.CreateUniqueTempDir());
 344   base::FilePath file_log_path = temp_dir.GetPath().Append("file.log");
 345
 346   // Set up logging.
 347   LoggingSettings settings;
 348   settings.logging_dest = LOG_TO_FILE;
 349   settings.log_file_path = file_log_path.value().c_str();
 350   InitLogging(settings);
 351
 352   LOG(ERROR) << kErrorLogMessage1;
 353
 354   // Duplicate the log FILE, close the original (to make sure we actually
 355   // duplicated it), and write to the duplicate.
 356   FILE* log_file_dup = DuplicateLogFILE();
 357   CHECK(log_file_dup);
 358   CloseLogFile();
 359   fprintf(log_file_dup, "%s\n", kErrorLogMessage2);
 360   fflush(log_file_dup);
 361
 362   // Check the messages were written to the log file.
 363   std::string written_logs;
 364   ASSERT_TRUE(base::ReadFileToString(file_log_path, &written_logs));
 365   ASSERT_NE(written_logs.find(kErrorLogMessage1), std::string::npos);
 366   ASSERT_NE(written_logs.find(kErrorLogMessage2), std::string::npos);
 367   fclose(log_file_dup);
 368 }
 369 #endif  // BUILDFLAG(IS_CHROMEOS_ASH)
 370
 371 #if !CHECK_WILL_STREAM() && BUILDFLAG(IS_WIN)
 372 NOINLINE void CheckContainingFunc(int death_location) {
 373   CHECK(death_location != 1);
 374   CHECK(death_location != 2);
 375   CHECK(death_location != 3);
 376 }
 377
 378 int GetCheckExceptionData(EXCEPTION_POINTERS* p, DWORD* code, void** addr) {
 379   *code = p->ExceptionRecord->ExceptionCode;
 380   *addr = p->ExceptionRecord->ExceptionAddress;
 381   return EXCEPTION_EXECUTE_HANDLER;
 382 }
 383
 384 TEST_F(LoggingTest, CheckCausesDistinctBreakpoints) {
 385   DWORD code1 = 0;
 386   DWORD code2 = 0;
 387   DWORD code3 = 0;
 388   void* addr1 = nullptr;
 389   void* addr2 = nullptr;
 390   void* addr3 = nullptr;
 391
 392   // Record the exception code and addresses.
 393   __try {
 394     CheckContainingFunc(1);
 395   } __except (
 396       GetCheckExceptionData(GetExceptionInformation(), &code1, &addr1)) {
 397   }
 398
 399   __try {
 400     CheckContainingFunc(2);
 401   } __except (
 402       GetCheckExceptionData(GetExceptionInformation(), &code2, &addr2)) {
 403   }
 404
 405   __try {
 406     CheckContainingFunc(3);
 407   } __except (
 408       GetCheckExceptionData(GetExceptionInformation(), &code3, &addr3)) {
 409   }
 410
 411   // Ensure that the exception codes are correct (in particular, breakpoints,
 412   // not access violations).
 413   EXPECT_EQ(STATUS_BREAKPOINT, code1);
 414   EXPECT_EQ(STATUS_BREAKPOINT, code2);
 415   EXPECT_EQ(STATUS_BREAKPOINT, code3);
 416
 417   // Ensure that none of the CHECKs are colocated.
 418   EXPECT_NE(addr1, addr2);
 419   EXPECT_NE(addr1, addr3);
 420   EXPECT_NE(addr2, addr3);
 421 }
 422 #elif BUILDFLAG(IS_FUCHSIA)
 423
 424 // CHECK causes a direct crash (without jumping to another function) only in
 425 // official builds. Unfortunately, continuous test coverage on official builds
 426 // is lower. Furthermore, since the Fuchsia implementation uses threads, it is
 427 // not possible to rely on an implementation of CHECK that calls abort(), which
 428 // takes down the whole process, preventing the thread exception handler from
 429 // handling the exception. DO_CHECK here falls back on IMMEDIATE_CRASH() in
 430 // non-official builds, to catch regressions earlier in the CQ.
 431 #if !CHECK_WILL_STREAM()
 432 #define DO_CHECK CHECK
 433 #else
 434 #define DO_CHECK(cond) \
 435   if (!(cond)) {       \
 436     IMMEDIATE_CRASH(); \
 437   }
 438 #endif
 439
 440 struct thread_data_t {
 441   // For signaling the thread ended properly.
 442   zx::event event;
 443   // For catching thread exceptions. Created by the crashing thread.
 444   zx::channel channel;
 445   // Location where the thread is expected to crash.
 446   int death_location;
 447 };
 448
 449 // Indicates the exception channel has been created successfully.
 450 constexpr zx_signals_t kChannelReadySignal = ZX_USER_SIGNAL_0;
 451
 452 // Indicates an error setting up the crash thread.
 453 constexpr zx_signals_t kCrashThreadErrorSignal = ZX_USER_SIGNAL_1;
 454
 455 void* CrashThread(void* arg) {
 456   thread_data_t* data = (thread_data_t*)arg;
 457   int death_location = data->death_location;
 458
 459   // Register the exception handler.
 460   zx_status_t status =
 461       zx::thread::self()->create_exception_channel(0, &data->channel);
 462   if (status != ZX_OK) {
 463     data->event.signal(0, kCrashThreadErrorSignal);
 464     return nullptr;
 465   }
 466   data->event.signal(0, kChannelReadySignal);
 467
 468   DO_CHECK(death_location != 1);
 469   DO_CHECK(death_location != 2);
 470   DO_CHECK(death_location != 3);
 471
 472   // We should never reach this point, signal the thread incorrectly ended
 473   // properly.
 474   data->event.signal(0, kCrashThreadErrorSignal);
 475   return nullptr;
 476 }
 477
 478 // Helper function to call pthread_exit(nullptr).
 479 _Noreturn __NO_SAFESTACK void exception_pthread_exit() {
 480   pthread_exit(nullptr);
 481 }
 482
 483 // Runs the CrashThread function in a separate thread.
 484 void SpawnCrashThread(int death_location, uintptr_t* child_crash_addr) {
 485   zx::event event;
 486   zx_status_t status = zx::event::create(0, &event);
 487   ASSERT_EQ(status, ZX_OK);
 488
 489   // Run the thread.
 490   thread_data_t thread_data = {std::move(event), zx::channel(), death_location};
 491   pthread_t thread;
 492   int ret = pthread_create(&thread, nullptr, CrashThread, &thread_data);
 493   ASSERT_EQ(ret, 0);
 494
 495   // Wait for the thread to set up its exception channel.
 496   zx_signals_t signals = 0;
 497   status =
 498       thread_data.event.wait_one(kChannelReadySignal | kCrashThreadErrorSignal,
 499                                  zx::time::infinite(), &signals);
 500   ASSERT_EQ(status, ZX_OK);
 501   ASSERT_EQ(signals, kChannelReadySignal);
 502
 503   // Wait for the exception and read it out of the channel.
 504   status =
 505       thread_data.channel.wait_one(ZX_CHANNEL_READABLE | ZX_CHANNEL_PEER_CLOSED,
 506                                    zx::time::infinite(), &signals);
 507   ASSERT_EQ(status, ZX_OK);
 508   // Check the thread did crash and not terminate.
 509   ASSERT_FALSE(signals & ZX_CHANNEL_PEER_CLOSED);
 510
 511   zx_exception_info_t exception_info;
 512   zx::exception exception;
 513   status = thread_data.channel.read(
 514       0, &exception_info, exception.reset_and_get_address(),
 515       sizeof(exception_info), 1, nullptr, nullptr);
 516   ASSERT_EQ(status, ZX_OK);
 517
 518   // Get the crash address and point the thread towards exiting.
 519   zx::thread zircon_thread;
 520   status = exception.get_thread(&zircon_thread);
 521   ASSERT_EQ(status, ZX_OK);
 522   zx_thread_state_general_regs_t buffer;
 523   status = zircon_thread.read_state(ZX_THREAD_STATE_GENERAL_REGS, &buffer,
 524                                     sizeof(buffer));
 525   ASSERT_EQ(status, ZX_OK);
 526 #if defined(ARCH_CPU_X86_64)
 527   *child_crash_addr = static_cast<uintptr_t>(buffer.rip);
 528   buffer.rip = reinterpret_cast<uintptr_t>(exception_pthread_exit);
 529 #elif defined(ARCH_CPU_ARM64)
 530   *child_crash_addr = static_cast<uintptr_t>(buffer.pc);
 531   buffer.pc = reinterpret_cast<uintptr_t>(exception_pthread_exit);
 532 #else
 533 #error Unsupported architecture
 534 #endif
 535   ASSERT_EQ(zircon_thread.write_state(ZX_THREAD_STATE_GENERAL_REGS, &buffer,
 536                                       sizeof(buffer)),
 537             ZX_OK);
 538
 539   // Clear the exception so the thread continues.
 540   uint32_t state = ZX_EXCEPTION_STATE_HANDLED;
 541   ASSERT_EQ(
 542       exception.set_property(ZX_PROP_EXCEPTION_STATE, &state, sizeof(state)),
 543       ZX_OK);
 544   exception.reset();
 545
 546   // Join the exiting pthread.
 547   ASSERT_EQ(pthread_join(thread, nullptr), 0);
 548 }
 549
 550 TEST_F(LoggingTest, CheckCausesDistinctBreakpoints) {
 551   uintptr_t child_crash_addr_1 = 0;
 552   uintptr_t child_crash_addr_2 = 0;
 553   uintptr_t child_crash_addr_3 = 0;
 554
 555   SpawnCrashThread(1, &child_crash_addr_1);
 556   SpawnCrashThread(2, &child_crash_addr_2);
 557   SpawnCrashThread(3, &child_crash_addr_3);
 558
 559   ASSERT_NE(0u, child_crash_addr_1);
 560   ASSERT_NE(0u, child_crash_addr_2);
 561   ASSERT_NE(0u, child_crash_addr_3);
 562   ASSERT_NE(child_crash_addr_1, child_crash_addr_2);
 563   ASSERT_NE(child_crash_addr_1, child_crash_addr_3);
 564   ASSERT_NE(child_crash_addr_2, child_crash_addr_3);
 565 }
 566 #elif BUILDFLAG(IS_POSIX) && !BUILDFLAG(IS_NACL) && !BUILDFLAG(IS_IOS) && \
 567     (defined(ARCH_CPU_X86_FAMILY) || defined(ARCH_CPU_ARM_FAMILY))
 568
 569 int g_child_crash_pipe;
 570
 571 void CheckCrashTestSighandler(int, siginfo_t* info, void* context_ptr) {
 572   // Conversely to what clearly stated in "man 2 sigaction", some Linux kernels
 573   // do NOT populate the |info->si_addr| in the case of a SIGTRAP. Hence we
 574   // need the arch-specific boilerplate below, which is inspired by breakpad.
 575   // At the same time, on OSX, ucontext.h is deprecated but si_addr works fine.
 576   uintptr_t crash_addr = 0;
 577 #if BUILDFLAG(IS_MAC)
 578   crash_addr = reinterpret_cast<uintptr_t>(info->si_addr);
 579 #else  // OS_*
 580   ucontext_t* context = reinterpret_cast<ucontext_t*>(context_ptr);
 581 #if defined(ARCH_CPU_X86)
 582   crash_addr = static_cast<uintptr_t>(context->uc_mcontext.gregs[REG_EIP]);
 583 #elif defined(ARCH_CPU_X86_64)
 584   crash_addr = static_cast<uintptr_t>(context->uc_mcontext.gregs[REG_RIP]);
 585 #elif defined(ARCH_CPU_ARMEL)
 586   crash_addr = static_cast<uintptr_t>(context->uc_mcontext.arm_pc);
 587 #elif defined(ARCH_CPU_ARM64)
 588   crash_addr = static_cast<uintptr_t>(context->uc_mcontext.pc);
 589 #endif  // ARCH_*
 590 #endif  // OS_*
 591   HANDLE_EINTR(write(g_child_crash_pipe, &crash_addr, sizeof(uintptr_t)));
 592   _exit(0);
 593 }
 594
 595 // CHECK causes a direct crash (without jumping to another function) only in
 596 // official builds. Unfortunately, continuous test coverage on official builds
 597 // is lower. DO_CHECK here falls back on a home-brewed implementation in
 598 // non-official builds, to catch regressions earlier in the CQ.
 599 #if !CHECK_WILL_STREAM()
 600 #define DO_CHECK CHECK
 601 #else
 602 #define DO_CHECK(cond) \
 603   if (!(cond))         \
 604   IMMEDIATE_CRASH()
 605 #endif
 606
 607 void CrashChildMain(int death_location) {
 608   struct sigaction act = {};
 609   act.sa_sigaction = CheckCrashTestSighandler;
 610   act.sa_flags = SA_SIGINFO;
 611   ASSERT_EQ(0, sigaction(SIGTRAP, &act, nullptr));
 612   ASSERT_EQ(0, sigaction(SIGBUS, &act, nullptr));
 613   ASSERT_EQ(0, sigaction(SIGILL, &act, nullptr));
 614   DO_CHECK(death_location != 1);
 615   DO_CHECK(death_location != 2);
 616   printf("\n");
 617   DO_CHECK(death_location != 3);
 618
 619   // Should never reach this point.
 620   const uintptr_t failed = 0;
 621   HANDLE_EINTR(write(g_child_crash_pipe, &failed, sizeof(uintptr_t)));
 622 }
 623
 624 void SpawnChildAndCrash(int death_location, uintptr_t* child_crash_addr) {
 625   int pipefd[2];
 626   ASSERT_EQ(0, pipe(pipefd));
 627
 628   int pid = fork();
 629   ASSERT_GE(pid, 0);
 630
 631   if (pid == 0) {      // child process.
 632     close(pipefd[0]);  // Close reader (parent) end.
 633     g_child_crash_pipe = pipefd[1];
 634     CrashChildMain(death_location);
 635     FAIL() << "The child process was supposed to crash. It didn't.";
 636   }
 637
 638   close(pipefd[1]);  // Close writer (child) end.
 639   DCHECK(child_crash_addr);
 640   int res = HANDLE_EINTR(read(pipefd[0], child_crash_addr, sizeof(uintptr_t)));
 641   ASSERT_EQ(static_cast<int>(sizeof(uintptr_t)), res);
 642 }
 643
 644 TEST_F(LoggingTest, CheckCausesDistinctBreakpoints) {
 645   uintptr_t child_crash_addr_1 = 0;
 646   uintptr_t child_crash_addr_2 = 0;
 647   uintptr_t child_crash_addr_3 = 0;
 648
 649   SpawnChildAndCrash(1, &child_crash_addr_1);
 650   SpawnChildAndCrash(2, &child_crash_addr_2);
 651   SpawnChildAndCrash(3, &child_crash_addr_3);
 652
 653   ASSERT_NE(0u, child_crash_addr_1);
 654   ASSERT_NE(0u, child_crash_addr_2);
 655   ASSERT_NE(0u, child_crash_addr_3);
 656   ASSERT_NE(child_crash_addr_1, child_crash_addr_2);
 657   ASSERT_NE(child_crash_addr_1, child_crash_addr_3);
 658   ASSERT_NE(child_crash_addr_2, child_crash_addr_3);
 659 }
 660 #endif  // BUILDFLAG(IS_POSIX)
 661
 662 TEST_F(LoggingTest, DebugLoggingReleaseBehavior) {
 663 #if DCHECK_IS_ON()
 664   int debug_only_variable = 1;
 665 #endif
 666   // These should avoid emitting references to |debug_only_variable|
 667   // in release mode.
 668   DLOG_IF(INFO, debug_only_variable) << "test";
 669   DLOG_ASSERT(debug_only_variable) << "test";
 670   DPLOG_IF(INFO, debug_only_variable) << "test";
 671   DVLOG_IF(1, debug_only_variable) << "test";
 672 }
 673
 674 TEST_F(LoggingTest, NestedLogAssertHandlers) {
 675   ::testing::InSequence dummy;
 676   ::testing::StrictMock<MockLogAssertHandler> handler_a, handler_b;
 677
 678   EXPECT_CALL(
 679       handler_a,
 680       HandleLogAssert(
 681           _, _, base::StringPiece("First assert must be caught by handler_a"),
 682           _));
 683   EXPECT_CALL(
 684       handler_b,
 685       HandleLogAssert(
 686           _, _, base::StringPiece("Second assert must be caught by handler_b"),
 687           _));
 688   EXPECT_CALL(
 689       handler_a,
 690       HandleLogAssert(
 691           _, _,
 692           base::StringPiece("Last assert must be caught by handler_a again"),
 693           _));
 694
 695   logging::ScopedLogAssertHandler scoped_handler_a(base::BindRepeating(
 696       &MockLogAssertHandler::HandleLogAssert, base::Unretained(&handler_a)));
 697
 698   // Using LOG(FATAL) rather than CHECK(false) here since log messages aren't
 699   // preserved for CHECKs in official builds.
 700   LOG(FATAL) << "First assert must be caught by handler_a";
 701
 702   {
 703     logging::ScopedLogAssertHandler scoped_handler_b(base::BindRepeating(
 704         &MockLogAssertHandler::HandleLogAssert, base::Unretained(&handler_b)));
 705     LOG(FATAL) << "Second assert must be caught by handler_b";
 706   }
 707
 708   LOG(FATAL) << "Last assert must be caught by handler_a again";
 709 }
 710
 711 // Test that defining an operator<< for a type in a namespace doesn't prevent
 712 // other code in that namespace from calling the operator<<(ostream, wstring)
 713 // defined by logging.h. This can fail if operator<<(ostream, wstring) can't be
 714 // found by ADL, since defining another operator<< prevents name lookup from
 715 // looking in the global namespace.
 716 namespace nested_test {
 717   class Streamable {};
 718   [[maybe_unused]] std::ostream& operator<<(std::ostream& out,
 719                                             const Streamable&) {
 720     return out << "Streamable";
 721   }
 722   TEST_F(LoggingTest, StreamingWstringFindsCorrectOperator) {
 723     std::wstring wstr = L"Hello World";
 724     std::ostringstream ostr;
 725     ostr << wstr;
 726     EXPECT_EQ("Hello World", ostr.str());
 727   }
 728 }  // namespace nested_test
 729
 730 TEST_F(LoggingTest, LogPrefix) {
 731   // Use a static because only captureless lambdas can be converted to a
 732   // function pointer for SetLogMessageHandler().
 733   static base::NoDestructor<std::string> log_string;
 734   SetLogMessageHandler([](int severity, const char* file, int line,
 735                           size_t start, const std::string& str) -> bool {
 736     *log_string = str;
 737     return true;
 738   });
 739
 740   // Logging with a prefix includes the prefix string.
 741   const char kPrefix[] = "prefix";
 742   SetLogPrefix(kPrefix);
 743   LOG(ERROR) << "test";  // Writes into |log_string|.
 744   EXPECT_NE(std::string::npos, log_string->find(kPrefix));
 745   // Logging without a prefix does not include the prefix string.
 746   SetLogPrefix(nullptr);
 747   LOG(ERROR) << "test";  // Writes into |log_string|.
 748   EXPECT_EQ(std::string::npos, log_string->find(kPrefix));
 749 }
 750
 751 #if BUILDFLAG(IS_CHROMEOS_ASH)
 752 TEST_F(LoggingTest, LogCrosSyslogFormat) {
 753   // Set log format to syslog format.
 754   scoped_logging_settings().SetLogFormat(LogFormat::LOG_FORMAT_SYSLOG);
 755
 756   const char* kTimestampPattern = R"(\d\d\d\d\-\d\d\-\d\d)"             // date
 757                                   R"(T\d\d\:\d\d\:\d\d\.\d\d\d\d\d\d)"  // time
 758                                   R"(Z.+\n)";  // timezone
 759
 760   // Use a static because only captureless lambdas can be converted to a
 761   // function pointer for SetLogMessageHandler().
 762   static base::NoDestructor<std::string> log_string;
 763   SetLogMessageHandler([](int severity, const char* file, int line,
 764                           size_t start, const std::string& str) -> bool {
 765     *log_string = str;
 766     return true;
 767   });
 768
 769   {
 770     // All flags are true.
 771     SetLogItems(true, true, true, true);
 772     const char* kExpected =
 773         R"(\S+ \d+ ERROR \S+\[\d+:\d+\]\: \[\S+\] message\n)";
 774
 775     LOG(ERROR) << "message";
 776
 777     EXPECT_THAT(*log_string, ::testing::MatchesRegex(kTimestampPattern));
 778     EXPECT_THAT(*log_string, ::testing::MatchesRegex(kExpected));
 779   }
 780
 781   {
 782     // Timestamp is true.
 783     SetLogItems(false, false, true, false);
 784     const char* kExpected = R"(\S+ ERROR \S+\: \[\S+\] message\n)";
 785
 786     LOG(ERROR) << "message";
 787
 788     EXPECT_THAT(*log_string, ::testing::MatchesRegex(kTimestampPattern));
 789     EXPECT_THAT(*log_string, ::testing::MatchesRegex(kExpected));
 790   }
 791
 792   {
 793     // PID and timestamp are true.
 794     SetLogItems(true, false, true, false);
 795     const char* kExpected = R"(\S+ ERROR \S+\[\d+\]: \[\S+\] message\n)";
 796
 797     LOG(ERROR) << "message";
 798
 799     EXPECT_THAT(*log_string, ::testing::MatchesRegex(kTimestampPattern));
 800     EXPECT_THAT(*log_string, ::testing::MatchesRegex(kExpected));
 801   }
 802
 803   {
 804     // ThreadID and timestamp are true.
 805     SetLogItems(false, true, true, false);
 806     const char* kExpected = R"(\S+ ERROR \S+\[:\d+\]: \[\S+\] message\n)";
 807
 808     LOG(ERROR) << "message";
 809
 810     EXPECT_THAT(*log_string, ::testing::MatchesRegex(kTimestampPattern));
 811     EXPECT_THAT(*log_string, ::testing::MatchesRegex(kExpected));
 812   }
 813
 814   {
 815     // All flags are false.
 816     SetLogItems(false, false, false, false);
 817     const char* kExpected = R"(ERROR \S+: \[\S+\] message\n)";
 818
 819     LOG(ERROR) << "message";
 820
 821     EXPECT_THAT(*log_string, ::testing::MatchesRegex(kExpected));
 822   }
 823 }
 824 #endif  // BUILDFLAG(IS_CHROMEOS_ASH)
 825
 826 // We define a custom operator<< for std::u16string so we can use it with
 827 // logging. This tests that conversion.
 828 TEST_F(LoggingTest, String16) {
 829   // Basic stream test.
 830   {
 831     std::ostringstream stream;
 832     stream << "Empty '" << std::u16string() << "' standard '"
 833            << std::u16string(u"Hello, world") << "'";
 834     EXPECT_STREQ("Empty '' standard 'Hello, world'", stream.str().c_str());
 835   }
 836
 837   // Interesting edge cases.
 838   {
 839     // These should each get converted to the invalid character: EF BF BD.
 840     std::u16string initial_surrogate;
 841     initial_surrogate.push_back(0xd800);
 842     std::u16string final_surrogate;
 843     final_surrogate.push_back(0xdc00);
 844
 845     // Old italic A = U+10300, will get converted to: F0 90 8C 80 'z'.
 846     std::u16string surrogate_pair;
 847     surrogate_pair.push_back(0xd800);
 848     surrogate_pair.push_back(0xdf00);
 849     surrogate_pair.push_back('z');
 850
 851     // Will get converted to the invalid char + 's': EF BF BD 's'.
 852     std::u16string unterminated_surrogate;
 853     unterminated_surrogate.push_back(0xd800);
 854     unterminated_surrogate.push_back('s');
 855
 856     std::ostringstream stream;
 857     stream << initial_surrogate << "," << final_surrogate << ","
 858            << surrogate_pair << "," << unterminated_surrogate;
 859
 860     EXPECT_STREQ("\xef\xbf\xbd,\xef\xbf\xbd,\xf0\x90\x8c\x80z,\xef\xbf\xbds",
 861                  stream.str().c_str());
 862   }
 863 }
 864
 865 // Tests that we don't VLOG from logging_unittest except when in the scope
 866 // of the ScopedVmoduleSwitches.
 867 TEST_F(LoggingTest, ScopedVmoduleSwitches) {
 868 #if BUILDFLAG(USE_RUNTIME_VLOG)
 869   EXPECT_TRUE(VLOG_IS_ON(0));
 870 #else
 871   // VLOG defaults to off when not USE_RUNTIME_VLOG.
 872   EXPECT_FALSE(VLOG_IS_ON(0));
 873 #endif  // BUILDFLAG(USE_RUNTIME_VLOG)
 874
 875   // To avoid unreachable-code warnings when VLOG is disabled at compile-time.
 876   int expected_logs = 0;
 877   if (VLOG_IS_ON(0))
 878     expected_logs += 1;
 879
 880   SetMinLogLevel(LOGGING_FATAL);
 881
 882   {
 883     MockLogSource mock_log_source;
 884     EXPECT_CALL(mock_log_source, Log()).Times(0);
 885
 886     VLOG(1) << mock_log_source.Log();
 887   }
 888
 889   {
 890     ScopedVmoduleSwitches scoped_vmodule_switches;
 891     scoped_vmodule_switches.InitWithSwitches(__FILE__ "=1");
 892     MockLogSource mock_log_source;
 893     EXPECT_CALL(mock_log_source, Log())
 894         .Times(expected_logs)
 895         .WillRepeatedly(Return("log message"));
 896
 897     VLOG(1) << mock_log_source.Log();
 898   }
 899
 900   {
 901     MockLogSource mock_log_source;
 902     EXPECT_CALL(mock_log_source, Log()).Times(0);
 903
 904     VLOG(1) << mock_log_source.Log();
 905   }
 906 }
 907
 908 TEST_F(LoggingTest, BuildCrashString) {
 909   EXPECT_EQ("file.cc:42: ",
 910             LogMessage("file.cc", 42, LOGGING_ERROR).BuildCrashString());
 911
 912   // BuildCrashString() should strip path/to/file prefix.
 913   LogMessage msg(
 914 #if BUILDFLAG(IS_WIN)
 915       "..\\foo\\bar\\file.cc",
 916 #else
 917       "../foo/bar/file.cc",
 918 #endif  // BUILDFLAG(IS_WIN)
 919       42, LOGGING_ERROR);
 920   msg.stream() << "Hello";
 921   EXPECT_EQ("file.cc:42: Hello", msg.BuildCrashString());
 922 }
 923
 924 #if !BUILDFLAG(USE_RUNTIME_VLOG)
 925 TEST_F(LoggingTest, BuildTimeVLOG) {
 926   // Use a static because only captureless lambdas can be converted to a
 927   // function pointer for SetLogMessageHandler().
 928   static base::NoDestructor<std::string> log_string;
 929   SetLogMessageHandler([](int severity, const char* file, int line,
 930                           size_t start, const std::string& str) -> bool {
 931     *log_string = str;
 932     return true;
 933   });
 934
 935   // No VLOG by default.
 936   EXPECT_FALSE(VLOG_IS_ON(0));
 937   VLOG(1) << "Expect not logged";
 938   EXPECT_TRUE(log_string->empty());
 939
 940   // Re-define ENABLED_VLOG_LEVEL to enable VLOG(1).
 941   // Note that ENABLED_VLOG_LEVEL has impact on all the code after it so please
 942   // keep this test case the last one in this file.
 943 #undef ENABLED_VLOG_LEVEL
 944 #define ENABLED_VLOG_LEVEL 1
 945
 946   EXPECT_TRUE(VLOG_IS_ON(1));
 947   EXPECT_FALSE(VLOG_IS_ON(2));
 948
 949   VLOG(1) << "Expect logged";
 950   EXPECT_THAT(*log_string, ::testing::MatchesRegex(".* Expect logged\n"));
 951
 952   log_string->clear();
 953   VLOG(2) << "Expect not logged";
 954   EXPECT_TRUE(log_string->empty());
 955 }
 956 #endif  // !BUILDFLAG(USE_RUNTIME_VLOG)
 957
 958 // NO NEW TESTS HERE
 959 // The test above redefines ENABLED_VLOG_LEVEL, so new tests should be added
 960 // before it.
 961
 962 }  // namespace
 963
 964 }  // namespace logging