diff --git a/bazel/ray.bzl b/bazel/ray.bzl index 53ba78e7f..169eeab24 100644 --- a/bazel/ray.bzl +++ b/bazel/ray.bzl @@ -3,7 +3,7 @@ load("@com_github_checkstyle_java//checkstyle:checkstyle.bzl", "checkstyle_test" load("@bazel_skylib//rules:copy_file.bzl", "copy_file") load("@bazel_common//tools/maven:pom_file.bzl", "pom_file") -COPTS = ["-DRAY_USE_GLOG"] + select({ +COPTS_WITHOUT_LOG = select({ "//:opt": ["-DBAZEL_OPT"], "//conditions:default": [], }) + select({ @@ -22,6 +22,8 @@ COPTS = ["-DRAY_USE_GLOG"] + select({ ], }) +COPTS = ["-DRAY_USE_SPDLOG"] + COPTS_WITHOUT_LOG + PYX_COPTS = select({ "//:msvc-cl": [ ], diff --git a/src/ray/util/logging.cc b/src/ray/util/logging.cc index 1f77ed7c0..578cc4049 100644 --- a/src/ray/util/logging.cc +++ b/src/ray/util/logging.cc @@ -30,8 +30,9 @@ #include #include #include +#include -#ifdef RAY_USE_GLOG +#if defined(RAY_USE_GLOG) || defined(RAY_USE_SPDLOG) #include #ifdef _MSC_VER #pragma warning(push) @@ -43,13 +44,20 @@ #endif #endif +#ifdef RAY_USE_SPDLOG +#include "spdlog/sinks/basic_file_sink.h" +#include "spdlog/sinks/rotating_file_sink.h" +#include "spdlog/sinks/stdout_color_sinks.h" +#include "spdlog/spdlog.h" +#endif + #include "ray/util/filesystem.h" namespace ray { std::string GetCallTrace() { std::string return_message = "Cannot get callstack information."; -#ifdef RAY_USE_GLOG +#if defined(RAY_USE_GLOG) || defined(RAY_USE_SPDLOG) return google::GetStackTraceToString(); #endif return return_message; @@ -73,6 +81,65 @@ struct StdoutLogger : public google::base::Logger { static StdoutLogger stdout_logger_singleton; #endif +#ifdef RAY_USE_SPDLOG +/// NOTE(lingxuan.zlx): we reuse glog const_basename function from its utils. +inline const char *ConstBasename(const char *filepath) { + const char *base = strrchr(filepath, '/'); +#ifdef OS_WINDOWS // Look for either path separator in Windows + if (!base) base = strrchr(filepath, '\\'); +#endif + return base ? (base + 1) : filepath; +} + +class SpdLogMessage final { + public: + explicit SpdLogMessage(const char *file, int line, int loglevel) : loglevel_(loglevel) { + stream() << ConstBasename(file) << ":" << line << ": "; + } + inline std::shared_ptr get_logger() { + auto logger = spdlog::get("ray_log_sink"); + if (!logger) { + logger = spdlog::get("stderr"); + } + // We just emit all log informations to stderr when no default logger has been created + // before starting ray log, which is for glog compatible. + if (!logger) { + logger = spdlog::stderr_color_mt("stderr"); + logger->set_pattern(RayLog::GetLogFormatPattern()); + } + return logger; + } + + inline void Flush() { + auto logger = get_logger(); + // To avoid dump duplicated stacktrace with installed failure signal + // handler, we have to check whether glog failure signal handler is enabled. + if (!RayLog::IsFailureSignalHandlerEnabled() && + loglevel_ == static_cast(spdlog::level::critical)) { + stream() << "\n*** StackTrace Information ***\n" << ray::GetCallTrace(); + } + // NOTE(lingxuan.zlx): See more fmt by visiting https://github.com/fmtlib/fmt. + logger->log(static_cast(loglevel_), /*fmt*/ "{}", + str_.str()); + logger->flush(); + if (loglevel_ == static_cast(spdlog::level::critical)) { + // For keeping same action with glog, process will be abort if it's fatal log. + std::abort(); + } + } + + ~SpdLogMessage() { Flush(); } + inline std::ostream &stream() { return str_; } + + private: + std::ostringstream str_; + int loglevel_; + + SpdLogMessage(const SpdLogMessage &) = delete; + SpdLogMessage &operator=(const SpdLogMessage &) = delete; +}; +#endif + // This is the default implementation of ray log, // which is independent of any libs. class CerrLog { @@ -118,6 +185,8 @@ class CerrLog { #ifdef RAY_USE_GLOG typedef google::LogMessage LoggingProvider; +#elif defined(RAY_USE_SPDLOG) +typedef ray::SpdLogMessage LoggingProvider; #else typedef ray::CerrLog LoggingProvider; #endif @@ -125,6 +194,11 @@ typedef ray::CerrLog LoggingProvider; RayLogLevel RayLog::severity_threshold_ = RayLogLevel::INFO; std::string RayLog::app_name_ = ""; std::string RayLog::log_dir_ = ""; +// Format pattern is 2020-08-21 17:00:00,000 I 100 1001 msg. +// %L is loglevel, %P is process id, %t for thread id. +std::string RayLog::log_format_pattern_ = "[%Y-%m-%d %H:%M:%S,%e %L %P %t] %v"; +long RayLog::log_rotation_max_size_ = 1 << 29; +long RayLog::log_rotation_file_num_ = 10; bool RayLog::is_failure_signal_handler_installed_ = false; #ifdef RAY_USE_GLOG @@ -133,8 +207,8 @@ using namespace google; // Glog's severity map. static int GetMappedSeverity(RayLogLevel severity) { switch (severity) { + case RayLogLevel::TRACE: case RayLogLevel::DEBUG: - return GLOG_INFO; case RayLogLevel::INFO: return GLOG_INFO; case RayLogLevel::WARNING: @@ -150,6 +224,28 @@ static int GetMappedSeverity(RayLogLevel severity) { } } +#elif defined(RAY_USE_SPDLOG) +// Spdlog's severity map. +static int GetMappedSeverity(RayLogLevel severity) { + switch (severity) { + case RayLogLevel::TRACE: + return spdlog::level::trace; + case RayLogLevel::DEBUG: + return spdlog::level::debug; + case RayLogLevel::INFO: + return spdlog::level::info; + case RayLogLevel::WARNING: + return spdlog::level::warn; + case RayLogLevel::ERROR: + return spdlog::level::err; + case RayLogLevel::FATAL: + return spdlog::level::critical; + default: + RAY_LOG(FATAL) << "Unsupported logging level: " << static_cast(severity); + // This return won't be hit but compiler needs it. + return spdlog::level::off; + } +} #endif void RayLog::StartRayLog(const std::string &app_name, RayLogLevel severity_threshold, @@ -177,9 +273,11 @@ void RayLog::StartRayLog(const std::string &app_name, RayLogLevel severity_thres severity_threshold_ = severity_threshold; app_name_ = app_name; log_dir_ = log_dir; +#if defined(RAY_USE_GLOG) || defined(RAY_USE_SPDLOG) #ifdef RAY_USE_GLOG google::InitGoogleLogging(app_name_.c_str()); int level = GetMappedSeverity(static_cast(severity_threshold_)); +#endif if (!log_dir_.empty()) { // Enable log file if log_dir_ is not empty. std::string dir_ends_with_slash = log_dir_; @@ -196,15 +294,61 @@ void RayLog::StartRayLog(const std::string &app_name, RayLogLevel severity_thres app_name_without_path = app_file_name; } } +#ifdef RAY_USE_GLOG app_name_without_path += "."; google::SetLogFilenameExtension(app_name_without_path.c_str()); google::SetLogDestination(level, dir_ends_with_slash.c_str()); FLAGS_stop_logging_if_full_disk = true; +#else +#ifdef _WIN32 + int pid = _getpid(); +#else + pid_t pid = getpid(); +#endif + // Reset log pattern and level and we assume a log file can be rotated with + // 10 files in max size 512M by default. + if (getenv("RAY_ROTATION_MAX_SIZE")) { + log_rotation_max_size_ = std::atol(getenv("RAY_RAOTATION_MAX_SIZE")); + } + if (getenv("RAY_ROTATION_FILE_NUM")) { + log_rotation_file_num_ = std::atol(getenv("RAY_ROTATION_FILE_NUM")); + } + spdlog::set_pattern(log_format_pattern_); + spdlog::set_level(static_cast(severity_threshold_)); + // Sink all log stuff to default file logger we defined here. We may need + // multiple sinks for different files or loglevel. + auto file_logger = spdlog::get("ray_log_sink"); + if (!file_logger) { + file_logger = + spdlog::rotating_logger_mt("ray_log_sink", + dir_ends_with_slash + app_name_without_path + "_" + + std::to_string(pid) + ".log", + log_rotation_max_size_, log_rotation_file_num_); + } + spdlog::set_default_logger(file_logger); +#endif } else { +#ifdef RAY_USE_GLOG // NOTE(lingxuan.zlx): If no specific log dir or empty directory string, // we use stdout by default. google::base::SetLogger(level, &stdout_logger_singleton); +#else + auto console_sink = std::make_shared(); + console_sink->set_pattern(log_format_pattern_); + auto level = static_cast(severity_threshold_); + console_sink->set_level(level); + + auto err_sink = std::make_shared(); + err_sink->set_pattern(log_format_pattern_); + err_sink->set_level(spdlog::level::err); + + auto logger = std::shared_ptr( + new spdlog::logger("ray_log_sink", {console_sink, err_sink})); + logger->set_level(level); + spdlog::set_default_logger(logger); +#endif } +#ifdef RAY_USE_GLOG for (int i = GLOG_INFO; i <= GLOG_FATAL; ++i) { if (i != level) { // NOTE(lingxuan.zlx): It means nothing can be printed or sinked to pass @@ -216,10 +360,11 @@ void RayLog::StartRayLog(const std::string &app_name, RayLogLevel severity_thres } google::SetStderrLogging(GetMappedSeverity(RayLogLevel::ERROR)); #endif +#endif } void RayLog::UninstallSignalAction() { -#ifdef RAY_USE_GLOG +#if defined(RAY_USE_GLOG) || defined(RAY_USE_SPDLOG) if (!is_failure_signal_handler_installed_) { return; } @@ -245,10 +390,39 @@ void RayLog::UninstallSignalAction() { } void RayLog::ShutDownRayLog() { -#ifdef RAY_USE_GLOG +#if defined(RAY_USE_GLOG) || defined(RAY_USE_SPDLOG) UninstallSignalAction(); - google::ShutdownGoogleLogging(); #endif +#if defined(RAY_USE_GLOG) + google::ShutdownGoogleLogging(); +#elif defined(RAY_USE_SPDLOG) + if (spdlog::default_logger()) { + spdlog::default_logger()->flush(); + } + spdlog::drop_all(); + spdlog::shutdown(); +#endif +} + +void WriteFailureMessage(const char *data, int size) { + // The data & size represent one line failure message. + // The second parameter `size-1` means we should strip last char `\n` + // for pretty printing. + if (nullptr != data && size > 0) { + RAY_LOG(ERROR) << std::string(data, size - 1); + } +#ifdef RAY_USE_SPDLOG + // If logger writes logs to files, logs are fully-buffered, which is different from + // stdout (line-buffered) and stderr (unbuffered). So always flush here in case logs are + // lost when logger writes logs to files. + if (spdlog::default_logger()) { + spdlog::default_logger()->flush(); + } +#endif +} + +bool RayLog::IsFailureSignalHandlerEnabled() { + return is_failure_signal_handler_installed_; } void RayLog::InstallFailureSignalHandler() { @@ -258,11 +432,12 @@ void RayLog::InstallFailureSignalHandler() { // If process crashes, don't display an error window. SetErrorMode(GetErrorMode() | SEM_NOGPFAULTERRORBOX); #endif -#ifdef RAY_USE_GLOG +#if defined(RAY_USE_GLOG) || defined(RAY_USE_SPDLOG) if (is_failure_signal_handler_installed_) { return; } google::InstallFailureSignalHandler(); + google::InstallFailureWriter(&WriteFailureMessage); is_failure_signal_handler_installed_ = true; #endif } @@ -271,13 +446,15 @@ bool RayLog::IsLevelEnabled(RayLogLevel log_level) { return log_level >= severity_threshold_; } +std::string RayLog::GetLogFormatPattern() { return log_format_pattern_; } + RayLog::RayLog(const char *file_name, int line_number, RayLogLevel severity) // glog does not have DEBUG level, we can handle it using is_enabled_. : logging_provider_(nullptr), is_enabled_(severity >= severity_threshold_) { -#ifdef RAY_USE_GLOG +#if defined(RAY_USE_GLOG) || defined(RAY_USE_SPDLOG) if (is_enabled_) { logging_provider_ = - new google::LogMessage(file_name, line_number, GetMappedSeverity(severity)); + new LoggingProvider(file_name, line_number, GetMappedSeverity(severity)); } #else auto logging_provider = new CerrLog(severity); @@ -288,13 +465,9 @@ RayLog::RayLog(const char *file_name, int line_number, RayLogLevel severity) std::ostream &RayLog::Stream() { auto logging_provider = reinterpret_cast(logging_provider_); -#ifdef RAY_USE_GLOG // Before calling this function, user should check IsEnabled. // When IsEnabled == false, logging_provider_ will be empty. return logging_provider->stream(); -#else - return logging_provider->Stream(); -#endif } bool RayLog::IsEnabled() const { return is_enabled_; } diff --git a/src/ray/util/logging.h b/src/ray/util/logging.h index dcbf1c375..98d8aa32c 100644 --- a/src/ray/util/logging.h +++ b/src/ray/util/logging.h @@ -49,7 +49,14 @@ namespace ray { /// providing a new detection function for debug or something like that. std::string GetCallTrace(); -enum class RayLogLevel { DEBUG = -1, INFO = 0, WARNING = 1, ERROR = 2, FATAL = 3 }; +enum class RayLogLevel { + TRACE = -2, + DEBUG = -1, + INFO = 0, + WARNING = 1, + ERROR = 2, + FATAL = 3 +}; #define RAY_LOG_INTERNAL(level) ::ray::RayLog(__FILE__, __LINE__, level) @@ -141,8 +148,14 @@ class RayLog : public RayLogBase { /// If glog is not installed, this function won't do anything. static void InstallFailureSignalHandler(); // Get the log level from environment variable. + + // To check failure signal handler enabled or not. + static bool IsFailureSignalHandlerEnabled(); + static RayLogLevel GetLogLevelFromEnv(); + static std::string GetLogFormatPattern(); + private: // Hide the implementation of log provider by void *. // Otherwise, lib user may define the same macro to use the correct header file. @@ -159,6 +172,12 @@ class RayLog : public RayLogBase { /// This flag is used to avoid calling UninstallSignalAction in ShutDownRayLog if /// InstallFailureSignalHandler was not called. static bool is_failure_signal_handler_installed_; + // Log format content. + static std::string log_format_pattern_; + // Log rotation file size limitation. + static long log_rotation_max_size_; + // Log rotation file number. + static long log_rotation_file_num_; protected: virtual std::ostream &Stream(); diff --git a/src/ray/util/logging_test.cc b/src/ray/util/logging_test.cc index 5096c32c3..8ec90b761 100644 --- a/src/ray/util/logging_test.cc +++ b/src/ray/util/logging_test.cc @@ -124,6 +124,27 @@ TEST(PrintLogTest, CallstackTraceTest) { } #endif +/// Catch abort signal handler for testing RAY_CHECK. +/// We'd better to run the following test case manually since process +/// will terminated if abort signal raising. +/* +bool get_abort_signal = false; +void signal_handler(int signum) { + RAY_LOG(WARNING) << "Interrupt signal (" << signum << ") received."; + get_abort_signal = signum == SIGABRT; + exit(0); +} + +TEST(PrintLogTest, RayCheckAbortTest) { + get_abort_signal = false; + // signal(SIGABRT, signal_handler); + ray::RayLog::InstallFailureSignalHandler(); + RAY_CHECK(0) << "Check for aborting"; + sleep(1); + EXPECT_TRUE(get_abort_signal); +} +*/ + } // namespace ray int main(int argc, char **argv) {