Home | History | Annotate | Download | only in base 
      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 "base/compiler_specific.h"
      6 #include "base/logging.h"
      7 #include "base/macros.h"
      8 
      9 #include "testing/gmock/include/gmock/gmock.h"
     10 #include "testing/gtest/include/gtest/gtest.h"
     11 
     12 #if defined(OS_POSIX)
     13 #include <signal.h>
     14 #include <unistd.h>
     15 #include "base/posix/eintr_wrapper.h"
     16 #endif  // OS_POSIX
     17 
     18 #if defined(OS_LINUX) || defined(OS_ANDROID)
     19 #include <ucontext.h>
     20 #endif
     21 
     22 #if defined(OS_WIN)
     23 #include <excpt.h>
     24 #include <windows.h>
     25 #endif  // OS_WIN
     26 
     27 namespace logging {
     28 
     29 namespace {
     30 
     31 using ::testing::Return;
     32 
     33 // Needs to be global since log assert handlers can't maintain state.
     34 int log_sink_call_count = 0;
     35 
     36 #if !defined(OFFICIAL_BUILD) || defined(DCHECK_ALWAYS_ON) || !defined(NDEBUG)
     37 void LogSink(const std::string& str) {
     38   ++log_sink_call_count;
     39 }
     40 #endif
     41 
     42 // Class to make sure any manipulations we do to the min log level are
     43 // contained (i.e., do not affect other unit tests).
     44 class LogStateSaver {
     45  public:
     46   LogStateSaver() : old_min_log_level_(GetMinLogLevel()) {}
     47 
     48   ~LogStateSaver() {
     49     SetMinLogLevel(old_min_log_level_);
     50     SetLogAssertHandler(NULL);
     51     log_sink_call_count = 0;
     52   }
     53 
     54  private:
     55   int old_min_log_level_;
     56 
     57   DISALLOW_COPY_AND_ASSIGN(LogStateSaver);
     58 };
     59 
     60 class LoggingTest : public testing::Test {
     61  private:
     62   LogStateSaver log_state_saver_;
     63 };
     64 
     65 class MockLogSource {
     66  public:
     67   MOCK_METHOD0(Log, const char*());
     68 };
     69 
     70 TEST_F(LoggingTest, BasicLogging) {
     71   MockLogSource mock_log_source;
     72   EXPECT_CALL(mock_log_source, Log())
     73       .Times(DCHECK_IS_ON() ? 16 : 8)
     74       .WillRepeatedly(Return("log message"));
     75 
     76   SetMinLogLevel(LOG_INFO);
     77 
     78   EXPECT_TRUE(LOG_IS_ON(INFO));
     79   EXPECT_TRUE((DCHECK_IS_ON() != 0) == DLOG_IS_ON(INFO));
     80   EXPECT_TRUE(VLOG_IS_ON(0));
     81 
     82   LOG(INFO) << mock_log_source.Log();
     83   LOG_IF(INFO, true) << mock_log_source.Log();
     84   PLOG(INFO) << mock_log_source.Log();
     85   PLOG_IF(INFO, true) << mock_log_source.Log();
     86   VLOG(0) << mock_log_source.Log();
     87   VLOG_IF(0, true) << mock_log_source.Log();
     88   VPLOG(0) << mock_log_source.Log();
     89   VPLOG_IF(0, true) << mock_log_source.Log();
     90 
     91   DLOG(INFO) << mock_log_source.Log();
     92   DLOG_IF(INFO, true) << mock_log_source.Log();
     93   DPLOG(INFO) << mock_log_source.Log();
     94   DPLOG_IF(INFO, true) << mock_log_source.Log();
     95   DVLOG(0) << mock_log_source.Log();
     96   DVLOG_IF(0, true) << mock_log_source.Log();
     97   DVPLOG(0) << mock_log_source.Log();
     98   DVPLOG_IF(0, true) << mock_log_source.Log();
     99 }
    100 
    101 TEST_F(LoggingTest, LogIsOn) {
    102 #if defined(NDEBUG)
    103   const bool kDfatalIsFatal = false;
    104 #else  // defined(NDEBUG)
    105   const bool kDfatalIsFatal = true;
    106 #endif  // defined(NDEBUG)
    107 
    108   SetMinLogLevel(LOG_INFO);
    109   EXPECT_TRUE(LOG_IS_ON(INFO));
    110   EXPECT_TRUE(LOG_IS_ON(WARNING));
    111   EXPECT_TRUE(LOG_IS_ON(ERROR));
    112   EXPECT_TRUE(LOG_IS_ON(FATAL));
    113   EXPECT_TRUE(LOG_IS_ON(DFATAL));
    114 
    115   SetMinLogLevel(LOG_WARNING);
    116   EXPECT_FALSE(LOG_IS_ON(INFO));
    117   EXPECT_TRUE(LOG_IS_ON(WARNING));
    118   EXPECT_TRUE(LOG_IS_ON(ERROR));
    119   EXPECT_TRUE(LOG_IS_ON(FATAL));
    120   EXPECT_TRUE(LOG_IS_ON(DFATAL));
    121 
    122   SetMinLogLevel(LOG_ERROR);
    123   EXPECT_FALSE(LOG_IS_ON(INFO));
    124   EXPECT_FALSE(LOG_IS_ON(WARNING));
    125   EXPECT_TRUE(LOG_IS_ON(ERROR));
    126   EXPECT_TRUE(LOG_IS_ON(FATAL));
    127   EXPECT_TRUE(LOG_IS_ON(DFATAL));
    128 
    129   // LOG_IS_ON(FATAL) should always be true.
    130   SetMinLogLevel(LOG_FATAL + 1);
    131   EXPECT_FALSE(LOG_IS_ON(INFO));
    132   EXPECT_FALSE(LOG_IS_ON(WARNING));
    133   EXPECT_FALSE(LOG_IS_ON(ERROR));
    134   EXPECT_TRUE(LOG_IS_ON(FATAL));
    135   EXPECT_TRUE(kDfatalIsFatal == LOG_IS_ON(DFATAL));
    136 }
    137 
    138 TEST_F(LoggingTest, LoggingIsLazyBySeverity) {
    139   MockLogSource mock_log_source;
    140   EXPECT_CALL(mock_log_source, Log()).Times(0);
    141 
    142   SetMinLogLevel(LOG_WARNING);
    143 
    144   EXPECT_FALSE(LOG_IS_ON(INFO));
    145   EXPECT_FALSE(DLOG_IS_ON(INFO));
    146   EXPECT_FALSE(VLOG_IS_ON(1));
    147 
    148   LOG(INFO) << mock_log_source.Log();
    149   LOG_IF(INFO, false) << mock_log_source.Log();
    150   PLOG(INFO) << mock_log_source.Log();
    151   PLOG_IF(INFO, false) << mock_log_source.Log();
    152   VLOG(1) << mock_log_source.Log();
    153   VLOG_IF(1, true) << mock_log_source.Log();
    154   VPLOG(1) << mock_log_source.Log();
    155   VPLOG_IF(1, true) << mock_log_source.Log();
    156 
    157   DLOG(INFO) << mock_log_source.Log();
    158   DLOG_IF(INFO, true) << mock_log_source.Log();
    159   DPLOG(INFO) << mock_log_source.Log();
    160   DPLOG_IF(INFO, true) << mock_log_source.Log();
    161   DVLOG(1) << mock_log_source.Log();
    162   DVLOG_IF(1, true) << mock_log_source.Log();
    163   DVPLOG(1) << mock_log_source.Log();
    164   DVPLOG_IF(1, true) << mock_log_source.Log();
    165 }
    166 
    167 TEST_F(LoggingTest, LoggingIsLazyByDestination) {
    168   MockLogSource mock_log_source;
    169   MockLogSource mock_log_source_error;
    170   EXPECT_CALL(mock_log_source, Log()).Times(0);
    171 
    172   // Severity >= ERROR is always printed to stderr.
    173   EXPECT_CALL(mock_log_source_error, Log()).Times(1).
    174       WillRepeatedly(Return("log message"));
    175 
    176   LoggingSettings settings;
    177   settings.logging_dest = LOG_NONE;
    178   InitLogging(settings);
    179 
    180   LOG(INFO) << mock_log_source.Log();
    181   LOG(WARNING) << mock_log_source.Log();
    182   LOG(ERROR) << mock_log_source_error.Log();
    183 }
    184 
    185 // Official builds have CHECKs directly call BreakDebugger.
    186 #if !defined(OFFICIAL_BUILD)
    187 
    188 TEST_F(LoggingTest, CheckStreamsAreLazy) {
    189   MockLogSource mock_log_source, uncalled_mock_log_source;
    190   EXPECT_CALL(mock_log_source, Log()).Times(8).
    191       WillRepeatedly(Return("check message"));
    192   EXPECT_CALL(uncalled_mock_log_source, Log()).Times(0);
    193 
    194   SetLogAssertHandler(&LogSink);
    195 
    196   CHECK(mock_log_source.Log()) << uncalled_mock_log_source.Log();
    197   PCHECK(!mock_log_source.Log()) << mock_log_source.Log();
    198   CHECK_EQ(mock_log_source.Log(), mock_log_source.Log())
    199       << uncalled_mock_log_source.Log();
    200   CHECK_NE(mock_log_source.Log(), mock_log_source.Log())
    201       << mock_log_source.Log();
    202 }
    203 
    204 #endif
    205 
    206 #if defined(OFFICIAL_BUILD) && defined(OS_WIN)
    207 NOINLINE void CheckContainingFunc(int death_location) {
    208   CHECK(death_location != 1);
    209   CHECK(death_location != 2);
    210   CHECK(death_location != 3);
    211 }
    212 
    213 int GetCheckExceptionData(EXCEPTION_POINTERS* p, DWORD* code, void** addr) {
    214   *code = p->ExceptionRecord->ExceptionCode;
    215   *addr = p->ExceptionRecord->ExceptionAddress;
    216   return EXCEPTION_EXECUTE_HANDLER;
    217 }
    218 
    219 TEST_F(LoggingTest, CheckCausesDistinctBreakpoints) {
    220   DWORD code1 = 0;
    221   DWORD code2 = 0;
    222   DWORD code3 = 0;
    223   void* addr1 = nullptr;
    224   void* addr2 = nullptr;
    225   void* addr3 = nullptr;
    226 
    227   // Record the exception code and addresses.
    228   __try {
    229     CheckContainingFunc(1);
    230   } __except (
    231       GetCheckExceptionData(GetExceptionInformation(), &code1, &addr1)) {
    232   }
    233 
    234   __try {
    235     CheckContainingFunc(2);
    236   } __except (
    237       GetCheckExceptionData(GetExceptionInformation(), &code2, &addr2)) {
    238   }
    239 
    240   __try {
    241     CheckContainingFunc(3);
    242   } __except (
    243       GetCheckExceptionData(GetExceptionInformation(), &code3, &addr3)) {
    244   }
    245 
    246   // Ensure that the exception codes are correct (in particular, breakpoints,
    247   // not access violations).
    248   EXPECT_EQ(STATUS_BREAKPOINT, code1);
    249   EXPECT_EQ(STATUS_BREAKPOINT, code2);
    250   EXPECT_EQ(STATUS_BREAKPOINT, code3);
    251 
    252   // Ensure that none of the CHECKs are colocated.
    253   EXPECT_NE(addr1, addr2);
    254   EXPECT_NE(addr1, addr3);
    255   EXPECT_NE(addr2, addr3);
    256 }
    257 
    258 #elif defined(OS_POSIX) && !defined(OS_NACL) && !defined(OS_IOS) && \
    259     (defined(ARCH_CPU_X86_FAMILY) || defined(ARCH_CPU_ARM_FAMILY))
    260 
    261 int g_child_crash_pipe;
    262 
    263 void CheckCrashTestSighandler(int, siginfo_t* info, void* context_ptr) {
    264   // Conversely to what clearly stated in "man 2 sigaction", some Linux kernels
    265   // do NOT populate the |info->si_addr| in the case of a SIGTRAP. Hence we
    266   // need the arch-specific boilerplate below, which is inspired by breakpad.
    267   // At the same time, on OSX, ucontext.h is deprecated but si_addr works fine.
    268   uintptr_t crash_addr = 0;
    269 #if defined(OS_MACOSX)
    270   crash_addr = reinterpret_cast<uintptr_t>(info->si_addr);
    271 #else  // OS_POSIX && !OS_MACOSX
    272   struct ucontext* context = reinterpret_cast<struct ucontext*>(context_ptr);
    273 #if defined(ARCH_CPU_X86)
    274   crash_addr = static_cast<uintptr_t>(context->uc_mcontext.gregs[REG_EIP]);
    275 #elif defined(ARCH_CPU_X86_64)
    276   crash_addr = static_cast<uintptr_t>(context->uc_mcontext.gregs[REG_RIP]);
    277 #elif defined(ARCH_CPU_ARMEL)
    278   crash_addr = static_cast<uintptr_t>(context->uc_mcontext.arm_pc);
    279 #elif defined(ARCH_CPU_ARM64)
    280   crash_addr = static_cast<uintptr_t>(context->uc_mcontext.pc);
    281 #endif  // ARCH_*
    282 #endif  // OS_POSIX && !OS_MACOSX
    283   HANDLE_EINTR(write(g_child_crash_pipe, &crash_addr, sizeof(uintptr_t)));
    284   _exit(0);
    285 }
    286 
    287 // CHECK causes a direct crash (without jumping to another function) only in
    288 // official builds. Unfortunately, continuous test coverage on official builds
    289 // is lower. DO_CHECK here falls back on a home-brewed implementation in
    290 // non-official builds, to catch regressions earlier in the CQ.
    291 #if defined(OFFICIAL_BUILD)
    292 #define DO_CHECK CHECK
    293 #else
    294 #define DO_CHECK(cond) \
    295   if (!(cond))         \
    296   IMMEDIATE_CRASH()
    297 #endif
    298 
    299 void CrashChildMain(int death_location) {
    300   struct sigaction act = {};
    301   act.sa_sigaction = CheckCrashTestSighandler;
    302   act.sa_flags = SA_SIGINFO;
    303   ASSERT_EQ(0, sigaction(SIGTRAP, &act, NULL));
    304   ASSERT_EQ(0, sigaction(SIGBUS, &act, NULL));
    305   ASSERT_EQ(0, sigaction(SIGILL, &act, NULL));
    306   DO_CHECK(death_location != 1);
    307   DO_CHECK(death_location != 2);
    308   printf("\n");
    309   DO_CHECK(death_location != 3);
    310 
    311   // Should never reach this point.
    312   const uintptr_t failed = 0;
    313   HANDLE_EINTR(write(g_child_crash_pipe, &failed, sizeof(uintptr_t)));
    314 };
    315 
    316 void SpawnChildAndCrash(int death_location, uintptr_t* child_crash_addr) {
    317   int pipefd[2];
    318   ASSERT_EQ(0, pipe(pipefd));
    319 
    320   int pid = fork();
    321   ASSERT_GE(pid, 0);
    322 
    323   if (pid == 0) {      // child process.
    324     close(pipefd[0]);  // Close reader (parent) end.
    325     g_child_crash_pipe = pipefd[1];
    326     CrashChildMain(death_location);
    327     FAIL() << "The child process was supposed to crash. It didn't.";
    328   }
    329 
    330   close(pipefd[1]);  // Close writer (child) end.
    331   DCHECK(child_crash_addr);
    332   int res = HANDLE_EINTR(read(pipefd[0], child_crash_addr, sizeof(uintptr_t)));
    333   ASSERT_EQ(static_cast<int>(sizeof(uintptr_t)), res);
    334 }
    335 
    336 TEST_F(LoggingTest, CheckCausesDistinctBreakpoints) {
    337   uintptr_t child_crash_addr_1 = 0;
    338   uintptr_t child_crash_addr_2 = 0;
    339   uintptr_t child_crash_addr_3 = 0;
    340 
    341   SpawnChildAndCrash(1, &child_crash_addr_1);
    342   SpawnChildAndCrash(2, &child_crash_addr_2);
    343   SpawnChildAndCrash(3, &child_crash_addr_3);
    344 
    345   ASSERT_NE(0u, child_crash_addr_1);
    346   ASSERT_NE(0u, child_crash_addr_2);
    347   ASSERT_NE(0u, child_crash_addr_3);
    348   ASSERT_NE(child_crash_addr_1, child_crash_addr_2);
    349   ASSERT_NE(child_crash_addr_1, child_crash_addr_3);
    350   ASSERT_NE(child_crash_addr_2, child_crash_addr_3);
    351 }
    352 #endif  // OS_POSIX
    353 
    354 TEST_F(LoggingTest, DebugLoggingReleaseBehavior) {
    355 #if !defined(NDEBUG) || defined(DCHECK_ALWAYS_ON)
    356   int debug_only_variable = 1;
    357 #endif
    358   // These should avoid emitting references to |debug_only_variable|
    359   // in release mode.
    360   DLOG_IF(INFO, debug_only_variable) << "test";
    361   DLOG_ASSERT(debug_only_variable) << "test";
    362   DPLOG_IF(INFO, debug_only_variable) << "test";
    363   DVLOG_IF(1, debug_only_variable) << "test";
    364 }
    365 
    366 TEST_F(LoggingTest, DcheckStreamsAreLazy) {
    367   MockLogSource mock_log_source;
    368   EXPECT_CALL(mock_log_source, Log()).Times(0);
    369 #if DCHECK_IS_ON()
    370   DCHECK(true) << mock_log_source.Log();
    371   DCHECK_EQ(0, 0) << mock_log_source.Log();
    372 #else
    373   DCHECK(mock_log_source.Log()) << mock_log_source.Log();
    374   DPCHECK(mock_log_source.Log()) << mock_log_source.Log();
    375   DCHECK_EQ(0, 0) << mock_log_source.Log();
    376   DCHECK_EQ(mock_log_source.Log(), static_cast<const char*>(NULL))
    377       << mock_log_source.Log();
    378 #endif
    379 }
    380 
    381 void DcheckEmptyFunction1() {
    382   // Provide a body so that Release builds do not cause the compiler to
    383   // optimize DcheckEmptyFunction1 and DcheckEmptyFunction2 as a single
    384   // function, which breaks the Dcheck tests below.
    385   LOG(INFO) << "DcheckEmptyFunction1";
    386 }
    387 void DcheckEmptyFunction2() {}
    388 
    389 TEST_F(LoggingTest, Dcheck) {
    390 #if defined(NDEBUG) && !defined(DCHECK_ALWAYS_ON)
    391   // Release build.
    392   EXPECT_FALSE(DCHECK_IS_ON());
    393   EXPECT_FALSE(DLOG_IS_ON(DCHECK));
    394 #elif defined(NDEBUG) && defined(DCHECK_ALWAYS_ON)
    395   // Release build with real DCHECKS.
    396   SetLogAssertHandler(&LogSink);
    397   EXPECT_TRUE(DCHECK_IS_ON());
    398   EXPECT_TRUE(DLOG_IS_ON(DCHECK));
    399 #else
    400   // Debug build.
    401   SetLogAssertHandler(&LogSink);
    402   EXPECT_TRUE(DCHECK_IS_ON());
    403   EXPECT_TRUE(DLOG_IS_ON(DCHECK));
    404 #endif
    405 
    406   EXPECT_EQ(0, log_sink_call_count);
    407   DCHECK(false);
    408   EXPECT_EQ(DCHECK_IS_ON() ? 1 : 0, log_sink_call_count);
    409   DPCHECK(false);
    410   EXPECT_EQ(DCHECK_IS_ON() ? 2 : 0, log_sink_call_count);
    411   DCHECK_EQ(0, 1);
    412   EXPECT_EQ(DCHECK_IS_ON() ? 3 : 0, log_sink_call_count);
    413 
    414   // Test DCHECK on std::nullptr_t
    415   log_sink_call_count = 0;
    416   const void* p_null = nullptr;
    417   const void* p_not_null = &p_null;
    418   DCHECK_EQ(p_null, nullptr);
    419   DCHECK_EQ(nullptr, p_null);
    420   DCHECK_NE(p_not_null, nullptr);
    421   DCHECK_NE(nullptr, p_not_null);
    422   EXPECT_EQ(0, log_sink_call_count);
    423 
    424   // Test DCHECK on a scoped enum.
    425   enum class Animal { DOG, CAT };
    426   DCHECK_EQ(Animal::DOG, Animal::DOG);
    427   EXPECT_EQ(0, log_sink_call_count);
    428   DCHECK_EQ(Animal::DOG, Animal::CAT);
    429   EXPECT_EQ(DCHECK_IS_ON() ? 1 : 0, log_sink_call_count);
    430 
    431   // Test DCHECK on functions and function pointers.
    432   log_sink_call_count = 0;
    433   struct MemberFunctions {
    434     void MemberFunction1() {
    435       // See the comment in DcheckEmptyFunction1().
    436       LOG(INFO) << "Do not merge with MemberFunction2.";
    437     }
    438     void MemberFunction2() {}
    439   };
    440   void (MemberFunctions::*mp1)() = &MemberFunctions::MemberFunction1;
    441   void (MemberFunctions::*mp2)() = &MemberFunctions::MemberFunction2;
    442   void (*fp1)() = DcheckEmptyFunction1;
    443   void (*fp2)() = DcheckEmptyFunction2;
    444   void (*fp3)() = DcheckEmptyFunction1;
    445   DCHECK_EQ(fp1, fp3);
    446   EXPECT_EQ(0, log_sink_call_count);
    447   DCHECK_EQ(mp1, &MemberFunctions::MemberFunction1);
    448   EXPECT_EQ(0, log_sink_call_count);
    449   DCHECK_EQ(mp2, &MemberFunctions::MemberFunction2);
    450   EXPECT_EQ(0, log_sink_call_count);
    451   DCHECK_EQ(fp1, fp2);
    452   EXPECT_EQ(DCHECK_IS_ON() ? 1 : 0, log_sink_call_count);
    453   DCHECK_EQ(mp2, &MemberFunctions::MemberFunction1);
    454   EXPECT_EQ(DCHECK_IS_ON() ? 2 : 0, log_sink_call_count);
    455 }
    456 
    457 TEST_F(LoggingTest, DcheckReleaseBehavior) {
    458   int some_variable = 1;
    459   // These should still reference |some_variable| so we don't get
    460   // unused variable warnings.
    461   DCHECK(some_variable) << "test";
    462   DPCHECK(some_variable) << "test";
    463   DCHECK_EQ(some_variable, 1) << "test";
    464 }
    465 
    466 TEST_F(LoggingTest, DCheckEqStatements) {
    467   bool reached = false;
    468   if (false)
    469     DCHECK_EQ(false, true);           // Unreached.
    470   else
    471     DCHECK_EQ(true, reached = true);  // Reached, passed.
    472   ASSERT_EQ(DCHECK_IS_ON() ? true : false, reached);
    473 
    474   if (false)
    475     DCHECK_EQ(false, true);           // Unreached.
    476 }
    477 
    478 TEST_F(LoggingTest, CheckEqStatements) {
    479   bool reached = false;
    480   if (false)
    481     CHECK_EQ(false, true);           // Unreached.
    482   else
    483     CHECK_EQ(true, reached = true);  // Reached, passed.
    484   ASSERT_TRUE(reached);
    485 
    486   if (false)
    487     CHECK_EQ(false, true);           // Unreached.
    488 }
    489 
    490 // Test that defining an operator<< for a type in a namespace doesn't prevent
    491 // other code in that namespace from calling the operator<<(ostream, wstring)
    492 // defined by logging.h. This can fail if operator<<(ostream, wstring) can't be
    493 // found by ADL, since defining another operator<< prevents name lookup from
    494 // looking in the global namespace.
    495 namespace nested_test {
    496   class Streamable {};
    497   ALLOW_UNUSED_TYPE std::ostream& operator<<(std::ostream& out,
    498                                              const Streamable&) {
    499     return out << "Streamable";
    500   }
    501   TEST_F(LoggingTest, StreamingWstringFindsCorrectOperator) {
    502     std::wstring wstr = L"Hello World";
    503     std::ostringstream ostr;
    504     ostr << wstr;
    505     EXPECT_EQ("Hello World", ostr.str());
    506   }
    507 }  // namespace nested_test
    508 
    509 }  // namespace
    510 
    511 }  // namespace logging
    512