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.
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"
22 #include "testing/gmock/include/gmock/gmock.h"
23 #include "testing/gtest/include/gtest/gtest.h"
28 #include "base/posix/eintr_wrapper.h"
31 #if defined(OS_LINUX) || defined(OS_ANDROID)
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>
56 #include "base/fuchsia/fuchsia_logging.h"
57 #include "base/fuchsia/process_context.h"
64 using ::testing::Return;
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).
71 LogStateSaver() : old_min_log_level_(GetMinLogLevel()) {}
74 SetMinLogLevel(old_min_log_level_);
78 int old_min_log_level_;
80 DISALLOW_COPY_AND_ASSIGN(LogStateSaver);
83 class LoggingTest : public testing::Test {
85 base::test::SingleThreadTaskEnvironment task_environment_{
86 base::test::SingleThreadTaskEnvironment::MainThreadType::IO};
87 LogStateSaver log_state_saver_;
92 MOCK_METHOD0(Log, const char*());
95 class MockLogAssertHandler {
99 void(const char*, int, const base::StringPiece, const base::StringPiece));
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"));
108 SetMinLogLevel(LOG_INFO);
110 EXPECT_TRUE(LOG_IS_ON(INFO));
111 EXPECT_EQ(DCHECK_IS_ON(), DLOG_IS_ON(INFO));
112 EXPECT_TRUE(VLOG_IS_ON(0));
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();
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();
133 TEST_F(LoggingTest, LogIsOn) {
135 const bool kDfatalIsFatal = false;
136 #else // defined(NDEBUG)
137 const bool kDfatalIsFatal = true;
138 #endif // defined(NDEBUG)
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));
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));
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));
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));
170 TEST_F(LoggingTest, LoggingIsLazyBySeverity) {
171 MockLogSource mock_log_source;
172 EXPECT_CALL(mock_log_source, Log()).Times(0);
174 SetMinLogLevel(LOG_WARNING);
176 EXPECT_FALSE(LOG_IS_ON(INFO));
177 EXPECT_FALSE(DLOG_IS_ON(INFO));
178 EXPECT_FALSE(VLOG_IS_ON(1));
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();
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();
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);
204 // Severity >= ERROR is always printed to stderr.
205 EXPECT_CALL(mock_log_source_error, Log()).Times(1).
206 WillRepeatedly(Return("log message"));
208 LoggingSettings settings;
209 settings.logging_dest = LOG_NONE;
210 InitLogging(settings);
212 LOG(INFO) << mock_log_source.Log();
213 LOG(WARNING) << mock_log_source.Log();
214 LOG(ERROR) << mock_log_source_error.Log();
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();
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();
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)
238 void TestForLogToStderr(int log_destinations,
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());
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();
254 InitLogging(settings);
256 // Create a file and change stderr to write to that file, to easily check
258 base::FilePath stderr_logs_path = temp_dir.GetPath().Append("stderr.log");
259 base::File stderr_logs = base::File(
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);
266 LOG(INFO) << kInfoLogMessage;
267 LOG(ERROR) << kErrorLogMessage;
269 // Restore the original stderr logging destination.
270 dup_result = dup2(stderr_backup.get(), STDERR_FILENO);
271 ASSERT_EQ(dup_result, STDERR_FILENO);
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;
281 TEST_F(LoggingTest, AlwaysLogErrorsToStderr) {
282 bool did_log_info = false;
283 bool did_log_error = false;
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);
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);
295 // ERRORs should not be logged to stderr if any destination besides FILE is
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);
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);
308 #if defined(OS_CHROMEOS)
309 TEST_F(LoggingTest, InitWithFileDescriptor) {
310 const char kErrorLogMessage[] = "something bad happened";
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");
320 LoggingSettings settings;
321 settings.logging_dest = LOG_TO_FILE;
322 settings.log_file = log_file;
323 InitLogging(settings);
325 LOG(ERROR) << kErrorLogMessage;
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);
333 TEST_F(LoggingTest, DuplicateLogFile) {
334 const char kErrorLogMessage1[] = "something really bad happened";
335 const char kErrorLogMessage2[] = "some other bad thing happened";
337 base::ScopedTempDir temp_dir;
338 ASSERT_TRUE(temp_dir.CreateUniqueTempDir());
339 base::FilePath file_log_path = temp_dir.GetPath().Append("file.log");
342 LoggingSettings settings;
343 settings.logging_dest = LOG_TO_FILE;
344 settings.log_file_path = file_log_path.value().c_str();
345 InitLogging(settings);
347 LOG(ERROR) << kErrorLogMessage1;
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();
354 fprintf(log_file_dup, "%s\n", kErrorLogMessage2);
355 fflush(log_file_dup);
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);
364 #endif // defined(OS_CHROMEOS)
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);
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;
379 TEST_F(LoggingTest, CheckCausesDistinctBreakpoints) {
383 void* addr1 = nullptr;
384 void* addr2 = nullptr;
385 void* addr3 = nullptr;
387 // Record the exception code and addresses.
389 CheckContainingFunc(1);
391 GetCheckExceptionData(GetExceptionInformation(), &code1, &addr1)) {
395 CheckContainingFunc(2);
397 GetCheckExceptionData(GetExceptionInformation(), &code2, &addr2)) {
401 CheckContainingFunc(3);
403 GetCheckExceptionData(GetExceptionInformation(), &code3, &addr3)) {
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);
412 // Ensure that none of the CHECKs are colocated.
413 EXPECT_NE(addr1, addr2);
414 EXPECT_NE(addr1, addr3);
415 EXPECT_NE(addr2, addr3);
417 #elif defined(OS_FUCHSIA)
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
429 #define DO_CHECK(cond) \
435 struct thread_data_t {
436 // For signaling the thread ended properly.
438 // For catching thread exceptions. Created by the crashing thread.
440 // Location where the thread is expected to crash.
444 // Indicates the exception channel has been created successfully.
445 constexpr zx_signals_t kChannelReadySignal = ZX_USER_SIGNAL_0;
447 // Indicates an error setting up the crash thread.
448 constexpr zx_signals_t kCrashThreadErrorSignal = ZX_USER_SIGNAL_1;
450 void* CrashThread(void* arg) {
451 thread_data_t* data = (thread_data_t*)arg;
452 int death_location = data->death_location;
454 // Register the exception handler.
456 zx::thread::self()->create_exception_channel(0, &data->channel);
457 if (status != ZX_OK) {
458 data->event.signal(0, kCrashThreadErrorSignal);
461 data->event.signal(0, kChannelReadySignal);
463 DO_CHECK(death_location != 1);
464 DO_CHECK(death_location != 2);
465 DO_CHECK(death_location != 3);
467 // We should never reach this point, signal the thread incorrectly ended
469 data->event.signal(0, kCrashThreadErrorSignal);
473 // Runs the CrashThread function in a separate thread.
474 void SpawnCrashThread(int death_location, uintptr_t* child_crash_addr) {
476 zx_status_t status = zx::event::create(0, &event);
477 ASSERT_EQ(status, ZX_OK);
480 thread_data_t thread_data = {std::move(event), zx::channel(), death_location};
482 int ret = pthread_create(&thread, nullptr, CrashThread, &thread_data);
485 // Wait for the thread to set up its exception channel.
486 zx_signals_t signals = 0;
488 thread_data.event.wait_one(kChannelReadySignal | kCrashThreadErrorSignal,
489 zx::time::infinite(), &signals);
490 ASSERT_EQ(status, ZX_OK);
491 ASSERT_EQ(signals, kChannelReadySignal);
493 // Wait for the exception and read it out of the channel.
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);
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);
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,
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);
521 #error Unsupported architecture
524 status = zircon_thread.kill();
525 ASSERT_EQ(status, ZX_OK);
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;
533 SpawnCrashThread(1, &child_crash_addr_1);
534 SpawnCrashThread(2, &child_crash_addr_2);
535 SpawnCrashThread(3, &child_crash_addr_3);
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);
544 #elif defined(OS_POSIX) && !defined(OS_NACL) && !defined(OS_IOS) && \
545 (defined(ARCH_CPU_X86_FAMILY) || defined(ARCH_CPU_ARM_FAMILY))
547 int g_child_crash_pipe;
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);
568 #endif // OS_POSIX && !OS_MACOSX
569 HANDLE_EINTR(write(g_child_crash_pipe, &crash_addr, sizeof(uintptr_t)));
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
580 #define DO_CHECK(cond) \
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);
595 DO_CHECK(death_location != 3);
597 // Should never reach this point.
598 const uintptr_t failed = 0;
599 HANDLE_EINTR(write(g_child_crash_pipe, &failed, sizeof(uintptr_t)));
602 void SpawnChildAndCrash(int death_location, uintptr_t* child_crash_addr) {
604 ASSERT_EQ(0, pipe(pipefd));
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.";
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);
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;
627 SpawnChildAndCrash(1, &child_crash_addr_1);
628 SpawnChildAndCrash(2, &child_crash_addr_2);
629 SpawnChildAndCrash(3, &child_crash_addr_3);
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);
640 TEST_F(LoggingTest, DebugLoggingReleaseBehavior) {
642 int debug_only_variable = 1;
644 // These should avoid emitting references to |debug_only_variable|
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";
652 TEST_F(LoggingTest, NestedLogAssertHandlers) {
653 ::testing::InSequence dummy;
654 ::testing::StrictMock<MockLogAssertHandler> handler_a, handler_b;
659 _, _, base::StringPiece("First assert must be caught by handler_a"),
664 _, _, base::StringPiece("Second assert must be caught by handler_b"),
670 base::StringPiece("Last assert must be caught by handler_a again"),
673 logging::ScopedLogAssertHandler scoped_handler_a(base::BindRepeating(
674 &MockLogAssertHandler::HandleLogAssert, base::Unretained(&handler_a)));
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";
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";
686 LOG(FATAL) << "Last assert must be caught by handler_a again";
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 {
696 ALLOW_UNUSED_TYPE std::ostream& operator<<(std::ostream& out,
698 return out << "Streamable";
700 TEST_F(LoggingTest, StreamingWstringFindsCorrectOperator) {
701 std::wstring wstr = L"Hello World";
702 std::ostringstream ostr;
704 EXPECT_EQ("Hello World", ostr.str());
706 } // namespace nested_test
708 #if defined(OS_FUCHSIA)
710 class TestLogListenerSafe
711 : public fuchsia::logger::testing::LogListenerSafe_TestBase {
713 TestLogListenerSafe() = default;
714 ~TestLogListenerSafe() override = default;
716 void set_on_dump_logs_done(base::OnceClosure on_dump_logs_done) {
717 on_dump_logs_done_ = std::move(on_dump_logs_done);
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;
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()));
740 void Done() override { std::move(on_dump_logs_done_).Run(); }
742 void NotImplemented_(const std::string& name) override {
743 ADD_FAILURE() << "NotImplemented_: " << name;
747 fuchsia::logger::LogListenerSafePtr log_listener_;
748 std::vector<fuchsia::logger::LogMessage> log_messages_;
749 base::OnceClosure on_dump_logs_done_;
751 DISALLOW_COPY_AND_ASSIGN(TestLogListenerSafe);
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;
759 TestLogListenerSafe listener;
760 fidl::Binding<fuchsia::logger::LogListenerSafe> binding(&listener);
762 fuchsia::logger::LogMessage logged_message;
764 base::RunLoop wait_for_message_loop;
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();
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()
781 ->Connect<fuchsia::logger::Log>();
782 listener.set_on_dump_logs_done(dump_logs);
783 logger->DumpLogsSafe(binding.NewBinding(), std::move(options));
786 // Start the first DumpLogs() call.
789 // Run until kLogMessage is received.
790 wait_for_message_loop.Run();
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()
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"));
807 SetMinLogLevel(LOG_INFO);
809 EXPECT_TRUE(LOG_IS_ON(INFO));
810 EXPECT_EQ(DCHECK_IS_ON(), DLOG_IS_ON(INFO));
812 ZX_LOG(INFO, ZX_ERR_INTERNAL) << mock_log_source.Log();
813 ZX_DLOG(INFO, ZX_ERR_INTERNAL) << mock_log_source.Log();
815 ZX_CHECK(true, ZX_ERR_INTERNAL);
816 ZX_DCHECK(true, ZX_ERR_INTERNAL);
818 #endif // defined(OS_FUCHSIA)
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;
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));
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));
846 SetLogMessageHandler(old_log_message_handler);
847 log_string_ptr = nullptr;
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! 💩";
859 uint32_t stack_start = 0;
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) {
867 uint32_t* stack_end_ptr = &stack_end;
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)
875 else if (*ptr == kLogEndMarker)
879 // Verify that start & end markers were found, somewhere, in-between
880 // this and the LogAssertHandler scope, in the LogMessage destructor's
882 ASSERT_TRUE(start_marker);
883 ASSERT_TRUE(end_marker);
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);
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);
896 // Trigger a log assertion, with a test message we can check for.
897 LOG(FATAL) << kTestMessage;
899 #endif // !defined(ADDRESS_SANITIZER)
903 } // namespace logging