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