• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
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/logging.h"
6 #include "base/bind.h"
7 #include "base/callback.h"
8 #include "base/compiler_specific.h"
9 #include "base/macros.h"
10 #include "base/strings/string_piece.h"
11 #include "base/test/scoped_feature_list.h"
12 #include "build/build_config.h"
13 
14 #include "testing/gmock/include/gmock/gmock.h"
15 #include "testing/gtest/include/gtest/gtest.h"
16 
17 #if defined(OS_POSIX)
18 #include <signal.h>
19 #include <unistd.h>
20 #include "base/posix/eintr_wrapper.h"
21 #endif  // OS_POSIX
22 
23 #if defined(OS_LINUX) || defined(OS_ANDROID)
24 #include <ucontext.h>
25 #endif
26 
27 #if defined(OS_WIN)
28 #include <excpt.h>
29 #include <windows.h>
30 #endif  // OS_WIN
31 
32 #if defined(OS_FUCHSIA)
33 #include <lib/zx/event.h>
34 #include <lib/zx/port.h>
35 #include <lib/zx/process.h>
36 #include <lib/zx/thread.h>
37 #include <lib/zx/time.h>
38 #include <zircon/process.h>
39 #include <zircon/syscalls/debug.h>
40 #include <zircon/syscalls/port.h>
41 #include <zircon/types.h>
42 #include "base/fuchsia/fuchsia_logging.h"
43 #endif
44 
45 namespace logging {
46 
47 namespace {
48 
49 using ::testing::Return;
50 using ::testing::_;
51 
52 // Needs to be global since log assert handlers can't maintain state.
53 int g_log_sink_call_count = 0;
54 
55 #if !defined(OFFICIAL_BUILD) || defined(DCHECK_ALWAYS_ON) || !defined(NDEBUG)
LogSink(const char * file,int line,const base::StringPiece message,const base::StringPiece stack_trace)56 void LogSink(const char* file,
57              int line,
58              const base::StringPiece message,
59              const base::StringPiece stack_trace) {
60   ++g_log_sink_call_count;
61 }
62 #endif
63 
64 // Class to make sure any manipulations we do to the min log level are
65 // contained (i.e., do not affect other unit tests).
66 class LogStateSaver {
67  public:
LogStateSaver()68   LogStateSaver() : old_min_log_level_(GetMinLogLevel()) {}
69 
~LogStateSaver()70   ~LogStateSaver() {
71     SetMinLogLevel(old_min_log_level_);
72     g_log_sink_call_count = 0;
73   }
74 
75  private:
76   int old_min_log_level_;
77 
78   DISALLOW_COPY_AND_ASSIGN(LogStateSaver);
79 };
80 
81 class LoggingTest : public testing::Test {
82  private:
83   LogStateSaver log_state_saver_;
84 };
85 
86 class MockLogSource {
87  public:
88   MOCK_METHOD0(Log, const char*());
89 };
90 
91 class MockLogAssertHandler {
92  public:
93   MOCK_METHOD4(
94       HandleLogAssert,
95       void(const char*, int, const base::StringPiece, const base::StringPiece));
96 };
97 
TEST_F(LoggingTest,BasicLogging)98 TEST_F(LoggingTest, BasicLogging) {
99   MockLogSource mock_log_source;
100   EXPECT_CALL(mock_log_source, Log())
101       .Times(DCHECK_IS_ON() ? 16 : 8)
102       .WillRepeatedly(Return("log message"));
103 
104   SetMinLogLevel(LOG_INFO);
105 
106   EXPECT_TRUE(LOG_IS_ON(INFO));
107   EXPECT_TRUE((DCHECK_IS_ON() != 0) == DLOG_IS_ON(INFO));
108   EXPECT_TRUE(VLOG_IS_ON(0));
109 
110   LOG(INFO) << mock_log_source.Log();
111   LOG_IF(INFO, true) << mock_log_source.Log();
112   PLOG(INFO) << mock_log_source.Log();
113   PLOG_IF(INFO, true) << mock_log_source.Log();
114   VLOG(0) << mock_log_source.Log();
115   VLOG_IF(0, true) << mock_log_source.Log();
116   VPLOG(0) << mock_log_source.Log();
117   VPLOG_IF(0, true) << mock_log_source.Log();
118 
119   DLOG(INFO) << mock_log_source.Log();
120   DLOG_IF(INFO, true) << mock_log_source.Log();
121   DPLOG(INFO) << mock_log_source.Log();
122   DPLOG_IF(INFO, true) << mock_log_source.Log();
123   DVLOG(0) << mock_log_source.Log();
124   DVLOG_IF(0, true) << mock_log_source.Log();
125   DVPLOG(0) << mock_log_source.Log();
126   DVPLOG_IF(0, true) << mock_log_source.Log();
127 }
128 
TEST_F(LoggingTest,LogIsOn)129 TEST_F(LoggingTest, LogIsOn) {
130 #if defined(NDEBUG)
131   const bool kDfatalIsFatal = false;
132 #else  // defined(NDEBUG)
133   const bool kDfatalIsFatal = true;
134 #endif  // defined(NDEBUG)
135 
136   SetMinLogLevel(LOG_INFO);
137   EXPECT_TRUE(LOG_IS_ON(INFO));
138   EXPECT_TRUE(LOG_IS_ON(WARNING));
139   EXPECT_TRUE(LOG_IS_ON(ERROR));
140   EXPECT_TRUE(LOG_IS_ON(FATAL));
141   EXPECT_TRUE(LOG_IS_ON(DFATAL));
142 
143   SetMinLogLevel(LOG_WARNING);
144   EXPECT_FALSE(LOG_IS_ON(INFO));
145   EXPECT_TRUE(LOG_IS_ON(WARNING));
146   EXPECT_TRUE(LOG_IS_ON(ERROR));
147   EXPECT_TRUE(LOG_IS_ON(FATAL));
148   EXPECT_TRUE(LOG_IS_ON(DFATAL));
149 
150   SetMinLogLevel(LOG_ERROR);
151   EXPECT_FALSE(LOG_IS_ON(INFO));
152   EXPECT_FALSE(LOG_IS_ON(WARNING));
153   EXPECT_TRUE(LOG_IS_ON(ERROR));
154   EXPECT_TRUE(LOG_IS_ON(FATAL));
155   EXPECT_TRUE(LOG_IS_ON(DFATAL));
156 
157   // LOG_IS_ON(FATAL) should always be true.
158   SetMinLogLevel(LOG_FATAL + 1);
159   EXPECT_FALSE(LOG_IS_ON(INFO));
160   EXPECT_FALSE(LOG_IS_ON(WARNING));
161   EXPECT_FALSE(LOG_IS_ON(ERROR));
162   EXPECT_TRUE(LOG_IS_ON(FATAL));
163   EXPECT_EQ(kDfatalIsFatal, LOG_IS_ON(DFATAL));
164 }
165 
TEST_F(LoggingTest,LoggingIsLazyBySeverity)166 TEST_F(LoggingTest, LoggingIsLazyBySeverity) {
167   MockLogSource mock_log_source;
168   EXPECT_CALL(mock_log_source, Log()).Times(0);
169 
170   SetMinLogLevel(LOG_WARNING);
171 
172   EXPECT_FALSE(LOG_IS_ON(INFO));
173   EXPECT_FALSE(DLOG_IS_ON(INFO));
174   EXPECT_FALSE(VLOG_IS_ON(1));
175 
176   LOG(INFO) << mock_log_source.Log();
177   LOG_IF(INFO, false) << mock_log_source.Log();
178   PLOG(INFO) << mock_log_source.Log();
179   PLOG_IF(INFO, false) << mock_log_source.Log();
180   VLOG(1) << mock_log_source.Log();
181   VLOG_IF(1, true) << mock_log_source.Log();
182   VPLOG(1) << mock_log_source.Log();
183   VPLOG_IF(1, true) << mock_log_source.Log();
184 
185   DLOG(INFO) << mock_log_source.Log();
186   DLOG_IF(INFO, true) << mock_log_source.Log();
187   DPLOG(INFO) << mock_log_source.Log();
188   DPLOG_IF(INFO, true) << mock_log_source.Log();
189   DVLOG(1) << mock_log_source.Log();
190   DVLOG_IF(1, true) << mock_log_source.Log();
191   DVPLOG(1) << mock_log_source.Log();
192   DVPLOG_IF(1, true) << mock_log_source.Log();
193 }
194 
TEST_F(LoggingTest,LoggingIsLazyByDestination)195 TEST_F(LoggingTest, LoggingIsLazyByDestination) {
196   MockLogSource mock_log_source;
197   MockLogSource mock_log_source_error;
198   EXPECT_CALL(mock_log_source, Log()).Times(0);
199 
200   // Severity >= ERROR is always printed to stderr.
201   EXPECT_CALL(mock_log_source_error, Log()).Times(1).
202       WillRepeatedly(Return("log message"));
203 
204   LoggingSettings settings;
205   settings.logging_dest = LOG_NONE;
206   InitLogging(settings);
207 
208   LOG(INFO) << mock_log_source.Log();
209   LOG(WARNING) << mock_log_source.Log();
210   LOG(ERROR) << mock_log_source_error.Log();
211 }
212 
213 // Official builds have CHECKs directly call BreakDebugger.
214 #if !defined(OFFICIAL_BUILD)
215 
216 // https://crbug.com/709067 tracks test flakiness on iOS.
217 #if defined(OS_IOS)
218 #define MAYBE_CheckStreamsAreLazy DISABLED_CheckStreamsAreLazy
219 #else
220 #define MAYBE_CheckStreamsAreLazy CheckStreamsAreLazy
221 #endif
TEST_F(LoggingTest,MAYBE_CheckStreamsAreLazy)222 TEST_F(LoggingTest, MAYBE_CheckStreamsAreLazy) {
223   MockLogSource mock_log_source, uncalled_mock_log_source;
224   EXPECT_CALL(mock_log_source, Log()).Times(8).
225       WillRepeatedly(Return("check message"));
226   EXPECT_CALL(uncalled_mock_log_source, Log()).Times(0);
227 
228   ScopedLogAssertHandler scoped_assert_handler(base::Bind(LogSink));
229 
230   CHECK(mock_log_source.Log()) << uncalled_mock_log_source.Log();
231   PCHECK(!mock_log_source.Log()) << mock_log_source.Log();
232   CHECK_EQ(mock_log_source.Log(), mock_log_source.Log())
233       << uncalled_mock_log_source.Log();
234   CHECK_NE(mock_log_source.Log(), mock_log_source.Log())
235       << mock_log_source.Log();
236 }
237 
238 #endif
239 
240 #if defined(OFFICIAL_BUILD) && defined(OS_WIN)
CheckContainingFunc(int death_location)241 NOINLINE void CheckContainingFunc(int death_location) {
242   CHECK(death_location != 1);
243   CHECK(death_location != 2);
244   CHECK(death_location != 3);
245 }
246 
GetCheckExceptionData(EXCEPTION_POINTERS * p,DWORD * code,void ** addr)247 int GetCheckExceptionData(EXCEPTION_POINTERS* p, DWORD* code, void** addr) {
248   *code = p->ExceptionRecord->ExceptionCode;
249   *addr = p->ExceptionRecord->ExceptionAddress;
250   return EXCEPTION_EXECUTE_HANDLER;
251 }
252 
TEST_F(LoggingTest,CheckCausesDistinctBreakpoints)253 TEST_F(LoggingTest, CheckCausesDistinctBreakpoints) {
254   DWORD code1 = 0;
255   DWORD code2 = 0;
256   DWORD code3 = 0;
257   void* addr1 = nullptr;
258   void* addr2 = nullptr;
259   void* addr3 = nullptr;
260 
261   // Record the exception code and addresses.
262   __try {
263     CheckContainingFunc(1);
264   } __except (
265       GetCheckExceptionData(GetExceptionInformation(), &code1, &addr1)) {
266   }
267 
268   __try {
269     CheckContainingFunc(2);
270   } __except (
271       GetCheckExceptionData(GetExceptionInformation(), &code2, &addr2)) {
272   }
273 
274   __try {
275     CheckContainingFunc(3);
276   } __except (
277       GetCheckExceptionData(GetExceptionInformation(), &code3, &addr3)) {
278   }
279 
280   // Ensure that the exception codes are correct (in particular, breakpoints,
281   // not access violations).
282   EXPECT_EQ(STATUS_BREAKPOINT, code1);
283   EXPECT_EQ(STATUS_BREAKPOINT, code2);
284   EXPECT_EQ(STATUS_BREAKPOINT, code3);
285 
286   // Ensure that none of the CHECKs are colocated.
287   EXPECT_NE(addr1, addr2);
288   EXPECT_NE(addr1, addr3);
289   EXPECT_NE(addr2, addr3);
290 }
291 #elif defined(OS_FUCHSIA)
292 
293 // CHECK causes a direct crash (without jumping to another function) only in
294 // official builds. Unfortunately, continuous test coverage on official builds
295 // is lower. Furthermore, since the Fuchsia implementation uses threads, it is
296 // not possible to rely on an implementation of CHECK that calls abort(), which
297 // takes down the whole process, preventing the thread exception handler from
298 // handling the exception. DO_CHECK here falls back on IMMEDIATE_CRASH() in
299 // non-official builds, to catch regressions earlier in the CQ.
300 #if defined(OFFICIAL_BUILD)
301 #define DO_CHECK CHECK
302 #else
303 #define DO_CHECK(cond) \
304   if (!(cond)) {       \
305     IMMEDIATE_CRASH(); \
306   }
307 #endif
308 
309 static const unsigned int kExceptionPortKey = 1u;
310 static const unsigned int kThreadEndedPortKey = 2u;
311 
312 struct thread_data_t {
313   // For signaling the thread ended properly.
314   zx::unowned_event event;
315   // For registering thread termination.
316   zx::unowned_port port;
317   // Location where the thread is expected to crash.
318   int death_location;
319 };
320 
CrashThread(void * arg)321 void* CrashThread(void* arg) {
322   zx_status_t status;
323 
324   thread_data_t* data = (thread_data_t*)arg;
325   int death_location = data->death_location;
326 
327   // Register the exception handler on the port.
328   status = zx::thread::self()->bind_exception_port(*data->port,
329                                                    kExceptionPortKey, 0);
330   if (status != ZX_OK) {
331     data->event->signal(0, ZX_USER_SIGNAL_0);
332     return nullptr;
333   }
334 
335   DO_CHECK(death_location != 1);
336   DO_CHECK(death_location != 2);
337   DO_CHECK(death_location != 3);
338 
339   // We should never reach this point, signal the thread incorrectly ended
340   // properly.
341   data->event->signal(0, ZX_USER_SIGNAL_0);
342   return nullptr;
343 }
344 
345 // Runs the CrashThread function in a separate thread.
SpawnCrashThread(int death_location,uintptr_t * child_crash_addr)346 void SpawnCrashThread(int death_location, uintptr_t* child_crash_addr) {
347   zx::port port;
348   zx::event event;
349   zx_status_t status;
350 
351   status = zx::port::create(0, &port);
352   ASSERT_EQ(status, ZX_OK);
353   status = zx::event::create(0, &event);
354   ASSERT_EQ(status, ZX_OK);
355 
356   // Register the thread ended event on the port.
357   status = event.wait_async(port, kThreadEndedPortKey, ZX_USER_SIGNAL_0,
358                             ZX_WAIT_ASYNC_ONCE);
359   ASSERT_EQ(status, ZX_OK);
360 
361   // Run the thread.
362   thread_data_t thread_data = {zx::unowned_event(event), zx::unowned_port(port),
363                                death_location};
364   pthread_t thread;
365   int ret = pthread_create(&thread, nullptr, CrashThread, &thread_data);
366   ASSERT_EQ(ret, 0);
367 
368   // Wait on the port.
369   zx_port_packet_t packet;
370   status = port.wait(zx::time::infinite(), &packet);
371   ASSERT_EQ(status, ZX_OK);
372   // Check the thread did crash and not terminate.
373   ASSERT_EQ(packet.key, kExceptionPortKey);
374 
375   // Get the crash address.
376   zx::thread zircon_thread;
377   status = zx::process::self()->get_child(packet.exception.tid,
378                                           ZX_RIGHT_SAME_RIGHTS, &zircon_thread);
379   ASSERT_EQ(status, ZX_OK);
380   zx_thread_state_general_regs_t buffer;
381   status = zircon_thread.read_state(ZX_THREAD_STATE_GENERAL_REGS, &buffer,
382                                     sizeof(buffer));
383   ASSERT_EQ(status, ZX_OK);
384 #if defined(ARCH_CPU_X86_64)
385   *child_crash_addr = static_cast<uintptr_t>(buffer.rip);
386 #elif defined(ARCH_CPU_ARM64)
387   *child_crash_addr = static_cast<uintptr_t>(buffer.pc);
388 #else
389 #error Unsupported architecture
390 #endif
391 
392   status = zircon_thread.kill();
393   ASSERT_EQ(status, ZX_OK);
394 }
395 
TEST_F(LoggingTest,CheckCausesDistinctBreakpoints)396 TEST_F(LoggingTest, CheckCausesDistinctBreakpoints) {
397   uintptr_t child_crash_addr_1 = 0;
398   uintptr_t child_crash_addr_2 = 0;
399   uintptr_t child_crash_addr_3 = 0;
400 
401   SpawnCrashThread(1, &child_crash_addr_1);
402   SpawnCrashThread(2, &child_crash_addr_2);
403   SpawnCrashThread(3, &child_crash_addr_3);
404 
405   ASSERT_NE(0u, child_crash_addr_1);
406   ASSERT_NE(0u, child_crash_addr_2);
407   ASSERT_NE(0u, child_crash_addr_3);
408   ASSERT_NE(child_crash_addr_1, child_crash_addr_2);
409   ASSERT_NE(child_crash_addr_1, child_crash_addr_3);
410   ASSERT_NE(child_crash_addr_2, child_crash_addr_3);
411 }
412 #elif defined(OS_POSIX) && !defined(OS_NACL) && !defined(OS_IOS) && \
413     (defined(ARCH_CPU_X86_FAMILY) || defined(ARCH_CPU_ARM_FAMILY))
414 
415 int g_child_crash_pipe;
416 
CheckCrashTestSighandler(int,siginfo_t * info,void * context_ptr)417 void CheckCrashTestSighandler(int, siginfo_t* info, void* context_ptr) {
418   // Conversely to what clearly stated in "man 2 sigaction", some Linux kernels
419   // do NOT populate the |info->si_addr| in the case of a SIGTRAP. Hence we
420   // need the arch-specific boilerplate below, which is inspired by breakpad.
421   // At the same time, on OSX, ucontext.h is deprecated but si_addr works fine.
422   uintptr_t crash_addr = 0;
423 #if defined(OS_MACOSX)
424   crash_addr = reinterpret_cast<uintptr_t>(info->si_addr);
425 #else  // OS_POSIX && !OS_MACOSX
426   ucontext_t* context = reinterpret_cast<ucontext_t*>(context_ptr);
427 #if defined(ARCH_CPU_X86)
428   crash_addr = static_cast<uintptr_t>(context->uc_mcontext.gregs[REG_EIP]);
429 #elif defined(ARCH_CPU_X86_64)
430   crash_addr = static_cast<uintptr_t>(context->uc_mcontext.gregs[REG_RIP]);
431 #elif defined(ARCH_CPU_ARMEL)
432   crash_addr = static_cast<uintptr_t>(context->uc_mcontext.arm_pc);
433 #elif defined(ARCH_CPU_ARM64)
434   crash_addr = static_cast<uintptr_t>(context->uc_mcontext.pc);
435 #endif  // ARCH_*
436 #endif  // OS_POSIX && !OS_MACOSX
437   HANDLE_EINTR(write(g_child_crash_pipe, &crash_addr, sizeof(uintptr_t)));
438   _exit(0);
439 }
440 
441 // CHECK causes a direct crash (without jumping to another function) only in
442 // official builds. Unfortunately, continuous test coverage on official builds
443 // is lower. DO_CHECK here falls back on a home-brewed implementation in
444 // non-official builds, to catch regressions earlier in the CQ.
445 #if defined(OFFICIAL_BUILD)
446 #define DO_CHECK CHECK
447 #else
448 #define DO_CHECK(cond) \
449   if (!(cond))         \
450   IMMEDIATE_CRASH()
451 #endif
452 
CrashChildMain(int death_location)453 void CrashChildMain(int death_location) {
454   struct sigaction act = {};
455   act.sa_sigaction = CheckCrashTestSighandler;
456   act.sa_flags = SA_SIGINFO;
457   ASSERT_EQ(0, sigaction(SIGTRAP, &act, nullptr));
458   ASSERT_EQ(0, sigaction(SIGBUS, &act, nullptr));
459   ASSERT_EQ(0, sigaction(SIGILL, &act, nullptr));
460   DO_CHECK(death_location != 1);
461   DO_CHECK(death_location != 2);
462   printf("\n");
463   DO_CHECK(death_location != 3);
464 
465   // Should never reach this point.
466   const uintptr_t failed = 0;
467   HANDLE_EINTR(write(g_child_crash_pipe, &failed, sizeof(uintptr_t)));
468 };
469 
SpawnChildAndCrash(int death_location,uintptr_t * child_crash_addr)470 void SpawnChildAndCrash(int death_location, uintptr_t* child_crash_addr) {
471   int pipefd[2];
472   ASSERT_EQ(0, pipe(pipefd));
473 
474   int pid = fork();
475   ASSERT_GE(pid, 0);
476 
477   if (pid == 0) {      // child process.
478     close(pipefd[0]);  // Close reader (parent) end.
479     g_child_crash_pipe = pipefd[1];
480     CrashChildMain(death_location);
481     FAIL() << "The child process was supposed to crash. It didn't.";
482   }
483 
484   close(pipefd[1]);  // Close writer (child) end.
485   DCHECK(child_crash_addr);
486   int res = HANDLE_EINTR(read(pipefd[0], child_crash_addr, sizeof(uintptr_t)));
487   ASSERT_EQ(static_cast<int>(sizeof(uintptr_t)), res);
488 }
489 
TEST_F(LoggingTest,CheckCausesDistinctBreakpoints)490 TEST_F(LoggingTest, CheckCausesDistinctBreakpoints) {
491   uintptr_t child_crash_addr_1 = 0;
492   uintptr_t child_crash_addr_2 = 0;
493   uintptr_t child_crash_addr_3 = 0;
494 
495   SpawnChildAndCrash(1, &child_crash_addr_1);
496   SpawnChildAndCrash(2, &child_crash_addr_2);
497   SpawnChildAndCrash(3, &child_crash_addr_3);
498 
499   ASSERT_NE(0u, child_crash_addr_1);
500   ASSERT_NE(0u, child_crash_addr_2);
501   ASSERT_NE(0u, child_crash_addr_3);
502   ASSERT_NE(child_crash_addr_1, child_crash_addr_2);
503   ASSERT_NE(child_crash_addr_1, child_crash_addr_3);
504   ASSERT_NE(child_crash_addr_2, child_crash_addr_3);
505 }
506 #endif  // OS_POSIX
507 
TEST_F(LoggingTest,DebugLoggingReleaseBehavior)508 TEST_F(LoggingTest, DebugLoggingReleaseBehavior) {
509 #if DCHECK_IS_ON()
510   int debug_only_variable = 1;
511 #endif
512   // These should avoid emitting references to |debug_only_variable|
513   // in release mode.
514   DLOG_IF(INFO, debug_only_variable) << "test";
515   DLOG_ASSERT(debug_only_variable) << "test";
516   DPLOG_IF(INFO, debug_only_variable) << "test";
517   DVLOG_IF(1, debug_only_variable) << "test";
518 }
519 
TEST_F(LoggingTest,DcheckStreamsAreLazy)520 TEST_F(LoggingTest, DcheckStreamsAreLazy) {
521   MockLogSource mock_log_source;
522   EXPECT_CALL(mock_log_source, Log()).Times(0);
523 #if DCHECK_IS_ON()
524   DCHECK(true) << mock_log_source.Log();
525   DCHECK_EQ(0, 0) << mock_log_source.Log();
526 #else
527   DCHECK(mock_log_source.Log()) << mock_log_source.Log();
528   DPCHECK(mock_log_source.Log()) << mock_log_source.Log();
529   DCHECK_EQ(0, 0) << mock_log_source.Log();
530   DCHECK_EQ(mock_log_source.Log(), static_cast<const char*>(nullptr))
531       << mock_log_source.Log();
532 #endif
533 }
534 
DcheckEmptyFunction1()535 void DcheckEmptyFunction1() {
536   // Provide a body so that Release builds do not cause the compiler to
537   // optimize DcheckEmptyFunction1 and DcheckEmptyFunction2 as a single
538   // function, which breaks the Dcheck tests below.
539   LOG(INFO) << "DcheckEmptyFunction1";
540 }
DcheckEmptyFunction2()541 void DcheckEmptyFunction2() {}
542 
543 #if DCHECK_IS_CONFIGURABLE
544 class ScopedDcheckSeverity {
545  public:
ScopedDcheckSeverity(LogSeverity new_severity)546   ScopedDcheckSeverity(LogSeverity new_severity) : old_severity_(LOG_DCHECK) {
547     LOG_DCHECK = new_severity;
548   }
549 
~ScopedDcheckSeverity()550   ~ScopedDcheckSeverity() { LOG_DCHECK = old_severity_; }
551 
552  private:
553   LogSeverity old_severity_;
554 };
555 #endif  // DCHECK_IS_CONFIGURABLE
556 
557 // https://crbug.com/709067 tracks test flakiness on iOS.
558 #if defined(OS_IOS)
559 #define MAYBE_Dcheck DISABLED_Dcheck
560 #else
561 #define MAYBE_Dcheck Dcheck
562 #endif
TEST_F(LoggingTest,MAYBE_Dcheck)563 TEST_F(LoggingTest, MAYBE_Dcheck) {
564 #if DCHECK_IS_CONFIGURABLE
565   // DCHECKs are enabled, and LOG_DCHECK is mutable, but defaults to non-fatal.
566   // Set it to LOG_FATAL to get the expected behavior from the rest of this
567   // test.
568   ScopedDcheckSeverity dcheck_severity(LOG_FATAL);
569 #endif  // DCHECK_IS_CONFIGURABLE
570 
571 #if defined(NDEBUG) && !defined(DCHECK_ALWAYS_ON)
572   // Release build.
573   EXPECT_FALSE(DCHECK_IS_ON());
574   EXPECT_FALSE(DLOG_IS_ON(DCHECK));
575 #elif defined(NDEBUG) && defined(DCHECK_ALWAYS_ON)
576   // Release build with real DCHECKS.
577   ScopedLogAssertHandler scoped_assert_handler(base::Bind(LogSink));
578   EXPECT_TRUE(DCHECK_IS_ON());
579   EXPECT_TRUE(DLOG_IS_ON(DCHECK));
580 #else
581   // Debug build.
582   ScopedLogAssertHandler scoped_assert_handler(base::Bind(LogSink));
583   EXPECT_TRUE(DCHECK_IS_ON());
584   EXPECT_TRUE(DLOG_IS_ON(DCHECK));
585 #endif
586 
587   // DCHECKs are fatal iff they're compiled in DCHECK_IS_ON() and the DCHECK
588   // log level is set to fatal.
589   const bool dchecks_are_fatal = DCHECK_IS_ON() && LOG_DCHECK == LOG_FATAL;
590   EXPECT_EQ(0, g_log_sink_call_count);
591   DCHECK(false);
592   EXPECT_EQ(dchecks_are_fatal ? 1 : 0, g_log_sink_call_count);
593   DPCHECK(false);
594   EXPECT_EQ(dchecks_are_fatal ? 2 : 0, g_log_sink_call_count);
595   DCHECK_EQ(0, 1);
596   EXPECT_EQ(dchecks_are_fatal ? 3 : 0, g_log_sink_call_count);
597 
598   // Test DCHECK on std::nullptr_t
599   g_log_sink_call_count = 0;
600   const void* p_null = nullptr;
601   const void* p_not_null = &p_null;
602   DCHECK_EQ(p_null, nullptr);
603   DCHECK_EQ(nullptr, p_null);
604   DCHECK_NE(p_not_null, nullptr);
605   DCHECK_NE(nullptr, p_not_null);
606   EXPECT_EQ(0, g_log_sink_call_count);
607 
608   // Test DCHECK on a scoped enum.
609   enum class Animal { DOG, CAT };
610   DCHECK_EQ(Animal::DOG, Animal::DOG);
611   EXPECT_EQ(0, g_log_sink_call_count);
612   DCHECK_EQ(Animal::DOG, Animal::CAT);
613   EXPECT_EQ(dchecks_are_fatal ? 1 : 0, g_log_sink_call_count);
614 
615   // Test DCHECK on functions and function pointers.
616   g_log_sink_call_count = 0;
617   struct MemberFunctions {
618     void MemberFunction1() {
619       // See the comment in DcheckEmptyFunction1().
620       LOG(INFO) << "Do not merge with MemberFunction2.";
621     }
622     void MemberFunction2() {}
623   };
624   void (MemberFunctions::*mp1)() = &MemberFunctions::MemberFunction1;
625   void (MemberFunctions::*mp2)() = &MemberFunctions::MemberFunction2;
626   void (*fp1)() = DcheckEmptyFunction1;
627   void (*fp2)() = DcheckEmptyFunction2;
628   void (*fp3)() = DcheckEmptyFunction1;
629   DCHECK_EQ(fp1, fp3);
630   EXPECT_EQ(0, g_log_sink_call_count);
631   DCHECK_EQ(mp1, &MemberFunctions::MemberFunction1);
632   EXPECT_EQ(0, g_log_sink_call_count);
633   DCHECK_EQ(mp2, &MemberFunctions::MemberFunction2);
634   EXPECT_EQ(0, g_log_sink_call_count);
635   DCHECK_EQ(fp1, fp2);
636   EXPECT_EQ(dchecks_are_fatal ? 1 : 0, g_log_sink_call_count);
637   DCHECK_EQ(mp2, &MemberFunctions::MemberFunction1);
638   EXPECT_EQ(dchecks_are_fatal ? 2 : 0, g_log_sink_call_count);
639 }
640 
TEST_F(LoggingTest,DcheckReleaseBehavior)641 TEST_F(LoggingTest, DcheckReleaseBehavior) {
642   int some_variable = 1;
643   // These should still reference |some_variable| so we don't get
644   // unused variable warnings.
645   DCHECK(some_variable) << "test";
646   DPCHECK(some_variable) << "test";
647   DCHECK_EQ(some_variable, 1) << "test";
648 }
649 
TEST_F(LoggingTest,DCheckEqStatements)650 TEST_F(LoggingTest, DCheckEqStatements) {
651   bool reached = false;
652   if (false)
653     DCHECK_EQ(false, true);           // Unreached.
654   else
655     DCHECK_EQ(true, reached = true);  // Reached, passed.
656   ASSERT_EQ(DCHECK_IS_ON() ? true : false, reached);
657 
658   if (false)
659     DCHECK_EQ(false, true);           // Unreached.
660 }
661 
TEST_F(LoggingTest,CheckEqStatements)662 TEST_F(LoggingTest, CheckEqStatements) {
663   bool reached = false;
664   if (false)
665     CHECK_EQ(false, true);           // Unreached.
666   else
667     CHECK_EQ(true, reached = true);  // Reached, passed.
668   ASSERT_TRUE(reached);
669 
670   if (false)
671     CHECK_EQ(false, true);           // Unreached.
672 }
673 
TEST_F(LoggingTest,NestedLogAssertHandlers)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::Bind(
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::Bind(
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 {};
operator <<(std::ostream & out,const Streamable &)718   ALLOW_UNUSED_TYPE std::ostream& operator<<(std::ostream& out,
719                                              const Streamable&) {
720     return out << "Streamable";
721   }
TEST_F(LoggingTest,StreamingWstringFindsCorrectOperator)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 #if DCHECK_IS_CONFIGURABLE
TEST_F(LoggingTest,ConfigurableDCheck)731 TEST_F(LoggingTest, ConfigurableDCheck) {
732   // Verify that DCHECKs default to non-fatal in configurable-DCHECK builds.
733   // Note that we require only that DCHECK is non-fatal by default, rather
734   // than requiring that it be exactly INFO, ERROR, etc level.
735   EXPECT_LT(LOG_DCHECK, LOG_FATAL);
736   DCHECK(false);
737 
738   // Verify that DCHECK* aren't hard-wired to crash on failure.
739   LOG_DCHECK = LOG_INFO;
740   DCHECK(false);
741   DCHECK_EQ(1, 2);
742 
743   // Verify that DCHECK does crash if LOG_DCHECK is set to LOG_FATAL.
744   LOG_DCHECK = LOG_FATAL;
745 
746   ::testing::StrictMock<MockLogAssertHandler> handler;
747   EXPECT_CALL(handler, HandleLogAssert(_, _, _, _)).Times(2);
748   {
749     logging::ScopedLogAssertHandler scoped_handler_b(base::Bind(
750         &MockLogAssertHandler::HandleLogAssert, base::Unretained(&handler)));
751     DCHECK(false);
752     DCHECK_EQ(1, 2);
753   }
754 }
755 
TEST_F(LoggingTest,ConfigurableDCheckFeature)756 TEST_F(LoggingTest, ConfigurableDCheckFeature) {
757   // Initialize FeatureList with and without DcheckIsFatal, and verify the
758   // value of LOG_DCHECK. Note that we don't require that DCHECK take a
759   // specific value when the feature is off, only that it is non-fatal.
760 
761   {
762     base::test::ScopedFeatureList feature_list;
763     feature_list.InitFromCommandLine("DcheckIsFatal", "");
764     EXPECT_EQ(LOG_DCHECK, LOG_FATAL);
765   }
766 
767   {
768     base::test::ScopedFeatureList feature_list;
769     feature_list.InitFromCommandLine("", "DcheckIsFatal");
770     EXPECT_LT(LOG_DCHECK, LOG_FATAL);
771   }
772 
773   // The default case is last, so we leave LOG_DCHECK in the default state.
774   {
775     base::test::ScopedFeatureList feature_list;
776     feature_list.InitFromCommandLine("", "");
777     EXPECT_LT(LOG_DCHECK, LOG_FATAL);
778   }
779 }
780 #endif  // DCHECK_IS_CONFIGURABLE
781 
782 #if defined(OS_FUCHSIA)
TEST_F(LoggingTest,FuchsiaLogging)783 TEST_F(LoggingTest, FuchsiaLogging) {
784   MockLogSource mock_log_source;
785   EXPECT_CALL(mock_log_source, Log())
786       .Times(DCHECK_IS_ON() ? 2 : 1)
787       .WillRepeatedly(Return("log message"));
788 
789   SetMinLogLevel(LOG_INFO);
790 
791   EXPECT_TRUE(LOG_IS_ON(INFO));
792   EXPECT_TRUE((DCHECK_IS_ON() != 0) == DLOG_IS_ON(INFO));
793 
794   ZX_LOG(INFO, ZX_ERR_INTERNAL) << mock_log_source.Log();
795   ZX_DLOG(INFO, ZX_ERR_INTERNAL) << mock_log_source.Log();
796 
797   ZX_CHECK(true, ZX_ERR_INTERNAL);
798   ZX_DCHECK(true, ZX_ERR_INTERNAL);
799 }
800 #endif  // defined(OS_FUCHSIA)
801 
802 }  // namespace
803 
804 }  // namespace logging
805