Log early messages with -printtoconsole

This ensures log messages prior to StartLogging() are replayed to
the console as well as to the debug log file.

Author: ajtowns

src/init.cpp

@@ -855,12 +855,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);

src/logging.cpp

@@ -42,22 +42,35 @@ static int FileWriteStr(const std::string &str, FILE *fp)
 bool BCLog::Logger::StartLogging()
 {
     std::lock_guard<std::mutex> scoped_lock(m_file_mutex);
-    if (!m_print_to_file) return true;
 
+    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;
 }
@@ -205,6 +218,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_file_mutex);
     std::string str_prefixed = str;
 
     if (m_log_threadnames && m_started_new_line) {
@@ -215,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);
-
-        // 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;
-                }
+        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) {
+                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

@@ -63,6 +63,7 @@ namespace BCLog {
         FILE* m_fileout = nullptr;
         std::mutex m_file_mutex;
         std::list<std::string> m_msgs_before_open;
+        bool m_buffering = true; //!< Buffer messages before logging can be started
 
         /**
          * m_started_new_line is a state variable that will suppress printing of
@@ -91,9 +92,11 @@ namespace BCLog {
         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 { return m_buffering || m_print_to_console || m_print_to_file; }
 
+        /** Start logging (and flush all buffered messages) */
         bool StartLogging();
+
         void ShrinkDebugFile();
 
         uint32_t GetCategoryMask() const { return m_categories.load(); }

test/functional/feature_config_args.py

@@ -61,9 +61,16 @@ def test_config_file_parser(self):
         with open(inc_conf_file2_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