Improve backend log: env variable setting and format refine. (#3662)

* Improve backend logging

* Address comment

* Fix Raul's comment

src/ray/id.cc

@@ -155,7 +155,11 @@ uint64_t MurmurHash64A(const void *key, int len, unsigned int seed) {
 size_t UniqueID::hash() const { return MurmurHash64A(&id_[0], kUniqueIDSize, 0); }
 
 std::ostream &operator<<(std::ostream &os, const UniqueID &id) {
-  os << id.hex();
+  if (id.is_nil()) {
+    os << "NIL_ID";
+  } else {
+    os << id.hex();
+  }
   return os;
 }
 

src/ray/raylet/node_manager.cc

@@ -512,7 +512,7 @@ void NodeManager::HandleActorStateTransition(const ActorID &actor_id,
   ActorRegistration actor_registration(data);
   RAY_LOG(DEBUG) << "Actor notification received: actor_id = " << actor_id
                  << ", node_manager_id = " << actor_registration.GetNodeManagerId()
-                 << ", state = " << static_cast<int64_t>(actor_registration.GetState())
+                 << ", state = " << EnumNameActorState(actor_registration.GetState())
                  << ", remaining_reconstructions = "
                  << actor_registration.GetRemainingReconstructions();
   // Update local registry.
@@ -639,10 +639,10 @@ void NodeManager::DispatchTasks(
 void NodeManager::ProcessClientMessage(
     const std::shared_ptr<LocalClientConnection> &client, int64_t message_type,
     const uint8_t *message_data) {
-  RAY_LOG(DEBUG) << "Message of type " << message_type;
-
   auto registered_worker = worker_pool_.GetRegisteredWorker(client);
   auto message_type_value = static_cast<protocol::MessageType>(message_type);
+  RAY_LOG(DEBUG) << "Message of " << protocol::EnumNameMessageType(message_type_value)
+                 << "(" << message_type << ")";
   if (registered_worker && registered_worker->IsDead()) {
     // For a worker that is marked as dead (because the driver has died already),
     // all the messages are ignored except DisconnectClient.
@@ -1212,9 +1212,12 @@ void NodeManager::SubmitTask(const Task &task, const Lineage &uncommitted_lineag
                              bool forwarded) {
   const TaskSpecification &spec = task.GetTaskSpecification();
   const TaskID &task_id = spec.TaskId();
-  RAY_LOG(DEBUG) << "Submitting task: task_id = " << task_id
-                 << ", actor_id = " << spec.ActorId()
-                 << ", actor_creation_id = " << spec.ActorCreationId();
+  RAY_LOG(DEBUG) << "Submitting task: task_id=" << task_id
+                 << ", actor_id=" << spec.ActorId()
+                 << ", actor_creation_id=" << spec.ActorCreationId()
+                 << ", actor_handle_id=" << spec.ActorHandleId()
+                 << ", actor_counter=" << spec.ActorCounter()
+                 << ", task_descriptor=" << spec.FunctionDescriptorString();
 
   if (local_queues_.HasTask(task_id)) {
     RAY_LOG(WARNING) << "Submitted task " << task_id
@@ -1474,7 +1477,8 @@ bool NodeManager::AssignTask(const Task &task) {
     return false;
   }
 
-  RAY_LOG(DEBUG) << "Assigning task to worker with pid " << worker->Pid();
+  RAY_LOG(DEBUG) << "Assigning task " << spec.TaskId() << " to worker with pid "
+                 << worker->Pid();
   flatbuffers::FlatBufferBuilder fbb;
 
   // Resource accounting: acquire resources for the assigned task.
@@ -1531,9 +1535,8 @@ bool NodeManager::AssignTask(const Task &task) {
           }
           // We started running the task, so the task is ready to write to GCS.
           if (!lineage_cache_.AddReadyTask(assigned_task)) {
-            RAY_LOG(WARNING) << "Task " << spec.TaskId() << " already in lineage cache. "
-                                                            "This is most likely due to "
-                                                            "reconstruction.";
+            RAY_LOG(WARNING) << "Task " << spec.TaskId() << " already in lineage cache."
+                             << " This is most likely due to reconstruction.";
           }
           // Mark the task as running.
           // (See design_docs/task_states.rst for the state transition diagram.)
@@ -1869,9 +1872,8 @@ void NodeManager::ForwardTask(const Task &task, const ClientID &node_id,
           // lineage cache since the receiving node is now responsible for writing
           // the task to the GCS.
           if (!lineage_cache_.RemoveWaitingTask(task_id)) {
-            RAY_LOG(WARNING) << "Task " << task_id << " already removed from the lineage "
-                                                      "cache. This is most likely due to "
-                                                      "reconstruction.";
+            RAY_LOG(WARNING) << "Task " << task_id << " already removed from the lineage"
+                             << " cache. This is most likely due to reconstruction.";
           }
           // Mark as forwarded so that the task and its lineage is not re-forwarded
           // in the future to the receiving node.

src/ray/raylet/task_spec.cc

@@ -1,5 +1,7 @@
 #include "task_spec.h"
 
+#include <sstream>
+
 #include "ray/common/common_protocol.h"
 #include "ray/gcs/format/gcs_generated.h"
 #include "ray/util/logging.h"
@@ -139,6 +141,21 @@ std::vector<std::string> TaskSpecification::FunctionDescriptor() const {
   return string_vec_from_flatbuf(*message->function_descriptor());
 }
 
+std::string TaskSpecification::FunctionDescriptorString() const {
+  auto message = flatbuffers::GetRoot<TaskInfo>(spec_.data());
+  auto list = string_vec_from_flatbuf(*message->function_descriptor());
+  std::ostringstream stream;
+  // The 4th is the code hash which is binary bits. No need to output it.
+  int size = std::min(static_cast<size_t>(3), list.size());
+  for (int i = 0; i < size; ++i) {
+    if (i != 0) {
+      stream << ",";
+    }
+    stream << list[i];
+  }
+  return stream.str();
+}
+
 int64_t TaskSpecification::NumArgs() const {
   auto message = flatbuffers::GetRoot<TaskInfo>(spec_.data());
   return message->args()->size();

src/ray/raylet/task_spec.h

@@ -160,6 +160,8 @@ class TaskSpecification {
   TaskID ParentTaskId() const;
   int64_t ParentCounter() const;
   std::vector<std::string> FunctionDescriptor() const;
+  // Output the function descriptor as a string for log purpose.
+  std::string FunctionDescriptorString() const;
   int64_t NumArgs() const;
   int64_t NumReturns() const;
   bool ArgByRef(int64_t arg_index) const;

src/ray/util/logging.cc

@@ -3,7 +3,10 @@
 #ifndef _WIN32
 #include <execinfo.h>
 #endif
+
+#include <signal.h>
 #include <stdlib.h>
+#include <algorithm>
 #include <cstdlib>
 #include <iostream>
 
@@ -92,6 +95,26 @@ static int GetMappedSeverity(RayLogLevel severity) {
 
 void RayLog::StartRayLog(const std::string &app_name, RayLogLevel severity_threshold,
                          const std::string &log_dir) {
+  const char *var_value = getenv("RAY_BACKEND_LOG_LEVEL");
+  if (var_value != nullptr) {
+    std::string data = var_value;
+    std::transform(data.begin(), data.end(), data.begin(), ::tolower);
+    if (data == "debug") {
+      severity_threshold = RayLogLevel::DEBUG;
+    } else if (data == "info") {
+      severity_threshold = RayLogLevel::INFO;
+    } else if (data == "warning") {
+      severity_threshold = RayLogLevel::WARNING;
+    } else if (data == "error") {
+      severity_threshold = RayLogLevel::ERROR;
+    } else if (data == "fatal") {
+      severity_threshold = RayLogLevel::FATAL;
+    } else {
+      RAY_LOG(WARNING) << "Unrecognized setting of RAY_BACKEND_LOG_LEVEL=" << var_value;
+    }
+    RAY_LOG(INFO) << "Set ray log level from environment variable RAY_BACKEND_LOG_LEVEL"
+                  << " to " << static_cast<int>(severity_threshold);
+  }
   severity_threshold_ = severity_threshold;
   app_name_ = app_name;
 #ifdef RAY_USE_GLOG
@@ -120,8 +143,25 @@ void RayLog::StartRayLog(const std::string &app_name, RayLogLevel severity_thres
 #endif
 }
 
+void RayLog::UninstallSignalAction() {
+#ifdef RAY_USE_GLOG
+  RAY_LOG(DEBUG) << "Uninstall signal handlers.";
+  // This signal list comes from glog's signalhandler.cc.
+  // https://github.com/google/glog/blob/master/src/signalhandler.cc#L58-L70
+  static std::vector<int> installed_signals({SIGSEGV, SIGILL, SIGFPE, SIGABRT, SIGTERM});
+  struct sigaction sig_action;
+  memset(&sig_action, 0, sizeof(sig_action));
+  sigemptyset(&sig_action.sa_mask);
+  sig_action.sa_handler = SIG_DFL;
+  for (int signal_num : installed_signals) {
+    sigaction(signal_num, &sig_action, NULL);
+  }
+#endif
+}
+
 void RayLog::ShutDownRayLog() {
 #ifdef RAY_USE_GLOG
+  UninstallSignalAction();
   google::ShutdownGoogleLogging();
 #endif
 }

src/ray/util/logging.h

@@ -82,6 +82,9 @@ class RayLog : public RayLogBase {
   /// The shutdown function of ray log which should be used with StartRayLog as a pair.
   static void ShutDownRayLog();
 
+  /// Uninstall the signal actions installed by InstallFailureSignalHandler.
+  static void UninstallSignalAction();
+
   /// Return whether or not the log level is enabled in current setting.
   ///
   /// \param log_level The input log level to test.