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

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);
         }
     }
 

src/libstore/build/derivation-goal.cc

@@ -1166,7 +1166,7 @@ HookReply DerivationGoal::tryBuildHook()
             }
             else {
                 s += "\n";
-                writeToStderr(s);
+                writeLogsToStderr(s);
             }
         }
 

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) {

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);
 
 }