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