util: Log early messages

Summary:
```
Early log messages are dropped on the floor and they'd never make it to
the console or debug log. This can be tested by running the test
included in this pull request without re-compiling the bitcoind.

Fix that by buffering early messages and flushing them as soon as all
logging options have been initialized and logging has been started.
```

Backport of core [[bitcoin/bitcoin#16112 | PR16112]].

Test Plan:
  ninja check check-functional

Reviewers: #bitcoin_abc, deadalnix

Reviewed By: #bitcoin_abc, deadalnix

Subscribers: deadalnix

Differential Revision: https://reviews.bitcoinabc.org/D5553

src/init.cpp

@@ -1410,11 +1410,6 @@ void InitLogging() {
     LogInstance().m_file_path = AbsPathForConfigVal(
         gArgs.GetArg("-debuglogfile", DEFAULT_DEBUGLOGFILE));
 
-    // Add newlines to the logfile to distinguish this execution from the last
-    // one; called before console logging is set up, so this is only sent to
-    // debug.log.
-    LogPrintf("\n\n\n\n\n");
-
     LogInstance().m_print_to_console = gArgs.GetBoolArg(
         "-printtoconsole", !gArgs.GetBoolArg("-daemon", false));
     LogInstance().m_log_timestamps =
@@ -1894,11 +1889,11 @@ bool AppInitMain(Config &config, RPCServer &rpcServer,
             // debug.log printing.
             logger.ShrinkDebugFile();
         }
+    }
 
-        if (!logger.OpenDebugLog()) {
-            return InitError(strprintf("Could not open debug log file %s",
-                                       logger.m_file_path.string()));
-        }
+    if (!logger.StartLogging()) {
+        return InitError(strprintf("Could not open debug log file %s",
+                                   logger.m_file_path.string()));
     }
 
     if (!logger.m_log_timestamps) {

src/logging.cpp

@@ -38,24 +38,44 @@ static int FileWriteStr(const std::string &str, FILE *fp) {
     return fwrite(str.data(), 1, str.size(), fp);
 }
 
-bool BCLog::Logger::OpenDebugLog() {
-    std::lock_guard<std::mutex> scoped_lock(m_file_mutex);
+bool BCLog::Logger::StartLogging() {
+    std::lock_guard<std::mutex> scoped_lock(m_cs);
 
+    assert(m_buffering);
     assert(m_fileout == nullptr);
-    assert(!m_file_path.empty());
 
-    m_fileout = fsbridge::fopen(m_file_path, "a");
-    if (!m_fileout) {
-        return false;
+    if (m_print_to_file) {
+        assert(!m_file_path.empty());
+        m_fileout = fsbridge::fopen(m_file_path, "a");
+        if (!m_fileout) {
+            return false;
+        }
+
+        // Unbuffered.
+        setbuf(m_fileout, nullptr);
+
+        // Add newlines to the logfile to distinguish this execution from the
+        // last one.
+        FileWriteStr("\n\n\n\n\n", m_fileout);
     }
 
-    // Unbuffered.
-    setbuf(m_fileout, nullptr);
     // Dump buffered messages from before we opened the log.
+    m_buffering = false;
     while (!m_msgs_before_open.empty()) {
-        FileWriteStr(m_msgs_before_open.front(), m_fileout);
+        const std::string &s = m_msgs_before_open.front();
+
+        if (m_print_to_file) {
+            FileWriteStr(s, m_fileout);
+        }
+        if (m_print_to_console) {
+            fwrite(s.data(), 1, s.size(), stdout);
+        }
+
         m_msgs_before_open.pop_front();
     }
+    if (m_print_to_console) {
+        fflush(stdout);
+    }
 
     return true;
 }
@@ -173,6 +193,7 @@ std::string BCLog::Logger::LogTimestampStr(const std::string &str) {
 }
 
 void BCLog::Logger::LogPrintStr(const std::string &str) {
+    std::lock_guard<std::mutex> scoped_lock(m_cs);
     std::string str_prefixed = str;
 
     if (m_log_threadnames && m_started_new_line) {
@@ -183,31 +204,32 @@ void BCLog::Logger::LogPrintStr(const std::string &str) {
 
     m_started_new_line = !str.empty() && str[str.size() - 1] == '\n';
 
+    if (m_buffering) {
+        // buffer if we haven't started logging yet
+        m_msgs_before_open.push_back(str_prefixed);
+        return;
+    }
+
     if (m_print_to_console) {
         // Print to console.
         fwrite(str_prefixed.data(), 1, str_prefixed.size(), stdout);
         fflush(stdout);
     }
     if (m_print_to_file) {
-        std::lock_guard<std::mutex> scoped_lock(m_file_mutex);
-
-        // Buffer if we haven't opened the log yet.
-        if (m_fileout == nullptr) {
-            m_msgs_before_open.push_back(str_prefixed);
-        } else {
-            // Reopen the log file, if requested.
-            if (m_reopen_file) {
-                m_reopen_file = false;
-                FILE *new_fileout = fsbridge::fopen(m_file_path, "a");
-                if (new_fileout) {
-                    // unbuffered.
-                    setbuf(m_fileout, nullptr);
-                    fclose(m_fileout);
-                    m_fileout = new_fileout;
-                }
+        assert(m_fileout != nullptr);
+
+        // Reopen the log file, if requested.
+        if (m_reopen_file) {
+            m_reopen_file = false;
+            FILE *new_fileout = fsbridge::fopen(m_file_path, "a");
+            if (new_fileout) {
+                // unbuffered.
+                setbuf(m_fileout, nullptr);
+                fclose(m_fileout);
+                m_fileout = new_fileout;
             }
-            FileWriteStr(str_prefixed, m_fileout);
         }
+        FileWriteStr(str_prefixed, m_fileout);
     }
 }
 

src/logging.h

@@ -59,9 +59,15 @@ enum LogFlags : uint32_t {
 
 class Logger {
 private:
+    // Can not use Mutex from sync.h because in debug mode it would cause a
+    // deadlock when a potential deadlock was detected
+    mutable std::mutex m_cs;
+    // GUARDED_BY(m_cs)
     FILE *m_fileout = nullptr;
-    std::mutex m_file_mutex;
+    // GUARDED_BY(m_cs)
     std::list<std::string> m_msgs_before_open;
+    //! Buffer messages before logging can be started. GUARDED_BY(m_cs)
+    bool m_buffering{true};
 
     /**
      * m_started_new_line is a state variable that will suppress printing of the
@@ -93,9 +99,14 @@ class Logger {
     void LogPrintStr(const std::string &str);
 
     /** Returns whether logs will be written to any output */
-    bool Enabled() const { return m_print_to_console || m_print_to_file; }
+    bool Enabled() const {
+        std::lock_guard<std::mutex> scoped_lock(m_cs);
+        return m_buffering || m_print_to_console || m_print_to_file;
+    }
+
+    /** Start logging (and flush all buffered messages) */
+    bool StartLogging();
 
-    bool OpenDebugLog();
     void ShrinkDebugFile();
 
     uint32_t GetCategoryMask() const { return m_categories.load(); }

test/functional/feature_config_args.py

@@ -42,9 +42,16 @@ def test_config_file_parser(self):
         with open(inc_conf_file_path, 'w', encoding='utf-8') as conf:
             conf.write('')  # clear
 
+    def test_log_buffer(self):
+        with self.nodes[0].assert_debug_log(expected_msgs=['Warning: parsed potentially confusing double-negative -connect=0']):
+            self.start_node(0, extra_args=['-noconnect=0'])
+        self.stop_node(0)
+
     def run_test(self):
         self.stop_node(0)
 
+        self.test_log_buffer()
+
         self.test_config_file_parser()
 
         # Remove the -datadir argument so it doesn't override the config file