From f874ed9aa1077a6b98bfa4ac8b0d397e11fc88b2 Mon Sep 17 00:00:00 2001 From: shockp Date: Sun, 5 Apr 2026 12:26:10 +0200 Subject: [PATCH 1/3] GH-49433: [C++] Buffer ARROW_LOG output to prevent thread interleaving When using the ARROW_LOG macros from multiple threads, messages were getting mingled together in stderr because the operator<< was writing directly to the global stream piece-by-piece. This commit introduces an internal std::ostringstream buffer to CerrLog so that messages are accumulated locally and flushed atomically upon destruction. --- cpp/src/arrow/util/logging.cc | 11 ++++++++--- cpp/src/arrow/util/logging_test.cc | 23 +++++++++++++++++++++++ 2 files changed, 31 insertions(+), 3 deletions(-) diff --git a/cpp/src/arrow/util/logging.cc b/cpp/src/arrow/util/logging.cc index 993c5306ca4a..416c238b8c12 100644 --- a/cpp/src/arrow/util/logging.cc +++ b/cpp/src/arrow/util/logging.cc @@ -24,6 +24,8 @@ #endif #include #include +#include +#include #ifdef ARROW_USE_GLOG @@ -67,7 +69,9 @@ class CerrLog { virtual ~CerrLog() { if (has_logged_) { - std::cerr << std::endl; + static std::mutex cerr_mutex; + std::lock_guard lock(cerr_mutex); + std::cerr << buffer_.str() << std::endl; } if (severity_ == ArrowLogLevel::ARROW_FATAL) { PrintBackTrace(); @@ -77,14 +81,14 @@ class CerrLog { std::ostream& Stream() { has_logged_ = true; - return std::cerr; + return buffer_; } template CerrLog& operator<<(const T& t) { if (severity_ != ArrowLogLevel::ARROW_DEBUG) { has_logged_ = true; - std::cerr << t; + buffer_ << t; } return *this; } @@ -92,6 +96,7 @@ class CerrLog { protected: const ArrowLogLevel severity_; bool has_logged_; + std::ostringstream buffer_; void PrintBackTrace() { #ifdef ARROW_WITH_BACKTRACE diff --git a/cpp/src/arrow/util/logging_test.cc b/cpp/src/arrow/util/logging_test.cc index 280edd6111c3..efc8e9c60dda 100644 --- a/cpp/src/arrow/util/logging_test.cc +++ b/cpp/src/arrow/util/logging_test.cc @@ -18,6 +18,8 @@ #include #include #include +#include +#include #include @@ -95,6 +97,27 @@ TEST(ArrowCheck, PayloadEvaluatedOnFailure) { ASSERT_TRUE(tracer.was_printed); } +TEST(ArrowLog, MultiThreadedLogging) { + constexpr int kNumThreads = 10; + constexpr int kNumMessges = 10; + std::vector threads; + + threads.reserve(kNumThreads); + + for (int i = 0; i < kNumThreads; ++i) { + threads.emplace_back([i]() { + for (int j = 0; j < kNumMessges; ++j) { + ARROW_LOG(INFO) << "Thread" << i << " message " << j + << " - testing thread safety."; + } + }); + } + + for (auto& thread : threads) { + thread.join(); + } +} + } // namespace util TEST(DcheckMacros, DoNotEvaluateReleaseMode) { From fdb92d69ba2208188461abdcba46d4a552bbd54b Mon Sep 17 00:00:00 2001 From: Antoine Pitrou Date: Wed, 22 Apr 2026 12:07:18 +0200 Subject: [PATCH 2/3] 1) use std::stringstream::view; 2) add comment to test --- cpp/src/arrow/util/logging.cc | 2 +- cpp/src/arrow/util/logging_test.cc | 20 ++++++++------------ 2 files changed, 9 insertions(+), 13 deletions(-) diff --git a/cpp/src/arrow/util/logging.cc b/cpp/src/arrow/util/logging.cc index 416c238b8c12..793f25052fe4 100644 --- a/cpp/src/arrow/util/logging.cc +++ b/cpp/src/arrow/util/logging.cc @@ -71,7 +71,7 @@ class CerrLog { if (has_logged_) { static std::mutex cerr_mutex; std::lock_guard lock(cerr_mutex); - std::cerr << buffer_.str() << std::endl; + std::cerr << buffer_.view() << std::endl; } if (severity_ == ArrowLogLevel::ARROW_FATAL) { PrintBackTrace(); diff --git a/cpp/src/arrow/util/logging_test.cc b/cpp/src/arrow/util/logging_test.cc index efc8e9c60dda..2b846afdd6ab 100644 --- a/cpp/src/arrow/util/logging_test.cc +++ b/cpp/src/arrow/util/logging_test.cc @@ -42,17 +42,11 @@ int64_t current_time_ms() { // This file just print some information using the logging macro. void PrintLog() { - ARROW_LOG(DEBUG) << "This is the" - << " DEBUG" - << " message"; - ARROW_LOG(INFO) << "This is the" - << " INFO message"; - ARROW_LOG(WARNING) << "This is the" - << " WARNING message"; - ARROW_LOG(ERROR) << "This is the" - << " ERROR message"; - ARROW_CHECK(true) << "This is a ARROW_CHECK" - << " message but it won't show up"; + ARROW_LOG(DEBUG) << "This is the" << " DEBUG" << " message"; + ARROW_LOG(INFO) << "This is the" << " INFO message"; + ARROW_LOG(WARNING) << "This is the" << " WARNING message"; + ARROW_LOG(ERROR) << "This is the" << " ERROR message"; + ARROW_CHECK(true) << "This is a ARROW_CHECK" << " message but it won't show up"; // The following 2 lines should not run since it will cause program failure. // ARROW_LOG(FATAL) << "This is the FATAL message"; // ARROW_CHECK(false) << "This is a ARROW_CHECK message but it won't show up"; @@ -98,6 +92,8 @@ TEST(ArrowCheck, PayloadEvaluatedOnFailure) { } TEST(ArrowLog, MultiThreadedLogging) { + // This is mostly a visual test that logging from multiple threads produces + // a clean output without interleaving messages (GH-49433). constexpr int kNumThreads = 10; constexpr int kNumMessges = 10; std::vector threads; @@ -107,7 +103,7 @@ TEST(ArrowLog, MultiThreadedLogging) { for (int i = 0; i < kNumThreads; ++i) { threads.emplace_back([i]() { for (int j = 0; j < kNumMessges; ++j) { - ARROW_LOG(INFO) << "Thread" << i << " message " << j + ARROW_LOG(INFO) << "Thread " << i << " message " << j << " - testing thread safety."; } }); From 776c12c10e4598df817ab633a5885f6a98accea3 Mon Sep 17 00:00:00 2001 From: Antoine Pitrou Date: Wed, 22 Apr 2026 12:22:36 +0200 Subject: [PATCH 3/3] Use move-constructed std::ostringstream::str() --- cpp/src/arrow/util/logging.cc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/cpp/src/arrow/util/logging.cc b/cpp/src/arrow/util/logging.cc index 793f25052fe4..9a61d261ed34 100644 --- a/cpp/src/arrow/util/logging.cc +++ b/cpp/src/arrow/util/logging.cc @@ -71,7 +71,7 @@ class CerrLog { if (has_logged_) { static std::mutex cerr_mutex; std::lock_guard lock(cerr_mutex); - std::cerr << buffer_.view() << std::endl; + std::cerr << std::move(buffer_).str() << std::endl; } if (severity_ == ArrowLogLevel::ARROW_FATAL) { PrintBackTrace();