logging_unittest.cc 31 KB

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