From 96191f8e682c1b9d9c432030e90beba8f3523714 Mon Sep 17 00:00:00 2001 From: Mirko Bonadei Date: Wed, 3 Aug 2022 08:12:33 +0000 Subject: [PATCH] Fine grain LogSink APIs. The goal of this CL is to create a new LogSink::OnLogMessage API which propagates the source location of the log to the log sinks. Bug: b/238157120 Change-Id: I5a12bf80fd9c5569ed7aa1ef9185eee58830b19f Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/269249 Commit-Queue: Mirko Bonadei Reviewed-by: Tomas Gunnarsson Reviewed-by: Danil Chapovalov Cr-Commit-Position: refs/heads/main@{#37672} --- rtc_base/BUILD.gn | 2 + rtc_base/logging.cc | 125 ++++++++++++++++++++--------------- rtc_base/logging.h | 75 +++++++++++++++------ rtc_base/logging_unittest.cc | 31 ++++++--- 4 files changed, 150 insertions(+), 83 deletions(-) diff --git a/rtc_base/BUILD.gn b/rtc_base/BUILD.gn index abcdb12d41..d65b4da8a5 100644 --- a/rtc_base/BUILD.gn +++ b/rtc_base/BUILD.gn @@ -411,12 +411,14 @@ rtc_library("logging") { ":platform_thread_types", ":stringutils", ":timeutils", + "../api/units:timestamp", "synchronization:mutex", ] absl_deps = [ "//third_party/abseil-cpp/absl/base:core_headers", "//third_party/abseil-cpp/absl/meta:type_traits", "//third_party/abseil-cpp/absl/strings", + "//third_party/abseil-cpp/absl/types:optional", ] if (build_with_chromium) { diff --git a/rtc_base/logging.cc b/rtc_base/logging.cc index 30b3b97e67..798c059fb3 100644 --- a/rtc_base/logging.cc +++ b/rtc_base/logging.cc @@ -43,6 +43,7 @@ static const int kMaxLogLineSize = 1024 - 60; #include "absl/base/attributes.h" #include "absl/strings/string_view.h" +#include "api/units/timestamp.h" #include "rtc_base/checks.h" #include "rtc_base/platform_thread_types.h" #include "rtc_base/string_encode.h" @@ -54,6 +55,7 @@ static const int kMaxLogLineSize = 1024 - 60; namespace rtc { namespace { + // By default, release builds don't log, debug builds at info level #if !defined(NDEBUG) constexpr LoggingSeverity kDefaultLoggingSeverity = LS_INFO; @@ -83,6 +85,31 @@ webrtc::Mutex& GetLoggingLock() { } // namespace +std::string LogLineRef::DefaultLogLine() const { + rtc::StringBuilder log_output; + if (timestamp_ != webrtc::Timestamp::MinusInfinity()) { + // TODO(kwiberg): Switch to absl::StrFormat, if binary size is ok. + char timestamp[50]; // Maximum string length of an int64_t is 20. + int len = + snprintf(timestamp, sizeof(timestamp), "[%03" PRId64 ":%03" PRId64 "]", + timestamp_.ms() / 1000, timestamp_.ms() % 1000); + RTC_DCHECK_LT(len, sizeof(timestamp)); + log_output << timestamp; + } + if (thread_id_.has_value()) { + log_output << "[" << *thread_id_ << "] "; + } + if (!filename_.empty()) { +#if defined(WEBRTC_ANDROID) + log_output << "(line " << line_ << "): "; +#else + log_output << "(" << filename_ << ":" << line_ << "): "; +#endif + } + log_output << message_; + return log_output.Release(); +} + ///////////////////////////////////////////////////////////////////////////// // LogMessage ///////////////////////////////////////////////////////////////////////////// @@ -97,8 +124,9 @@ ABSL_CONST_INIT LogSink* LogMessage::streams_ RTC_GUARDED_BY(GetLoggingLock()) = nullptr; ABSL_CONST_INIT std::atomic LogMessage::streams_empty_ = {true}; -// Boolean options default to false (0) -bool LogMessage::thread_, LogMessage::timestamp_; +// Boolean options default to false. +ABSL_CONST_INIT bool LogMessage::log_thread_ = false; +ABSL_CONST_INIT bool LogMessage::log_timestamp_ = false; LogMessage::LogMessage(const char* file, int line, LoggingSeverity sev) : LogMessage(file, line, sev, ERRCTX_NONE, 0) {} @@ -107,35 +135,27 @@ LogMessage::LogMessage(const char* file, int line, LoggingSeverity sev, LogErrorContext err_ctx, - int err) - : severity_(sev) { - if (timestamp_) { + int err) { + log_line_.set_severity(sev); + if (log_timestamp_) { // Use SystemTimeMillis so that even if tests use fake clocks, the timestamp // in log messages represents the real system time. int64_t time = TimeDiff(SystemTimeMillis(), LogStartTime()); // Also ensure WallClockStartTime is initialized, so that it matches // LogStartTime. WallClockStartTime(); - // TODO(kwiberg): Switch to absl::StrFormat, if binary size is ok. - char timestamp[50]; // Maximum string length of an int64_t is 20. - int len = - snprintf(timestamp, sizeof(timestamp), "[%03" PRId64 ":%03" PRId64 "]", - time / 1000, time % 1000); - RTC_DCHECK_LT(len, sizeof(timestamp)); - print_stream_ << timestamp; + log_line_.set_timestamp(webrtc::Timestamp::Millis(time)); } - if (thread_) { - PlatformThreadId id = CurrentThreadId(); - print_stream_ << "[" << id << "] "; + if (log_thread_) { + log_line_.set_thread_id(CurrentThreadId()); } if (file != nullptr) { + log_line_.set_filename(FilenameFromPath(file)); + log_line_.set_line(line); #if defined(WEBRTC_ANDROID) - tag_ = FilenameFromPath(file); - print_stream_ << "(line " << line << "): "; -#else - print_stream_ << "(" << FilenameFromPath(file) << ":" << line << "): "; + log_line_.set_tag(log_line_.filename()); #endif } @@ -176,8 +196,8 @@ LogMessage::LogMessage(const char* file, int line, LoggingSeverity sev, const char* tag) - : LogMessage(file, line, sev, ERRCTX_NONE, 0 /* err */) { - tag_ = tag; + : LogMessage(file, line, sev, ERRCTX_NONE, /*err=*/0) { + log_line_.set_tag(tag); print_stream_ << tag << ": "; } #endif @@ -185,31 +205,23 @@ LogMessage::LogMessage(const char* file, LogMessage::~LogMessage() { FinishPrintStream(); - const std::string str = print_stream_.Release(); + log_line_.set_message(print_stream_.Release()); - if (severity_ >= g_dbg_sev) { -#if defined(WEBRTC_ANDROID) - OutputToDebug(str, severity_, tag_); -#else - OutputToDebug(str, severity_); -#endif + if (log_line_.severity() >= g_dbg_sev) { + OutputToDebug(log_line_); } webrtc::MutexLock lock(&GetLoggingLock()); for (LogSink* entry = streams_; entry != nullptr; entry = entry->next_) { - if (severity_ >= entry->min_severity_) { -#if defined(WEBRTC_ANDROID) - entry->OnLogMessage(str, severity_, tag_); -#else - entry->OnLogMessage(str, severity_); -#endif + if (log_line_.severity() >= entry->min_severity_) { + entry->OnLogMessage(log_line_); } } } void LogMessage::AddTag(const char* tag) { #ifdef WEBRTC_ANDROID - tag_ = tag; + log_line_.set_tag(tag); #endif } @@ -235,11 +247,11 @@ uint32_t LogMessage::WallClockStartTime() { } void LogMessage::LogThreads(bool on) { - thread_ = on; + log_thread_ = on; } void LogMessage::LogTimestamps(bool on) { - timestamp_ = on; + log_timestamp_ = on; } void LogMessage::LogToDebug(LoggingSeverity min_sev) { @@ -343,15 +355,8 @@ void LogMessage::UpdateMinLogSeverity() g_min_sev = min_sev; } -#if defined(WEBRTC_ANDROID) -void LogMessage::OutputToDebug(absl::string_view msg, - LoggingSeverity severity, - const char* tag) { -#else -void LogMessage::OutputToDebug(absl::string_view msg, - LoggingSeverity severity) { -#endif - std::string msg_str(msg); +void LogMessage::OutputToDebug(const LogLineRef& log_line) { + std::string msg_str = log_line.DefaultLogLine(); bool log_to_stderr = log_to_stderr_; #if defined(WEBRTC_MAC) && !defined(WEBRTC_IOS) && defined(NDEBUG) // On the Mac, all stderr output goes to the Console log and causes clutter. @@ -382,8 +387,8 @@ void LogMessage::OutputToDebug(absl::string_view msg, if (HANDLE error_handle = ::GetStdHandle(STD_ERROR_HANDLE)) { log_to_stderr = false; DWORD written = 0; - ::WriteFile(error_handle, msg.data(), static_cast(msg.size()), - &written, 0); + ::WriteFile(error_handle, msg_str.c_str(), + static_cast(msg_str.size()), &written, 0); } } #endif // WEBRTC_WIN @@ -394,7 +399,7 @@ void LogMessage::OutputToDebug(absl::string_view msg, // Also write to stderr which maybe available to executable started // from the shell. int prio; - switch (severity) { + switch (log_line.severity()) { case LS_VERBOSE: prio = ANDROID_LOG_VERBOSE; break; @@ -411,22 +416,24 @@ void LogMessage::OutputToDebug(absl::string_view msg, prio = ANDROID_LOG_UNKNOWN; } - int size = msg.size(); - int line = 0; + int size = msg_str.size(); + int current_line = 0; int idx = 0; const int max_lines = size / kMaxLogLineSize + 1; if (max_lines == 1) { - __android_log_print(prio, tag, "%.*s", size, msg_str.c_str()); + __android_log_print(prio, log_line.tag().data(), "%.*s", size, + msg_str.c_str()); } else { while (size > 0) { const int len = std::min(size, kMaxLogLineSize); // Use the size of the string in the format (msg may have \0 in the // middle). - __android_log_print(prio, tag, "[%d/%d] %.*s", line + 1, max_lines, len, + __android_log_print(prio, log_line.tag().data(), "[%d/%d] %.*s", + current_line + 1, max_lines, len, msg_str.c_str() + idx); idx += len; size -= len; - ++line; + ++current_line; } } #endif // WEBRTC_ANDROID @@ -543,6 +550,16 @@ void Log(const LogArgType* fmt, ...) { #endif namespace rtc { +// Default implementation, override is recomended. +void LogSink::OnLogMessage(const LogLineRef& log_line) { +#if defined(WEBRTC_ANDROID) + OnLogMessage(log_line.DefaultLogLine(), log_line.severity(), + log_line.tag().data()); +#else + OnLogMessage(log_line.DefaultLogLine(), log_line.severity()); +#endif +} + // Inefficient default implementation, override is recommended. void LogSink::OnLogMessage(const std::string& msg, LoggingSeverity severity, diff --git a/rtc_base/logging.h b/rtc_base/logging.h index 88b0359c02..9aa2bf2901 100644 --- a/rtc_base/logging.h +++ b/rtc_base/logging.h @@ -55,6 +55,9 @@ #include "absl/base/attributes.h" #include "absl/meta/type_traits.h" #include "absl/strings/string_view.h" +#include "absl/types/optional.h" +#include "api/units/timestamp.h" +#include "rtc_base/platform_thread_types.h" #include "rtc_base/strings/string_builder.h" #include "rtc_base/system/inline.h" @@ -101,6 +104,46 @@ enum LogErrorContext { }; class LogMessage; + +// LogLineRef encapsulates all the information required to generate a log line. +// It is used both internally to LogMessage but also as a parameter to +// LogSink::OnLogMessage, allowing custom LogSinks to format the log in +// the most flexible way. +class LogLineRef { + public: + absl::string_view message() { return message_; } + absl::string_view filename() { return filename_; }; + int line() { return line_; }; + absl::optional thread_id() { return thread_id_; }; + webrtc::Timestamp timestamp() { return timestamp_; }; + absl::string_view tag() const { return tag_; }; + LoggingSeverity severity() const { return severity_; } + + std::string DefaultLogLine() const; + + private: + friend class LogMessage; + void set_message(std::string message) { message_ = std::move(message); } + void set_filename(absl::string_view filename) { filename_ = filename; } + void set_line(int line) { line_ = line; } + void set_thread_id(absl::optional thread_id) { + thread_id_ = thread_id; + } + void set_timestamp(webrtc::Timestamp timestamp) { timestamp_ = timestamp; } + void set_tag(absl::string_view tag) { tag_ = tag; } + void set_severity(LoggingSeverity severity) { severity_ = severity; } + + std::string message_; + absl::string_view filename_; + int line_ = 0; + absl::optional thread_id_; + webrtc::Timestamp timestamp_ = webrtc::Timestamp::MinusInfinity(); + // The default Android debug output tag. + absl::string_view tag_ = "libjingle"; + // The severity level of this message + LoggingSeverity severity_; +}; + // Virtual sink interface that can receive log messages. class LogSink { public: @@ -119,6 +162,7 @@ class LogSink { virtual void OnLogMessage(absl::string_view message, LoggingSeverity severity); virtual void OnLogMessage(absl::string_view message); + virtual void OnLogMessage(const LogLineRef& line); private: friend class ::rtc::LogMessage; @@ -536,26 +580,14 @@ class LogMessage { // Updates min_sev_ appropriately when debug sinks change. static void UpdateMinLogSeverity(); -// These write out the actual log messages. -#if defined(WEBRTC_ANDROID) - static void OutputToDebug(absl::string_view msg, - LoggingSeverity severity, - const char* tag); -#else - static void OutputToDebug(absl::string_view msg, LoggingSeverity severity); -#endif // defined(WEBRTC_ANDROID) + // This writes out the actual log messages. + static void OutputToDebug(const LogLineRef& log_line_ref); // Called from the dtor (or from a test) to append optional extra error // information to the log stream and a newline character. void FinishPrintStream(); - // The severity level of this message - LoggingSeverity severity_; - -#if defined(WEBRTC_ANDROID) - // The default Android debug output tag. - const char* tag_ = "libjingle"; -#endif + LogLineRef log_line_; // String data generated in the constructor, that should be appended to // the message before output. @@ -570,8 +602,9 @@ class LogMessage { // are added/removed. static std::atomic streams_empty_; - // Flags for formatting options - static bool thread_, timestamp_; + // Flags for formatting options and their potential values. + static bool log_thread_; + static bool log_timestamp_; // Determines if logs will be directed to stderr in debug mode. static bool log_to_stderr_; @@ -579,11 +612,15 @@ class LogMessage { // Next methods do nothing; no one will call these functions. inline static void UpdateMinLogSeverity() {} #if defined(WEBRTC_ANDROID) - inline static void OutputToDebug(absl::string_view msg, + inline static void OutputToDebug(absl::string_view filename, + int line, + absl::string_view msg, LoggingSeverity severity, const char* tag) {} #else - inline static void OutputToDebug(absl::string_view msg, + inline static void OutputToDebug(absl::string_view filename, + int line, + absl::string_view msg, LoggingSeverity severity) {} #endif // defined(WEBRTC_ANDROID) inline void FinishPrintStream() {} diff --git a/rtc_base/logging_unittest.cc b/rtc_base/logging_unittest.cc index c267778951..2c6a6be209 100644 --- a/rtc_base/logging_unittest.cc +++ b/rtc_base/logging_unittest.cc @@ -55,7 +55,7 @@ class LogMessageForTesting : public LogMessage { const std::string& get_extra() const { return extra_; } #if defined(WEBRTC_ANDROID) - const char* get_tag() const { return tag_; } + const char* get_tag() const { return log_line_.tag().data(); } #endif // Returns the contents of the internal log stream. @@ -216,17 +216,28 @@ TEST(LogTest, CheckExtraErrorField) { } TEST(LogTest, CheckFilePathParsed) { - LogMessageForTesting log_msg("some/path/myfile.cc", 100, LS_INFO); - log_msg.stream() << "<- Does this look right?"; - - const std::string stream = log_msg.GetPrintStream(); + std::string str; + LogSinkImpl stream(&str); + LogMessage::AddLogToStream(&stream, LS_INFO); + EXPECT_EQ(LS_INFO, LogMessage::GetLogToStream(&stream)); #if defined(WEBRTC_ANDROID) - const char* tag = log_msg.get_tag(); - EXPECT_NE(nullptr, strstr(tag, "myfile.cc")); - EXPECT_NE(std::string::npos, stream.find("100")); -#else - EXPECT_NE(std::string::npos, stream.find("(myfile.cc:100)")); + const char* tag = nullptr; #endif + { + LogMessageForTesting log_msg("some/path/myfile.cc", 100, LS_INFO); + log_msg.stream() << "<- Does this look right?"; +#if defined(WEBRTC_ANDROID) + tag = log_msg.get_tag(); +#endif + } + +#if defined(WEBRTC_ANDROID) + EXPECT_NE(nullptr, strstr(tag, "myfile.cc")); + EXPECT_NE(std::string::npos, str.find("100")); +#else + EXPECT_NE(std::string::npos, str.find("(myfile.cc:100)")); +#endif + LogMessage::RemoveLogToStream(&stream); } #if defined(WEBRTC_ANDROID)