libutil: make basic loggers thread-safe

SimpleLogger is not fully thread-safe, and all loggers that wrap it are
also not safe accordingly. this does not affect much, but in rare cases
it can cause interleaving of messages on stderr when used with the json
or raw log formats. the fix applied here is a bit of a hack, but fixing
this properly requires rearchitecting the logger infrastructure. nested
loggers are not the most natural abstraction here, and it is biting us.

Change-Id: Ifbf34fe1e85c60e73b59faee50e7411c7b5e7c12

4 files changed, 22 insertions, 13 deletions

diff --git a/src/libmain/progress-bar.cc b/src/libmain/progress-bar.cc
index 48a52f442..f0270df04 100644
--- a/src/libmain/progress-bar.cc
+++ b/src/libmain/progress-bar.cc
@@ -91,7 +91,7 @@ void ProgressBar::resume()
             nextWakeup = draw(*state, {});
             state.wait_for(quitCV, std::chrono::milliseconds(50));
         }
-        writeToStderr("\r\e[K");
+        writeLogsToStderr("\r\e[K");
     });
 }
 
@@ -124,7 +124,7 @@ void ProgressBar::log(State & state, Verbosity lvl, std::string_view s)
     } else {
         auto s2 = s + ANSI_NORMAL "\n";
         if (!isTTY) s2 = filterANSIEscapes(s2, true);
-        writeToStderr(s2);
+        writeLogsToStderr(s2);
     }
 }
 
@@ -322,9 +322,9 @@ void ProgressBar::eraseProgressDisplay(State & state)
 {
     if (printMultiline && (state.lastLines >= 1)) {
         // FIXME: make sure this works on windows
-        writeToStderr(fmt("\e[G\e[%dF\e[J", state.lastLines));
+        writeLogsToStderr(fmt("\e[G\e[%dF\e[J", state.lastLines));
     } else {
-        writeToStderr("\r\e[K");
+        writeLogsToStderr("\r\e[K");
     }
 }
 
@@ -346,7 +346,7 @@ std::chrono::milliseconds ProgressBar::draw(State & state, const std::optional<s
     state.lastLines = 0;
 
     if (s != std::nullopt)
-        writeToStderr(filterANSIEscapes(s.value(), !isTTY) + ANSI_NORMAL "\n");
+        writeLogsToStderr(filterANSIEscapes(s.value(), !isTTY) + ANSI_NORMAL "\n");
 
     std::string line;
     std::string status = getStatus(state);
@@ -356,7 +356,7 @@ std::chrono::milliseconds ProgressBar::draw(State & state, const std::optional<s
         line += "]";
     }
     if (printMultiline && !line.empty()) {
-        writeToStderr(filterANSIEscapes(line, false, width) + ANSI_NORMAL "\n");
+        writeLogsToStderr(filterANSIEscapes(line, false, width) + ANSI_NORMAL "\n");
         state.lastLines++;
     }
 
@@ -398,7 +398,7 @@ std::chrono::milliseconds ProgressBar::draw(State & state, const std::optional<s
 
             if (printMultiline) {
                 if (state.lastLines < (height -1)) {
-                    writeToStderr(filterANSIEscapes(activity_line, false, width) + ANSI_NORMAL "\n");
+                    writeLogsToStderr(filterANSIEscapes(activity_line, false, width) + ANSI_NORMAL "\n");
                     state.lastLines++;
                 } else moreActivities++;
             }
@@ -406,7 +406,7 @@ std::chrono::milliseconds ProgressBar::draw(State & state, const std::optional<s
     }
 
     if (printMultiline && moreActivities)
-        writeToStderr(fmt("And %d more...", moreActivities));
+        writeLogsToStderr(fmt("And %d more...", moreActivities));
 
     if (!printMultiline) {
         if (!line.empty()) {
@@ -414,7 +414,7 @@ std::chrono::milliseconds ProgressBar::draw(State & state, const std::optional<s
         }
         line += activity_line;
         if (!line.empty()) {
-            writeToStderr(filterANSIEscapes(line, false, width) + ANSI_NORMAL);
+            writeLogsToStderr(filterANSIEscapes(line, false, width) + ANSI_NORMAL);
         }
     }
 
diff --git a/src/libstore/build/derivation-goal.cc b/src/libstore/build/derivation-goal.cc
index 6d86a44d0..7cf8a55c9 100644
--- a/src/libstore/build/derivation-goal.cc
+++ b/src/libstore/build/derivation-goal.cc
@@ -1166,7 +1166,7 @@ HookReply DerivationGoal::tryBuildHook()
             }
             else {
                 s += "\n";
-                writeToStderr(s);
+                writeLogsToStderr(s);
             }
         }
 
diff --git a/src/libutil/logging.cc b/src/libutil/logging.cc
index fecbc89ac..d674c9651 100644
--- a/src/libutil/logging.cc
+++ b/src/libutil/logging.cc
@@ -77,7 +77,7 @@ public:
             prefix = std::string("<") + c + ">";
         }
 
-        writeToStderr(prefix + filterANSIEscapes(s, !tty) + "\n");
+        writeLogsToStderr(prefix + filterANSIEscapes(s, !tty) + "\n");
     }
 
     void logEI(const ErrorInfo & ei) override
@@ -117,8 +117,17 @@ Verbosity verbosityFromIntClamped(int val)
     return static_cast<Verbosity>(clamped);
 }
 
-void writeToStderr(std::string_view s)
+void writeLogsToStderr(std::string_view s)
 {
+    static std::mutex lock;
+
+    // make sure only one thread uses this function at any given time.
+    // multiple concurrent threads can have deleterious effects on log
+    // output, especially when layering structured formats (like JSON)
+    // on top of a SimpleLogger which is itself not thread-safe. every
+    // Logger instance should be thread-safe in an ideal world, but we
+    // cannot really enforce that on a per-logger level at this point.
+    std::unique_lock _lock(lock);
     try {
         writeFull(STDERR_FILENO, s, false);
     } catch (SysError & e) {
diff --git a/src/libutil/logging.hh b/src/libutil/logging.hh
index 96f9f0782..b2d73d8ba 100644
--- a/src/libutil/logging.hh
+++ b/src/libutil/logging.hh
@@ -283,6 +283,6 @@ inline void warn(const std::string & fs, const Args & ... args)
     logger->warn(HintFmt(fs, args...).str());
 }
 
-void writeToStderr(std::string_view s);
+void writeLogsToStderr(std::string_view s);
 
 }