diff --git a/src/ray/object_manager/object_manager.cc b/src/ray/object_manager/object_manager.cc index 7e0e3cb89..7b6a7f6e7 100644 --- a/src/ray/object_manager/object_manager.cc +++ b/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 - << "from Plasma store. It may have been evicted."; + RAY_LOG_EVERY_N_OR_DEBUG(INFO, 100) + << "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 - << ". It may have been evicted."; + RAY_LOG_EVERY_N_OR_DEBUG(INFO, 100) + << "Ignoring stale read request for already deleted object: " << object_id; return; } auto chunk_object_reader = std::make_shared( diff --git a/src/ray/util/logging.h b/src/ray/util/logging.h index f46d03968..c75bfbec1 100644 --- a/src/ray/util/logging.h +++ b/src/ray/util/logging.h @@ -48,6 +48,7 @@ #pragma once +#include #include #include #include @@ -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 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 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_; diff --git a/src/ray/util/logging_test.cc b/src/ray/util/logging_test.cc index d1875b9f6..fc7c555e4 100644 --- a/src/ray/util/logging_test.cc +++ b/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++) { - RAY_LOG_EVERY_N(INFO, 3) << "this is a test log"; + static int non_fallback_counter = 0; + 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) {