[core][usability] fix noisy push related log (#17250)

src/ray/object_manager/object_manager.cc

@@ -391,8 +391,8 @@ void ObjectManager::PushLocalObject(const ObjectID &object_id, const NodeID &nod
       buffer_pool_.CreateObjectReader(object_id, owner_address);
   Status status = reader_status.second;
   if (!status.ok()) {
-    RAY_LOG(ERROR) << "Failed to read object " << object_id
+    RAY_LOG_EVERY_N_OR_DEBUG(INFO, 100)
-                   << "from Plasma store. It may have been evicted.";
+        << "Ignoring stale read request for already deleted object: " << object_id;
     return;
   }
 
@@ -434,8 +434,8 @@ void ObjectManager::PushFromFilesystem(const ObjectID &object_id, const NodeID &
         auto optional_spilled_object =
             SpilledObjectReader::CreateSpilledObjectReader(spilled_url);
         if (!optional_spilled_object.has_value()) {
-          RAY_LOG(ERROR) << "Failed to load spilled object " << object_id
+          RAY_LOG_EVERY_N_OR_DEBUG(INFO, 100)
-                         << ". It may have been evicted.";
+              << "Ignoring stale read request for already deleted object: " << object_id;
           return;
         }
         auto chunk_object_reader = std::make_shared<ChunkObjectReader>(

src/ray/util/logging.h

@@ -48,6 +48,7 @@
 
 #pragma once
 
+#include <gtest/gtest_prod.h>
 #include <atomic>
 #include <chrono>
 #include <iostream>
@@ -127,11 +128,25 @@ enum class RayLogLevel {
 
 #define RAY_LOG_OCCURRENCES RAY_LOG_EVERY_N_VARNAME(occurrences_, __LINE__)
 
+// Occasional logging, log every n'th occurrence of an event.
 #define RAY_LOG_EVERY_N(level, n)                             \
   static std::atomic<uint64_t> RAY_LOG_OCCURRENCES(0);        \
   if (ray::RayLog::IsLevelEnabled(ray::RayLogLevel::level) && \
       RAY_LOG_OCCURRENCES.fetch_add(1) % n == 0)              \
-  RAY_LOG_INTERNAL(ray::RayLogLevel::level) << "[" << RAY_LOG_OCCURRENCES - 1 << "] "
+  RAY_LOG_INTERNAL(ray::RayLogLevel::level) << "[" << RAY_LOG_OCCURRENCES << "] "
+
+// Occasional logging with DEBUG fallback:
+// If DEBUG is not enabled, log every n'th occurrence of an event.
+// Otherwise, if DEBUG is enabled, always log as DEBUG events.
+#define RAY_LOG_EVERY_N_OR_DEBUG(level, n)                              \
+  static std::atomic<uint64_t> RAY_LOG_OCCURRENCES(0);                  \
+  if (ray::RayLog::IsLevelEnabled(ray::RayLogLevel::DEBUG) ||           \
+      (ray::RayLog::IsLevelEnabled(ray::RayLogLevel::level) &&          \
+       RAY_LOG_OCCURRENCES.fetch_add(1) % n == 0))                      \
+  RAY_LOG_INTERNAL(ray::RayLog::IsLevelEnabled(ray::RayLogLevel::level) \
+                       ? ray::RayLogLevel::level                        \
+                       : ray::RayLogLevel::DEBUG)                       \
+      << "[" << RAY_LOG_OCCURRENCES << "] "
 
 /// Macros for RAY_LOG_EVERY_MS
 #define RAY_LOG_TIME_PERIOD RAY_LOG_EVERY_N_VARNAME(timePeriod_, __LINE__)
@@ -225,6 +240,8 @@ class RayLog : public RayLogBase {
   static std::string GetLoggerName();
 
  private:
+  FRIEND_TEST(PrintLogTest, TestRayLogEveryNOrDebug);
+  FRIEND_TEST(PrintLogTest, TestRayLogEveryN);
   // Hide the implementation of log provider by void *.
   // Otherwise, lib user may define the same macro to use the correct header file.
   void *logging_provider_;

src/ray/util/logging_test.cc

@@ -63,20 +63,104 @@ TEST(PrintLogTest, LogTestWithoutInit) {
 using testing::internal::CaptureStderr;
 using testing::internal::GetCapturedStderr;
 
-TEST(PrintLogTest, TestRayLogEveryN) {
+namespace {
+void VerifyOnlyNthOccurenceLogged(bool fallback_to_debug) {
+  const std::string kLogStr = "this is a test log";
   CaptureStderr();
-  for (int i = 0; i < 10; i++) {
+  static int non_fallback_counter = 0;
-    RAY_LOG_EVERY_N(INFO, 3) << "this is a test log";
+  static int fallback_counter = 0;
+  int &counter = fallback_to_debug ? fallback_counter : non_fallback_counter;
+  for (int i = 0; i < 9; i++) {
+    counter++;
+    if (fallback_to_debug) {
+      RAY_LOG_EVERY_N_OR_DEBUG(INFO, 3) << kLogStr;
+    } else {
+      RAY_LOG_EVERY_N(INFO, 3) << kLogStr;
+    }
   }
   std::string output = GetCapturedStderr();
-  for (int i = 0; i < 10; i++) {
+  for (int i = counter - 8; i <= counter; i++) {
     std::string expected_str = absl::StrFormat("[%d] this is a test log", i);
-    if (i % 3 == 0) {
+    if (i % 3 == 1) {
       EXPECT_THAT(output, HasSubstr(expected_str));
     } else {
       EXPECT_THAT(output, Not(HasSubstr(expected_str)));
     }
   }
+
+  size_t occurrences = 0;
+  std::string::size_type start = 0;
+
+  while ((start = output.find(kLogStr, start)) != std::string::npos) {
+    ++occurrences;
+    start += kLogStr.length();
+  }
+  EXPECT_EQ(occurrences, 3);
+}
+
+void VerifyAllOccurenceLogged() {
+  const std::string kLogStr = "this is a test log";
+  CaptureStderr();
+  for (int i = 0; i < 10; i++) {
+    RAY_LOG_EVERY_N_OR_DEBUG(INFO, 3) << kLogStr;
+  }
+  std::string output = GetCapturedStderr();
+  size_t occurrences = 0;
+  std::string::size_type start = 0;
+  while ((start = output.find("[0] this is a test log", start)) != std::string::npos) {
+    ++occurrences;
+    start += kLogStr.length();
+  }
+  EXPECT_EQ(occurrences, 10);
+}
+
+void VerifyNothingLogged(bool fallback_to_debug) {
+  const std::string kLogStr = "this is a test log";
+  CaptureStderr();
+  for (int i = 0; i < 10; i++) {
+    if (fallback_to_debug) {
+      RAY_LOG_EVERY_N_OR_DEBUG(INFO, 3) << kLogStr;
+    } else {
+      RAY_LOG_EVERY_N(INFO, 3) << kLogStr;
+    };
+  }
+  std::string output = GetCapturedStderr();
+
+  size_t occurrences = 0;
+  std::string::size_type start = 0;
+
+  while ((start = output.find(kLogStr, start)) != std::string::npos) {
+    ++occurrences;
+    start += kLogStr.length();
+  }
+  EXPECT_EQ(occurrences, 0);
+}
+}  // namespace
+
+TEST(PrintLogTest, TestRayLogEveryN) {
+  RayLog::severity_threshold_ = RayLogLevel::INFO;
+  VerifyOnlyNthOccurenceLogged(/*fallback_to_debug*/ false);
+
+  RayLog::severity_threshold_ = RayLogLevel::DEBUG;
+  VerifyOnlyNthOccurenceLogged(/*fallback_to_debug*/ false);
+
+  RayLog::severity_threshold_ = RayLogLevel::WARNING;
+  VerifyNothingLogged(/*fallback_to_debug*/ false);
+
+  RayLog::severity_threshold_ = RayLogLevel::INFO;
+}
+
+TEST(PrintLogTest, TestRayLogEveryNOrDebug) {
+  RayLog::severity_threshold_ = RayLogLevel::INFO;
+  VerifyOnlyNthOccurenceLogged(/*fallback_to_debug*/ true);
+
+  RayLog::severity_threshold_ = RayLogLevel::DEBUG;
+  VerifyAllOccurenceLogged();
+
+  RayLog::severity_threshold_ = RayLogLevel::WARNING;
+  VerifyNothingLogged(/*fallback_to_debug*/ true);
+
+  RayLog::severity_threshold_ = RayLogLevel::INFO;
 }
 
 TEST(PrintLogTest, TestRayLogEveryMs) {