[Log] new spdlog tool for ray (#10967)

* spdlog support

* fatal abort for spdlog

* print all logs in stderr if no logger given

* fix log test

* install signal handler for spdlog by reusing glog lib

* fix lint

* Avoid duplicated dump

* log rotation and fmt comments

* fix

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": [
     ],

src/ray/util/logging.cc

@@ -30,8 +30,9 @@
 #include <cstdlib>
 #include <fstream>
 #include <iostream>
+#include <sstream>
 
-#ifdef RAY_USE_GLOG
+#if defined(RAY_USE_GLOG) || defined(RAY_USE_SPDLOG)
 #include <sys/stat.h>
 #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<spdlog::logger> 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<int>(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<spdlog::level::level_enum>(loglevel_), /*fmt*/ "{}",
+                str_.str());
+    logger->flush();
+    if (loglevel_ == static_cast<int>(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<int>(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<RayLogLevel>(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<spdlog::level::level_enum>(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<spdlog::sinks::stdout_color_sink_mt>();
+    console_sink->set_pattern(log_format_pattern_);
+    auto level = static_cast<spdlog::level::level_enum>(severity_threshold_);
+    console_sink->set_level(level);
+
+    auto err_sink = std::make_shared<spdlog::sinks::stderr_color_sink_mt>();
+    err_sink->set_pattern(log_format_pattern_);
+    err_sink->set_level(spdlog::level::err);
+
+    auto logger = std::shared_ptr<spdlog::logger>(
+        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<LoggingProvider *>(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_; }

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();

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