From 765ae6bcfc62148de629f68315fdf8cd1bc35342 Mon Sep 17 00:00:00 2001 From: Spencer Low Date: Thu, 17 Sep 2015 19:36:10 -0700 Subject: [PATCH] base logging: fix errno restoring, severity conditionality, dangling ifs Fix LOG() to properly save and restore errno. Test this properly. Only do logging if severity is >= the minimum. Fix dangling if statements in CHECK(), CHECK_STR{EQ,NE}(). Test this properly. Fix base logging tests on Windows. All libbase_tests now pass on Windows. Change place to lock, so the lock can protect logging of all data in LogMessage. Change-Id: I7ff531c67ae10a99ef0a2bbfe279aa77282d5ae9 Signed-off-by: Spencer Low --- adb/adb_trace.h | 2 - base/include/base/logging.h | 74 +++++++++++++++++++++------- base/logging.cpp | 57 +++++++++------------ base/logging_test.cpp | 98 +++++++++++++++++++++++++++++++++++-- 4 files changed, 172 insertions(+), 59 deletions(-) diff --git a/adb/adb_trace.h b/adb/adb_trace.h index 623108e9b..b4155dffd 100644 --- a/adb/adb_trace.h +++ b/adb/adb_trace.h @@ -50,9 +50,7 @@ void adb_trace_init(char**); #define D(...) \ do { \ if (ADB_TRACING) { \ - int saved_errno = errno; \ LOG(INFO) << android::base::StringPrintf(__VA_ARGS__); \ - errno = saved_errno; \ } \ } while (0) diff --git a/base/include/base/logging.h b/base/include/base/logging.h index 283a7bc90..30f690657 100644 --- a/base/include/base/logging.h +++ b/base/include/base/logging.h @@ -87,30 +87,64 @@ extern void InitLogging(char* argv[]); // Replace the current logger. extern void SetLogger(LogFunction&& logger); +// Get the minimum severity level for logging. +extern LogSeverity GetMinimumLogSeverity(); + +class ErrnoRestorer { + public: + ErrnoRestorer() + : saved_errno_(errno) { + } + + ~ErrnoRestorer() { + errno = saved_errno_; + } + + // Allow this object to evaluate to false which is useful in macros. + operator bool() const { + return false; + } + + private: + const int saved_errno_; + + DISALLOW_COPY_AND_ASSIGN(ErrnoRestorer); +}; + // Logs a message to logcat on Android otherwise to stderr. If the severity is // FATAL it also causes an abort. For example: // // LOG(FATAL) << "We didn't expect to reach here"; -#define LOG(severity) \ - ::android::base::LogMessage(__FILE__, __LINE__, ::android::base::DEFAULT, \ - ::android::base::severity, -1).stream() +#define LOG(severity) LOG_TO(DEFAULT, severity) // Logs a message to logcat with the specified log ID on Android otherwise to // stderr. If the severity is FATAL it also causes an abort. -#define LOG_TO(dest, severity) \ - ::android::base::LogMessage(__FILE__, __LINE__, ::android::base::dest, \ - ::android::base::severity, -1).stream() +// Use an if-else statement instead of just an if statement here. So if there is a +// else statement after LOG() macro, it won't bind to the if statement in the macro. +// do-while(0) statement doesn't work here. Because we need to support << operator +// following the macro, like "LOG(DEBUG) << xxx;". +#define LOG_TO(dest, severity) \ + if (LIKELY(::android::base::severity < ::android::base::GetMinimumLogSeverity())) \ + ; \ + else \ + ::android::base::ErrnoRestorer() ? *(std::ostream*)nullptr : \ + ::android::base::LogMessage(__FILE__, __LINE__, \ + ::android::base::dest, \ + ::android::base::severity, -1).stream() // A variant of LOG that also logs the current errno value. To be used when // library calls fail. -#define PLOG(severity) \ - ::android::base::LogMessage(__FILE__, __LINE__, ::android::base::DEFAULT, \ - ::android::base::severity, errno).stream() +#define PLOG(severity) PLOG_TO(DEFAULT, severity) // Behaves like PLOG, but logs to the specified log ID. -#define PLOG_TO(dest, severity) \ - ::android::base::LogMessage(__FILE__, __LINE__, ::android::base::dest, \ - ::android::base::severity, errno).stream() +#define PLOG_TO(dest, severity) \ + if (LIKELY(::android::base::severity < ::android::base::GetMinimumLogSeverity())) \ + ; \ + else \ + ::android::base::ErrnoRestorer() ? *(std::ostream*)nullptr : \ + ::android::base::LogMessage(__FILE__, __LINE__, \ + ::android::base::dest, \ + ::android::base::severity, errno).stream() // Marker that code is yet to be implemented. #define UNIMPLEMENTED(level) \ @@ -122,11 +156,13 @@ extern void SetLogger(LogFunction&& logger); // // CHECK(false == true) results in a log message of // "Check failed: false == true". -#define CHECK(x) \ - if (UNLIKELY(!(x))) \ - ::android::base::LogMessage(__FILE__, __LINE__, ::android::base::DEFAULT, \ - ::android::base::FATAL, -1).stream() \ - << "Check failed: " #x << " " +#define CHECK(x) \ + if (LIKELY((x))) \ + ; \ + else \ + ::android::base::LogMessage(__FILE__, __LINE__, ::android::base::DEFAULT, \ + ::android::base::FATAL, -1).stream() \ + << "Check failed: " #x << " " // Helper for CHECK_xx(x,y) macros. #define CHECK_OP(LHS, RHS, OP) \ @@ -153,7 +189,9 @@ extern void SetLogger(LogFunction&& logger); // Helper for CHECK_STRxx(s1,s2) macros. #define CHECK_STROP(s1, s2, sense) \ - if (UNLIKELY((strcmp(s1, s2) == 0) != sense)) \ + if (LIKELY((strcmp(s1, s2) == 0) == sense)) \ + ; \ + else \ LOG(FATAL) << "Check failed: " \ << "\"" << s1 << "\"" \ << (sense ? " == " : " != ") << "\"" << s2 << "\"" diff --git a/base/logging.cpp b/base/logging.cpp index e9e06dfc4..6bfaaec2c 100644 --- a/base/logging.cpp +++ b/base/logging.cpp @@ -139,6 +139,10 @@ static bool gInitialized = false; static LogSeverity gMinimumLogSeverity = INFO; static std::unique_ptr gProgramInvocationName; +LogSeverity GetMinimumLogSeverity() { + return gMinimumLogSeverity; +} + static const char* ProgramInvocationName() { if (gProgramInvocationName == nullptr) { gProgramInvocationName.reset(new std::string(getprogname())); @@ -200,20 +204,6 @@ void InitLogging(char* argv[], LogFunction&& logger) { InitLogging(argv); } -// TODO: make this public; it's independently useful. -class ErrnoRestorer { - public: - ErrnoRestorer(int saved_errno) : saved_errno_(saved_errno) { - } - - ~ErrnoRestorer() { - errno = saved_errno_; - } - - private: - const int saved_errno_; -}; - void InitLogging(char* argv[]) { if (gInitialized) { return; @@ -286,13 +276,12 @@ static const char* GetFileBasename(const char* file) { class LogMessageData { public: LogMessageData(const char* file, unsigned int line, LogId id, - LogSeverity severity, int error, int saved_errno) + LogSeverity severity, int error) : file_(GetFileBasename(file)), line_number_(line), id_(id), severity_(severity), - error_(error), - errno_restorer_(saved_errno) { + error_(error) { } const char* GetFile() const { @@ -330,39 +319,38 @@ class LogMessageData { const LogId id_; const LogSeverity severity_; const int error_; - ErrnoRestorer errno_restorer_; DISALLOW_COPY_AND_ASSIGN(LogMessageData); }; LogMessage::LogMessage(const char* file, unsigned int line, LogId id, LogSeverity severity, int error) - : data_(new LogMessageData(file, line, id, severity, error, errno)) { + : data_(new LogMessageData(file, line, id, severity, error)) { } LogMessage::~LogMessage() { - if (data_->GetSeverity() < gMinimumLogSeverity) { - return; // No need to format something we're not going to output. - } - // Finish constructing the message. if (data_->GetError() != -1) { data_->GetBuffer() << ": " << strerror(data_->GetError()); } std::string msg(data_->ToString()); - if (msg.find('\n') == std::string::npos) { - LogLine(data_->GetFile(), data_->GetLineNumber(), data_->GetId(), - data_->GetSeverity(), msg.c_str()); - } else { - msg += '\n'; - size_t i = 0; - while (i < msg.size()) { - size_t nl = msg.find('\n', i); - msg[nl] = '\0'; + { + // Do the actual logging with the lock held. + lock_guard lock(logging_lock); + if (msg.find('\n') == std::string::npos) { LogLine(data_->GetFile(), data_->GetLineNumber(), data_->GetId(), - data_->GetSeverity(), &msg[i]); - i = nl + 1; + data_->GetSeverity(), msg.c_str()); + } else { + msg += '\n'; + size_t i = 0; + while (i < msg.size()) { + size_t nl = msg.find('\n', i); + msg[nl] = '\0'; + LogLine(data_->GetFile(), data_->GetLineNumber(), data_->GetId(), + data_->GetSeverity(), &msg[i]); + i = nl + 1; + } } } @@ -382,7 +370,6 @@ std::ostream& LogMessage::stream() { void LogMessage::LogLine(const char* file, unsigned int line, LogId id, LogSeverity severity, const char* message) { const char* tag = ProgramInvocationName(); - lock_guard lock(logging_lock); gLogger(id, severity, tag, file, line, message); } diff --git a/base/logging_test.cpp b/base/logging_test.cpp index c12dfa5f3..9cf1aade0 100644 --- a/base/logging_test.cpp +++ b/base/logging_test.cpp @@ -18,6 +18,10 @@ #include +#if defined(_WIN32) +#include +#endif + #include #include @@ -49,6 +53,11 @@ class CapturedStderr { private: void init() { +#if defined(_WIN32) + // On Windows, stderr is often buffered, so make sure it is unbuffered so + // that we can immediately read back what was written to stderr. + ASSERT_EQ(0, setvbuf(stderr, NULL, _IONBF, 0)); +#endif old_stderr_ = dup(STDERR_FILENO); ASSERT_NE(-1, old_stderr_); ASSERT_NE(-1, dup2(fd(), STDERR_FILENO)); @@ -57,21 +66,58 @@ class CapturedStderr { void reset() { ASSERT_NE(-1, dup2(old_stderr_, STDERR_FILENO)); ASSERT_EQ(0, close(old_stderr_)); + // Note: cannot restore prior setvbuf() setting. } TemporaryFile temp_file_; int old_stderr_; }; +#if defined(_WIN32) +static void ExitSignalAbortHandler(int) { + _exit(3); +} +#endif + +static void SuppressAbortUI() { +#if defined(_WIN32) + // We really just want to call _set_abort_behavior(0, _CALL_REPORTFAULT) to + // suppress the Windows Error Reporting dialog box, but that API is not + // available in the OS-supplied C Runtime, msvcrt.dll, that we currently + // use (it is available in the Visual Studio C runtime). + // + // Instead, we setup a SIGABRT handler, which is called in abort() right + // before calling Windows Error Reporting. In the handler, we exit the + // process just like abort() does. + ASSERT_NE(SIG_ERR, signal(SIGABRT, ExitSignalAbortHandler)); +#endif +} + TEST(logging, CHECK) { - ASSERT_DEATH(CHECK(false), "Check failed: false "); + ASSERT_DEATH({SuppressAbortUI(); CHECK(false);}, "Check failed: false "); CHECK(true); - ASSERT_DEATH(CHECK_EQ(0, 1), "Check failed: 0 == 1 "); + ASSERT_DEATH({SuppressAbortUI(); CHECK_EQ(0, 1);}, "Check failed: 0 == 1 "); CHECK_EQ(0, 0); - ASSERT_DEATH(CHECK_STREQ("foo", "bar"), R"(Check failed: "foo" == "bar")"); + ASSERT_DEATH({SuppressAbortUI(); CHECK_STREQ("foo", "bar");}, + R"(Check failed: "foo" == "bar")"); CHECK_STREQ("foo", "foo"); + + // Test whether CHECK() and CHECK_STREQ() have a dangling if with no else. + bool flag = false; + if (true) + CHECK(true); + else + flag = true; + EXPECT_FALSE(flag) << "CHECK macro probably has a dangling if with no else"; + + flag = false; + if (true) + CHECK_STREQ("foo", "foo"); + else + flag = true; + EXPECT_FALSE(flag) << "CHECK_STREQ probably has a dangling if with no else"; } std::string make_log_pattern(android::base::LogSeverity severity, @@ -85,7 +131,7 @@ std::string make_log_pattern(android::base::LogSeverity severity, } TEST(logging, LOG) { - ASSERT_DEATH(LOG(FATAL) << "foobar", "foobar"); + ASSERT_DEATH({SuppressAbortUI(); LOG(FATAL) << "foobar";}, "foobar"); // We can't usefully check the output of any of these on Windows because we // don't have std::regex, but we can at least make sure we printed at least as @@ -148,6 +194,50 @@ TEST(logging, LOG) { ASSERT_TRUE(std::regex_search(output, message_regex)) << output; #endif } + + // Test whether LOG() saves and restores errno. + { + CapturedStderr cap; + errno = 12345; + LOG(INFO) << (errno = 67890); + EXPECT_EQ(12345, errno) << "errno was not restored"; + + ASSERT_EQ(0, lseek(cap.fd(), SEEK_SET, 0)); + + std::string output; + android::base::ReadFdToString(cap.fd(), &output); + EXPECT_NE(nullptr, strstr(output.c_str(), "67890")) << output; + +#if !defined(_WIN32) + std::regex message_regex( + make_log_pattern(android::base::INFO, "67890")); + ASSERT_TRUE(std::regex_search(output, message_regex)) << output; +#endif + } + + // Test whether LOG() has a dangling if with no else. + { + CapturedStderr cap; + + // Do the test two ways: once where we hypothesize that LOG()'s if + // will evaluate to true (when severity is high enough) and once when we + // expect it to evaluate to false (when severity is not high enough). + bool flag = false; + if (true) + LOG(INFO) << "foobar"; + else + flag = true; + + EXPECT_FALSE(flag) << "LOG macro probably has a dangling if with no else"; + + flag = false; + if (true) + LOG(VERBOSE) << "foobar"; + else + flag = true; + + EXPECT_FALSE(flag) << "LOG macro probably has a dangling if with no else"; + } } TEST(logging, PLOG) {