From 9f3db0d4b08e663bbfd9265f06f10fc219317331 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E7=8E=8B=E8=81=83?= Date: Fri, 25 Aug 2023 11:54:34 +0800 Subject: [PATCH] [SKV-714] fix: support core dump for fatal logging in simple_logger::dsn_logv and call fatal logging exactly once for the assertion (#1580) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 社区pr: https://github.com/apache/incubator-pegasus/pull/1580 和社区代码不太一样的是, 2.4.0的断言还要支持c风格的format string (dassert), 就还要用到snprintf, 但snprintf又要给一个char类型的固定大小的buffer. 因此 简单起见, dassert还是打印两行日志, 第一行是error级别的日志, 第二行是fatal级别 的日志. https://github.com/apache/incubator-pegasus/issues/1579 Following fixes are included in this PR to solve the problems: - support core dump for fatal logging in `simple_logger::dsn_logv`; - call fatal logging exactly once for the assertion macros `CHECK*`; - add fail point to keep the logging test running without termination. --- src/rdsn/include/dsn/c/api_utilities.h | 20 ++++++++-- src/rdsn/include/dsn/dist/fmt_logging.h | 8 ++-- src/rdsn/src/utils/simple_logger.cpp | 37 +++++++++++++++--- src/rdsn/src/utils/simple_logger.h | 50 +++++++++++++------------ src/rdsn/src/utils/test/logging.cpp | 18 +++++++-- 5 files changed, 92 insertions(+), 41 deletions(-) diff --git a/src/rdsn/include/dsn/c/api_utilities.h b/src/rdsn/include/dsn/c/api_utilities.h index 828b1f9dc8..a120d38f9e 100644 --- a/src/rdsn/include/dsn/c/api_utilities.h +++ b/src/rdsn/include/dsn/c/api_utilities.h @@ -86,19 +86,33 @@ extern DSN_API void dsn_coredump(); // __FILENAME__ macro comes from the cmake, in which we calculate a filename without path. #define dlog(level, ...) \ do { \ - if (level >= dsn_log_start_level) \ + if (level >= dsn_log_start_level) { \ dsn_logf(__FILENAME__, __FUNCTION__, __LINE__, level, __VA_ARGS__); \ + } \ } while (false) #define dinfo(...) dlog(LOG_LEVEL_INFORMATION, __VA_ARGS__) #define ddebug(...) dlog(LOG_LEVEL_DEBUG, __VA_ARGS__) #define dwarn(...) dlog(LOG_LEVEL_WARNING, __VA_ARGS__) #define derror(...) dlog(LOG_LEVEL_ERROR, __VA_ARGS__) #define dfatal(...) dlog(LOG_LEVEL_FATAL, __VA_ARGS__) + +// TODO(wangdan): dsn_coredump() is unnecessary here, since dfatal() would call it in dsn_logv(). +// +// However, removing it would lead to "undefined reference to ..." as below: +// ../libdsn_utils.so: undefined reference to `dsn::ranger::operator|(dsn::ranger::access_type, ...' +// ../libdsn_utils.so: undefined reference to `dsn_exit(int)' +// ../libdsn_utils.so: undefined reference to `dsn::perf_counters::get_app_counter(char const*, ...' +// ../libdsn_utils.so: undefined reference to `dsn::perf_counters::perf_counters()' +// ../libdsn_utils.so: undefined reference to `dsn::perf_counters::~perf_counters()' +// ../libdsn_utils.so: undefined reference to `dsn::tools::sys_exit' +// ../libdsn_utils.so: undefined reference to `dsn_coredump()' +// +// We could leave it here, until it could be resolved. #define dassert(x, ...) \ do { \ if (dsn_unlikely(!(x))) { \ - dlog(LOG_LEVEL_FATAL, "assertion expression: " #x); \ - dlog(LOG_LEVEL_FATAL, __VA_ARGS__); \ + derror("assertion expression: " #x); \ + dfatal(__VA_ARGS__); \ dsn_coredump(); \ } \ } while (false) diff --git a/src/rdsn/include/dsn/dist/fmt_logging.h b/src/rdsn/include/dsn/dist/fmt_logging.h index 51f4089319..b2488e607f 100644 --- a/src/rdsn/include/dsn/dist/fmt_logging.h +++ b/src/rdsn/include/dsn/dist/fmt_logging.h @@ -27,9 +27,10 @@ #define dlog_f(level, ...) \ do { \ - if (level >= dsn_log_start_level) \ + if (level >= dsn_log_start_level) { \ dsn_log( \ __FILENAME__, __FUNCTION__, __LINE__, level, fmt::format(__VA_ARGS__).c_str()); \ + } \ } while (false) #define dinfo_f(...) dlog_f(LOG_LEVEL_INFORMATION, __VA_ARGS__) #define ddebug_f(...) dlog_f(LOG_LEVEL_DEBUG, __VA_ARGS__) @@ -39,9 +40,8 @@ #define dassert_f(x, ...) \ do { \ if (dsn_unlikely(!(x))) { \ - dlog_f(LOG_LEVEL_FATAL, "assertion expression: " #x); \ - dlog_f(LOG_LEVEL_FATAL, __VA_ARGS__); \ - dsn_coredump(); \ + derror_f("assertion expression: " #x); \ + dfatal_f(__VA_ARGS__); \ } \ } while (false) diff --git a/src/rdsn/src/utils/simple_logger.cpp b/src/rdsn/src/utils/simple_logger.cpp index 834ca498cb..33f96e75ff 100644 --- a/src/rdsn/src/utils/simple_logger.cpp +++ b/src/rdsn/src/utils/simple_logger.cpp @@ -32,10 +32,15 @@ #include #include #include +#include +#include #include #include #include #include +#include +#include +#include #include #include @@ -67,6 +72,28 @@ DSN_DEFINE_validator(stderr_start_level, [](const char *level) -> bool { return strcmp(level, "LOG_LEVEL_INVALID") != 0; }); +namespace { + +inline void process_fatal_log(dsn_log_level_t log_level) +{ + if (dsn_likely(log_level < LOG_LEVEL_FATAL)) { + return; + } + + bool coredump = true; + FAIL_POINT_INJECT_NOT_RETURN_F("coredump_for_fatal_log", [&coredump](dsn::string_view str) { + dassert_f(buf2bool(str, coredump), + "invalid coredump toggle for fatal log, should be true or false: {}", + str); + }); + + if (dsn_likely(coredump)) { + dsn_coredump(); + } +} + +} // anonymous namespace + screen_logger::screen_logger(bool short_header) : logging_provider("./", "") { _short_header = short_header; @@ -100,9 +127,7 @@ void screen_logger::dsn_logv(const char *file, vprintf(fmt, args); printf("\n"); - if (dsn_unlikely(log_level >= LOG_LEVEL_FATAL)) { - dsn_coredump(); - } + process_fatal_log(log_level); } void screen_logger::flush() { ::fflush(stdout); } @@ -272,6 +297,8 @@ void simple_logger::dsn_logv(const char *file, printf("\n"); } + process_fatal_log(log_level); + if (_file_bytes >= FLAGS_max_log_file_bytes) { create_log_file(); } @@ -304,9 +331,7 @@ void simple_logger::dsn_log(const char *file, printf("%s\n", str); } - if (dsn_unlikely(log_level >= LOG_LEVEL_FATAL)) { - dsn_coredump(); - } + process_fatal_log(log_level); if (_file_bytes >= FLAGS_max_log_file_bytes) { create_log_file(); diff --git a/src/rdsn/src/utils/simple_logger.h b/src/rdsn/src/utils/simple_logger.h index 7cdd5ab02d..8711e13884 100644 --- a/src/rdsn/src/utils/simple_logger.h +++ b/src/rdsn/src/utils/simple_logger.h @@ -43,18 +43,20 @@ class screen_logger : public logging_provider screen_logger(const char *log_dir, const char *role_name); virtual ~screen_logger(void); - virtual void dsn_logv(const char *file, - const char *function, - const int line, - dsn_log_level_t log_level, - const char *fmt, - va_list args); - - virtual void dsn_log(const char *file, - const char *function, - const int line, - dsn_log_level_t log_level, - const char *str){}; + void dsn_logv(const char *file, + const char *function, + const int line, + dsn_log_level_t log_level, + const char *fmt, + va_list args) override; + + void dsn_log(const char *file, + const char *function, + const int line, + dsn_log_level_t log_level, + const char *str) override + { + } virtual void flush(); @@ -73,18 +75,18 @@ class simple_logger : public logging_provider simple_logger(const char *log_dir, const char *role_name); virtual ~simple_logger(void); - virtual void dsn_logv(const char *file, - const char *function, - const int line, - dsn_log_level_t log_level, - const char *fmt, - va_list args); - - virtual void dsn_log(const char *file, - const char *function, - const int line, - dsn_log_level_t log_level, - const char *str); + void dsn_logv(const char *file, + const char *function, + const int line, + dsn_log_level_t log_level, + const char *fmt, + va_list args) override; + + void dsn_log(const char *file, + const char *function, + const int line, + dsn_log_level_t log_level, + const char *str) override; virtual void flush(); diff --git a/src/rdsn/src/utils/test/logging.cpp b/src/rdsn/src/utils/test/logging.cpp index 03cc31cbb6..c5f55935c0 100644 --- a/src/rdsn/src/utils/test/logging.cpp +++ b/src/rdsn/src/utils/test/logging.cpp @@ -35,8 +35,9 @@ #include #include -#include #include +#include +#include TEST(core, logging) { @@ -61,7 +62,7 @@ TEST(core, logging_big_log) big_str.c_str()); } -TEST(core, dlog_f) +TEST(core, dlog) { struct test_case { @@ -74,7 +75,16 @@ TEST(core, dlog_f) {dsn_log_level_t::LOG_LEVEL_ERROR, "\\x00%d\\x00\\x01%n/nm"}, {dsn_log_level_t::LOG_LEVEL_FATAL, "\\x00%d\\x00\\x01%n/nm"}}; - for (auto test : tests) { - dlog_f(test.level, "sortkey = {}", test.str); + dsn::fail::setup(); + dsn::fail::cfg("coredump_for_fatal_log", "void(false)"); + + for (const auto &test : tests) { + // Test logging_provider::dsn_log + dlog_f(test.level, "dlog_f: sortkey = {}", test.str); + + // Test logging_provider::dsn_logv + dlog(test.level, "dlog: sortkey = %s", test.str.c_str()); } + + dsn::fail::teardown(); }