Support pluggable backend log lib with glog (#2695)

* [WIP] Support different backend log lib

* Refine code, unify level, address comment

* Address comment and change formatter

* Fix linux building failure.

* Fix lint

* Remove log4cplus.

* Add log init to raylet main and add test to travis.

* Address comment and refine.

* Update logging_test.cc

.travis.yml

@@ -182,6 +182,7 @@ install:
   - ./src/ray/raylet/lineage_cache_test
   - ./src/ray/raylet/task_dependency_manager_test
   - ./src/ray/raylet/reconstruction_policy_test
+  - ./src/ray/util/logging_test --gtest_filter=PrintLogTest*
 
   - bash ../src/common/test/run_tests.sh
   - bash ../src/plasma/test/run_tests.sh

CMakeLists.txt

@@ -34,6 +34,10 @@ option(RAY_USE_NEW_GCS
   "Use the new GCS implementation"
   OFF)
 
+option(RAY_USE_GLOG
+  "Build the logging system using glog"
+  ON)
+
 if (RAY_USE_NEW_GCS)
   add_definitions(-DRAY_USE_NEW_GCS)
 endif()

cmake/Modules/ThirdpartyToolchain.cmake

@@ -94,3 +94,39 @@ endif()
 set(Boost_USE_STATIC_LIBS ON)
 find_package(Boost COMPONENTS system filesystem REQUIRED)
 include_directories(${Boost_INCLUDE_DIR})
+
+if(RAY_USE_GLOG)
+  message(STATUS "Starting to build glog")
+  set(GLOG_VERSION "0.3.5")
+  set(GLOG_CMAKE_CXX_FLAGS ${EP_CXX_FLAGS} "-fPIC")
+
+  set(GLOG_URL "https://github.com/google/glog/archive/v${GLOG_VERSION}.tar.gz")
+  set(GLOG_PREFIX "${CMAKE_CURRENT_BINARY_DIR}/glog_ep-prefix/src/glog_ep")
+  set(GLOG_HOME "${GLOG_PREFIX}")
+  set(GLOG_INCLUDE_DIR "${GLOG_PREFIX}/include")
+  set(GLOG_STATIC_LIB "${GLOG_PREFIX}/lib/libglog.a")
+
+  set(GLOG_CMAKE_ARGS -DCMAKE_BUILD_TYPE=${CMAKE_BUILD_TYPE}
+                        -DCMAKE_INSTALL_PREFIX=${GLOG_PREFIX}
+                        -DBUILD_SHARED_LIBS=OFF
+                        -DBUILD_TESTING=OFF
+                        -DWITH_GFLAGS=OFF
+                        -DCMAKE_CXX_FLAGS_${UPPERCASE_BUILD_TYPE}=${GLOG_CMAKE_CXX_FLAGS}
+                        -DCMAKE_C_FLAGS_${UPPERCASE_BUILD_TYPE}=${EP_C_FLAGS}
+                        -DCMAKE_CXX_FLAGS=${GLOG_CMAKE_CXX_FLAGS})
+
+  ExternalProject_Add(glog_ep
+    URL ${GLOG_URL}
+    ${EP_LOG_OPTIONS}
+    BUILD_IN_SOURCE 1
+    BUILD_BYPRODUCTS "${GLOG_STATIC_LIB}"
+    CMAKE_ARGS ${GLOG_CMAKE_ARGS})
+
+  message(STATUS "GLog include dir: ${GLOG_INCLUDE_DIR}")
+  message(STATUS "GLog static library: ${GLOG_STATIC_LIB}")
+  include_directories(SYSTEM ${GLOG_INCLUDE_DIR})
+  ADD_THIRDPARTY_LIB(glog
+    STATIC_LIB ${GLOG_STATIC_LIB})
+
+  add_dependencies(glog glog_ep)
+endif()

src/common/redis_module/CMakeLists.txt

@@ -14,4 +14,7 @@ endif()
 add_library(ray_redis_module SHARED ray_redis_module.cc)
 
 target_compile_options(ray_redis_module PUBLIC ${REDIS_MODULE_CFLAGS} -fPIC)
-target_link_libraries(ray_redis_module ${REDIS_MODULE_LDFLAGS})
+target_link_libraries(ray_redis_module
+    # RAY_CHECK needs this lib.
+    LINK_PUBLIC ray_static
+    ${REDIS_MODULE_LDFLAGS})

src/ray/CMakeLists.txt

@@ -36,6 +36,7 @@ set(RAY_SRCS
   gcs/task_table.cc
   gcs/redis_context.cc
   gcs/asio.cc
+  util/logging.cc
   common/client_connection.cc
   object_manager/object_manager_client_connection.cc
   object_manager/connection_pool.cc
@@ -61,6 +62,15 @@ set(RAY_SRCS
   raylet/raylet.cc
 )
 
+set(RAY_LIB_STATIC_LINK_LIBS ${PLASMA_STATIC_LIB} ${ARROW_STATIC_LIB})
+set(RAY_LIB_DEPENDENCIES gen_gcs_fbs gen_object_manager_fbs gen_node_manager_fbs gen_local_scheduler_fbs ${COMMON_FBS_OUTPUT_FILES})
+
+if(RAY_USE_GLOG)
+  set(CMAKE_CXX_FLAGS "${CMAKE_CXX_FLAGS} -DRAY_USE_GLOG")
+  set(RAY_LIB_STATIC_LINK_LIBS ${RAY_LIB_STATIC_LINK_LIBS} ${GLOG_STATIC_LIB})
+  set(RAY_LIB_DEPENDENCIES ${RAY_LIB_DEPENDENCIES} glog)
+endif()
+
 install(FILES
   api.h
   id.h
@@ -79,6 +89,6 @@ ADD_RAY_LIB(ray
   SOURCES ${RAY_SRCS} ${AE_SRCS} ${HIREDIS_SRCS} ${UTIL_SRCS}
     # TODO: When raylet replaces the old backend, please remove the dependency gen_local_scheduler_fbs.
     # TODO: When remove the included Task.h from table.h, please remove the dependency gen_common_python_fbs.
-    DEPENDENCIES gen_gcs_fbs gen_object_manager_fbs gen_node_manager_fbs gen_local_scheduler_fbs ${COMMON_FBS_OUTPUT_FILES}
+    DEPENDENCIES ${RAY_LIB_DEPENDENCIES}
     SHARED_LINK_LIBS ""
-    STATIC_LINK_LIBS ${PLASMA_STATIC_LIB} ${ARROW_STATIC_LIB})
+    STATIC_LINK_LIBS ${RAY_LIB_STATIC_LINK_LIBS})

src/ray/raylet/main.cc

@@ -6,6 +6,7 @@
 
 #ifndef RAYLET_TEST
 int main(int argc, char *argv[]) {
+  RayLog::StartRayLog(argv[0], RAY_INFO);
   RAY_CHECK(argc == 10);
 
   const std::string raylet_socket_name = std::string(argv[1]);
@@ -104,5 +105,6 @@ int main(int argc, char *argv[]) {
   signals.async_wait(handler);
 
   main_service.run();
+  RayLog::ShutDownRayLog();
 }
 #endif

src/ray/util/CMakeLists.txt

@@ -5,3 +5,5 @@ install(FILES
   visibility.h
   DESTINATION "${CMAKE_INSTALL_INCLUDEDIR}/ray/util"
 )
+
+ADD_RAY_TEST(logging_test STATIC_LINK_LIBS ray_static gtest pthread)

src/ray/util/logging.cc

@@ -0,0 +1,140 @@
+#include <cstdlib>
+#include <iostream>
+
+#include "ray/util/logging.h"
+
+#ifdef RAY_USE_GLOG
+#include "glog/logging.h"
+#endif
+
+namespace ray {
+
+// This is the default implementation of ray log,
+// which is independent of any libs.
+class CerrLog {
+ public:
+  CerrLog(int severity) : severity_(severity), has_logged_(false) {}
+
+  virtual ~CerrLog() {
+    if (has_logged_) {
+      std::cerr << std::endl;
+    }
+    if (severity_ == RAY_FATAL) {
+      PrintBackTrace();
+      std::abort();
+    }
+  }
+
+  std::ostream &Stream() {
+    has_logged_ = true;
+    return std::cerr;
+  }
+
+  template <class T>
+  CerrLog &operator<<(const T &t) {
+    if (severity_ != RAY_DEBUG) {
+      has_logged_ = true;
+      std::cerr << t;
+    }
+    return *this;
+  }
+
+ protected:
+  const int severity_;
+  bool has_logged_;
+
+  void PrintBackTrace() {
+#if defined(_EXECINFO_H) || !defined(_WIN32)
+    void *buffer[255];
+    const int calls = backtrace(buffer, sizeof(buffer) / sizeof(void *));
+    backtrace_symbols_fd(buffer, calls, 1);
+#endif
+  }
+};
+
+int RayLog::severity_threshold_ = RAY_INFO;
+
+#ifdef RAY_USE_GLOG
+using namespace google;
+
+// Glog's severity map.
+static int GetMappedSeverity(int severity) {
+  switch (severity) {
+  case RAY_DEBUG:
+    return GLOG_INFO;
+  case RAY_INFO:
+    return GLOG_INFO;
+  case RAY_WARNING:
+    return GLOG_WARNING;
+  case RAY_ERROR:
+    return GLOG_ERROR;
+  case RAY_FATAL:
+    return GLOG_FATAL;
+  default:
+    RAY_LOG(FATAL) << "Unsupported logging level: " << severity;
+    // This return won't be hit but compiler needs it.
+    return GLOG_FATAL;
+  }
+}
+
+#endif
+
+void RayLog::StartRayLog(const std::string &app_name, int severity_threshold,
+                         const std::string &log_dir) {
+#ifdef RAY_USE_GLOG
+  severity_threshold_ = severity_threshold;
+  int mapped_severity_threshold = GetMappedSeverity(severity_threshold_);
+  google::InitGoogleLogging(app_name.c_str());
+  google::SetStderrLogging(mapped_severity_threshold);
+  // Enble log file if log_dir is not empty.
+  if (!log_dir.empty()) {
+    auto dir_ends_with_slash = log_dir;
+    if (log_dir[log_dir.length() - 1] != '/') {
+      dir_ends_with_slash += "/";
+    }
+    auto app_name_without_path = app_name;
+    if (app_name.empty()) {
+      app_name_without_path = "DefaultApp";
+    } else {
+      // Find the app name without the path.
+      size_t pos = app_name.rfind('/');
+      if (pos != app_name.npos && pos + 1 < app_name.length()) {
+        app_name_without_path = app_name.substr(pos + 1);
+      }
+    }
+    google::SetLogFilenameExtension(app_name_without_path.c_str());
+    google::SetLogDestination(mapped_severity_threshold, log_dir.c_str());
+  }
+#endif
+}
+
+void RayLog::ShutDownRayLog() {
+#ifdef RAY_USE_GLOG
+  google::ShutdownGoogleLogging();
+#endif
+}
+
+RayLog::RayLog(const char *file_name, int line_number, int severity) {
+#ifdef RAY_USE_GLOG
+  // glog does not have DEBUG level, we can handle it here.
+  if (severity >= severity_threshold_) {
+    logging_provider_.reset(
+        new google::LogMessage(file_name, line_number, GetMappedSeverity(severity)));
+  }
+#else
+  logging_provider_.reset(new CerrLog(severity));
+  *logging_provider_ << file_name << ":" << line_number << ": ";
+#endif
+}
+
+std::ostream &RayLog::Stream() {
+#ifdef RAY_USE_GLOG
+  return logging_provider_->stream();
+#else
+  return logging_provider_->Stream();
+#endif
+}
+
+RayLog::~RayLog() { logging_provider_.reset(); }
+
+}  // namespace ray

src/ray/util/logging.h

@@ -7,16 +7,24 @@
 
 #include <cstdlib>
 #include <iostream>
+#include <memory>
 
 #include "ray/util/macros.h"
 
+// Forward declaration for the log provider.
+#ifdef RAY_USE_GLOG
+namespace google {
+class LogMessage;
+}  // namespace google
+typedef google::LogMessage LoggingProvider;
+#else
 namespace ray {
+class CerrLog;
+}  // namespace ray
+typedef ray::CerrLog LoggingProvider;
+#endif
 
-// Stubbed versions of macros defined in glog/logging.h, intended for
-// environments where glog headers aren't available.
-//
-// Add more as needed.
-
+namespace ray {
 // Log levels. LOG ignores them, so their values are abitrary.
 
 #define RAY_DEBUG (-1)
@@ -25,22 +33,21 @@ namespace ray {
 #define RAY_ERROR 2
 #define RAY_FATAL 3
 
-#define RAY_LOG_INTERNAL(level) \
-  ::ray::internal::CerrLog(level) << __FILE__ << ":" << __LINE__ << ": "
+#define RAY_LOG_INTERNAL(level) ::ray::RayLog(__FILE__, __LINE__, level)
 
 #define RAY_LOG(level) RAY_LOG_INTERNAL(RAY_##level)
-#define RAY_IGNORE_EXPR(expr) ((void) (expr));
+#define RAY_IGNORE_EXPR(expr) ((void)(expr))
 
-#define RAY_CHECK(condition)                             \
-  (condition) ? 0 : ::ray::internal::FatalLog(RAY_FATAL) \
-                        << __FILE__ << ":" << __LINE__   \
-                        << " Check failed: " #condition " "
+#define RAY_CHECK(condition)                                                          \
+  (condition) ? RAY_IGNORE_EXPR(0) : ::ray::Voidify() &                               \
+                                         ::ray::RayLog(__FILE__, __LINE__, RAY_FATAL) \
+                                             << " Check failed: " #condition " "
 
 #ifdef NDEBUG
 
 #define RAY_DCHECK(condition) \
-  RAY_IGNORE_EXPR(condition)  \
-  while (false) ::ray::internal::NullLog()
+  RAY_IGNORE_EXPR(condition); \
+  while (false) ::ray::RayLogBase()
 
 #else
 
@@ -48,74 +55,62 @@ namespace ray {
 
 #endif  // NDEBUG
 
-namespace internal {
+// To make the logging lib plugable with other logging libs and make
+// the implementation unawared by the user, RayLog is only a declaration
+// which hide the implementation into logging.cc file.
+// In logging.cc, we can choose different log libs using different macros.
 
-class NullLog {
+// This is also a null log which does not output anything.
+class RayLogBase {
  public:
-  template <class T>
-  NullLog &operator<<(const T &t) {
+  virtual ~RayLogBase(){};
+
+  template <typename T>
+  RayLogBase &operator<<(const T &t) {
     RAY_IGNORE_EXPR(t);
     return *this;
   }
 };
 
-class CerrLog {
+class RayLog : public RayLogBase {
  public:
-  CerrLog(int severity)  // NOLINT(runtime/explicit)
-      : severity_(severity),
-        has_logged_(false) {}
+  RayLog(const char *file_name, int line_number, int severity);
+  virtual ~RayLog();
 
-  virtual ~CerrLog() {
-    if (has_logged_) {
-      std::cerr << std::endl;
-    }
-    // This code is duplicated in the FatalLog class.
-    if (severity_ == RAY_FATAL) {
-#if defined(_EXECINFO_H) || !defined(_WIN32)
-      void *buffer[255];
-      const int calls = backtrace(buffer, sizeof(buffer) / sizeof(void *));
-      backtrace_symbols_fd(buffer, calls, 1);
-#endif
-      std::abort();
-    }
-  }
-
-  template <class T>
-  CerrLog &operator<<(const T &t) {
-    if (severity_ != RAY_DEBUG) {
-      has_logged_ = true;
-      std::cerr << t;
+  template <typename T>
+  RayLogBase &operator<<(const T &t) {
+    if (logging_provider_ == nullptr) {
+      // This means the logging level is lower than the threshold.
+      RAY_IGNORE_EXPR(t);
+    } else {
+      this->Stream() << t;
     }
     return *this;
   }
 
- protected:
-  const int severity_;
-  bool has_logged_;
+  // The init function of ray log for a program which should be called only once.
+  // If logDir is empty, the log won't output to file.
+  static void StartRayLog(const std::string &appName, int severity_threshold = RAY_ERROR,
+                          const std::string &logDir = "");
+  // The shutdown function of ray log which should be used with StartRayLog as a pair.
+  static void ShutDownRayLog();
+
+ private:
+  std::ostream &Stream();
+  std::unique_ptr<LoggingProvider> logging_provider_;
+  static int severity_threshold_;
 };
 
-// Clang-tidy isn't smart enough to determine that DCHECK using CerrLog doesn't
-// return so we create a new class to give it a hint.
-class FatalLog : public CerrLog {
+// This class make RAY_CHECK compilation pass to change the << operator to void.
+// This class is copied from glog.
+class Voidify {
  public:
-  explicit FatalLog(int /* severity */)  // NOLINT
-      : CerrLog(RAY_FATAL) {}            // NOLINT
-
-  RAY_NORETURN ~FatalLog() {
-    if (has_logged_) {
-      std::cerr << std::endl;
-#if defined(_EXECINFO_H) || !defined(_WIN32)
-      void *buffer[255];
-      const int calls = backtrace(buffer, sizeof(buffer) / sizeof(void *));
-      backtrace_symbols_fd(buffer, calls, 1);
-#endif
-    }
-    std::abort();
-  }
+  Voidify() {}
+  // This has to be an operator with a precedence lower than << but
+  // higher than ?:
+  void operator&(RayLogBase &) {}
 };
 
-}  // namespace internal
-
 }  // namespace ray
 
 #endif  // RAY_UTIL_LOGGING_H

src/ray/util/logging_test.cc

@@ -0,0 +1,79 @@
+#include <chrono>
+#include <cstdlib>
+#include <iostream>
+
+#include "gtest/gtest.h"
+#include "ray/util/logging.h"
+
+namespace ray {
+
+int64_t current_time_ms() {
+  std::chrono::milliseconds ms_since_epoch =
+      std::chrono::duration_cast<std::chrono::milliseconds>(
+          std::chrono::steady_clock::now().time_since_epoch());
+  return ms_since_epoch.count();
+}
+
+// This is not really test.
+// This file just print some information using the logging macro.
+
+void PrintLog() {
+  RAY_LOG(DEBUG) << "This is the DEBUG message";
+  RAY_LOG(INFO) << "This is the INFO message";
+  RAY_LOG(WARNING) << "This is the WARNING message";
+  RAY_LOG(ERROR) << "This is the ERROR message";
+  RAY_CHECK(true) << "This is a RAY_CHECK message but it won't show up";
+  // The following 2 lines should not run since it will cause program failure.
+  // RAY_LOG(FATAL) << "This is the FATAL message";
+  // RAY_CHECK(false) << "This is a RAY_CHECK message but it won't show up";
+}
+
+TEST(PrintLogTest, LogTestWithoutInit) {
+  // Without RayLog::StartRayLog, this should also work.
+  PrintLog();
+}
+
+TEST(PrintLogTest, LogTestWithInit) {
+  // Test empty app name.
+  RayLog::StartRayLog("", RAY_DEBUG);
+  PrintLog();
+  RayLog::ShutDownRayLog();
+}
+
+// This test will output large amount of logs to stderr, should be disabled in travis.
+TEST(LogPerfTest, PerfTest) {
+  RayLog::StartRayLog("/fake/path/to/appdire/LogPerfTest", RAY_ERROR, "/tmp/");
+  int rounds = 100000;
+
+  int64_t start_time = current_time_ms();
+  for (int i = 0; i < rounds; ++i) {
+    RAY_LOG(DEBUG) << "This is the RAY_DEBUG message";
+  }
+  int64_t elapsed = current_time_ms() - start_time;
+  std::cout << "Testing DEBUG log for " << rounds << " rounds takes " << elapsed << " ms."
+            << std::endl;
+
+  start_time = current_time_ms();
+  for (int i = 0; i < rounds; ++i) {
+    RAY_LOG(ERROR) << "This is the RAY_ERROR message";
+  }
+  elapsed = current_time_ms() - start_time;
+  std::cout << "Testing RAY_ERROR log for " << rounds << " rounds takes " << elapsed
+            << " ms." << std::endl;
+
+  start_time = current_time_ms();
+  for (int i = 0; i < rounds; ++i) {
+    RAY_CHECK(i >= 0) << "This is a RAY_CHECK message but it won't show up";
+  }
+  elapsed = current_time_ms() - start_time;
+  std::cout << "Testing RAY_CHECK(true) for " << rounds << " rounds takes " << elapsed
+            << " ms." << std::endl;
+  RayLog::ShutDownRayLog();
+}
+
+}  // namespace ray
+
+int main(int argc, char **argv) {
+  ::testing::InitGoogleTest(&argc, argv);
+  return RUN_ALL_TESTS();
+}