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/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/scoped_feature_list.h"
18 #include "base/test/task_environment.h"
19 #include "build/build_config.h"
20
21 #include "testing/gmock/include/gmock/gmock.h"
22 #include "testing/gtest/include/gtest/gtest.h"
23
24 #if defined(OS_POSIX)
25 #include <signal.h>
26 #include <unistd.h>
27 #include "base/posix/eintr_wrapper.h"
28 #endif // OS_POSIX
29
30 #if defined(OS_LINUX) || defined(OS_ANDROID)
31 #include <ucontext.h>
32 #endif
33
34 #if defined(OS_WIN)
35 #include <windows.h>
36 #include <excpt.h>
37 #endif // OS_WIN
38
39 #if defined(OS_FUCHSIA)
40 #include <fuchsia/logger/cpp/fidl.h>
41 #include <fuchsia/logger/cpp/fidl_test_base.h>
42 #include <lib/fidl/cpp/binding.h>
43 #include <lib/sys/cpp/component_context.h>
44 #include <lib/zx/channel.h>
45 #include <lib/zx/event.h>
46 #include <lib/zx/exception.h>
47 #include <lib/zx/process.h>
48 #include <lib/zx/thread.h>
49 #include <lib/zx/time.h>
50 #include <zircon/process.h>
51 #include <zircon/syscalls/debug.h>
52 #include <zircon/syscalls/exception.h>
53 #include <zircon/types.h>
54
55 #include "base/fuchsia/default_context.h"
56 #include "base/fuchsia/fuchsia_logging.h"
57 #endif // OS_FUCHSIA
58
59 namespace logging {
60
61 namespace {
62
63 using ::testing::Return;
64 using ::testing::_;
65
66 // Needs to be global since log assert handlers can't maintain state.
67 int g_log_sink_call_count = 0;
68
69 #if !defined(OFFICIAL_BUILD) || defined(DCHECK_ALWAYS_ON) || !defined(NDEBUG)
LogSink(const char * file,int line,const base::StringPiece message,const base::StringPiece stack_trace)70 void LogSink(const char* file,
71 int line,
72 const base::StringPiece message,
73 const base::StringPiece stack_trace) {
74 ++g_log_sink_call_count;
75 }
76 #endif
77
78 // Class to make sure any manipulations we do to the min log level are
79 // contained (i.e., do not affect other unit tests).
80 class LogStateSaver {
81 public:
LogStateSaver()82 LogStateSaver() : old_min_log_level_(GetMinLogLevel()) {}
83
~LogStateSaver()84 ~LogStateSaver() {
85 SetMinLogLevel(old_min_log_level_);
86 g_log_sink_call_count = 0;
87 }
88
89 private:
90 int old_min_log_level_;
91
92 DISALLOW_COPY_AND_ASSIGN(LogStateSaver);
93 };
94
95 class LoggingTest : public testing::Test {
96 private:
97 base::test::SingleThreadTaskEnvironment task_environment_{
98 base::test::SingleThreadTaskEnvironment::MainThreadType::IO};
99 LogStateSaver log_state_saver_;
100 };
101
102 class MockLogSource {
103 public:
104 MOCK_METHOD0(Log, const char*());
105 };
106
107 class MockLogAssertHandler {
108 public:
109 MOCK_METHOD4(
110 HandleLogAssert,
111 void(const char*, int, const base::StringPiece, const base::StringPiece));
112 };
113
TEST_F(LoggingTest,BasicLogging)114 TEST_F(LoggingTest, BasicLogging) {
115 MockLogSource mock_log_source;
116 EXPECT_CALL(mock_log_source, Log())
117 .Times(DCHECK_IS_ON() ? 16 : 8)
118 .WillRepeatedly(Return("log message"));
119
120 SetMinLogLevel(LOG_INFO);
121
122 EXPECT_TRUE(LOG_IS_ON(INFO));
123 EXPECT_EQ(DCHECK_IS_ON(), DLOG_IS_ON(INFO));
124 EXPECT_TRUE(VLOG_IS_ON(0));
125
126 LOG(INFO) << mock_log_source.Log();
127 LOG_IF(INFO, true) << mock_log_source.Log();
128 PLOG(INFO) << mock_log_source.Log();
129 PLOG_IF(INFO, true) << mock_log_source.Log();
130 VLOG(0) << mock_log_source.Log();
131 VLOG_IF(0, true) << mock_log_source.Log();
132 VPLOG(0) << mock_log_source.Log();
133 VPLOG_IF(0, true) << mock_log_source.Log();
134
135 DLOG(INFO) << mock_log_source.Log();
136 DLOG_IF(INFO, true) << mock_log_source.Log();
137 DPLOG(INFO) << mock_log_source.Log();
138 DPLOG_IF(INFO, true) << mock_log_source.Log();
139 DVLOG(0) << mock_log_source.Log();
140 DVLOG_IF(0, true) << mock_log_source.Log();
141 DVPLOG(0) << mock_log_source.Log();
142 DVPLOG_IF(0, true) << mock_log_source.Log();
143 }
144
TEST_F(LoggingTest,LogIsOn)145 TEST_F(LoggingTest, LogIsOn) {
146 #if defined(NDEBUG)
147 const bool kDfatalIsFatal = false;
148 #else // defined(NDEBUG)
149 const bool kDfatalIsFatal = true;
150 #endif // defined(NDEBUG)
151
152 SetMinLogLevel(LOG_INFO);
153 EXPECT_TRUE(LOG_IS_ON(INFO));
154 EXPECT_TRUE(LOG_IS_ON(WARNING));
155 EXPECT_TRUE(LOG_IS_ON(ERROR));
156 EXPECT_TRUE(LOG_IS_ON(FATAL));
157 EXPECT_TRUE(LOG_IS_ON(DFATAL));
158
159 SetMinLogLevel(LOG_WARNING);
160 EXPECT_FALSE(LOG_IS_ON(INFO));
161 EXPECT_TRUE(LOG_IS_ON(WARNING));
162 EXPECT_TRUE(LOG_IS_ON(ERROR));
163 EXPECT_TRUE(LOG_IS_ON(FATAL));
164 EXPECT_TRUE(LOG_IS_ON(DFATAL));
165
166 SetMinLogLevel(LOG_ERROR);
167 EXPECT_FALSE(LOG_IS_ON(INFO));
168 EXPECT_FALSE(LOG_IS_ON(WARNING));
169 EXPECT_TRUE(LOG_IS_ON(ERROR));
170 EXPECT_TRUE(LOG_IS_ON(FATAL));
171 EXPECT_TRUE(LOG_IS_ON(DFATAL));
172
173 // LOG_IS_ON(FATAL) should always be true.
174 SetMinLogLevel(LOG_FATAL + 1);
175 EXPECT_FALSE(LOG_IS_ON(INFO));
176 EXPECT_FALSE(LOG_IS_ON(WARNING));
177 EXPECT_FALSE(LOG_IS_ON(ERROR));
178 EXPECT_TRUE(LOG_IS_ON(FATAL));
179 EXPECT_EQ(kDfatalIsFatal, LOG_IS_ON(DFATAL));
180 }
181
TEST_F(LoggingTest,LoggingIsLazyBySeverity)182 TEST_F(LoggingTest, LoggingIsLazyBySeverity) {
183 MockLogSource mock_log_source;
184 EXPECT_CALL(mock_log_source, Log()).Times(0);
185
186 SetMinLogLevel(LOG_WARNING);
187
188 EXPECT_FALSE(LOG_IS_ON(INFO));
189 EXPECT_FALSE(DLOG_IS_ON(INFO));
190 EXPECT_FALSE(VLOG_IS_ON(1));
191
192 LOG(INFO) << mock_log_source.Log();
193 LOG_IF(INFO, false) << mock_log_source.Log();
194 PLOG(INFO) << mock_log_source.Log();
195 PLOG_IF(INFO, false) << mock_log_source.Log();
196 VLOG(1) << mock_log_source.Log();
197 VLOG_IF(1, true) << mock_log_source.Log();
198 VPLOG(1) << mock_log_source.Log();
199 VPLOG_IF(1, true) << mock_log_source.Log();
200
201 DLOG(INFO) << mock_log_source.Log();
202 DLOG_IF(INFO, true) << mock_log_source.Log();
203 DPLOG(INFO) << mock_log_source.Log();
204 DPLOG_IF(INFO, true) << mock_log_source.Log();
205 DVLOG(1) << mock_log_source.Log();
206 DVLOG_IF(1, true) << mock_log_source.Log();
207 DVPLOG(1) << mock_log_source.Log();
208 DVPLOG_IF(1, true) << mock_log_source.Log();
209 }
210
TEST_F(LoggingTest,LoggingIsLazyByDestination)211 TEST_F(LoggingTest, LoggingIsLazyByDestination) {
212 MockLogSource mock_log_source;
213 MockLogSource mock_log_source_error;
214 EXPECT_CALL(mock_log_source, Log()).Times(0);
215
216 // Severity >= ERROR is always printed to stderr.
217 EXPECT_CALL(mock_log_source_error, Log()).Times(1).
218 WillRepeatedly(Return("log message"));
219
220 LoggingSettings settings;
221 settings.logging_dest = LOG_NONE;
222 InitLogging(settings);
223
224 LOG(INFO) << mock_log_source.Log();
225 LOG(WARNING) << mock_log_source.Log();
226 LOG(ERROR) << mock_log_source_error.Log();
227 }
228
229 // Check that logging to stderr is gated on LOG_TO_STDERR.
TEST_F(LoggingTest,LogToStdErrFlag)230 TEST_F(LoggingTest, LogToStdErrFlag) {
231 LoggingSettings settings;
232 settings.logging_dest = LOG_NONE;
233 InitLogging(settings);
234 MockLogSource mock_log_source;
235 EXPECT_CALL(mock_log_source, Log()).Times(0);
236 LOG(INFO) << mock_log_source.Log();
237
238 settings.logging_dest = LOG_TO_STDERR;
239 MockLogSource mock_log_source_stderr;
240 InitLogging(settings);
241 EXPECT_CALL(mock_log_source_stderr, Log()).Times(1).WillOnce(Return("foo"));
242 LOG(INFO) << mock_log_source_stderr.Log();
243 }
244
245 // Check that messages with severity ERROR or higher are always logged to
246 // stderr if no log-destinations are set, other than LOG_TO_FILE.
247 // This test is currently only POSIX-compatible.
248 #if defined(OS_POSIX) || defined(OS_FUCHSIA)
249 namespace {
TestForLogToStderr(int log_destinations,bool * did_log_info,bool * did_log_error)250 void TestForLogToStderr(int log_destinations,
251 bool* did_log_info,
252 bool* did_log_error) {
253 const char kInfoLogMessage[] = "This is an INFO level message";
254 const char kErrorLogMessage[] = "Here we have a message of level ERROR";
255 base::ScopedTempDir temp_dir;
256 ASSERT_TRUE(temp_dir.CreateUniqueTempDir());
257
258 // Set up logging.
259 LoggingSettings settings;
260 settings.logging_dest = log_destinations;
261 base::FilePath file_logs_path;
262 if (log_destinations & LOG_TO_FILE) {
263 file_logs_path = temp_dir.GetPath().Append("file.log");
264 settings.log_file_path = file_logs_path.value().c_str();
265 }
266 InitLogging(settings);
267
268 // Create a file and change stderr to write to that file, to easily check
269 // contents.
270 base::FilePath stderr_logs_path = temp_dir.GetPath().Append("stderr.log");
271 base::File stderr_logs = base::File(
272 stderr_logs_path,
273 base::File::FLAG_CREATE | base::File::FLAG_WRITE | base::File::FLAG_READ);
274 base::ScopedFD stderr_backup = base::ScopedFD(dup(STDERR_FILENO));
275 int dup_result = dup2(stderr_logs.GetPlatformFile(), STDERR_FILENO);
276 ASSERT_EQ(dup_result, STDERR_FILENO);
277
278 LOG(INFO) << kInfoLogMessage;
279 LOG(ERROR) << kErrorLogMessage;
280
281 // Restore the original stderr logging destination.
282 dup_result = dup2(stderr_backup.get(), STDERR_FILENO);
283 ASSERT_EQ(dup_result, STDERR_FILENO);
284
285 // Check which of the messages were written to stderr.
286 std::string written_logs;
287 ASSERT_TRUE(base::ReadFileToString(stderr_logs_path, &written_logs));
288 *did_log_info = written_logs.find(kInfoLogMessage) != std::string::npos;
289 *did_log_error = written_logs.find(kErrorLogMessage) != std::string::npos;
290 }
291 } // namespace
292
TEST_F(LoggingTest,AlwaysLogErrorsToStderr)293 TEST_F(LoggingTest, AlwaysLogErrorsToStderr) {
294 bool did_log_info = false;
295 bool did_log_error = false;
296
297 // When no destinations are specified, ERRORs should still log to stderr.
298 TestForLogToStderr(LOG_NONE, &did_log_info, &did_log_error);
299 EXPECT_FALSE(did_log_info);
300 EXPECT_TRUE(did_log_error);
301
302 // Logging only to a file should also log ERRORs to stderr as well.
303 TestForLogToStderr(LOG_TO_FILE, &did_log_info, &did_log_error);
304 EXPECT_FALSE(did_log_info);
305 EXPECT_TRUE(did_log_error);
306
307 // ERRORs should not be logged to stderr if any destination besides FILE is
308 // set.
309 TestForLogToStderr(LOG_TO_SYSTEM_DEBUG_LOG, &did_log_info, &did_log_error);
310 EXPECT_FALSE(did_log_info);
311 EXPECT_FALSE(did_log_error);
312
313 // Both ERRORs and INFO should be logged if LOG_TO_STDERR is set.
314 TestForLogToStderr(LOG_TO_STDERR, &did_log_info, &did_log_error);
315 EXPECT_TRUE(did_log_info);
316 EXPECT_TRUE(did_log_error);
317 }
318 #endif
319
320 #if defined(OS_CHROMEOS)
TEST_F(LoggingTest,InitWithFileDescriptor)321 TEST_F(LoggingTest, InitWithFileDescriptor) {
322 const char kErrorLogMessage[] = "something bad happened";
323
324 // Open a file to pass to the InitLogging.
325 base::ScopedTempDir temp_dir;
326 ASSERT_TRUE(temp_dir.CreateUniqueTempDir());
327 base::FilePath file_log_path = temp_dir.GetPath().Append("file.log");
328 FILE* log_file = fopen(file_log_path.value().c_str(), "w");
329 CHECK(log_file);
330
331 // Set up logging.
332 LoggingSettings settings;
333 settings.logging_dest = LOG_TO_FILE;
334 settings.log_file = log_file;
335 InitLogging(settings);
336
337 LOG(ERROR) << kErrorLogMessage;
338
339 // Check the message was written to the log file.
340 std::string written_logs;
341 ASSERT_TRUE(base::ReadFileToString(file_log_path, &written_logs));
342 ASSERT_NE(written_logs.find(kErrorLogMessage), std::string::npos);
343 }
344
TEST_F(LoggingTest,DuplicateLogFile)345 TEST_F(LoggingTest, DuplicateLogFile) {
346 const char kErrorLogMessage1[] = "something really bad happened";
347 const char kErrorLogMessage2[] = "some other bad thing happened";
348
349 base::ScopedTempDir temp_dir;
350 ASSERT_TRUE(temp_dir.CreateUniqueTempDir());
351 base::FilePath file_log_path = temp_dir.GetPath().Append("file.log");
352
353 // Set up logging.
354 LoggingSettings settings;
355 settings.logging_dest = LOG_TO_FILE;
356 settings.log_file_path = file_log_path.value().c_str();
357 InitLogging(settings);
358
359 LOG(ERROR) << kErrorLogMessage1;
360
361 // Duplicate the log FILE, close the original (to make sure we actually
362 // duplicated it), and write to the duplicate.
363 FILE* log_file_dup = DuplicateLogFILE();
364 CHECK(log_file_dup);
365 CloseLogFile();
366 fprintf(log_file_dup, "%s\n", kErrorLogMessage2);
367 fflush(log_file_dup);
368
369 // Check the messages were written to the log file.
370 std::string written_logs;
371 ASSERT_TRUE(base::ReadFileToString(file_log_path, &written_logs));
372 ASSERT_NE(written_logs.find(kErrorLogMessage1), std::string::npos);
373 ASSERT_NE(written_logs.find(kErrorLogMessage2), std::string::npos);
374 fclose(log_file_dup);
375 }
376 #endif // defined(OS_CHROMEOS)
377
378 // Official builds have CHECKs directly call BreakDebugger.
379 #if !defined(OFFICIAL_BUILD)
380
381 // https://crbug.com/709067 tracks test flakiness on iOS.
382 #if defined(OS_IOS)
383 #define MAYBE_CheckStreamsAreLazy DISABLED_CheckStreamsAreLazy
384 #else
385 #define MAYBE_CheckStreamsAreLazy CheckStreamsAreLazy
386 #endif
TEST_F(LoggingTest,MAYBE_CheckStreamsAreLazy)387 TEST_F(LoggingTest, MAYBE_CheckStreamsAreLazy) {
388 MockLogSource mock_log_source, uncalled_mock_log_source;
389 EXPECT_CALL(mock_log_source, Log()).Times(8).
390 WillRepeatedly(Return("check message"));
391 EXPECT_CALL(uncalled_mock_log_source, Log()).Times(0);
392
393 ScopedLogAssertHandler scoped_assert_handler(base::BindRepeating(LogSink));
394
395 CHECK(mock_log_source.Log()) << uncalled_mock_log_source.Log();
396 PCHECK(!mock_log_source.Log()) << mock_log_source.Log();
397 CHECK_EQ(mock_log_source.Log(), mock_log_source.Log())
398 << uncalled_mock_log_source.Log();
399 CHECK_NE(mock_log_source.Log(), mock_log_source.Log())
400 << mock_log_source.Log();
401 }
402
403 #endif
404
405 #if defined(OFFICIAL_BUILD) && defined(OS_WIN)
CheckContainingFunc(int death_location)406 NOINLINE void CheckContainingFunc(int death_location) {
407 CHECK(death_location != 1);
408 CHECK(death_location != 2);
409 CHECK(death_location != 3);
410 }
411
GetCheckExceptionData(EXCEPTION_POINTERS * p,DWORD * code,void ** addr)412 int GetCheckExceptionData(EXCEPTION_POINTERS* p, DWORD* code, void** addr) {
413 *code = p->ExceptionRecord->ExceptionCode;
414 *addr = p->ExceptionRecord->ExceptionAddress;
415 return EXCEPTION_EXECUTE_HANDLER;
416 }
417
TEST_F(LoggingTest,CheckCausesDistinctBreakpoints)418 TEST_F(LoggingTest, CheckCausesDistinctBreakpoints) {
419 DWORD code1 = 0;
420 DWORD code2 = 0;
421 DWORD code3 = 0;
422 void* addr1 = nullptr;
423 void* addr2 = nullptr;
424 void* addr3 = nullptr;
425
426 // Record the exception code and addresses.
427 __try {
428 CheckContainingFunc(1);
429 } __except (
430 GetCheckExceptionData(GetExceptionInformation(), &code1, &addr1)) {
431 }
432
433 __try {
434 CheckContainingFunc(2);
435 } __except (
436 GetCheckExceptionData(GetExceptionInformation(), &code2, &addr2)) {
437 }
438
439 __try {
440 CheckContainingFunc(3);
441 } __except (
442 GetCheckExceptionData(GetExceptionInformation(), &code3, &addr3)) {
443 }
444
445 // Ensure that the exception codes are correct (in particular, breakpoints,
446 // not access violations).
447 EXPECT_EQ(STATUS_BREAKPOINT, code1);
448 EXPECT_EQ(STATUS_BREAKPOINT, code2);
449 EXPECT_EQ(STATUS_BREAKPOINT, code3);
450
451 // Ensure that none of the CHECKs are colocated.
452 EXPECT_NE(addr1, addr2);
453 EXPECT_NE(addr1, addr3);
454 EXPECT_NE(addr2, addr3);
455 }
456 #elif defined(OS_FUCHSIA)
457
458 // CHECK causes a direct crash (without jumping to another function) only in
459 // official builds. Unfortunately, continuous test coverage on official builds
460 // is lower. Furthermore, since the Fuchsia implementation uses threads, it is
461 // not possible to rely on an implementation of CHECK that calls abort(), which
462 // takes down the whole process, preventing the thread exception handler from
463 // handling the exception. DO_CHECK here falls back on IMMEDIATE_CRASH() in
464 // non-official builds, to catch regressions earlier in the CQ.
465 #if defined(OFFICIAL_BUILD)
466 #define DO_CHECK CHECK
467 #else
468 #define DO_CHECK(cond) \
469 if (!(cond)) { \
470 IMMEDIATE_CRASH(); \
471 }
472 #endif
473
474 struct thread_data_t {
475 // For signaling the thread ended properly.
476 zx::event event;
477 // For catching thread exceptions. Created by the crashing thread.
478 zx::channel channel;
479 // Location where the thread is expected to crash.
480 int death_location;
481 };
482
483 // Indicates the exception channel has been created successfully.
484 constexpr zx_signals_t kChannelReadySignal = ZX_USER_SIGNAL_0;
485
486 // Indicates an error setting up the crash thread.
487 constexpr zx_signals_t kCrashThreadErrorSignal = ZX_USER_SIGNAL_1;
488
CrashThread(void * arg)489 void* CrashThread(void* arg) {
490 thread_data_t* data = (thread_data_t*)arg;
491 int death_location = data->death_location;
492
493 // Register the exception handler.
494 zx_status_t status =
495 zx::thread::self()->create_exception_channel(0, &data->channel);
496 if (status != ZX_OK) {
497 data->event.signal(0, kCrashThreadErrorSignal);
498 return nullptr;
499 }
500 data->event.signal(0, kChannelReadySignal);
501
502 DO_CHECK(death_location != 1);
503 DO_CHECK(death_location != 2);
504 DO_CHECK(death_location != 3);
505
506 // We should never reach this point, signal the thread incorrectly ended
507 // properly.
508 data->event.signal(0, kCrashThreadErrorSignal);
509 return nullptr;
510 }
511
512 // Runs the CrashThread function in a separate thread.
SpawnCrashThread(int death_location,uintptr_t * child_crash_addr)513 void SpawnCrashThread(int death_location, uintptr_t* child_crash_addr) {
514 zx::event event;
515 zx_status_t status = zx::event::create(0, &event);
516 ASSERT_EQ(status, ZX_OK);
517
518 // Run the thread.
519 thread_data_t thread_data = {std::move(event), zx::channel(), death_location};
520 pthread_t thread;
521 int ret = pthread_create(&thread, nullptr, CrashThread, &thread_data);
522 ASSERT_EQ(ret, 0);
523
524 // Wait for the thread to set up its exception channel.
525 zx_signals_t signals = 0;
526 status =
527 thread_data.event.wait_one(kChannelReadySignal | kCrashThreadErrorSignal,
528 zx::time::infinite(), &signals);
529 ASSERT_EQ(status, ZX_OK);
530 ASSERT_EQ(signals, kChannelReadySignal);
531
532 // Wait for the exception and read it out of the channel.
533 status =
534 thread_data.channel.wait_one(ZX_CHANNEL_READABLE | ZX_CHANNEL_PEER_CLOSED,
535 zx::time::infinite(), &signals);
536 ASSERT_EQ(status, ZX_OK);
537 // Check the thread did crash and not terminate.
538 ASSERT_FALSE(signals & ZX_CHANNEL_PEER_CLOSED);
539
540 zx_exception_info_t exception_info;
541 zx::exception exception;
542 status = thread_data.channel.read(
543 0, &exception_info, exception.reset_and_get_address(),
544 sizeof(exception_info), 1, nullptr, nullptr);
545 ASSERT_EQ(status, ZX_OK);
546
547 // Get the crash address.
548 zx::thread zircon_thread;
549 status = exception.get_thread(&zircon_thread);
550 ASSERT_EQ(status, ZX_OK);
551 zx_thread_state_general_regs_t buffer;
552 status = zircon_thread.read_state(ZX_THREAD_STATE_GENERAL_REGS, &buffer,
553 sizeof(buffer));
554 ASSERT_EQ(status, ZX_OK);
555 #if defined(ARCH_CPU_X86_64)
556 *child_crash_addr = static_cast<uintptr_t>(buffer.rip);
557 #elif defined(ARCH_CPU_ARM64)
558 *child_crash_addr = static_cast<uintptr_t>(buffer.pc);
559 #else
560 #error Unsupported architecture
561 #endif
562
563 status = zircon_thread.kill();
564 ASSERT_EQ(status, ZX_OK);
565 }
566
TEST_F(LoggingTest,CheckCausesDistinctBreakpoints)567 TEST_F(LoggingTest, CheckCausesDistinctBreakpoints) {
568 uintptr_t child_crash_addr_1 = 0;
569 uintptr_t child_crash_addr_2 = 0;
570 uintptr_t child_crash_addr_3 = 0;
571
572 SpawnCrashThread(1, &child_crash_addr_1);
573 SpawnCrashThread(2, &child_crash_addr_2);
574 SpawnCrashThread(3, &child_crash_addr_3);
575
576 ASSERT_NE(0u, child_crash_addr_1);
577 ASSERT_NE(0u, child_crash_addr_2);
578 ASSERT_NE(0u, child_crash_addr_3);
579 ASSERT_NE(child_crash_addr_1, child_crash_addr_2);
580 ASSERT_NE(child_crash_addr_1, child_crash_addr_3);
581 ASSERT_NE(child_crash_addr_2, child_crash_addr_3);
582 }
583 #elif defined(OS_POSIX) && !defined(OS_NACL) && !defined(OS_IOS) && \
584 (defined(ARCH_CPU_X86_FAMILY) || defined(ARCH_CPU_ARM_FAMILY))
585
586 int g_child_crash_pipe;
587
CheckCrashTestSighandler(int,siginfo_t * info,void * context_ptr)588 void CheckCrashTestSighandler(int, siginfo_t* info, void* context_ptr) {
589 // Conversely to what clearly stated in "man 2 sigaction", some Linux kernels
590 // do NOT populate the |info->si_addr| in the case of a SIGTRAP. Hence we
591 // need the arch-specific boilerplate below, which is inspired by breakpad.
592 // At the same time, on OSX, ucontext.h is deprecated but si_addr works fine.
593 uintptr_t crash_addr = 0;
594 #if defined(OS_MACOSX) || defined(OS_BSD)
595 crash_addr = reinterpret_cast<uintptr_t>(info->si_addr);
596 #else // OS_POSIX && !OS_MACOSX
597 struct ucontext_t* context = reinterpret_cast<ucontext_t*>(context_ptr);
598 #if defined(ARCH_CPU_X86)
599 crash_addr = static_cast<uintptr_t>(context->uc_mcontext.gregs[REG_EIP]);
600 #elif defined(ARCH_CPU_X86_64)
601 crash_addr = static_cast<uintptr_t>(context->uc_mcontext.gregs[REG_RIP]);
602 #elif defined(ARCH_CPU_ARMEL)
603 crash_addr = static_cast<uintptr_t>(context->uc_mcontext.arm_pc);
604 #elif defined(ARCH_CPU_ARM64)
605 crash_addr = static_cast<uintptr_t>(context->uc_mcontext.pc);
606 #endif // ARCH_*
607 #endif // OS_POSIX && !OS_MACOSX
608 HANDLE_EINTR(write(g_child_crash_pipe, &crash_addr, sizeof(uintptr_t)));
609 _exit(0);
610 }
611
612 // CHECK causes a direct crash (without jumping to another function) only in
613 // official builds. Unfortunately, continuous test coverage on official builds
614 // is lower. DO_CHECK here falls back on a home-brewed implementation in
615 // non-official builds, to catch regressions earlier in the CQ.
616 #if defined(OFFICIAL_BUILD)
617 #define DO_CHECK CHECK
618 #else
619 #define DO_CHECK(cond) \
620 if (!(cond)) \
621 IMMEDIATE_CRASH()
622 #endif
623
CrashChildMain(int death_location)624 void CrashChildMain(int death_location) {
625 struct sigaction act = {};
626 act.sa_sigaction = CheckCrashTestSighandler;
627 act.sa_flags = SA_SIGINFO;
628 ASSERT_EQ(0, sigaction(SIGTRAP, &act, nullptr));
629 ASSERT_EQ(0, sigaction(SIGBUS, &act, nullptr));
630 ASSERT_EQ(0, sigaction(SIGILL, &act, nullptr));
631 DO_CHECK(death_location != 1);
632 DO_CHECK(death_location != 2);
633 printf("\n");
634 DO_CHECK(death_location != 3);
635
636 // Should never reach this point.
637 const uintptr_t failed = 0;
638 HANDLE_EINTR(write(g_child_crash_pipe, &failed, sizeof(uintptr_t)));
639 }
640
SpawnChildAndCrash(int death_location,uintptr_t * child_crash_addr)641 void SpawnChildAndCrash(int death_location, uintptr_t* child_crash_addr) {
642 int pipefd[2];
643 ASSERT_EQ(0, pipe(pipefd));
644
645 int pid = fork();
646 ASSERT_GE(pid, 0);
647
648 if (pid == 0) { // child process.
649 close(pipefd[0]); // Close reader (parent) end.
650 g_child_crash_pipe = pipefd[1];
651 CrashChildMain(death_location);
652 FAIL() << "The child process was supposed to crash. It didn't.";
653 }
654
655 close(pipefd[1]); // Close writer (child) end.
656 DCHECK(child_crash_addr);
657 int res = HANDLE_EINTR(read(pipefd[0], child_crash_addr, sizeof(uintptr_t)));
658 ASSERT_EQ(static_cast<int>(sizeof(uintptr_t)), res);
659 }
660
TEST_F(LoggingTest,CheckCausesDistinctBreakpoints)661 TEST_F(LoggingTest, CheckCausesDistinctBreakpoints) {
662 uintptr_t child_crash_addr_1 = 0;
663 uintptr_t child_crash_addr_2 = 0;
664 uintptr_t child_crash_addr_3 = 0;
665
666 SpawnChildAndCrash(1, &child_crash_addr_1);
667 SpawnChildAndCrash(2, &child_crash_addr_2);
668 SpawnChildAndCrash(3, &child_crash_addr_3);
669
670 ASSERT_NE(0u, child_crash_addr_1);
671 ASSERT_NE(0u, child_crash_addr_2);
672 ASSERT_NE(0u, child_crash_addr_3);
673 ASSERT_NE(child_crash_addr_1, child_crash_addr_2);
674 ASSERT_NE(child_crash_addr_1, child_crash_addr_3);
675 ASSERT_NE(child_crash_addr_2, child_crash_addr_3);
676 }
677 #endif // OS_POSIX
678
TEST_F(LoggingTest,DebugLoggingReleaseBehavior)679 TEST_F(LoggingTest, DebugLoggingReleaseBehavior) {
680 #if DCHECK_IS_ON()
681 int debug_only_variable = 1;
682 #endif
683 // These should avoid emitting references to |debug_only_variable|
684 // in release mode.
685 DLOG_IF(INFO, debug_only_variable) << "test";
686 DLOG_ASSERT(debug_only_variable) << "test";
687 DPLOG_IF(INFO, debug_only_variable) << "test";
688 DVLOG_IF(1, debug_only_variable) << "test";
689 }
690
TEST_F(LoggingTest,DcheckStreamsAreLazy)691 TEST_F(LoggingTest, DcheckStreamsAreLazy) {
692 MockLogSource mock_log_source;
693 EXPECT_CALL(mock_log_source, Log()).Times(0);
694 #if DCHECK_IS_ON()
695 DCHECK(true) << mock_log_source.Log();
696 DCHECK_EQ(0, 0) << mock_log_source.Log();
697 #else
698 DCHECK(mock_log_source.Log()) << mock_log_source.Log();
699 DPCHECK(mock_log_source.Log()) << mock_log_source.Log();
700 DCHECK_EQ(0, 0) << mock_log_source.Log();
701 DCHECK_EQ(mock_log_source.Log(), static_cast<const char*>(nullptr))
702 << mock_log_source.Log();
703 #endif
704 }
705
DcheckEmptyFunction1()706 void DcheckEmptyFunction1() {
707 // Provide a body so that Release builds do not cause the compiler to
708 // optimize DcheckEmptyFunction1 and DcheckEmptyFunction2 as a single
709 // function, which breaks the Dcheck tests below.
710 LOG(INFO) << "DcheckEmptyFunction1";
711 }
DcheckEmptyFunction2()712 void DcheckEmptyFunction2() {}
713
714 #if defined(DCHECK_IS_CONFIGURABLE)
715 class ScopedDcheckSeverity {
716 public:
ScopedDcheckSeverity(LogSeverity new_severity)717 ScopedDcheckSeverity(LogSeverity new_severity) : old_severity_(LOG_DCHECK) {
718 LOG_DCHECK = new_severity;
719 }
720
~ScopedDcheckSeverity()721 ~ScopedDcheckSeverity() { LOG_DCHECK = old_severity_; }
722
723 private:
724 LogSeverity old_severity_;
725 };
726 #endif // defined(DCHECK_IS_CONFIGURABLE)
727
728 // https://crbug.com/709067 tracks test flakiness on iOS.
729 #if defined(OS_IOS)
730 #define MAYBE_Dcheck DISABLED_Dcheck
731 #else
732 #define MAYBE_Dcheck Dcheck
733 #endif
TEST_F(LoggingTest,MAYBE_Dcheck)734 TEST_F(LoggingTest, MAYBE_Dcheck) {
735 #if defined(DCHECK_IS_CONFIGURABLE)
736 // DCHECKs are enabled, and LOG_DCHECK is mutable, but defaults to non-fatal.
737 // Set it to LOG_FATAL to get the expected behavior from the rest of this
738 // test.
739 ScopedDcheckSeverity dcheck_severity(LOG_FATAL);
740 #endif // defined(DCHECK_IS_CONFIGURABLE)
741
742 #if defined(NDEBUG) && !defined(DCHECK_ALWAYS_ON)
743 // Release build.
744 EXPECT_FALSE(DCHECK_IS_ON());
745 EXPECT_FALSE(DLOG_IS_ON(DCHECK));
746 #elif defined(NDEBUG) && defined(DCHECK_ALWAYS_ON)
747 // Release build with real DCHECKS.
748 ScopedLogAssertHandler scoped_assert_handler(base::BindRepeating(LogSink));
749 EXPECT_TRUE(DCHECK_IS_ON());
750 EXPECT_TRUE(DLOG_IS_ON(DCHECK));
751 #else
752 // Debug build.
753 ScopedLogAssertHandler scoped_assert_handler(base::BindRepeating(LogSink));
754 EXPECT_TRUE(DCHECK_IS_ON());
755 EXPECT_TRUE(DLOG_IS_ON(DCHECK));
756 #endif
757
758 // DCHECKs are fatal iff they're compiled in DCHECK_IS_ON() and the DCHECK
759 // log level is set to fatal.
760 const bool dchecks_are_fatal = DCHECK_IS_ON() && LOG_DCHECK == LOG_FATAL;
761 EXPECT_EQ(0, g_log_sink_call_count);
762 DCHECK(false);
763 EXPECT_EQ(dchecks_are_fatal ? 1 : 0, g_log_sink_call_count);
764 DPCHECK(false);
765 EXPECT_EQ(dchecks_are_fatal ? 2 : 0, g_log_sink_call_count);
766 DCHECK_EQ(0, 1);
767 EXPECT_EQ(dchecks_are_fatal ? 3 : 0, g_log_sink_call_count);
768
769 // Test DCHECK on std::nullptr_t
770 g_log_sink_call_count = 0;
771 const void* p_null = nullptr;
772 const void* p_not_null = &p_null;
773 DCHECK_EQ(p_null, nullptr);
774 DCHECK_EQ(nullptr, p_null);
775 DCHECK_NE(p_not_null, nullptr);
776 DCHECK_NE(nullptr, p_not_null);
777 EXPECT_EQ(0, g_log_sink_call_count);
778
779 // Test DCHECK on a scoped enum.
780 enum class Animal { DOG, CAT };
781 DCHECK_EQ(Animal::DOG, Animal::DOG);
782 EXPECT_EQ(0, g_log_sink_call_count);
783 DCHECK_EQ(Animal::DOG, Animal::CAT);
784 EXPECT_EQ(dchecks_are_fatal ? 1 : 0, g_log_sink_call_count);
785
786 // Test DCHECK on functions and function pointers.
787 g_log_sink_call_count = 0;
788 struct MemberFunctions {
789 void MemberFunction1() {
790 // See the comment in DcheckEmptyFunction1().
791 LOG(INFO) << "Do not merge with MemberFunction2.";
792 }
793 void MemberFunction2() {}
794 };
795 void (MemberFunctions::*mp1)() = &MemberFunctions::MemberFunction1;
796 void (MemberFunctions::*mp2)() = &MemberFunctions::MemberFunction2;
797 void (*fp1)() = DcheckEmptyFunction1;
798 void (*fp2)() = DcheckEmptyFunction2;
799 void (*fp3)() = DcheckEmptyFunction1;
800 DCHECK_EQ(fp1, fp3);
801 EXPECT_EQ(0, g_log_sink_call_count);
802 DCHECK_EQ(mp1, &MemberFunctions::MemberFunction1);
803 EXPECT_EQ(0, g_log_sink_call_count);
804 DCHECK_EQ(mp2, &MemberFunctions::MemberFunction2);
805 EXPECT_EQ(0, g_log_sink_call_count);
806 DCHECK_EQ(fp1, fp2);
807 EXPECT_EQ(dchecks_are_fatal ? 1 : 0, g_log_sink_call_count);
808 DCHECK_EQ(mp2, &MemberFunctions::MemberFunction1);
809 EXPECT_EQ(dchecks_are_fatal ? 2 : 0, g_log_sink_call_count);
810 }
811
TEST_F(LoggingTest,DcheckReleaseBehavior)812 TEST_F(LoggingTest, DcheckReleaseBehavior) {
813 int some_variable = 1;
814 // These should still reference |some_variable| so we don't get
815 // unused variable warnings.
816 DCHECK(some_variable) << "test";
817 DPCHECK(some_variable) << "test";
818 DCHECK_EQ(some_variable, 1) << "test";
819 }
820
TEST_F(LoggingTest,DCheckEqStatements)821 TEST_F(LoggingTest, DCheckEqStatements) {
822 bool reached = false;
823 if (false)
824 DCHECK_EQ(false, true); // Unreached.
825 else
826 DCHECK_EQ(true, reached = true); // Reached, passed.
827 ASSERT_EQ(DCHECK_IS_ON() ? true : false, reached);
828
829 if (false)
830 DCHECK_EQ(false, true); // Unreached.
831 }
832
TEST_F(LoggingTest,CheckEqStatements)833 TEST_F(LoggingTest, CheckEqStatements) {
834 bool reached = false;
835 if (false)
836 CHECK_EQ(false, true); // Unreached.
837 else
838 CHECK_EQ(true, reached = true); // Reached, passed.
839 ASSERT_TRUE(reached);
840
841 if (false)
842 CHECK_EQ(false, true); // Unreached.
843 }
844
TEST_F(LoggingTest,NestedLogAssertHandlers)845 TEST_F(LoggingTest, NestedLogAssertHandlers) {
846 ::testing::InSequence dummy;
847 ::testing::StrictMock<MockLogAssertHandler> handler_a, handler_b;
848
849 EXPECT_CALL(
850 handler_a,
851 HandleLogAssert(
852 _, _, base::StringPiece("First assert must be caught by handler_a"),
853 _));
854 EXPECT_CALL(
855 handler_b,
856 HandleLogAssert(
857 _, _, base::StringPiece("Second assert must be caught by handler_b"),
858 _));
859 EXPECT_CALL(
860 handler_a,
861 HandleLogAssert(
862 _, _,
863 base::StringPiece("Last assert must be caught by handler_a again"),
864 _));
865
866 logging::ScopedLogAssertHandler scoped_handler_a(base::BindRepeating(
867 &MockLogAssertHandler::HandleLogAssert, base::Unretained(&handler_a)));
868
869 // Using LOG(FATAL) rather than CHECK(false) here since log messages aren't
870 // preserved for CHECKs in official builds.
871 LOG(FATAL) << "First assert must be caught by handler_a";
872
873 {
874 logging::ScopedLogAssertHandler scoped_handler_b(base::BindRepeating(
875 &MockLogAssertHandler::HandleLogAssert, base::Unretained(&handler_b)));
876 LOG(FATAL) << "Second assert must be caught by handler_b";
877 }
878
879 LOG(FATAL) << "Last assert must be caught by handler_a again";
880 }
881
882 // Test that defining an operator<< for a type in a namespace doesn't prevent
883 // other code in that namespace from calling the operator<<(ostream, wstring)
884 // defined by logging.h. This can fail if operator<<(ostream, wstring) can't be
885 // found by ADL, since defining another operator<< prevents name lookup from
886 // looking in the global namespace.
887 namespace nested_test {
888 class Streamable {};
operator <<(std::ostream & out,const Streamable &)889 ALLOW_UNUSED_TYPE std::ostream& operator<<(std::ostream& out,
890 const Streamable&) {
891 return out << "Streamable";
892 }
TEST_F(LoggingTest,StreamingWstringFindsCorrectOperator)893 TEST_F(LoggingTest, StreamingWstringFindsCorrectOperator) {
894 std::wstring wstr = L"Hello World";
895 std::ostringstream ostr;
896 ostr << wstr;
897 EXPECT_EQ("Hello World", ostr.str());
898 }
899 } // namespace nested_test
900
901 #if defined(DCHECK_IS_CONFIGURABLE)
TEST_F(LoggingTest,ConfigurableDCheck)902 TEST_F(LoggingTest, ConfigurableDCheck) {
903 // Verify that DCHECKs default to non-fatal in configurable-DCHECK builds.
904 // Note that we require only that DCHECK is non-fatal by default, rather
905 // than requiring that it be exactly INFO, ERROR, etc level.
906 EXPECT_LT(LOG_DCHECK, LOG_FATAL);
907 DCHECK(false);
908
909 // Verify that DCHECK* aren't hard-wired to crash on failure.
910 LOG_DCHECK = LOG_INFO;
911 DCHECK(false);
912 DCHECK_EQ(1, 2);
913
914 // Verify that DCHECK does crash if LOG_DCHECK is set to LOG_FATAL.
915 LOG_DCHECK = LOG_FATAL;
916
917 ::testing::StrictMock<MockLogAssertHandler> handler;
918 EXPECT_CALL(handler, HandleLogAssert(_, _, _, _)).Times(2);
919 {
920 logging::ScopedLogAssertHandler scoped_handler_b(base::BindRepeating(
921 &MockLogAssertHandler::HandleLogAssert, base::Unretained(&handler)));
922 DCHECK(false);
923 DCHECK_EQ(1, 2);
924 }
925 }
926
TEST_F(LoggingTest,ConfigurableDCheckFeature)927 TEST_F(LoggingTest, ConfigurableDCheckFeature) {
928 // Initialize FeatureList with and without DcheckIsFatal, and verify the
929 // value of LOG_DCHECK. Note that we don't require that DCHECK take a
930 // specific value when the feature is off, only that it is non-fatal.
931
932 {
933 base::test::ScopedFeatureList feature_list;
934 feature_list.InitFromCommandLine("DcheckIsFatal", "");
935 EXPECT_EQ(LOG_DCHECK, LOG_FATAL);
936 }
937
938 {
939 base::test::ScopedFeatureList feature_list;
940 feature_list.InitFromCommandLine("", "DcheckIsFatal");
941 EXPECT_LT(LOG_DCHECK, LOG_FATAL);
942 }
943
944 // The default case is last, so we leave LOG_DCHECK in the default state.
945 {
946 base::test::ScopedFeatureList feature_list;
947 feature_list.InitFromCommandLine("", "");
948 EXPECT_LT(LOG_DCHECK, LOG_FATAL);
949 }
950 }
951 #endif // defined(DCHECK_IS_CONFIGURABLE)
952
953 #if defined(OS_FUCHSIA)
954
955 class TestLogListener : public fuchsia::logger::testing::LogListener_TestBase {
956 public:
957 TestLogListener() = default;
958 ~TestLogListener() override = default;
959
RunUntilDone()960 void RunUntilDone() {
961 base::RunLoop loop;
962 dump_logs_done_quit_closure_ = loop.QuitClosure();
963 loop.Run();
964 }
965
DidReceiveString(base::StringPiece message,fuchsia::logger::LogMessage * logged_message)966 bool DidReceiveString(base::StringPiece message,
967 fuchsia::logger::LogMessage* logged_message) {
968 for (const auto& log_message : log_messages_) {
969 if (log_message.msg.find(message.as_string()) != std::string::npos) {
970 *logged_message = log_message;
971 return true;
972 }
973 }
974 return false;
975 }
976
977 // LogListener implementation.
LogMany(std::vector<fuchsia::logger::LogMessage> messages)978 void LogMany(std::vector<fuchsia::logger::LogMessage> messages) override {
979 log_messages_.insert(log_messages_.end(),
980 std::make_move_iterator(messages.begin()),
981 std::make_move_iterator(messages.end()));
982 }
983
Done()984 void Done() override { std::move(dump_logs_done_quit_closure_).Run(); }
985
NotImplemented_(const std::string & name)986 void NotImplemented_(const std::string& name) override {
987 NOTIMPLEMENTED() << name;
988 }
989
990 private:
991 fuchsia::logger::LogListenerPtr log_listener_;
992 std::vector<fuchsia::logger::LogMessage> log_messages_;
993 base::OnceClosure dump_logs_done_quit_closure_;
994
995 DISALLOW_COPY_AND_ASSIGN(TestLogListener);
996 };
997
998 // Verifies that calling the log macro goes to the Fuchsia system logs.
TEST_F(LoggingTest,FuchsiaSystemLogging)999 TEST_F(LoggingTest, FuchsiaSystemLogging) {
1000 const char kLogMessage[] = "system log!";
1001 LOG(ERROR) << kLogMessage;
1002
1003 TestLogListener listener;
1004 fidl::Binding<fuchsia::logger::LogListener> binding(&listener);
1005
1006 fuchsia::logger::LogMessage logged_message;
1007 do {
1008 std::unique_ptr<fuchsia::logger::LogFilterOptions> options =
1009 std::make_unique<fuchsia::logger::LogFilterOptions>();
1010 options->tags = {"base_unittests__exec"};
1011 fuchsia::logger::LogPtr logger =
1012 base::fuchsia::ComponentContextForCurrentProcess()
1013 ->svc()
1014 ->Connect<fuchsia::logger::Log>();
1015 logger->DumpLogs(binding.NewBinding(), std::move(options));
1016 listener.RunUntilDone();
1017 } while (!listener.DidReceiveString(kLogMessage, &logged_message));
1018
1019 EXPECT_EQ(logged_message.severity,
1020 static_cast<int32_t>(fuchsia::logger::LogLevelFilter::ERROR));
1021 ASSERT_EQ(logged_message.tags.size(), 1u);
1022 EXPECT_EQ(logged_message.tags[0], base::CommandLine::ForCurrentProcess()
1023 ->GetProgram()
1024 .BaseName()
1025 .AsUTF8Unsafe());
1026 }
1027
TEST_F(LoggingTest,FuchsiaLogging)1028 TEST_F(LoggingTest, FuchsiaLogging) {
1029 MockLogSource mock_log_source;
1030 EXPECT_CALL(mock_log_source, Log())
1031 .Times(DCHECK_IS_ON() ? 2 : 1)
1032 .WillRepeatedly(Return("log message"));
1033
1034 SetMinLogLevel(LOG_INFO);
1035
1036 EXPECT_TRUE(LOG_IS_ON(INFO));
1037 EXPECT_EQ(DCHECK_IS_ON(), DLOG_IS_ON(INFO));
1038
1039 ZX_LOG(INFO, ZX_ERR_INTERNAL) << mock_log_source.Log();
1040 ZX_DLOG(INFO, ZX_ERR_INTERNAL) << mock_log_source.Log();
1041
1042 ZX_CHECK(true, ZX_ERR_INTERNAL);
1043 ZX_DCHECK(true, ZX_ERR_INTERNAL);
1044 }
1045 #endif // defined(OS_FUCHSIA)
1046
TEST_F(LoggingTest,LogPrefix)1047 TEST_F(LoggingTest, LogPrefix) {
1048 // Set up a callback function to capture the log output string.
1049 auto old_log_message_handler = GetLogMessageHandler();
1050 // Use a static because only captureless lambdas can be converted to a
1051 // function pointer for SetLogMessageHandler().
1052 static std::string* log_string_ptr = nullptr;
1053 std::string log_string;
1054 log_string_ptr = &log_string;
1055 SetLogMessageHandler([](int severity, const char* file, int line,
1056 size_t start, const std::string& str) -> bool {
1057 *log_string_ptr = str;
1058 return true;
1059 });
1060
1061 // Logging with a prefix includes the prefix string after the opening '['.
1062 const char kPrefix[] = "prefix";
1063 SetLogPrefix(kPrefix);
1064 LOG(ERROR) << "test"; // Writes into |log_string|.
1065 EXPECT_EQ(1u, log_string.find(kPrefix));
1066
1067 // Logging without a prefix does not include the prefix string.
1068 SetLogPrefix(nullptr);
1069 LOG(ERROR) << "test"; // Writes into |log_string|.
1070 EXPECT_EQ(std::string::npos, log_string.find(kPrefix));
1071
1072 // Clean up.
1073 SetLogMessageHandler(old_log_message_handler);
1074 log_string_ptr = nullptr;
1075 }
1076
1077 #if !defined(ADDRESS_SANITIZER) && !defined(MEMORY_SANITIZER) && \
1078 !BUILDFLAG(IS_HWASAN)
1079 // Since we scan potentially uninitialized portions of the stack, we can't run
1080 // this test under any sanitizer that checks for uninitialized reads.
TEST_F(LoggingTest,LogMessageMarkersOnStack)1081 TEST_F(LoggingTest, LogMessageMarkersOnStack) {
1082 const uint32_t kLogStartMarker = 0xbedead01;
1083 const uint32_t kLogEndMarker = 0x5050dead;
1084 const char kTestMessage[] = "Oh noes! I have crashed! ";
1085
1086 uint32_t stack_start = 0;
1087
1088 // Install a LogAssertHandler which will scan between |stack_start| and its
1089 // local-scope stack for the start & end markers, and verify the message.
1090 ScopedLogAssertHandler assert_handler(base::BindRepeating(
1091 [](uint32_t* stack_start_ptr, const char* file, int line,
1092 const base::StringPiece message, const base::StringPiece stack_trace) {
1093 uint32_t stack_end;
1094 uint32_t* stack_end_ptr = &stack_end;
1095
1096 // Scan the stack for the expected markers.
1097 uint32_t* start_marker = nullptr;
1098 uint32_t* end_marker = nullptr;
1099 for (uint32_t* ptr = stack_end_ptr; ptr <= stack_start_ptr; ++ptr) {
1100 if (*ptr == kLogStartMarker)
1101 start_marker = ptr;
1102 else if (*ptr == kLogEndMarker)
1103 end_marker = ptr;
1104 }
1105
1106 // Verify that start & end markers were found, somewhere, in-between
1107 // this and the LogAssertHandler scope, in the LogMessage destructor's
1108 // stack frame.
1109 ASSERT_TRUE(start_marker);
1110 ASSERT_TRUE(end_marker);
1111
1112 // Verify that the |message| is found in-between the markers.
1113 const char* start_char_marker =
1114 reinterpret_cast<char*>(start_marker + 1);
1115 const char* end_char_marker = reinterpret_cast<char*>(end_marker);
1116
1117 const base::StringPiece stack_view(start_char_marker,
1118 end_char_marker - start_char_marker);
1119 ASSERT_FALSE(stack_view.find(message) == base::StringPiece::npos);
1120 },
1121 &stack_start));
1122
1123 // Trigger a log assertion, with a test message we can check for.
1124 LOG(FATAL) << kTestMessage;
1125 }
1126 #endif // !defined(ADDRESS_SANITIZER)
1127
1128 const char* kToStringResult = "to_string";
1129 const char* kOstreamResult = "ostream";
1130
1131 struct StructWithOstream {};
1132
operator <<(std::ostream & out,const StructWithOstream &)1133 std::ostream& operator<<(std::ostream& out, const StructWithOstream&) {
1134 return out << kOstreamResult;
1135 }
1136
TEST(MakeCheckOpValueStringTest,HasOnlyOstream)1137 TEST(MakeCheckOpValueStringTest, HasOnlyOstream) {
1138 std::ostringstream oss;
1139 logging::MakeCheckOpValueString(&oss, StructWithOstream());
1140 EXPECT_EQ(kOstreamResult, oss.str());
1141 }
1142
1143 struct StructWithToString {
ToStringlogging::__anon56ea5ac40111::StructWithToString1144 std::string ToString() const { return kToStringResult; }
1145 };
1146
TEST(MakeCheckOpValueStringTest,HasOnlyToString)1147 TEST(MakeCheckOpValueStringTest, HasOnlyToString) {
1148 std::ostringstream oss;
1149 logging::MakeCheckOpValueString(&oss, StructWithToString());
1150 EXPECT_EQ(kToStringResult, oss.str());
1151 }
1152
1153 struct StructWithToStringAndOstream {
ToStringlogging::__anon56ea5ac40111::StructWithToStringAndOstream1154 std::string ToString() const { return kToStringResult; }
1155 };
1156
operator <<(std::ostream & out,const StructWithToStringAndOstream &)1157 std::ostream& operator<<(std::ostream& out,
1158 const StructWithToStringAndOstream&) {
1159 return out << kOstreamResult;
1160 }
1161
TEST(MakeCheckOpValueStringTest,HasOstreamAndToString)1162 TEST(MakeCheckOpValueStringTest, HasOstreamAndToString) {
1163 std::ostringstream oss;
1164 logging::MakeCheckOpValueString(&oss, StructWithToStringAndOstream());
1165 EXPECT_EQ(kOstreamResult, oss.str());
1166 }
1167
1168 } // namespace
1169
1170 } // namespace logging
1171