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