base/logging_unittest.cc

   1 // Copyright (c) 2011 The Chromium Authors. All rights reserved.
   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
   7 #include "base/bind.h"
   8 #include "base/callback.h"
   9 #include "base/compiler_specific.h"
  10 #include "base/files/file_util.h"
  11 #include "base/files/scoped_temp_dir.h"
  12 #include "base/logging.h"
  13 #include "base/macros.h"
  14 #include "base/run_loop.h"
  15 #include "base/sanitizer_buildflags.h"
  16 #include "base/strings/string_piece.h"
  17 #include "base/test/bind_test_util.h"
  18 #include "base/test/scoped_feature_list.h"
  19 #include "base/test/task_environment.h"
  20 #include "build/build_config.h"
  21
  22 #include "testing/gmock/include/gmock/gmock.h"
  23 #include "testing/gtest/include/gtest/gtest.h"
  24
  25 #if defined(OS_POSIX)
  26 #include <signal.h>
  27 #include <unistd.h>
  28 #include "base/posix/eintr_wrapper.h"
  29 #endif  // OS_POSIX
  30
  31 #if defined(OS_LINUX) || defined(OS_ANDROID)
  32 #include <ucontext.h>
  33 #endif
  34
  35 #if defined(OS_WIN)
  36 #include <windows.h>
  37 #include <excpt.h>
  38 #endif  // OS_WIN
  39
  40 #if defined(OS_FUCHSIA)
  41 #include <fuchsia/logger/cpp/fidl.h>
  42 #include <fuchsia/logger/cpp/fidl_test_base.h>
  43 #include <lib/fidl/cpp/binding.h>
  44 #include <lib/sys/cpp/component_context.h>
  45 #include <lib/zx/channel.h>
  46 #include <lib/zx/event.h>
  47 #include <lib/zx/exception.h>
  48 #include <lib/zx/process.h>
  49 #include <lib/zx/thread.h>
  50 #include <lib/zx/time.h>
  51 #include <zircon/process.h>
  52 #include <zircon/syscalls/debug.h>
  53 #include <zircon/syscalls/exception.h>
  54 #include <zircon/types.h>
  55
  56 #include "base/fuchsia/fuchsia_logging.h"
  57 #include "base/fuchsia/process_context.h"
  58 #endif  // OS_FUCHSIA
  59
  60 namespace logging {
  61
  62 namespace {
  63
  64 using ::testing::Return;
  65 using ::testing::_;
  66
  67 // Class to make sure any manipulations we do to the min log level are
  68 // contained (i.e., do not affect other unit tests).
  69 class LogStateSaver {
  70  public:
  71   LogStateSaver() : old_min_log_level_(GetMinLogLevel()) {}
  72
  73   ~LogStateSaver() {
  74     SetMinLogLevel(old_min_log_level_);
  75   }
  76
  77  private:
  78   int old_min_log_level_;
  79
  80   DISALLOW_COPY_AND_ASSIGN(LogStateSaver);
  81 };
  82
  83 class LoggingTest : public testing::Test {
  84  private:
  85   base::test::SingleThreadTaskEnvironment task_environment_{
  86       base::test::SingleThreadTaskEnvironment::MainThreadType::IO};
  87   LogStateSaver log_state_saver_;
  88 };
  89
  90 class MockLogSource {
  91  public:
  92   MOCK_METHOD0(Log, const char*());
  93 };
  94
  95 class MockLogAssertHandler {
  96  public:
  97   MOCK_METHOD4(
  98       HandleLogAssert,
  99       void(const char*, int, const base::StringPiece, const base::StringPiece));
 100 };
 101
 102 TEST_F(LoggingTest, BasicLogging) {
 103   MockLogSource mock_log_source;
 104   EXPECT_CALL(mock_log_source, Log())
 105       .Times(DCHECK_IS_ON() ? 16 : 8)
 106       .WillRepeatedly(Return("log message"));
 107
 108   SetMinLogLevel(LOG_INFO);
 109
 110   EXPECT_TRUE(LOG_IS_ON(INFO));
 111   EXPECT_EQ(DCHECK_IS_ON(), DLOG_IS_ON(INFO));
 112   EXPECT_TRUE(VLOG_IS_ON(0));
 113
 114   LOG(INFO) << mock_log_source.Log();
 115   LOG_IF(INFO, true) << mock_log_source.Log();
 116   PLOG(INFO) << mock_log_source.Log();
 117   PLOG_IF(INFO, true) << mock_log_source.Log();
 118   VLOG(0) << mock_log_source.Log();
 119   VLOG_IF(0, true) << mock_log_source.Log();
 120   VPLOG(0) << mock_log_source.Log();
 121   VPLOG_IF(0, true) << mock_log_source.Log();
 122
 123   DLOG(INFO) << mock_log_source.Log();
 124   DLOG_IF(INFO, true) << mock_log_source.Log();
 125   DPLOG(INFO) << mock_log_source.Log();
 126   DPLOG_IF(INFO, true) << mock_log_source.Log();
 127   DVLOG(0) << mock_log_source.Log();
 128   DVLOG_IF(0, true) << mock_log_source.Log();
 129   DVPLOG(0) << mock_log_source.Log();
 130   DVPLOG_IF(0, true) << mock_log_source.Log();
 131 }
 132
 133 TEST_F(LoggingTest, LogIsOn) {
 134 #if defined(NDEBUG)
 135   const bool kDfatalIsFatal = false;
 136 #else  // defined(NDEBUG)
 137   const bool kDfatalIsFatal = true;
 138 #endif  // defined(NDEBUG)
 139
 140   SetMinLogLevel(LOG_INFO);
 141   EXPECT_TRUE(LOG_IS_ON(INFO));
 142   EXPECT_TRUE(LOG_IS_ON(WARNING));
 143   EXPECT_TRUE(LOG_IS_ON(ERROR));
 144   EXPECT_TRUE(LOG_IS_ON(FATAL));
 145   EXPECT_TRUE(LOG_IS_ON(DFATAL));
 146
 147   SetMinLogLevel(LOG_WARNING);
 148   EXPECT_FALSE(LOG_IS_ON(INFO));
 149   EXPECT_TRUE(LOG_IS_ON(WARNING));
 150   EXPECT_TRUE(LOG_IS_ON(ERROR));
 151   EXPECT_TRUE(LOG_IS_ON(FATAL));
 152   EXPECT_TRUE(LOG_IS_ON(DFATAL));
 153
 154   SetMinLogLevel(LOG_ERROR);
 155   EXPECT_FALSE(LOG_IS_ON(INFO));
 156   EXPECT_FALSE(LOG_IS_ON(WARNING));
 157   EXPECT_TRUE(LOG_IS_ON(ERROR));
 158   EXPECT_TRUE(LOG_IS_ON(FATAL));
 159   EXPECT_TRUE(LOG_IS_ON(DFATAL));
 160
 161   // LOG_IS_ON(FATAL) should always be true.
 162   SetMinLogLevel(LOG_FATAL + 1);
 163   EXPECT_FALSE(LOG_IS_ON(INFO));
 164   EXPECT_FALSE(LOG_IS_ON(WARNING));
 165   EXPECT_FALSE(LOG_IS_ON(ERROR));
 166   EXPECT_TRUE(LOG_IS_ON(FATAL));
 167   EXPECT_EQ(kDfatalIsFatal, LOG_IS_ON(DFATAL));
 168 }
 169
 170 TEST_F(LoggingTest, LoggingIsLazyBySeverity) {
 171   MockLogSource mock_log_source;
 172   EXPECT_CALL(mock_log_source, Log()).Times(0);
 173
 174   SetMinLogLevel(LOG_WARNING);
 175
 176   EXPECT_FALSE(LOG_IS_ON(INFO));
 177   EXPECT_FALSE(DLOG_IS_ON(INFO));
 178   EXPECT_FALSE(VLOG_IS_ON(1));
 179
 180   LOG(INFO) << mock_log_source.Log();
 181   LOG_IF(INFO, false) << mock_log_source.Log();
 182   PLOG(INFO) << mock_log_source.Log();
 183   PLOG_IF(INFO, false) << mock_log_source.Log();
 184   VLOG(1) << mock_log_source.Log();
 185   VLOG_IF(1, true) << mock_log_source.Log();
 186   VPLOG(1) << mock_log_source.Log();
 187   VPLOG_IF(1, true) << mock_log_source.Log();
 188
 189   DLOG(INFO) << mock_log_source.Log();
 190   DLOG_IF(INFO, true) << mock_log_source.Log();
 191   DPLOG(INFO) << mock_log_source.Log();
 192   DPLOG_IF(INFO, true) << mock_log_source.Log();
 193   DVLOG(1) << mock_log_source.Log();
 194   DVLOG_IF(1, true) << mock_log_source.Log();
 195   DVPLOG(1) << mock_log_source.Log();
 196   DVPLOG_IF(1, true) << mock_log_source.Log();
 197 }
 198
 199 TEST_F(LoggingTest, LoggingIsLazyByDestination) {
 200   MockLogSource mock_log_source;
 201   MockLogSource mock_log_source_error;
 202   EXPECT_CALL(mock_log_source, Log()).Times(0);
 203
 204   // Severity >= ERROR is always printed to stderr.
 205   EXPECT_CALL(mock_log_source_error, Log()).Times(1).
 206       WillRepeatedly(Return("log message"));
 207
 208   LoggingSettings settings;
 209   settings.logging_dest = LOG_NONE;
 210   InitLogging(settings);
 211
 212   LOG(INFO) << mock_log_source.Log();
 213   LOG(WARNING) << mock_log_source.Log();
 214   LOG(ERROR) << mock_log_source_error.Log();
 215 }
 216
 217 // Check that logging to stderr is gated on LOG_TO_STDERR.
 218 TEST_F(LoggingTest, LogToStdErrFlag) {
 219   LoggingSettings settings;
 220   settings.logging_dest = LOG_NONE;
 221   InitLogging(settings);
 222   MockLogSource mock_log_source;
 223   EXPECT_CALL(mock_log_source, Log()).Times(0);
 224   LOG(INFO) << mock_log_source.Log();
 225
 226   settings.logging_dest = LOG_TO_STDERR;
 227   MockLogSource mock_log_source_stderr;
 228   InitLogging(settings);
 229   EXPECT_CALL(mock_log_source_stderr, Log()).Times(1).WillOnce(Return("foo"));
 230   LOG(INFO) << mock_log_source_stderr.Log();
 231 }
 232
 233 // Check that messages with severity ERROR or higher are always logged to
 234 // stderr if no log-destinations are set, other than LOG_TO_FILE.
 235 // This test is currently only POSIX-compatible.
 236 #if defined(OS_POSIX) || defined(OS_FUCHSIA)
 237 namespace {
 238 void TestForLogToStderr(int log_destinations,
 239                         bool* did_log_info,
 240                         bool* did_log_error) {
 241   const char kInfoLogMessage[] = "This is an INFO level message";
 242   const char kErrorLogMessage[] = "Here we have a message of level ERROR";
 243   base::ScopedTempDir temp_dir;
 244   ASSERT_TRUE(temp_dir.CreateUniqueTempDir());
 245
 246   // Set up logging.
 247   LoggingSettings settings;
 248   settings.logging_dest = log_destinations;
 249   base::FilePath file_logs_path;
 250   if (log_destinations & LOG_TO_FILE) {
 251     file_logs_path = temp_dir.GetPath().Append("file.log");
 252     settings.log_file_path = file_logs_path.value().c_str();
 253   }
 254   InitLogging(settings);
 255
 256   // Create a file and change stderr to write to that file, to easily check
 257   // contents.
 258   base::FilePath stderr_logs_path = temp_dir.GetPath().Append("stderr.log");
 259   base::File stderr_logs = base::File(
 260       stderr_logs_path,
 261       base::File::FLAG_CREATE | base::File::FLAG_WRITE | base::File::FLAG_READ);
 262   base::ScopedFD stderr_backup = base::ScopedFD(dup(STDERR_FILENO));
 263   int dup_result = dup2(stderr_logs.GetPlatformFile(), STDERR_FILENO);
 264   ASSERT_EQ(dup_result, STDERR_FILENO);
 265
 266   LOG(INFO) << kInfoLogMessage;
 267   LOG(ERROR) << kErrorLogMessage;
 268
 269   // Restore the original stderr logging destination.
 270   dup_result = dup2(stderr_backup.get(), STDERR_FILENO);
 271   ASSERT_EQ(dup_result, STDERR_FILENO);
 272
 273   // Check which of the messages were written to stderr.
 274   std::string written_logs;
 275   ASSERT_TRUE(base::ReadFileToString(stderr_logs_path, &written_logs));
 276   *did_log_info = written_logs.find(kInfoLogMessage) != std::string::npos;
 277   *did_log_error = written_logs.find(kErrorLogMessage) != std::string::npos;
 278 }
 279 }  // namespace
 280
 281 TEST_F(LoggingTest, AlwaysLogErrorsToStderr) {
 282   bool did_log_info = false;
 283   bool did_log_error = false;
 284
 285   // When no destinations are specified, ERRORs should still log to stderr.
 286   TestForLogToStderr(LOG_NONE, &did_log_info, &did_log_error);
 287   EXPECT_FALSE(did_log_info);
 288   EXPECT_TRUE(did_log_error);
 289
 290   // Logging only to a file should also log ERRORs to stderr as well.
 291   TestForLogToStderr(LOG_TO_FILE, &did_log_info, &did_log_error);
 292   EXPECT_FALSE(did_log_info);
 293   EXPECT_TRUE(did_log_error);
 294
 295   // ERRORs should not be logged to stderr if any destination besides FILE is
 296   // set.
 297   TestForLogToStderr(LOG_TO_SYSTEM_DEBUG_LOG, &did_log_info, &did_log_error);
 298   EXPECT_FALSE(did_log_info);
 299   EXPECT_FALSE(did_log_error);
 300
 301   // Both ERRORs and INFO should be logged if LOG_TO_STDERR is set.
 302   TestForLogToStderr(LOG_TO_STDERR, &did_log_info, &did_log_error);
 303   EXPECT_TRUE(did_log_info);
 304   EXPECT_TRUE(did_log_error);
 305 }
 306 #endif
 307
 308 #if defined(OS_CHROMEOS)
 309 TEST_F(LoggingTest, InitWithFileDescriptor) {
 310   const char kErrorLogMessage[] = "something bad happened";
 311
 312   // Open a file to pass to the InitLogging.
 313   base::ScopedTempDir temp_dir;
 314   ASSERT_TRUE(temp_dir.CreateUniqueTempDir());
 315   base::FilePath file_log_path = temp_dir.GetPath().Append("file.log");
 316   FILE* log_file = fopen(file_log_path.value().c_str(), "w");
 317   CHECK(log_file);
 318
 319   // Set up logging.
 320   LoggingSettings settings;
 321   settings.logging_dest = LOG_TO_FILE;
 322   settings.log_file = log_file;
 323   InitLogging(settings);
 324
 325   LOG(ERROR) << kErrorLogMessage;
 326
 327   // Check the message was written to the log file.
 328   std::string written_logs;
 329   ASSERT_TRUE(base::ReadFileToString(file_log_path, &written_logs));
 330   ASSERT_NE(written_logs.find(kErrorLogMessage), std::string::npos);
 331 }
 332
 333 TEST_F(LoggingTest, DuplicateLogFile) {
 334   const char kErrorLogMessage1[] = "something really bad happened";
 335   const char kErrorLogMessage2[] = "some other bad thing happened";
 336
 337   base::ScopedTempDir temp_dir;
 338   ASSERT_TRUE(temp_dir.CreateUniqueTempDir());
 339   base::FilePath file_log_path = temp_dir.GetPath().Append("file.log");
 340
 341   // Set up logging.
 342   LoggingSettings settings;
 343   settings.logging_dest = LOG_TO_FILE;
 344   settings.log_file_path = file_log_path.value().c_str();
 345   InitLogging(settings);
 346
 347   LOG(ERROR) << kErrorLogMessage1;
 348
 349   // Duplicate the log FILE, close the original (to make sure we actually
 350   // duplicated it), and write to the duplicate.
 351   FILE* log_file_dup = DuplicateLogFILE();
 352   CHECK(log_file_dup);
 353   CloseLogFile();
 354   fprintf(log_file_dup, "%s\n", kErrorLogMessage2);
 355   fflush(log_file_dup);
 356
 357   // Check the messages were written to the log file.
 358   std::string written_logs;
 359   ASSERT_TRUE(base::ReadFileToString(file_log_path, &written_logs));
 360   ASSERT_NE(written_logs.find(kErrorLogMessage1), std::string::npos);
 361   ASSERT_NE(written_logs.find(kErrorLogMessage2), std::string::npos);
 362   fclose(log_file_dup);
 363 }
 364 #endif  // defined(OS_CHROMEOS)
 365
 366 #if defined(OFFICIAL_BUILD) && defined(OS_WIN)
 367 NOINLINE void CheckContainingFunc(int death_location) {
 368   CHECK(death_location != 1);
 369   CHECK(death_location != 2);
 370   CHECK(death_location != 3);
 371 }
 372
 373 int GetCheckExceptionData(EXCEPTION_POINTERS* p, DWORD* code, void** addr) {
 374   *code = p->ExceptionRecord->ExceptionCode;
 375   *addr = p->ExceptionRecord->ExceptionAddress;
 376   return EXCEPTION_EXECUTE_HANDLER;
 377 }
 378
 379 TEST_F(LoggingTest, CheckCausesDistinctBreakpoints) {
 380   DWORD code1 = 0;
 381   DWORD code2 = 0;
 382   DWORD code3 = 0;
 383   void* addr1 = nullptr;
 384   void* addr2 = nullptr;
 385   void* addr3 = nullptr;
 386
 387   // Record the exception code and addresses.
 388   __try {
 389     CheckContainingFunc(1);
 390   } __except (
 391       GetCheckExceptionData(GetExceptionInformation(), &code1, &addr1)) {
 392   }
 393
 394   __try {
 395     CheckContainingFunc(2);
 396   } __except (
 397       GetCheckExceptionData(GetExceptionInformation(), &code2, &addr2)) {
 398   }
 399
 400   __try {
 401     CheckContainingFunc(3);
 402   } __except (
 403       GetCheckExceptionData(GetExceptionInformation(), &code3, &addr3)) {
 404   }
 405
 406   // Ensure that the exception codes are correct (in particular, breakpoints,
 407   // not access violations).
 408   EXPECT_EQ(STATUS_BREAKPOINT, code1);
 409   EXPECT_EQ(STATUS_BREAKPOINT, code2);
 410   EXPECT_EQ(STATUS_BREAKPOINT, code3);
 411
 412   // Ensure that none of the CHECKs are colocated.
 413   EXPECT_NE(addr1, addr2);
 414   EXPECT_NE(addr1, addr3);
 415   EXPECT_NE(addr2, addr3);
 416 }
 417 #elif defined(OS_FUCHSIA)
 418
 419 // CHECK causes a direct crash (without jumping to another function) only in
 420 // official builds. Unfortunately, continuous test coverage on official builds
 421 // is lower. Furthermore, since the Fuchsia implementation uses threads, it is
 422 // not possible to rely on an implementation of CHECK that calls abort(), which
 423 // takes down the whole process, preventing the thread exception handler from
 424 // handling the exception. DO_CHECK here falls back on IMMEDIATE_CRASH() in
 425 // non-official builds, to catch regressions earlier in the CQ.
 426 #if defined(OFFICIAL_BUILD)
 427 #define DO_CHECK CHECK
 428 #else
 429 #define DO_CHECK(cond) \
 430   if (!(cond)) {       \
 431     IMMEDIATE_CRASH(); \
 432   }
 433 #endif
 434
 435 struct thread_data_t {
 436   // For signaling the thread ended properly.
 437   zx::event event;
 438   // For catching thread exceptions. Created by the crashing thread.
 439   zx::channel channel;
 440   // Location where the thread is expected to crash.
 441   int death_location;
 442 };
 443
 444 // Indicates the exception channel has been created successfully.
 445 constexpr zx_signals_t kChannelReadySignal = ZX_USER_SIGNAL_0;
 446
 447 // Indicates an error setting up the crash thread.
 448 constexpr zx_signals_t kCrashThreadErrorSignal = ZX_USER_SIGNAL_1;
 449
 450 void* CrashThread(void* arg) {
 451   thread_data_t* data = (thread_data_t*)arg;
 452   int death_location = data->death_location;
 453
 454   // Register the exception handler.
 455   zx_status_t status =
 456       zx::thread::self()->create_exception_channel(0, &data->channel);
 457   if (status != ZX_OK) {
 458     data->event.signal(0, kCrashThreadErrorSignal);
 459     return nullptr;
 460   }
 461   data->event.signal(0, kChannelReadySignal);
 462
 463   DO_CHECK(death_location != 1);
 464   DO_CHECK(death_location != 2);
 465   DO_CHECK(death_location != 3);
 466
 467   // We should never reach this point, signal the thread incorrectly ended
 468   // properly.
 469   data->event.signal(0, kCrashThreadErrorSignal);
 470   return nullptr;
 471 }
 472
 473 // Runs the CrashThread function in a separate thread.
 474 void SpawnCrashThread(int death_location, uintptr_t* child_crash_addr) {
 475   zx::event event;
 476   zx_status_t status = zx::event::create(0, &event);
 477   ASSERT_EQ(status, ZX_OK);
 478
 479   // Run the thread.
 480   thread_data_t thread_data = {std::move(event), zx::channel(), death_location};
 481   pthread_t thread;
 482   int ret = pthread_create(&thread, nullptr, CrashThread, &thread_data);
 483   ASSERT_EQ(ret, 0);
 484
 485   // Wait for the thread to set up its exception channel.
 486   zx_signals_t signals = 0;
 487   status =
 488       thread_data.event.wait_one(kChannelReadySignal | kCrashThreadErrorSignal,
 489                                  zx::time::infinite(), &signals);
 490   ASSERT_EQ(status, ZX_OK);
 491   ASSERT_EQ(signals, kChannelReadySignal);
 492
 493   // Wait for the exception and read it out of the channel.
 494   status =
 495       thread_data.channel.wait_one(ZX_CHANNEL_READABLE | ZX_CHANNEL_PEER_CLOSED,
 496                                    zx::time::infinite(), &signals);
 497   ASSERT_EQ(status, ZX_OK);
 498   // Check the thread did crash and not terminate.
 499   ASSERT_FALSE(signals & ZX_CHANNEL_PEER_CLOSED);
 500
 501   zx_exception_info_t exception_info;
 502   zx::exception exception;
 503   status = thread_data.channel.read(
 504       0, &exception_info, exception.reset_and_get_address(),
 505       sizeof(exception_info), 1, nullptr, nullptr);
 506   ASSERT_EQ(status, ZX_OK);
 507
 508   // Get the crash address.
 509   zx::thread zircon_thread;
 510   status = exception.get_thread(&zircon_thread);
 511   ASSERT_EQ(status, ZX_OK);
 512   zx_thread_state_general_regs_t buffer;
 513   status = zircon_thread.read_state(ZX_THREAD_STATE_GENERAL_REGS, &buffer,
 514                                     sizeof(buffer));
 515   ASSERT_EQ(status, ZX_OK);
 516 #if defined(ARCH_CPU_X86_64)
 517   *child_crash_addr = static_cast<uintptr_t>(buffer.rip);
 518 #elif defined(ARCH_CPU_ARM64)
 519   *child_crash_addr = static_cast<uintptr_t>(buffer.pc);
 520 #else
 521 #error Unsupported architecture
 522 #endif
 523
 524   status = zircon_thread.kill();
 525   ASSERT_EQ(status, ZX_OK);
 526 }
 527
 528 TEST_F(LoggingTest, CheckCausesDistinctBreakpoints) {
 529   uintptr_t child_crash_addr_1 = 0;
 530   uintptr_t child_crash_addr_2 = 0;
 531   uintptr_t child_crash_addr_3 = 0;
 532
 533   SpawnCrashThread(1, &child_crash_addr_1);
 534   SpawnCrashThread(2, &child_crash_addr_2);
 535   SpawnCrashThread(3, &child_crash_addr_3);
 536
 537   ASSERT_NE(0u, child_crash_addr_1);
 538   ASSERT_NE(0u, child_crash_addr_2);
 539   ASSERT_NE(0u, child_crash_addr_3);
 540   ASSERT_NE(child_crash_addr_1, child_crash_addr_2);
 541   ASSERT_NE(child_crash_addr_1, child_crash_addr_3);
 542   ASSERT_NE(child_crash_addr_2, child_crash_addr_3);
 543 }
 544 #elif defined(OS_POSIX) && !defined(OS_NACL) && !defined(OS_IOS) && \
 545     (defined(ARCH_CPU_X86_FAMILY) || defined(ARCH_CPU_ARM_FAMILY))
 546
 547 int g_child_crash_pipe;
 548
 549 void CheckCrashTestSighandler(int, siginfo_t* info, void* context_ptr) {
 550   // Conversely to what clearly stated in "man 2 sigaction", some Linux kernels
 551   // do NOT populate the |info->si_addr| in the case of a SIGTRAP. Hence we
 552   // need the arch-specific boilerplate below, which is inspired by breakpad.
 553   // At the same time, on OSX, ucontext.h is deprecated but si_addr works fine.
 554   uintptr_t crash_addr = 0;
 555 #if defined(OS_MACOSX)
 556   crash_addr = reinterpret_cast<uintptr_t>(info->si_addr);
 557 #else  // OS_POSIX && !OS_MACOSX
 558   ucontext_t* context = reinterpret_cast<ucontext_t*>(context_ptr);
 559 #if defined(ARCH_CPU_X86)
 560   crash_addr = static_cast<uintptr_t>(context->uc_mcontext.gregs[REG_EIP]);
 561 #elif defined(ARCH_CPU_X86_64)
 562   crash_addr = static_cast<uintptr_t>(context->uc_mcontext.gregs[REG_RIP]);
 563 #elif defined(ARCH_CPU_ARMEL)
 564   crash_addr = static_cast<uintptr_t>(context->uc_mcontext.arm_pc);
 565 #elif defined(ARCH_CPU_ARM64)
 566   crash_addr = static_cast<uintptr_t>(context->uc_mcontext.pc);
 567 #endif  // ARCH_*
 568 #endif  // OS_POSIX && !OS_MACOSX
 569   HANDLE_EINTR(write(g_child_crash_pipe, &crash_addr, sizeof(uintptr_t)));
 570   _exit(0);
 571 }
 572
 573 // CHECK causes a direct crash (without jumping to another function) only in
 574 // official builds. Unfortunately, continuous test coverage on official builds
 575 // is lower. DO_CHECK here falls back on a home-brewed implementation in
 576 // non-official builds, to catch regressions earlier in the CQ.
 577 #if defined(OFFICIAL_BUILD)
 578 #define DO_CHECK CHECK
 579 #else
 580 #define DO_CHECK(cond) \
 581   if (!(cond))         \
 582   IMMEDIATE_CRASH()
 583 #endif
 584
 585 void CrashChildMain(int death_location) {
 586   struct sigaction act = {};
 587   act.sa_sigaction = CheckCrashTestSighandler;
 588   act.sa_flags = SA_SIGINFO;
 589   ASSERT_EQ(0, sigaction(SIGTRAP, &act, nullptr));
 590   ASSERT_EQ(0, sigaction(SIGBUS, &act, nullptr));
 591   ASSERT_EQ(0, sigaction(SIGILL, &act, nullptr));
 592   DO_CHECK(death_location != 1);
 593   DO_CHECK(death_location != 2);
 594   printf("\n");
 595   DO_CHECK(death_location != 3);
 596
 597   // Should never reach this point.
 598   const uintptr_t failed = 0;
 599   HANDLE_EINTR(write(g_child_crash_pipe, &failed, sizeof(uintptr_t)));
 600 }
 601
 602 void SpawnChildAndCrash(int death_location, uintptr_t* child_crash_addr) {
 603   int pipefd[2];
 604   ASSERT_EQ(0, pipe(pipefd));
 605
 606   int pid = fork();
 607   ASSERT_GE(pid, 0);
 608
 609   if (pid == 0) {      // child process.
 610     close(pipefd[0]);  // Close reader (parent) end.
 611     g_child_crash_pipe = pipefd[1];
 612     CrashChildMain(death_location);
 613     FAIL() << "The child process was supposed to crash. It didn't.";
 614   }
 615
 616   close(pipefd[1]);  // Close writer (child) end.
 617   DCHECK(child_crash_addr);
 618   int res = HANDLE_EINTR(read(pipefd[0], child_crash_addr, sizeof(uintptr_t)));
 619   ASSERT_EQ(static_cast<int>(sizeof(uintptr_t)), res);
 620 }
 621
 622 TEST_F(LoggingTest, CheckCausesDistinctBreakpoints) {
 623   uintptr_t child_crash_addr_1 = 0;
 624   uintptr_t child_crash_addr_2 = 0;
 625   uintptr_t child_crash_addr_3 = 0;
 626
 627   SpawnChildAndCrash(1, &child_crash_addr_1);
 628   SpawnChildAndCrash(2, &child_crash_addr_2);
 629   SpawnChildAndCrash(3, &child_crash_addr_3);
 630
 631   ASSERT_NE(0u, child_crash_addr_1);
 632   ASSERT_NE(0u, child_crash_addr_2);
 633   ASSERT_NE(0u, child_crash_addr_3);
 634   ASSERT_NE(child_crash_addr_1, child_crash_addr_2);
 635   ASSERT_NE(child_crash_addr_1, child_crash_addr_3);
 636   ASSERT_NE(child_crash_addr_2, child_crash_addr_3);
 637 }
 638 #endif  // OS_POSIX
 639
 640 TEST_F(LoggingTest, DebugLoggingReleaseBehavior) {
 641 #if DCHECK_IS_ON()
 642   int debug_only_variable = 1;
 643 #endif
 644   // These should avoid emitting references to |debug_only_variable|
 645   // in release mode.
 646   DLOG_IF(INFO, debug_only_variable) << "test";
 647   DLOG_ASSERT(debug_only_variable) << "test";
 648   DPLOG_IF(INFO, debug_only_variable) << "test";
 649   DVLOG_IF(1, debug_only_variable) << "test";
 650 }
 651
 652 TEST_F(LoggingTest, NestedLogAssertHandlers) {
 653   ::testing::InSequence dummy;
 654   ::testing::StrictMock<MockLogAssertHandler> handler_a, handler_b;
 655
 656   EXPECT_CALL(
 657       handler_a,
 658       HandleLogAssert(
 659           _, _, base::StringPiece("First assert must be caught by handler_a"),
 660           _));
 661   EXPECT_CALL(
 662       handler_b,
 663       HandleLogAssert(
 664           _, _, base::StringPiece("Second assert must be caught by handler_b"),
 665           _));
 666   EXPECT_CALL(
 667       handler_a,
 668       HandleLogAssert(
 669           _, _,
 670           base::StringPiece("Last assert must be caught by handler_a again"),
 671           _));
 672
 673   logging::ScopedLogAssertHandler scoped_handler_a(base::BindRepeating(
 674       &MockLogAssertHandler::HandleLogAssert, base::Unretained(&handler_a)));
 675
 676   // Using LOG(FATAL) rather than CHECK(false) here since log messages aren't
 677   // preserved for CHECKs in official builds.
 678   LOG(FATAL) << "First assert must be caught by handler_a";
 679
 680   {
 681     logging::ScopedLogAssertHandler scoped_handler_b(base::BindRepeating(
 682         &MockLogAssertHandler::HandleLogAssert, base::Unretained(&handler_b)));
 683     LOG(FATAL) << "Second assert must be caught by handler_b";
 684   }
 685
 686   LOG(FATAL) << "Last assert must be caught by handler_a again";
 687 }
 688
 689 // Test that defining an operator<< for a type in a namespace doesn't prevent
 690 // other code in that namespace from calling the operator<<(ostream, wstring)
 691 // defined by logging.h. This can fail if operator<<(ostream, wstring) can't be
 692 // found by ADL, since defining another operator<< prevents name lookup from
 693 // looking in the global namespace.
 694 namespace nested_test {
 695   class Streamable {};
 696   ALLOW_UNUSED_TYPE std::ostream& operator<<(std::ostream& out,
 697                                              const Streamable&) {
 698     return out << "Streamable";
 699   }
 700   TEST_F(LoggingTest, StreamingWstringFindsCorrectOperator) {
 701     std::wstring wstr = L"Hello World";
 702     std::ostringstream ostr;
 703     ostr << wstr;
 704     EXPECT_EQ("Hello World", ostr.str());
 705   }
 706 }  // namespace nested_test
 707
 708 #if defined(OS_FUCHSIA)
 709
 710 class TestLogListenerSafe
 711     : public fuchsia::logger::testing::LogListenerSafe_TestBase {
 712  public:
 713   TestLogListenerSafe() = default;
 714   ~TestLogListenerSafe() override = default;
 715
 716   void set_on_dump_logs_done(base::OnceClosure on_dump_logs_done) {
 717     on_dump_logs_done_ = std::move(on_dump_logs_done);
 718   }
 719
 720   bool DidReceiveString(base::StringPiece message,
 721                         fuchsia::logger::LogMessage* logged_message) {
 722     for (const auto& log_message : log_messages_) {
 723       if (log_message.msg.find(message.as_string()) != std::string::npos) {
 724         *logged_message = log_message;
 725         return true;
 726       }
 727     }
 728     return false;
 729   }
 730
 731   // LogListener implementation.
 732   void LogMany(std::vector<fuchsia::logger::LogMessage> messages,
 733                LogManyCallback callback) override {
 734     log_messages_.insert(log_messages_.end(),
 735                          std::make_move_iterator(messages.begin()),
 736                          std::make_move_iterator(messages.end()));
 737     callback();
 738   }
 739
 740   void Done() override { std::move(on_dump_logs_done_).Run(); }
 741
 742   void NotImplemented_(const std::string& name) override {
 743     ADD_FAILURE() << "NotImplemented_: " << name;
 744   }
 745
 746  private:
 747   fuchsia::logger::LogListenerSafePtr log_listener_;
 748   std::vector<fuchsia::logger::LogMessage> log_messages_;
 749   base::OnceClosure on_dump_logs_done_;
 750
 751   DISALLOW_COPY_AND_ASSIGN(TestLogListenerSafe);
 752 };
 753
 754 // Verifies that calling the log macro goes to the Fuchsia system logs.
 755 TEST_F(LoggingTest, FuchsiaSystemLogging) {
 756   const char kLogMessage[] = "system log!";
 757   LOG(ERROR) << kLogMessage;
 758
 759   TestLogListenerSafe listener;
 760   fidl::Binding<fuchsia::logger::LogListenerSafe> binding(&listener);
 761
 762   fuchsia::logger::LogMessage logged_message;
 763
 764   base::RunLoop wait_for_message_loop;
 765
 766   // |dump_logs| checks whether the expected log line has been received yet,
 767   // and invokes DumpLogs() if not. It passes itself as the completion callback,
 768   // so that when the call completes it can check again for the expected message
 769   // and re-invoke DumpLogs(), or quit the loop, as appropriate.
 770   base::RepeatingClosure dump_logs = base::BindLambdaForTesting([&]() {
 771     if (listener.DidReceiveString(kLogMessage, &logged_message)) {
 772       wait_for_message_loop.Quit();
 773       return;
 774     }
 775
 776     std::unique_ptr<fuchsia::logger::LogFilterOptions> options =
 777         std::make_unique<fuchsia::logger::LogFilterOptions>();
 778     options->tags = {"base_unittests__exec"};
 779     fuchsia::logger::LogPtr logger = base::ComponentContextForProcess()
 780                                          ->svc()
 781                                          ->Connect<fuchsia::logger::Log>();
 782     listener.set_on_dump_logs_done(dump_logs);
 783     logger->DumpLogsSafe(binding.NewBinding(), std::move(options));
 784   });
 785
 786   // Start the first DumpLogs() call.
 787   dump_logs.Run();
 788
 789   // Run until kLogMessage is received.
 790   wait_for_message_loop.Run();
 791
 792   EXPECT_EQ(logged_message.severity,
 793             static_cast<int32_t>(fuchsia::logger::LogLevelFilter::ERROR));
 794   ASSERT_EQ(logged_message.tags.size(), 1u);
 795   EXPECT_EQ(logged_message.tags[0], base::CommandLine::ForCurrentProcess()
 796                                         ->GetProgram()
 797                                         .BaseName()
 798                                         .AsUTF8Unsafe());
 799 }
 800
 801 TEST_F(LoggingTest, FuchsiaLogging) {
 802   MockLogSource mock_log_source;
 803   EXPECT_CALL(mock_log_source, Log())
 804       .Times(DCHECK_IS_ON() ? 2 : 1)
 805       .WillRepeatedly(Return("log message"));
 806
 807   SetMinLogLevel(LOG_INFO);
 808
 809   EXPECT_TRUE(LOG_IS_ON(INFO));
 810   EXPECT_EQ(DCHECK_IS_ON(), DLOG_IS_ON(INFO));
 811
 812   ZX_LOG(INFO, ZX_ERR_INTERNAL) << mock_log_source.Log();
 813   ZX_DLOG(INFO, ZX_ERR_INTERNAL) << mock_log_source.Log();
 814
 815   ZX_CHECK(true, ZX_ERR_INTERNAL);
 816   ZX_DCHECK(true, ZX_ERR_INTERNAL);
 817 }
 818 #endif  // defined(OS_FUCHSIA)
 819
 820 TEST_F(LoggingTest, LogPrefix) {
 821   // Set up a callback function to capture the log output string.
 822   auto old_log_message_handler = GetLogMessageHandler();
 823   // Use a static because only captureless lambdas can be converted to a
 824   // function pointer for SetLogMessageHandler().
 825   static std::string* log_string_ptr = nullptr;
 826   std::string log_string;
 827   log_string_ptr = &log_string;
 828   SetLogMessageHandler([](int severity, const char* file, int line,
 829                           size_t start, const std::string& str) -> bool {
 830     *log_string_ptr = str;
 831     return true;
 832   });
 833
 834   // Logging with a prefix includes the prefix string after the opening '['.
 835   const char kPrefix[] = "prefix";
 836   SetLogPrefix(kPrefix);
 837   LOG(ERROR) << "test";  // Writes into |log_string|.
 838   EXPECT_EQ(1u, log_string.find(kPrefix));
 839
 840   // Logging without a prefix does not include the prefix string.
 841   SetLogPrefix(nullptr);
 842   LOG(ERROR) << "test";  // Writes into |log_string|.
 843   EXPECT_EQ(std::string::npos, log_string.find(kPrefix));
 844
 845   // Clean up.
 846   SetLogMessageHandler(old_log_message_handler);
 847   log_string_ptr = nullptr;
 848 }
 849
 850 #if !defined(ADDRESS_SANITIZER) && !defined(MEMORY_SANITIZER) && \
 851     !BUILDFLAG(IS_HWASAN)
 852 // Since we scan potentially uninitialized portions of the stack, we can't run
 853 // this test under any sanitizer that checks for uninitialized reads.
 854 TEST_F(LoggingTest, LogMessageMarkersOnStack) {
 855   const uint32_t kLogStartMarker = 0xbedead01;
 856   const uint32_t kLogEndMarker = 0x5050dead;
 857   const char kTestMessage[] = "Oh noes! I have crashed! 💩";
 858
 859   uint32_t stack_start = 0;
 860
 861   // Install a LogAssertHandler which will scan between |stack_start| and its
 862   // local-scope stack for the start & end markers, and verify the message.
 863   ScopedLogAssertHandler assert_handler(base::BindRepeating(
 864       [](uint32_t* stack_start_ptr, const char* file, int line,
 865          const base::StringPiece message, const base::StringPiece stack_trace) {
 866         uint32_t stack_end;
 867         uint32_t* stack_end_ptr = &stack_end;
 868
 869         // Scan the stack for the expected markers.
 870         uint32_t* start_marker = nullptr;
 871         uint32_t* end_marker = nullptr;
 872         for (uint32_t* ptr = stack_end_ptr; ptr <= stack_start_ptr; ++ptr) {
 873           if (*ptr == kLogStartMarker)
 874             start_marker = ptr;
 875           else if (*ptr == kLogEndMarker)
 876             end_marker = ptr;
 877         }
 878
 879         // Verify that start & end markers were found, somewhere, in-between
 880         // this and the LogAssertHandler scope, in the LogMessage destructor's
 881         // stack frame.
 882         ASSERT_TRUE(start_marker);
 883         ASSERT_TRUE(end_marker);
 884
 885         // Verify that the |message| is found in-between the markers.
 886         const char* start_char_marker =
 887             reinterpret_cast<char*>(start_marker + 1);
 888         const char* end_char_marker = reinterpret_cast<char*>(end_marker);
 889
 890         const base::StringPiece stack_view(start_char_marker,
 891                                            end_char_marker - start_char_marker);
 892         ASSERT_FALSE(stack_view.find(message) == base::StringPiece::npos);
 893       },
 894       &stack_start));
 895
 896   // Trigger a log assertion, with a test message we can check for.
 897   LOG(FATAL) << kTestMessage;
 898 }
 899 #endif  // !defined(ADDRESS_SANITIZER)
 900
 901 }  // namespace
 902
 903 }  // namespace logging