improve error handling, add functional test

Author: LarryRuane

src/init/common.cpp

@@ -92,6 +92,7 @@ void SetLoggingOptions(const ArgsManager& args)
 #endif
     LogInstance().m_log_sourcelocations = args.GetBoolArg("-logsourcelocations", DEFAULT_LOGSOURCELOCATIONS);
     LogInstance().m_rotate_keep = args.GetArg("-debuglogrotatekeep", DEFAULT_DEBUGLOGROTATEKEEP);
+    LogInstance().m_rotate_requested = args.IsArgSet("-debuglogrotatekeep") && LogInstance().m_rotate_keep > 0;
     LogInstance().m_file_limit = args.GetArg("-debugloglimit", DEFAULT_DEBUGLOGMB);
 
     fLogIPs = args.GetBoolArg("-logips", DEFAULT_LOGIPS);
@@ -130,9 +131,11 @@ bool StartLogging(const ArgsManager& args)
             LogInstance().ShrinkDebugFile();
         }
     }
-    if (!LogInstance().StartLogging()) {
-            return InitError(strprintf(Untranslated("Could not open debug log file %s"),
-                LogInstance().m_file_path.string()));
+    {
+        const std::string err_msg = LogInstance().StartLogging();
+        if (!err_msg.empty()) {
+            return InitError(Untranslated(err_msg));
+        }
     }
 
     if (!LogInstance().m_log_timestamps)

src/logging.cpp

@@ -73,7 +73,7 @@ void BCLog::Logger::StartRotate()
     RemoveRotate();
 }
 
-bool BCLog::Logger::StartLogging()
+const std::string BCLog::Logger::StartLogging()
 {
     StdLockGuard scoped_lock(m_cs);
 
@@ -84,18 +84,42 @@ bool BCLog::Logger::StartLogging()
         assert(!m_file_path.empty());
         m_fileout = fsbridge::fopen(m_file_path, "a");
         if (!m_fileout) {
-            return false;
+            return strprintf("Could not open debug log file %s", m_file_path.string());
         }
+
         // Special files (e.g. device nodes) may not have a size.
         try {
             m_file_size = fs::file_size(m_file_path);
         } catch (const fs::filesystem_error&) {
             // We can't do log rotation if it's not a regular file.
+            if (m_rotate_requested) {
+                return strprintf(
+                    "The debug log file %s does not appear to be a regular file; "
+                    "this prevents log rotation. Please disable log rotation by "
+                    "specifying -debuglogrotatekeep=0 or specify a regular file "
+                    "as the debug log file using -debuglogfile.",
+                    m_file_path.string());
+            }
             m_rotate_keep = 0;
         }
         // It gets complicated to add a timestamp to an arbitrary file name,
         // so require "debug.log".
-        if (m_file_path.filename() != "debug.log") m_rotate_keep = 0;
+        if (m_file_path.filename() != "debug.log") {
+            if (m_rotate_requested) {
+                return strprintf(
+                    "The debug log file %s is not named \"debug.log\"; "
+                    "this prevents log rotation. Please disable log rotation by "
+                    "specifying -debuglogrotatekeep=0 or specify a debug log file "
+                    "path that ends in \"/debug.log\" using -debuglogfile.",
+                    m_file_path.string());
+            }
+            m_rotate_keep = 0;
+        }
+        if (m_file_limit == 0) {
+            return strprintf(
+                "The debug log file %s size limit in MB must be greater than zero.",
+                m_file_path.string());
+        }
         if (m_rotate_keep > 0) StartRotate();
 
         setbuf(m_fileout, nullptr); // unbuffered
@@ -120,7 +144,7 @@ bool BCLog::Logger::StartLogging()
     }
     if (m_print_to_console) fflush(stdout);
 
-    return true;
+    return {};
 }
 
 void BCLog::Logger::DisconnectTestLogger()

src/logging.h

@@ -109,6 +109,8 @@ namespace BCLog {
         int m_file_limit;
         /** The number of old (rotated) debug.log files to retain */
         int m_rotate_keep;
+        /** Whether log rotation was explicitly requested */
+        bool m_rotate_requested;
         std::atomic<bool> m_reopen_file{false};
 
         /** Send a string to the log output */
@@ -136,8 +138,8 @@ namespace BCLog {
             m_print_callbacks.erase(it);
         }
 
-        /** Start logging (and flush all buffered messages) */
-        bool StartLogging();
+        /** Start logging (and flush all buffered messages), returns error string (empty if none ) */
+        const std::string StartLogging();
         /** Initialize debug.log rotation (find existing rotated debug.log files) */
         void StartRotate() EXCLUSIVE_LOCKS_REQUIRED(m_cs);
         /** Remove (delete) excess debug.log rotation files */

test/functional/feature_logging.py

@@ -8,6 +8,7 @@
 
 from test_framework.test_framework import BitcoinTestFramework
 from test_framework.test_node import ErrorMatch
+from test_framework.util import assert_equal
 
 
 class LoggingTest(BitcoinTestFramework):
@@ -69,6 +70,40 @@ def run_test(self):
         # just sanity check no crash here
         self.restart_node(0, ["-debuglogfile=%s" % os.devnull])
 
+        # a nonstandard name can't be combined with log rotation
+        self.stop_node(0)
+        args = ["-debuglogfile=notdebug.log", "-debuglogrotatekeep=2"]
+        exp_stderr = r"Error: .* this prevents log rotation"
+        self.nodes[0].assert_start_raises_init_error(args, exp_stderr, match=ErrorMatch.PARTIAL_REGEX)
+        assert not os.path.isfile(os.path.join(invdir, "notdebug.log"))
+
+        # It's not necessary to test -debuglogrotate=0, because all functional tests run that way
+        # (and some of them break if the debug log file does get rotated. So just test rotation.
+        self.stop_node(0)
+        self.start_node(0, ["-debuglogrotatekeep=2", "-debugloglimit=1"])
+        self.log.info("Generating a bunch of log messages")
+        # Each getblockcount RPC logs 251 bytes, so 13k of them generates
+        # more than 3 MB of logging, which will test that one of the
+        # rotated log files gets deleted.
+        for _ in range(13000):
+            self.nodes[0].getblockcount()
+        n_debugfiles = 0
+        with os.scandir(os.path.join(self.nodes[0].datadir, 'regtest')) as it:
+            for entry in it:
+                if not entry.name.startswith('debug'):
+                    continue
+                if not entry.name.endswith('.log'):
+                    continue
+                # the name should be either debug.log or like debug-2021-07-09T01:49:59Z.log
+                assert len(entry.name) == 9 or len(entry.name) == 30
+                # rotated files should have sizes slightly more than 1 MB
+                if len(entry.name) == 30:
+                    assert entry.stat().st_size > 1000000
+                    assert entry.stat().st_size < int(1000000 * 1.01)
+                n_debugfiles += 1
+        # There should be debug.log and two rotated files
+        assert_equal(n_debugfiles, 3)
+
 
 if __name__ == '__main__':
     LoggingTest().main()