Skip to content

Commit

Permalink
[SKV-714] fix: support core dump for fatal logging in simple_logger::…
Browse files Browse the repository at this point in the history 
…dsn_logv and call fatal logging exactly once for the assertion (apache#1580)

社区pr: apache#1580

和社区代码不太一样的是, 2.4.0的断言还要支持c风格的format string (dassert),
就还要用到snprintf, 但snprintf又要给一个char类型的固定大小的buffer. 因此
简单起见, dassert还是打印两行日志, 第一行是error级别的日志, 第二行是fatal级别
的日志.

apache#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.
  • Loading branch information
王聃 committed Aug 25, 2023
1 parent ca7fe1a commit 9f3db0d
Show file tree
Hide file tree
Showing 5 changed files with 92 additions and 41 deletions.
20 changes: 17 additions & 3 deletions src/rdsn/include/dsn/c/api_utilities.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
8 changes: 4 additions & 4 deletions src/rdsn/include/dsn/dist/fmt_logging.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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__)
Expand All @@ -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)

Expand Down
37 changes: 31 additions & 6 deletions src/rdsn/src/utils/simple_logger.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -32,10 +32,15 @@
#include <sys/stat.h>
#include <sys/types.h>
#include <unistd.h>
#include <dsn/dist/fmt_logging.h>
#include <dsn/utility/fail_point.h>
#include <dsn/utility/filesystem.h>
#include <dsn/utility/glob_posix.h>
#include <dsn/utility/safe_strerror_posix.h>
#include <dsn/utility/flags.h>
#include <dsn/utility/ports.h>
#include <dsn/utility/string_conv.h>
#include <dsn/utility/string_view.h>
#include <dsn/utils/time_utils.h>
#include <fmt/format.h>

Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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); }
Expand Down Expand Up @@ -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();
}
Expand Down Expand Up @@ -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();
Expand Down
50 changes: 26 additions & 24 deletions src/rdsn/src/utils/simple_logger.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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();

Expand All @@ -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();

Expand Down
18 changes: 14 additions & 4 deletions src/rdsn/src/utils/test/logging.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -35,8 +35,9 @@

#include <gtest/gtest.h>
#include <iostream>
#include <dsn/dist/fmt_logging.h>
#include <dsn/c/api_utilities.h>
#include <dsn/dist/fmt_logging.h>
#include <dsn/utility/fail_point.h>

TEST(core, logging)
{
Expand All @@ -61,7 +62,7 @@ TEST(core, logging_big_log)
big_str.c_str());
}

TEST(core, dlog_f)
TEST(core, dlog)
{
struct test_case
{
Expand All @@ -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();
}

0 comments on commit 9f3db0d

Please sign in to comment.