This is an automated email from the ASF dual-hosted git repository. jiashunzhu pushed a commit to branch master in repository https://gitbox.apache.org/repos/asf/brpc.git
The following commit(s) were added to refs/heads/master by this push: new b36ce2c3 Log function name (#2247) b36ce2c3 is described below commit b36ce2c34064a1b141e0441245840eabc336dfa9 Author: Bright Chen <chenguangmin...@foxmail.com> AuthorDate: Mon Jun 5 05:01:02 2023 +0800 Log function name (#2247) --- src/butil/logging.cc | 169 +++++++++++++++++++++++++++++++++++++---------- src/butil/logging.h | 89 +++++++++++++++++++------ test/logging_unittest.cc | 56 ++++++++++++++++ 3 files changed, 258 insertions(+), 56 deletions(-) diff --git a/src/butil/logging.cc b/src/butil/logging.cc index fa0dbae8..544a5cab 100644 --- a/src/butil/logging.cc +++ b/src/butil/logging.cc @@ -142,6 +142,8 @@ DEFINE_bool(log_hostname, false, "Add host after pid in each log so" DEFINE_bool(log_year, false, "Log year in datetime part in each log"); +DEFINE_bool(log_func_name, false, "Log function name in each log"); + namespace { LoggingDestination logging_destination = LOG_DEFAULT; @@ -244,7 +246,7 @@ public: UnlockLogging(); } - static void Init(LogLockingState lock_log, const PathChar* new_log_file) { + static void Init(LogLockingState lock_log, const LogChar* new_log_file) { if (initialized) return; lock_log_file = lock_log; @@ -467,8 +469,9 @@ static void PrintLogSeverity(std::ostream& os, int severity) { } } -void PrintLogPrefix( - std::ostream& os, int severity, const char* file, int line) { +void PrintLogPrefix(std::ostream& os, int severity, + const char* file, int line, + const char* func) { PrintLogSeverity(os, severity); #if defined(OS_LINUX) timeval tv; @@ -507,12 +510,23 @@ void PrintLogPrefix( } os << ' ' << hostname; } - os << ' ' << file << ':' << line << "] "; + os << ' ' << file << ':' << line; + if (func && *func != '\0') { + os << " " << func; + } + os << "] "; + os.fill(prev_fill); } -static void PrintLogPrefixAsJSON( - std::ostream& os, int severity, const char* file, int line) { +void PrintLogPrefix(std::ostream& os, int severity, + const char* file, int line) { + PrintLogPrefix(os, severity, file, line, ""); +} + +static void PrintLogPrefixAsJSON(std::ostream& os, int severity, + const char* file, const char* func, + int line) { // severity os << "\"L\":\""; if (severity < 0) { @@ -563,7 +577,11 @@ static void PrintLogPrefixAsJSON( } os << "\"host\":\"" << hostname << "\","; } - os << "\"C\":\"" << file << ':' << line << "\""; + os << "\"C\":\"" << file << ':' << line; + if (func && *func != '\0') { + os << " " << func; + } + os << "\""; } void EscapeJson(std::ostream& os, const butil::StringPiece& s) { @@ -590,15 +608,14 @@ inline void OutputLog(std::ostream& os, const butil::StringPiece& s) { } } -void PrintLog(std::ostream& os, - int severity, const char* file, int line, - const butil::StringPiece& content) { +void PrintLog(std::ostream& os, int severity, const char* file, int line, + const char* func, const butil::StringPiece& content) { if (!FLAGS_log_as_json) { - PrintLogPrefix(os, severity, file, line); + PrintLogPrefix(os, severity, file, line, func); OutputLog(os, content); } else { os << '{'; - PrintLogPrefixAsJSON(os, severity, file, line); + PrintLogPrefixAsJSON(os, severity, file, func, line); bool pair_quote = false; if (content.empty() || content[0] != '"') { // not a json, add a 'M' field @@ -618,6 +635,12 @@ void PrintLog(std::ostream& os, } } +void PrintLog(std::ostream& os, + int severity, const char* file, int line, + const butil::StringPiece& content) { + PrintLog(os, severity, file, line, "", content); +} + // A log message handler that gets notified of every log message we process. class DoublyBufferedLogSink : public butil::DoublyBufferedData<LogSink*> { public: @@ -719,10 +742,16 @@ void DisplayDebugMessageInDialog(const std::string& str) { #endif // !defined(NDEBUG) -bool StringSink::OnLogMessage(int severity, const char* file, int line, +bool StringSink::OnLogMessage(int severity, const char* file, int line, + const butil::StringPiece& content) { + return OnLogMessage(severity, file, line, "", content); +} + +bool StringSink::OnLogMessage(int severity, const char* file, + int line, const char* func, const butil::StringPiece& content) { std::ostringstream os; - PrintLog(os, severity, file, line, content); + PrintLog(os, severity, file, line, func, content); const std::string msg = os.str(); { butil::AutoLock lock_guard(_lock); @@ -765,7 +794,7 @@ void CharArrayStreamBuf::reset() { setp(_data, _data + _size); } -LogStream& LogStream::SetPosition(const PathChar* file, int line, +LogStream& LogStream::SetPosition(const LogChar* file, int line, LogSeverity severity) { _file = file; _line = line; @@ -773,6 +802,16 @@ LogStream& LogStream::SetPosition(const PathChar* file, int line, return *this; } +LogStream& LogStream::SetPosition(const LogChar* file, int line, + const LogChar* func, + LogSeverity severity) { + _file = file; + _line = line; + _func = func; + _severity = severity; + return *this; +} + #if defined(__GNUC__) static bthread_key_t stream_bkey; static pthread_key_t stream_pkey; @@ -826,7 +865,9 @@ static LogStream** get_or_new_tls_stream_array() { return a; } -inline LogStream* CreateLogStream(const PathChar* file, int line, +inline LogStream* CreateLogStream(const LogChar* file, + int line, + const LogChar* func, LogSeverity severity) { int slot = 0; if (severity >= 0) { @@ -840,11 +881,17 @@ inline LogStream* CreateLogStream(const PathChar* file, int line, stream_array[slot] = stream; } if (stream->empty()) { - stream->SetPosition(file, line, severity); + stream->SetPosition(file, line, func, severity); } return stream; } +inline LogStream* CreateLogStream(const LogChar* file, + int line, + LogSeverity severity) { + return CreateLogStream(file, line, "", severity); +} + inline void DestroyLogStream(LogStream* stream) { if (stream != NULL) { stream->Flush(); @@ -853,10 +900,17 @@ inline void DestroyLogStream(LogStream* stream) { #else -inline LogStream* CreateLogStream(const PathChar* file, int line, +inline LogStream* CreateLogStream(const LogChar* file, int line, + LogSeverity severity) { + return CreateLogStream(file, line, "", severity); +} + + +inline LogStream* CreateLogStream(const LogChar* file, int line, + const LogChar* func, LogSeverity severity) { LogStream* stream = new LogStream; - stream->SetPosition(file, line, severity); + stream->SetPosition(file, line, func, severity); return stream; } @@ -875,12 +929,18 @@ public: bool OnLogMessage(int severity, const char* file, int line, const butil::StringPiece& content) override { + return OnLogMessage(severity, file, line, "", content); + } + + bool OnLogMessage(int severity, const char* file, + int line, const char* func, + const butil::StringPiece& content) override { // There's a copy here to concatenate prefix and content. Since // DefaultLogSink is hardly used right now, the copy is irrelevant. // A LogSink focused on performance should also be able to handle // non-continuous inputs which is a must to maximize performance. std::ostringstream os; - PrintLog(os, severity, file, line, content); + PrintLog(os, severity, file, line, func, content); os << '\n'; std::string log = os.str(); @@ -971,7 +1031,15 @@ void LogStream::FlushWithoutReset() { DoublyBufferedLogSink::ScopedPtr ptr; if (DoublyBufferedLogSink::GetInstance()->Read(&ptr) == 0 && (*ptr) != NULL) { - if ((*ptr)->OnLogMessage(_severity, _file, _line, content())) { + bool result = false; + if (FLAGS_log_func_name) { + result = (*ptr)->OnLogMessage(_severity, _file, _line, + _func, content()); + } else { + result = (*ptr)->OnLogMessage(_severity, _file, + _line, content()); + } + if (result) { goto FINISH_LOGGING; } #ifdef BAIDU_INTERNAL @@ -984,14 +1052,19 @@ void LogStream::FlushWithoutReset() { #ifdef BAIDU_INTERNAL if (!tried_comlog) { if (ComlogSink::GetInstance()->OnLogMessage( - _severity, _file, _line, content())) { + _severity, _file, _line, _func, content())) { goto FINISH_LOGGING; } } #endif if (!tried_default) { - DefaultLogSink::GetInstance()->OnLogMessage( - _severity, _file, _line, content()); + if (FLAGS_log_func_name) { + DefaultLogSink::GetInstance()->OnLogMessage( + _severity, _file, _line, _func, content()); + } else { + DefaultLogSink::GetInstance()->OnLogMessage( + _severity, _file, _line, content()); + } } FINISH_LOGGING: @@ -1021,19 +1094,31 @@ FINISH_LOGGING: } } -LogMessage::LogMessage(const char* file, int line, LogSeverity severity) { - _stream = CreateLogStream(file, line, severity); +LogMessage::LogMessage(const char* file, int line, LogSeverity severity) + : LogMessage(file, line, "", severity) {} + +LogMessage::LogMessage(const char* file, int line, + const char* func, LogSeverity severity) { + _stream = CreateLogStream(file, line, func, severity); } -LogMessage::LogMessage(const char* file, int line, std::string* result) { - _stream = CreateLogStream(file, line, BLOG_FATAL); +LogMessage::LogMessage(const char* file, int line, std::string* result) + : LogMessage(file, line, "", result) {} + +LogMessage::LogMessage(const char* file, int line, + const char* func, std::string* result) { + _stream = CreateLogStream(file, line, func, BLOG_FATAL); *_stream << "Check failed: " << *result; delete result; } LogMessage::LogMessage(const char* file, int line, LogSeverity severity, - std::string* result) { - _stream = CreateLogStream(file, line, severity); + std::string* result) + : LogMessage(file, line, "", severity, result) {} + +LogMessage::LogMessage(const char* file, int line, const char* func, + LogSeverity severity, std::string* result) { + _stream = CreateLogStream(file, line, func, severity); *_stream << "Check failed: " << *result; delete result; } @@ -1098,8 +1183,16 @@ Win32ErrorLogMessage::Win32ErrorLogMessage(const char* file, int line, LogSeverity severity, SystemErrorCode err) - : err_(err), - log_message_(file, line, severity) { + : Win32ErrorLogMessage(file, line, "", severity, err) { +} + +Win32ErrorLogMessage::Win32ErrorLogMessage(const char* file, + int line, + const char* func, + LogSeverity severity, + SystemErrorCode err) + : err_(err) + , log_message_(file, line, func, severity) { } Win32ErrorLogMessage::~Win32ErrorLogMessage() { @@ -1114,9 +1207,15 @@ ErrnoLogMessage::ErrnoLogMessage(const char* file, int line, LogSeverity severity, SystemErrorCode err) - : err_(err), - log_message_(file, line, severity) { -} + : ErrnoLogMessage(file, line, "", severity, err) {} + +ErrnoLogMessage::ErrnoLogMessage(const char* file, + int line, + const char* func, + LogSeverity severity, + SystemErrorCode err) + : err_(err) + , log_message_(file, line, func, severity) {} ErrnoLogMessage::~ErrnoLogMessage() { stream() << ": " << SystemErrorCodeToString(err_); diff --git a/src/butil/logging.h b/src/butil/logging.h index e2a41098..8138af34 100644 --- a/src/butil/logging.h +++ b/src/butil/logging.h @@ -204,9 +204,9 @@ namespace logging { // TODO(avi): do we want to do a unification of character types here? #if defined(OS_WIN) -typedef wchar_t PathChar; +typedef wchar_t LogChar; #else -typedef char PathChar; +typedef char LogChar; #endif // Where to record logging output? A flat file and/or system debug log @@ -254,7 +254,7 @@ struct BUTIL_EXPORT LoggingSettings { // The three settings below have an effect only when LOG_TO_FILE is // set in |logging_dest|. - const PathChar* log_file; + const LogChar* log_file; LogLockingState lock_log; OldFileDeletionState delete_old; }; @@ -308,6 +308,11 @@ public: // Returns true to stop further processing. virtual bool OnLogMessage(int severity, const char* file, int line, const butil::StringPiece& log_content) = 0; + virtual bool OnLogMessage(int severity, const char* file, + int line, const char* func, + const butil::StringPiece& log_content) { + return true; + } private: DISALLOW_COPY_AND_ASSIGN(LogSink); }; @@ -324,11 +329,19 @@ void PrintLog(std::ostream& os, int severity, const char* file, int line, const butil::StringPiece& content); +void PrintLog(std::ostream& os, + int severity, const char* file, int line, + const char* func, const butil::StringPiece& content); + // The LogSink mainly for unit-testing. Logs will be appended to it. class StringSink : public LogSink, public std::string { public: bool OnLogMessage(int severity, const char* file, int line, - const butil::StringPiece& log_content) override; + const butil::StringPiece& log_content) override; + + bool OnLogMessage(int severity, const char* file, + int line, const char* func, + const butil::StringPiece& log_content) override; private: butil::Lock _lock; }; @@ -365,7 +378,7 @@ const LogSeverity BLOG_DFATAL = BLOG_ERROR; // by LOG() and LOG_IF, etc. Since these are used all over our code, it's // better to have compact code for these operations. #define BAIDU_COMPACT_LOG_EX(severity, ClassName, ...) \ - ::logging::ClassName(__FILE__, __LINE__, \ + ::logging::ClassName(__FILE__, __LINE__, __func__, \ ::logging::BLOG_##severity, ##__VA_ARGS__) #define BAIDU_COMPACK_LOG(severity) \ @@ -418,8 +431,8 @@ DECLARE_int32(v); extern const int VLOG_UNINITIALIZED; // Called to initialize a VLOG callsite. -bool add_vlog_site(const int** v, const PathChar* filename, int line_no, - int required_v); +bool add_vlog_site(const int** v, const LogChar* filename, + int line_no, int required_v); class VLogSitePrinter { public: @@ -476,15 +489,24 @@ void print_vlog_sites(VLogSitePrinter*); // file/line can be specified at running-time. This is useful for printing // logs with known file/line inside a LogSink or LogMessageHandler -#define LOG_AT_STREAM(severity, file, line) \ +#define GET_LOG_AT_MACRO(_1, _2, _3, _4, NAME, ...) NAME + +#define LOG_AT_STREAM1(severity, file, line) \ ::logging::LogMessage(file, line, ::logging::BLOG_##severity).stream() +#define LOG_AT_STREAM2(severity, file, line, func) \ + ::logging::LogMessage(file, line, func, ::logging::BLOG_##severity).stream() +#define LOG_AT_STREAM(...) GET_LOG_AT_MACRO(__VA_ARGS__, LOG_AT_STREAM2, LOG_AT_STREAM1)(__VA_ARGS__) -#define LOG_AT(severity, file, line) \ +#define LOG_AT1(severity, file, line) \ BAIDU_LAZY_STREAM(LOG_AT_STREAM(severity, file, line), LOG_IS_ON(severity)) +#define LOG_AT2(severity, file, line, func) \ + BAIDU_LAZY_STREAM(LOG_AT_STREAM(severity, file, line, func), LOG_IS_ON(severity)) +#define LOG_AT(...) GET_LOG_AT_MACRO(__VA_ARGS__, LOG_AT2, LOG_AT1)(__VA_ARGS__) + // The VLOG macros log with negative verbosities. #define VLOG_STREAM(verbose_level) \ - ::logging::LogMessage(__FILE__, __LINE__, -(verbose_level)).stream() + ::logging::LogMessage(__FILE__, __LINE__, __func__, -(verbose_level)).stream() #define VLOG(verbose_level) \ BAIDU_LAZY_STREAM(VLOG_STREAM(verbose_level), VLOG_IS_ON(verbose_level)) @@ -512,11 +534,11 @@ void print_vlog_sites(VLogSitePrinter*); #if defined (OS_WIN) #define VPLOG_STREAM(verbose_level) \ - ::logging::Win32ErrorLogMessage(__FILE__, __LINE__, -verbose_level, \ + ::logging::Win32ErrorLogMessage(__FILE__, __LINE__, __func__, -verbose_level, \ ::logging::GetLastSystemErrorCode()).stream() #elif defined(OS_POSIX) #define VPLOG_STREAM(verbose_level) \ - ::logging::ErrnoLogMessage(__FILE__, __LINE__, -verbose_level, \ + ::logging::ErrnoLogMessage(__FILE__, __LINE__, __func__, -verbose_level, \ ::logging::GetLastSystemErrorCode()).stream() #endif @@ -587,7 +609,7 @@ void print_vlog_sites(VLogSitePrinter*); if (std::string* _result = \ ::logging::Check##name##Impl((val1), (val2), \ #val1 " " #op " " #val2)) \ - ::logging::LogMessage(__FILE__, __LINE__, _result).stream().SetCheck() + ::logging::LogMessage(__FILE__, __LINE__, __func__, _result).stream().SetCheck() #endif @@ -815,7 +837,8 @@ const LogSeverity BLOG_DCHECK = BLOG_INFO; ::logging::Check##name##Impl((val1), (val2), \ #val1 " " #op " " #val2)) \ ::logging::LogMessage( \ - __FILE__, __LINE__, ::logging::BLOG_DCHECK, \ + __FILE__, __LINE__, __func__, \ + ::logging::BLOG_DCHECK, \ _result).stream() // Equality/Inequality checks - compare two values, and log a @@ -862,7 +885,7 @@ BUTIL_EXPORT std::string SystemErrorCodeToString(SystemErrorCode error_code); class CharArrayStreamBuf : public std::streambuf { public: explicit CharArrayStreamBuf() : _data(NULL), _size(0) {} - ~CharArrayStreamBuf(); + ~CharArrayStreamBuf() override; int overflow(int ch) override; int sync() override; @@ -879,8 +902,8 @@ class LogStream : virtual private CharArrayStreamBuf, public std::ostream { friend void DestroyLogStream(LogStream*); public: LogStream() - : std::ostream(this), _file("-"), _line(0), _severity(0) - , _noflush(false), _is_check(false) { + : std::ostream(this), _file("-"), _line(0), _func("-") + , _severity(0) , _noflush(false), _is_check(false) { } ~LogStream() { @@ -903,7 +926,10 @@ public: } // Reset the log prefix: "I0711 15:14:01.830110 12735 server.cpp:93] " - LogStream& SetPosition(const PathChar* file, int line, LogSeverity); + LogStream& SetPosition(const LogChar* file, int line, LogSeverity); + + // Reset the log prefix: "E0711 15:14:01.830110 12735 server.cpp:752 StartInternal] " + LogStream& SetPosition(const LogChar* file, int line, const LogChar* func, LogSeverity); // Make FlushIfNeed() no-op once. LogStream& DontFlushOnce() { @@ -924,8 +950,9 @@ public: std::string content_str() const { return std::string(pbase(), pptr() - pbase()); } - const PathChar* file() const { return _file; } + const LogChar* file() const { return _file; } int line() const { return _line; } + const LogChar* func() const { return _func; } LogSeverity severity() const { return _severity; } private: @@ -948,8 +975,9 @@ private: } } - const PathChar* _file; + const LogChar* _file; int _line; + const LogChar* _func; LogSeverity _severity; bool _noflush; bool _is_check; @@ -968,14 +996,20 @@ class BUTIL_EXPORT LogMessage { public: // Used for LOG(severity). LogMessage(const char* file, int line, LogSeverity severity); + LogMessage(const char* file, int line, const char* func, + LogSeverity severity); // Used for CHECK_EQ(), etc. Takes ownership of the given string. // Implied severity = BLOG_FATAL. LogMessage(const char* file, int line, std::string* result); + LogMessage(const char* file, int line, const char* func, + std::string* result); // Used for DCHECK_EQ(), etc. Takes ownership of the given string. LogMessage(const char* file, int line, LogSeverity severity, std::string* result); + LogMessage(const char* file, int line, const char* func, + LogSeverity severity, std::string* result); ~LogMessage(); @@ -991,7 +1025,8 @@ private: // A non-macro interface to the log facility; (useful // when the logging level is not a compile-time constant). inline void LogAtLevel(int const log_level, const butil::StringPiece &msg) { - LogMessage(__FILE__, __LINE__, log_level).stream() << msg; + LogMessage(__FILE__, __LINE__, __func__, + log_level).stream() << msg; } // This class is used to explicitly ignore values in the conditional @@ -1014,6 +1049,12 @@ public: LogSeverity severity, SystemErrorCode err); + Win32ErrorLogMessage(const char* file, + int line, + const char* func, + LogSeverity severity, + SystemErrorCode err); + // Appends the error message before destructing the encapsulated class. ~Win32ErrorLogMessage(); @@ -1034,6 +1075,12 @@ public: LogSeverity severity, SystemErrorCode err); + ErrnoLogMessage(const char* file, + int line, + const char* func, + LogSeverity severity, + SystemErrorCode err); + // Appends the error message before destructing the encapsulated class. ~ErrnoLogMessage(); diff --git a/test/logging_unittest.cc b/test/logging_unittest.cc index 08d0bfc1..ca025ee9 100644 --- a/test/logging_unittest.cc +++ b/test/logging_unittest.cc @@ -13,6 +13,7 @@ namespace logging { DECLARE_bool(crash_on_fatal_log); DECLARE_int32(v); +DECLARE_bool(log_func_name); namespace { @@ -419,6 +420,61 @@ TEST_F(LoggingTest, limited_logging) { } } +void CheckFunctionName() { + const char* func_name = __func__; + DCHECK(1) << "test"; + ASSERT_EQ(func_name, LOG_STREAM(DCHECK).func()); + + LOG(DEBUG) << "test" << noflush; + ASSERT_EQ(func_name, LOG_STREAM(DEBUG).func()); + LOG(INFO) << "test" << noflush; + ASSERT_EQ(func_name, LOG_STREAM(INFO).func()); + LOG(WARNING) << "test" << noflush; + ASSERT_EQ(func_name, LOG_STREAM(WARNING).func()); + LOG(WARNING) << "test" << noflush; + ASSERT_EQ(func_name, LOG_STREAM(WARNING).func()); + LOG(ERROR) << "test" << noflush; + ASSERT_EQ(func_name, LOG_STREAM(ERROR).func()); + LOG(FATAL) << "test" << noflush; + ASSERT_EQ(func_name, LOG_STREAM(FATAL).func()); + + errno = EINTR; + PLOG(DEBUG) << "test" << noflush; + ASSERT_EQ(func_name, PLOG_STREAM(DEBUG).func()); + PLOG(INFO) << "test" << noflush; + ASSERT_EQ(func_name, PLOG_STREAM(INFO).func()); + PLOG(WARNING) << "test" << noflush; + ASSERT_EQ(func_name, PLOG_STREAM(WARNING).func()); + PLOG(WARNING) << "test" << noflush; + ASSERT_EQ(func_name, PLOG_STREAM(WARNING).func()); + PLOG(ERROR) << "test" << noflush; + ASSERT_EQ(func_name, PLOG_STREAM(ERROR).func()); + PLOG(FATAL) << "test" << noflush; + ASSERT_EQ(func_name, PLOG_STREAM(FATAL).func()); + + ::logging::StringSink log_str; + ::logging::LogSink* old_sink = ::logging::SetLogSink(&log_str); + LOG_AT(WARNING, "specified_file.cc", 12345, "log_at") << "file/line is specified"; + // the file:line part should be using the argument given by us. + ASSERT_NE(std::string::npos, log_str.find("specified_file.cc:12345 log_at")); + ::logging::SetLogSink(old_sink); + + EXPECT_FALSE(GFLAGS_NS::SetCommandLineOption("v", "1").empty()); + VLOG(100) << "test" << noflush; + ASSERT_EQ(func_name, VLOG_STREAM(100).func()); +} + +TEST_F(LoggingTest, log_func) { + bool old_crash_on_fatal_log = ::logging::FLAGS_crash_on_fatal_log; + ::logging::FLAGS_crash_on_fatal_log = false; + + ::logging::FLAGS_log_func_name = true; + CheckFunctionName(); + ::logging::FLAGS_log_func_name = false; + + ::logging::FLAGS_crash_on_fatal_log = old_crash_on_fatal_log; +} + } // namespace } // namespace logging --------------------------------------------------------------------- To unsubscribe, e-mail: dev-unsubscr...@brpc.apache.org For additional commands, e-mail: dev-h...@brpc.apache.org