Merge 0853d8d2fd into merged_master (Bitcoin PR #16112)

src/init.cpp

@@ -901,12 +901,6 @@ void InitLogging()
 {
     LogInstance().m_print_to_file = !gArgs.IsArgNegated("-debuglogfile");
     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 = gArgs.GetBoolArg("-logtimestamps", DEFAULT_LOGTIMESTAMPS);
     LogInstance().m_log_time_micros = gArgs.GetBoolArg("-logtimemicros", DEFAULT_LOGTIMEMICROS);
@@ -1288,10 +1282,10 @@ bool AppInitMain(InitInterfaces& interfaces)
             // and because this needs to happen before any other debug.log printing
             LogInstance().ShrinkDebugFile();
         }
-        if (!LogInstance().OpenDebugLog()) {
+    }
+    if (!LogInstance().StartLogging()) {
             return InitError(strprintf("Could not open debug log file %s",
                 LogInstance().m_file_path.string()));
-        }
     }
 
     if (!LogInstance().m_log_timestamps)

src/logging.cpp

@@ -39,24 +39,38 @@ static int FileWriteStr(const std::string &str, FILE *fp)
     return fwrite(str.data(), 1, str.size(), fp);
 }
 
-bool BCLog::Logger::OpenDebugLog()
+bool BCLog::Logger::StartLogging()
 {
-    std::lock_guard<std::mutex> scoped_lock(m_file_mutex);
+    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;
+        }
+
+        setbuf(m_fileout, nullptr); // unbuffered
+
+        // Add newlines to the logfile to distinguish this execution from the
+        // last one.
+        FileWriteStr("\n\n\n\n\n", m_fileout);
     }
 
-    setbuf(m_fileout, nullptr); // unbuffered
     // 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;
 }
@@ -202,8 +216,9 @@ std::string BCLog::Logger::LogTimestampStr(const std::string& str)
     return strStamped;
 }
 
-void BCLog::Logger::LogPrintStr(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) {
@@ -214,32 +229,31 @@ 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);
+        assert(m_fileout != nullptr);
 
-        // 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) {
-                    setbuf(new_fileout, nullptr); // unbuffered
-                    fclose(m_fileout);
-                    m_fileout = new_fileout;
-                }
+        // 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) {
+                setbuf(new_fileout, nullptr); // unbuffered
+                fclose(m_fileout);
+                m_fileout = new_fileout;
             }
-            FileWriteStr(str_prefixed, m_fileout);
         }
+        FileWriteStr(str_prefixed, m_fileout);
     }
 }
 

src/logging.h

@@ -60,9 +60,10 @@ namespace BCLog {
     class Logger
     {
     private:
-        FILE* m_fileout = nullptr;
-        std::mutex m_file_mutex;
-        std::list<std::string> m_msgs_before_open;
+        mutable std::mutex m_cs;                   // Can not use Mutex from sync.h because in debug mode it would cause a deadlock when a potential deadlock was detected
+        FILE* m_fileout = nullptr;                 // GUARDED_BY(m_cs)
+        std::list<std::string> m_msgs_before_open; // GUARDED_BY(m_cs)
+        bool m_buffering{true};                    //!< Buffer messages before logging can be started. GUARDED_BY(m_cs)
 
         /**
          * m_started_new_line is a state variable that will suppress printing of
@@ -88,12 +89,18 @@ namespace BCLog {
         std::atomic<bool> m_reopen_file{false};
 
         /** Send a string to the log output */
-        void LogPrintStr(const std::string &str);
+        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

@@ -60,9 +60,16 @@ class ConfArgsTest(BitcoinTestFramework):
         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