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