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 <mbonadei@webrtc.org>
Reviewed-by: Tomas Gunnarsson <tommi@webrtc.org>
Reviewed-by: Danil Chapovalov <danilchap@webrtc.org>
Cr-Commit-Position: refs/heads/main@{#37672}
This commit is contained in:
Mirko Bonadei
2022-08-03 08:12:33 +00:00
committed by WebRTC LUCI CQ
parent 85bb04c7ba
commit 96191f8e68
4 changed files with 150 additions and 83 deletions

View File

@ -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) {

View File

@ -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<bool> 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<DWORD>(msg.size()),
&written, 0);
::WriteFile(error_handle, msg_str.c_str(),
static_cast<DWORD>(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,

View File

@ -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<PlatformThreadId> 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<PlatformThreadId> 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<PlatformThreadId> 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<bool> 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() {}

View File

@ -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)