What the developer wrote
Authored by j-berman
Fix logging deadlock
What changed, and why it matters
This patch fixes a deadlock bug in Monero's logging system. A deadlock is a situation where two or more parts of the program get stuck waiting on each other forever, which can freeze the software. The fix changes how log messages are built so that user-provided code (which might itself use locks) is evaluated before the logger takes its own internal lock, preventing the logger's lock and user locks from being held at the same time in a way that could cause a freeze. The commit includes a new test that reproduces the deadlock scenario.
Apply the patch and run the new logging.deadlock unit test to confirm the deadlock is resolved. Review any custom logging macros or direct el::base::Writer usage in downstream code to ensure arguments are pre-formatted and no direct operator<< of arbitrary types is relied upon.
Security signals we found
Deadlock in logging subsystem
Arbitrary code execution during log message construction under internal lock
Cross-thread lock-order inversion between application mutex and logger mutex
Patch includes regression test reproducing the deadlock
Evidence from the diff
The commit resolves a logging deadlock by pre-formatting log message arguments into a std::string before invoking the easylogging++ Writer. Previously, the Writer’s operator<< templates could execute arbitrary user code (e.g., lambdas returning strings while holding locks) while the logging subsystem’s internal lock was held. The patch introduces a LOG_TO_STRING macro in misc_log_ex.h that serializes the log expression into a string first, then passes only the resulting string to el::base::Writer. The easylogging++ Writer is also narrowed to only accept const std::string&, removing templated operator<< overloads that previously accepted arbitrary types and stream manipulators. A new unit test (logging.deadlock) reproduces the cross-thread lock ordering issue: one thread logs while a lambda holds an inner mutex, and another thread acquires the same inner mutex during logging, which previously could deadlock.
Changed components
contrib/epee/include/misc_log_ex.hexternal/easylogging++/easylogging++.ccexternal/easylogging++/easylogging++.hsrc/cryptonote_protocol/cryptonote_protocol_handler.inltests/unit_tests/logging.cppInspect captured patch +76 / −29
diff --git a/contrib/epee/include/misc_log_ex.h b/contrib/epee/include/misc_log_ex.h
index 269425e..4b0a09a 100644
--- a/contrib/epee/include/misc_log_ex.h
+++ b/contrib/epee/include/misc_log_ex.h
@@ -30,6 +30,7 @@
#ifdef __cplusplus
+#include <sstream>
#include <string>
#include "easylogging++.h"
@@ -40,9 +41,15 @@
#define MAX_LOG_FILE_SIZE 104850000 // 100 MB - 7600 bytes
#define MAX_LOG_FILES 10
+#define LOG_TO_STRING(x) \
+ std::stringstream ss; \
+ ss << x; \
+ const std::string str = ss.str();
+
#define MCLOG_TYPE(level, cat, color, type, x) do { \
if (el::Loggers::allowed(level, cat)) { \
- el::base::Writer(level, color, __FILE__, __LINE__, ELPP_FUNC, type).construct(cat) << x; \
+ LOG_TO_STRING(x); \
+ el::base::Writer(level, color, __FILE__, __LINE__, ELPP_FUNC, type).construct(cat) << str; \
} \
} while (0)
@@ -91,7 +98,8 @@
do { \
if (el::Loggers::allowed(level, cat)) { \
init; \
- el::base::Writer(level, color, __FILE__, __LINE__, ELPP_FUNC, type).construct(cat) << x; \
+ LOG_TO_STRING(x); \
+ el::base::Writer(level, color, __FILE__, __LINE__, ELPP_FUNC, type).construct(cat) << str; \
} \
} while(0)
#define MIDEBUG(init, x) IFLOG(el::Level::Debug, MONERO_DEFAULT_LOG_CATEGORY, el::Color::Default, el::base::DispatchAction::NormalLog, init, x)
diff --git a/external/easylogging++/easylogging++.cc b/external/easylogging++/easylogging++.cc
index 4a645f4..d60b8e2 100644
--- a/external/easylogging++/easylogging++.cc
+++ b/external/easylogging++/easylogging++.cc
@@ -3065,8 +3065,9 @@ void Writer::triggerDispatch(void) {
}
if (m_proceed && m_level == Level::Fatal
&& !ELPP->hasFlag(LoggingFlag::DisableApplicationAbortOnFatalLog)) {
+ const std::string str = "Aborting application. Reason: Fatal log at [" + std::string(m_file) + ":" + std::to_string(m_line) + "]";
base::Writer(Level::Warning, Color::Default, m_file, m_line, m_func).construct(1, base::consts::kDefaultLoggerId)
- << "Aborting application. Reason: Fatal log at [" << m_file << ":" << m_line << "]";
+ << str;
std::stringstream reasonStream;
reasonStream << "Fatal log at [" << m_file << ":" << m_line << "]"
<< " If you wish to disable 'abort on fatal log' please use "
diff --git a/external/easylogging++/easylogging++.h b/external/easylogging++/easylogging++.h
index f2f6ff1..dfc71a9 100644
--- a/external/easylogging++/easylogging++.h
+++ b/external/easylogging++/easylogging++.h
@@ -3275,9 +3275,7 @@ class Writer : base::NoCopy {
processDispatch();
}
- template <typename T>
- inline typename std::enable_if<std::is_integral<T>::value, Writer&>::type
- operator<<(T log) {
+ Writer& operator<<(const std::string &log) {
#if ELPP_LOGGING_ENABLED
if (m_proceed) {
m_messageBuilder << log;
@@ -3286,26 +3284,6 @@ class Writer : base::NoCopy {
return *this;
}
- template <typename T>
- inline typename std::enable_if<!std::is_integral<T>::value, Writer&>::type
- operator<<(const T& log) {
-#if ELPP_LOGGING_ENABLED
- if (m_proceed) {
- m_messageBuilder << log;
- }
-#endif // ELPP_LOGGING_ENABLED
- return *this;
- }
-
- inline Writer& operator<<(std::ostream& (*log)(std::ostream&)) {
-#if ELPP_LOGGING_ENABLED
- if (m_proceed) {
- m_messageBuilder << log;
- }
-#endif // ELPP_LOGGING_ENABLED
- return *this;
- }
-
inline operator bool() {
return true;
}
@@ -3622,8 +3600,9 @@ class DefaultPerformanceTrackingCallback : public PerformanceTrackingCallback {
ss << ELPP_LITERAL("]");
}
}
+ const std::string str = ss.str();
el::base::Writer(m_data->performanceTracker()->level(), m_data->file(), m_data->line(), m_data->func()).construct(1,
- m_data->loggerId().c_str()) << ss.str();
+ m_data->loggerId().c_str()) << str;
}
private:
const PerformanceTrackingData* m_data;
diff --git a/src/cryptonote_protocol/cryptonote_protocol_handler.inl b/src/cryptonote_protocol/cryptonote_protocol_handler.inl
index 30b9b07..8b88cb7 100644
--- a/src/cryptonote_protocol/cryptonote_protocol_handler.inl
+++ b/src/cryptonote_protocol/cryptonote_protocol_handler.inl
@@ -48,6 +48,7 @@
#include "net/network_throttle-detail.hpp"
#include "common/pruning.h"
#include "common/util.h"
+#include "misc_log_ex.h"
#undef MONERO_DEFAULT_LOG_CATEGORY
#define MONERO_DEFAULT_LOG_CATEGORY "net.cn"
@@ -59,8 +60,10 @@
const char *cat = "net.p2p.msg"; \
if (ELPP->vRegistry()->allowed(level, cat)) { \
init; \
- if (test) \
- el::base::Writer(level, el::Color::Default, __FILE__, __LINE__, ELPP_FUNC, el::base::DispatchAction::NormalLog).construct(cat) << x; \
+ if (test) { \
+ LOG_TO_STRING(x); \
+ el::base::Writer(level, el::Color::Default, __FILE__, __LINE__, ELPP_FUNC, el::base::DispatchAction::NormalLog).construct(cat) << str; \
+ } \
} \
} while(0)
diff --git a/tests/unit_tests/logging.cpp b/tests/unit_tests/logging.cpp
index 618ccb1..198293c 100644
--- a/tests/unit_tests/logging.cpp
+++ b/tests/unit_tests/logging.cpp
@@ -28,6 +28,10 @@
//
// Parts of this file are originally copyright (c) 2012-2013 The Cryptonote developers
+#include <condition_variable>
+#include <mutex>
+#include <thread>
+
#include <boost/filesystem.hpp>
#include "gtest/gtest.h"
#include "file_io_utils.h"
@@ -251,3 +255,55 @@ TEST(logging, empty_configuration)
EXPECT_NO_THROW(log1.configure(cfg));
EXPECT_EQ(log1.typedConfigurations()->filename(el::Level::Info), "");
}
+
+TEST(logging, deadlock)
+{
+ std::mutex inner_mutex;
+
+ // 1. Thread 1 starts logger
+ // 2. Thread 2 grabs inner mutex shared across threads
+ // 3. Thread 2 logs
+ // 4. Thread 1 grabs inner mutex shared across threads
+ // 5. Thread 1 finishes logging
+ std::condition_variable cv1, cv2;
+ std::mutex mutex1, mutex2;
+ std::unique_lock<std::mutex> lock_until_t1_starts_logger(mutex1);
+ std::unique_lock<std::mutex> lock_until_t2_finishes_logging(mutex2);
+ bool t1_started_logger = false;
+ bool t2_finished_logging = false;
+
+ const auto thread1_func = [&]
+ {
+ const auto thread1_inner_func = [&]() -> std::string
+ {
+ t1_started_logger = true;
+ lock_until_t1_starts_logger.unlock();
+ cv1.notify_one();
+ cv2.wait(lock_until_t2_finishes_logging, [&]{return t2_finished_logging;});
+
+ std::lock_guard<std::mutex> guard(inner_mutex);
+ return "world!";
+ };
+ MGINFO("Hello, " << thread1_inner_func() << " - Sincerely, thread 1");
+ };
+
+ const auto thread2_func = [&]
+ {
+ cv1.wait(lock_until_t1_starts_logger, [&]{return t1_started_logger;});
+
+ {
+ std::lock_guard<std::mutex> guard(inner_mutex);
+ MGINFO("Hello, world! - Sincerely, thread 2");
+ }
+
+ t2_finished_logging = true;
+ lock_until_t2_finishes_logging.unlock();
+ cv2.notify_one();
+ };
+
+ std::thread t1(thread1_func);
+ std::thread t2(thread2_func);
+
+ t1.join();
+ t2.join();
+}
Why this scored 64/100
Community notes
Notes can correct, qualify, or add evidence to the AI analysis. Every note shown here has been validated by a human moderator.
The AI analysis stands alone for now. Submit a note if you can add evidence or important context.