Bug 49

Test log callback writes to std::cout from several threads unlocked

Status

Fixed

Symptom

Data race; worst effect seen: sanitizer report only

Where seen

Libmultiprocess tests (mptest)

Trigger

Writing log output

First reported

2025-10-02 (first report)

Fixed

2025-10-07

Fix

mp#222

Shipped to Bitcoin Core

bitcoin#33518, bitcoin#33519

Summary

The mptest log callback wrote to std::cout from several threads at once without a lock, which ThreadSanitizer reported as a data race inside libc++'s stream formatting once libc++ itself was built with TSan. The defect was in test code and did not affect users. Fixed in mp#222 ("test, ci: Fix threadsanitizer errors in mptest") by logging through KJ_LOG instead.

What happened

ryanofsky switched the libmultiprocess sanitize CI job to a TSan-instrumented libc++ in mp#222 (2025-10-02), to catch a different test race that had been reported in Bitcoin Core CI. mptest immediately reported a TSan data race on std::__1::ios_base::width between a worker thread and the main thread, both inside operator<< called from the test's EventLoop log callback at test/mp/test/test.cpp:71. The mp#222 description notes that these errors "are suppressed in bitcoin CI". No issue or CI failure was filed for it.

Root cause

TestSetup, the fixture that runs a client and server for most mptest tests, created its EventLoop in test/mp/test/test.cpp with this log callback:

std::cout << "LOG" << (int)log_data.level << ": " << log_data.message << "\n";

libmultiprocess calls the log callback on whichever thread produces the message (the event loop thread, server worker threads, the main test thread), and the callback took no lock. libc++'s formatted output reads and resets the stream's width field without synchronization, which TSan flags once libc++ is instrumented. The C++ standard says concurrent use of the synchronized standard stream objects does not cause a data race, so this is arguably a libc++ shortcoming as much as a test bug. Bitcoin Core has suppressed race:std::__1::ios_base::* in its TSan suppressions since 2021 (bitcoin#23366), which is why its CI never showed this.

The callback used printf, which locks stdout, from the initial commit until c8351c5f0b70 ("refactor: Remove locale-dependent function calls", mp#156) replaced it with std::cout. From then on it was a race, but libmultiprocess's CI did not instrument the standard library and Bitcoin Core's CI suppressed the report.

The code

The test fixture TestSetup in test/mp/test/test.cpp, quoted from ca3c05d56709^, gives each test's EventLoop a log callback that writes to std::cout without a lock:

EventLoop loop("mptest", [](mp::LogMessage log_data) {
    std::cout << "LOG" << (int)log_data.level << ": " << log_data.message << "\n";
    if (log_data.level == mp::Log::Raise) throw std::runtime_error(log_data.message);
});

libmultiprocess calls the callback on whichever thread logs: the event-loop thread, server worker threads, or the main test thread when it makes a client call. When two threads log at once, both run libc++'s operator<< on std::cout, which reads and then resets the stream's width field without synchronization. With an instrumented libc++, TSan reports a read in ios_base::width() on one thread racing a write in ios_base::width(long) from the callback on the main thread.

The fix (ca3c05d56709) logs through KJ instead. The KJ_STRINGIFY(Log) function it adds to include/mp/proxy-io.h and src/mp/proxy.cpp, which lets KJ_LOG print the level, is omitted:

@@ -67,9 +66,10 @@ public:
     TestSetup(bool client_owns_connection = true)
         : thread{[&] {
-              EventLoop loop("mptest", [](mp::LogMessage log_data) {
-                  std::cout << "LOG" << (int)log_data.level << ": " << log_data.message << "\n";
-                  if (log_data.level == mp::Log::Raise) throw std::runtime_error(log_data.message);
+              EventLoop loop("mptest", [](mp::LogMessage log) {
+                  // Info logs are not printed by default, but will be shown with `mptest --verbose`
+                  KJ_LOG(INFO, log.level, log.message);
+                  if (log.level == mp::Log::Raise) throw std::runtime_error(log.message);
               });

KJ's logger builds each message as a local string and passes it to write() on stderr, so threads that log at the same time no longer share any std::ostream formatting state.

Fix

The fix commit ca3c05d56709 replaces the std::cout line with KJ_LOG(INFO, log.level, log.message), which is thread-safe and only printed with mptest --verbose. To make that compile it adds a KJ_STRINGIFY(Log) function in include/mp/proxy-io.h and src/mp/proxy.cpp (+20/-4 in total). @theuni had already noted that the std::cout line was a placeholder he had meant to revisit. He had ported that line to the new LogMessage callback signature in mp#220 ("Add log levels and advertise them to users via logging callback").

Timeline

• 2025-02-07: introduced by c8351c5f0b70, merged in mp#156.
• 2025-10-02: found by ryanofsky when libc++ was first built with TSan in libmultiprocess CI.
• 2025-10-07: fix merged in mp#222.
• 2025-10-10: shipped to Bitcoin Core master in the subtree update bitcoin#33518; 2025-10-16: to the 30.x branch in the subtree update bitcoin#33519.

Classification

The survey's classification of this bug. The explorer charts these fields across all bugs; the method page explains them.