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