Merge bitcoin/bitcoin#28318: logging: Simplify API for level based logging

e60fc7d5d34f23cccbff6e4f5f3d716fa8dad50c logging: Replace uses of LogPrintfCategory (Anthony Towns)
f7ce5ac08c669ac763e275bb7c82dcfb2b1b6c33 logging: add LogError, LogWarning, LogInfo, LogDebug, LogTrace (Anthony Towns)
fbd7642c8e5b70327e019382320f5ef0a651ecc5 logging: add -loglevelalways=1 option (Anthony Towns)
782bb6a05663ad7a53908e910d0f42b49b881e09 logging: treat BCLog::ALL like BCLog::NONE (Anthony Towns)
667ce3e3297645527b07314e1d5a82275fb25845 logging: Drop BCLog::Level::None (Anthony Towns)
ab34dc6012351e7b8aab871dd9d2b38ade1cd9bc logging: Log Info messages unconditionally (Anthony Towns)
dfe98b6874da04e45f68d17575c1e8a5431ca9bc logging: make [cat:debug] and [info] implicit (Anthony Towns)
c5c76dc615677d226c9f6b3f2b66d833315d40da logging: refactor: pull prefix code out (Anthony Towns)

Pull request description:

  Replace `LogPrint*` functions with severity based logging functions:

   * `LogInfo(...)`, `LogWarning(...)`, `LogError(...)` for unconditional (uncategorised) logging (replaces `LogPrintf`)
   * `LogDebug(CATEGORY, ...)` and `LogTrace(CATEGORY, ...)` for conditional logging (replaces `LogPrint`)
   * `LogPrintLevel(CATEGORY, LEVEL, ...)` for when the level isn't known in advance, or a category needs to be added for an info/warning/error log message (mostly unchanged, but rarely needed)

  Logs look roughly as they do now with `LogInfo` not having an `[info]` prefix, and `LogDebug` having a `[cat]` prefix, rather than a `[cat:debug]` prefix. This removes `BCLog::Level::None` entirely -- for `LogFlags::NONE` just use `Level::Info`, for any actual category, use `Level::Debug`.

  Adds docs to developer-notes about when to use which level.

  Adds `-loglevelalways=1` option so that you get `[net:debug]`, `[all:info]`, `[all:warning]` etc, which might be helpful for automated parsing, or just if you like everything to be consistent. Defaults to off to reduce noise in the default config, and to avoid unnecessary changes on upgrades.

  Changes the behaviour of `LogPrintLevel(CATEGORY, BCLog::Level::Info, ...)` to be logged unconditionally, rather than only being an additional optional logging level in addition to trace and debug. Does not change the behaviour of `LogPrintLevel(NONE, Debug, ...)` and `LogPrintLevel(NONE, Trace, ...)` being no-ops.

ACKs for top commit:
  maflcko:
    re-ACK e60fc7d5d34f23cccbff6e4f5f3d716fa8dad50c 🌚
  achow101:
    ACK e60fc7d5d34f23cccbff6e4f5f3d716fa8dad50c
  stickies-v:
    ACK e60fc7d5d34f23cccbff6e4f5f3d716fa8dad50c
  jamesob:
    ACK e60fc7d5d34f23cccbff6e4f5f3d716fa8dad50c ([`jamesob/ackr/28318.1.ajtowns.logging_simplify_api_for`](https://github.com/jamesob/bitcoin/tree/ackr/28318.1.ajtowns.logging_simplify_api_for))

Tree-SHA512: e7a4588779b148242495b7b6f64198a00c314cd57100affab11c43e9d39c9bbf85118ee2002792087fdcffdea08c84576e20844b3079f27083e26ddd7ca15d7f

8 files changed, 90 insertions, 52 deletions

diff --git a/src/httpserver.cpp b/src/httpserver.cpp
index e26ea6a596..71134d442f 100644
--- a/src/httpserver.cpp
+++ b/src/httpserver.cpp
@@ -463,7 +463,7 @@ bool InitHTTPServer(const util::SignalInterrupt& interrupt)
 
     LogPrint(BCLog::HTTP, "Initialized HTTP server\n");
     int workQueueDepth = std::max((long)gArgs.GetIntArg("-rpcworkqueue", DEFAULT_HTTP_WORKQUEUE), 1L);
-    LogPrintfCategory(BCLog::HTTP, "creating work queue of depth %d\n", workQueueDepth);
+    LogDebug(BCLog::HTTP, "creating work queue of depth %d\n", workQueueDepth);
 
     g_work_queue = std::make_unique<WorkQueue<HTTPClosure>>(workQueueDepth);
     // transfer ownership to eventBase/HTTP via .release()
@@ -485,9 +485,8 @@ static std::vector<std::thread> g_thread_http_workers;
 
 void StartHTTPServer()
 {
-    LogPrint(BCLog::HTTP, "Starting HTTP server\n");
     int rpcThreads = std::max((long)gArgs.GetIntArg("-rpcthreads", DEFAULT_HTTP_THREADS), 1L);
-    LogPrintfCategory(BCLog::HTTP, "starting %d worker threads\n", rpcThreads);
+    LogInfo("Starting HTTP server with %d worker threads\n", rpcThreads);
     g_thread_http = std::thread(ThreadHTTP, eventBase);
 
     for (int i = 0; i < rpcThreads; i++) {
diff --git a/src/init.cpp b/src/init.cpp
index 39ee9fe60d..b825c8ce21 100644
--- a/src/init.cpp
+++ b/src/init.cpp
@@ -1545,7 +1545,7 @@ bool AppInitMain(NodeContext& node, interfaces::BlockAndHeaderTipInfo* tip_info)
         if (status == node::ChainstateLoadStatus::SUCCESS) {
             uiInterface.InitMessage(_("Verifying blocks…").translated);
             if (chainman.m_blockman.m_have_pruned && options.check_blocks > MIN_BLOCKS_TO_KEEP) {
-                LogPrintfCategory(BCLog::PRUNE, "pruned datadir may not have more than %d blocks; only checking available blocks\n",
+                LogWarning("pruned datadir may not have more than %d blocks; only checking available blocks\n",
                                   MIN_BLOCKS_TO_KEEP);
             }
             std::tie(status, error) = catch_exceptions([&]{ return VerifyLoadedChainstate(chainman, options);});
diff --git a/src/init/common.cpp b/src/init/common.cpp
index f3f7c696c5..6560258ef5 100644
--- a/src/init/common.cpp
+++ b/src/init/common.cpp
@@ -40,6 +40,7 @@ void AddLoggingArgs(ArgsManager& argsman)
 #endif
     argsman.AddArg("-logsourcelocations", strprintf("Prepend debug output with name of the originating source location (source file, line number and function name) (default: %u)", DEFAULT_LOGSOURCELOCATIONS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
     argsman.AddArg("-logtimemicros", strprintf("Add microsecond precision to debug timestamps (default: %u)", DEFAULT_LOGTIMEMICROS), ArgsManager::ALLOW_ANY | ArgsManager::DEBUG_ONLY, OptionsCategory::DEBUG_TEST);
+    argsman.AddArg("-loglevelalways", strprintf("Always prepend a category and level (default: %u)", DEFAULT_LOGLEVELALWAYS), ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
     argsman.AddArg("-printtoconsole", "Send trace/debug info to console (default: 1 when no -daemon. To disable logging to file, set -nodebuglogfile)", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
     argsman.AddArg("-shrinkdebugfile", "Shrink debug.log file on client startup (default: 1 when no -debug)", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
 }
@@ -55,6 +56,7 @@ void SetLoggingOptions(const ArgsManager& args)
     LogInstance().m_log_threadnames = args.GetBoolArg("-logthreadnames", DEFAULT_LOGTHREADNAMES);
 #endif
     LogInstance().m_log_sourcelocations = args.GetBoolArg("-logsourcelocations", DEFAULT_LOGSOURCELOCATIONS);
+    LogInstance().m_always_print_category_level = args.GetBoolArg("-loglevelalways", DEFAULT_LOGLEVELALWAYS);
 
     fLogIPs = args.GetBoolArg("-logips", DEFAULT_LOGIPS);
 }
diff --git a/src/logging.cpp b/src/logging.cpp
index 08bfa1f7a4..42f100ded6 100644
--- a/src/logging.cpp
+++ b/src/logging.cpp
@@ -126,9 +126,9 @@ bool BCLog::Logger::WillLogCategory(BCLog::LogFlags category) const
 
 bool BCLog::Logger::WillLogCategoryLevel(BCLog::LogFlags category, BCLog::Level level) const
 {
-    // Log messages at Warning and Error level unconditionally, so that
+    // Log messages at Info, Warning and Error level unconditionally, so that
     // important troubleshooting information doesn't get lost.
-    if (level >= BCLog::Level::Warning) return true;
+    if (level >= BCLog::Level::Info) return true;
 
     if (!WillLogCategory(category)) return false;
 
@@ -202,7 +202,7 @@ bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str)
     return false;
 }
 
-std::string BCLog::Logger::LogLevelToStr(BCLog::Level level) const
+std::string BCLog::Logger::LogLevelToStr(BCLog::Level level)
 {
     switch (level) {
     case BCLog::Level::Trace:
@@ -215,8 +215,6 @@ std::string BCLog::Logger::LogLevelToStr(BCLog::Level level) const
         return "warning";
     case BCLog::Level::Error:
         return "error";
-    case BCLog::Level::None:
-        return "";
     }
     assert(false);
 }
@@ -307,8 +305,6 @@ static std::optional<BCLog::Level> GetLogLevel(const std::string& level_str)
         return BCLog::Level::Warning;
     } else if (level_str == "error") {
         return BCLog::Level::Error;
-    } else if (level_str == "none") {
-        return BCLog::Level::None;
     } else {
         return std::nullopt;
     }
@@ -341,7 +337,7 @@ static constexpr std::array<BCLog::Level, 3> LogLevelsList()
 std::string BCLog::Logger::LogLevelsString() const
 {
     const auto& levels = LogLevelsList();
-    return Join(std::vector<BCLog::Level>{levels.begin(), levels.end()}, ", ", [this](BCLog::Level level) { return LogLevelToStr(level); });
+    return Join(std::vector<BCLog::Level>{levels.begin(), levels.end()}, ", ", [](BCLog::Level level) { return LogLevelToStr(level); });
 }
 
 std::string BCLog::Logger::LogTimestampStr(const std::string& str)
@@ -392,29 +388,39 @@ namespace BCLog {
     }
 } // namespace BCLog
 
-void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, int source_line, BCLog::LogFlags category, BCLog::Level level)
+std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level level) const
 {
-    StdLockGuard scoped_lock(m_cs);
-    std::string str_prefixed = LogEscapeMessage(str);
+    if (category == LogFlags::NONE) category = LogFlags::ALL;
 
-    if ((category != LogFlags::NONE || level != Level::None) && m_started_new_line) {
-        std::string s{"["};
+    const bool has_category{m_always_print_category_level || category != LogFlags::ALL};
 
-        if (category != LogFlags::NONE) {
-            s += LogCategoryToStr(category);
-        }
+    // If there is no category, Info is implied
+    if (!has_category && level == Level::Info) return {};
 
-        if (category != LogFlags::NONE && level != Level::None) {
-            // Only add separator if both flag and level are not NONE
-            s += ":";
-        }
+    std::string s{"["};
+    if (has_category) {
+        s += LogCategoryToStr(category);
+    }
 
-        if (level != Level::None) {
-            s += LogLevelToStr(level);
-        }
+    if (m_always_print_category_level || !has_category || level != Level::Debug) {
+        // If there is a category, Debug is implied, so don't add the level
+
+        // Only add separator if we have a category
+        if (has_category) s += ":";
+        s += Logger::LogLevelToStr(level);
+    }
+
+    s += "] ";
+    return s;
+}
 
-        s += "] ";
-        str_prefixed.insert(0, s);
+void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, int source_line, BCLog::LogFlags category, BCLog::Level level)
+{
+    StdLockGuard scoped_lock(m_cs);
+    std::string str_prefixed = LogEscapeMessage(str);
+
+    if (m_started_new_line) {
+        str_prefixed.insert(0, GetLogPrefix(category, level));
     }
 
     if (m_log_sourcelocations && m_started_new_line) {
diff --git a/src/logging.h b/src/logging.h
index f7380d8928..525e0aec6d 100644
--- a/src/logging.h
+++ b/src/logging.h
@@ -25,6 +25,7 @@ static const bool DEFAULT_LOGIPS        = false;
 static const bool DEFAULT_LOGTIMESTAMPS = true;
 static const bool DEFAULT_LOGTHREADNAMES = false;
 static const bool DEFAULT_LOGSOURCELOCATIONS = false;
+static constexpr bool DEFAULT_LOGLEVELALWAYS = false;
 extern const char * const DEFAULT_DEBUGLOGFILE;
 
 extern bool fLogIPs;
@@ -77,7 +78,6 @@ namespace BCLog {
         Info,      // Default
         Warning,
         Error,
-        None, // Internal use only
     };
     constexpr auto DEFAULT_LOG_LEVEL{Level::Debug};
 
@@ -120,10 +120,13 @@ namespace BCLog {
         bool m_log_time_micros = DEFAULT_LOGTIMEMICROS;
         bool m_log_threadnames = DEFAULT_LOGTHREADNAMES;
         bool m_log_sourcelocations = DEFAULT_LOGSOURCELOCATIONS;
+        bool m_always_print_category_level = DEFAULT_LOGLEVELALWAYS;
 
         fs::path m_file_path;
         std::atomic<bool> m_reopen_file{false};
 
+        std::string GetLogPrefix(LogFlags category, Level level) const;
+
         /** Send a string to the log output */
         void LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, int source_line, BCLog::LogFlags category, BCLog::Level level);
 
@@ -194,7 +197,7 @@ namespace BCLog {
         std::string LogLevelsString() const;
 
         //! Returns the string representation of a log level.
-        std::string LogLevelToStr(BCLog::Level level) const;
+        static std::string LogLevelToStr(BCLog::Level level);
 
         bool DefaultShrinkDebugFile() const;
     };
@@ -234,22 +237,17 @@ static inline void LogPrintf_(const std::string& logging_function, const std::st
 #define LogPrintLevel_(category, level, ...) LogPrintf_(__func__, __FILE__, __LINE__, category, level, __VA_ARGS__)
 
 // Log unconditionally.
-#define LogPrintf(...) LogPrintLevel_(BCLog::LogFlags::NONE, BCLog::Level::None, __VA_ARGS__)
+#define LogInfo(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Info, __VA_ARGS__)
+#define LogWarning(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Warning, __VA_ARGS__)
+#define LogError(...) LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Error, __VA_ARGS__)
 
-// Log unconditionally, prefixing the output with the passed category name.
-#define LogPrintfCategory(category, ...) LogPrintLevel_(category, BCLog::Level::None, __VA_ARGS__)
+// Deprecated unconditional logging.
+#define LogPrintf(...) LogInfo(__VA_ARGS__)
+#define LogPrintfCategory(category, ...) LogPrintLevel_(category, BCLog::Level::Info, __VA_ARGS__)
 
 // Use a macro instead of a function for conditional logging to prevent
 // evaluating arguments when logging for the category is not enabled.
 
-// Log conditionally, prefixing the output with the passed category name.
-#define LogPrint(category, ...)                                        \
-    do {                                                               \
-        if (LogAcceptCategory((category), BCLog::Level::Debug)) {      \
-            LogPrintLevel_(category, BCLog::Level::None, __VA_ARGS__); \
-        }                                                              \
-    } while (0)
-
 // Log conditionally, prefixing the output with the passed category name and severity level.
 #define LogPrintLevel(category, level, ...)               \
     do {                                                  \
@@ -258,6 +256,13 @@ static inline void LogPrintf_(const std::string& logging_function, const std::st
         }                                                 \
     } while (0)
 
+// Log conditionally, prefixing the output with the passed category name.
+#define LogDebug(category, ...) LogPrintLevel(category, BCLog::Level::Debug, __VA_ARGS__)
+#define LogTrace(category, ...) LogPrintLevel(category, BCLog::Level::Trace, __VA_ARGS__)
+
+// Deprecated conditional logging
+#define LogPrint(category, ...)  LogDebug(category, __VA_ARGS__)
+
 template <typename... Args>
 bool error(const char* fmt, const Args&... args)
 {
diff --git a/src/net_processing.cpp b/src/net_processing.cpp
index df54a62f28..683a7aa10f 100644
--- a/src/net_processing.cpp
+++ b/src/net_processing.cpp
@@ -4405,7 +4405,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
         }
 
         if (received_new_header) {
-            LogPrintfCategory(BCLog::NET, "Saw new cmpctblock header hash=%s peer=%d\n",
+            LogInfo("Saw new cmpctblock header hash=%s peer=%d\n",
                 blockhash.ToString(), pfrom.GetId());
         }
 
diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp
index e448805e69..88e3ec94b7 100644
--- a/src/test/logging_tests.cpp
+++ b/src/test/logging_tests.cpp
@@ -84,27 +84,32 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintf_, LogSetup)
 {
     LogInstance().m_log_sourcelocations = true;
     LogPrintf_("fn1", "src1", 1, BCLog::LogFlags::NET, BCLog::Level::Debug, "foo1: %s\n", "bar1");
-    LogPrintf_("fn2", "src2", 2, BCLog::LogFlags::NET, BCLog::Level::None, "foo2: %s\n", "bar2");
-    LogPrintf_("fn3", "src3", 3, BCLog::LogFlags::NONE, BCLog::Level::Debug, "foo3: %s\n", "bar3");
-    LogPrintf_("fn4", "src4", 4, BCLog::LogFlags::NONE, BCLog::Level::None, "foo4: %s\n", "bar4");
+    LogPrintf_("fn2", "src2", 2, BCLog::LogFlags::NET, BCLog::Level::Info, "foo2: %s\n", "bar2");
+    LogPrintf_("fn3", "src3", 3, BCLog::LogFlags::ALL, BCLog::Level::Debug, "foo3: %s\n", "bar3");
+    LogPrintf_("fn4", "src4", 4, BCLog::LogFlags::ALL, BCLog::Level::Info, "foo4: %s\n", "bar4");
+    LogPrintf_("fn5", "src5", 5, BCLog::LogFlags::NONE, BCLog::Level::Debug, "foo5: %s\n", "bar5");
+    LogPrintf_("fn6", "src6", 6, BCLog::LogFlags::NONE, BCLog::Level::Info, "foo6: %s\n", "bar6");
     std::ifstream file{tmp_log_path};
     std::vector<std::string> log_lines;
     for (std::string log; std::getline(file, log);) {
         log_lines.push_back(log);
     }
     std::vector<std::string> expected = {
-        "[src1:1] [fn1] [net:debug] foo1: bar1",
-        "[src2:2] [fn2] [net] foo2: bar2",
+        "[src1:1] [fn1] [net] foo1: bar1",
+        "[src2:2] [fn2] [net:info] foo2: bar2",
         "[src3:3] [fn3] [debug] foo3: bar3",
         "[src4:4] [fn4] foo4: bar4",
+        "[src5:5] [fn5] [debug] foo5: bar5",
+        "[src6:6] [fn6] foo6: bar6",
     };
     BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
 }
 
-BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup)
+BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacrosDeprecated, LogSetup)
 {
     LogPrintf("foo5: %s\n", "bar5");
     LogPrint(BCLog::NET, "foo6: %s\n", "bar6");
+    LogPrintLevel(BCLog::NET, BCLog::Level::Trace, "foo4: %s\n", "bar4"); // not logged
     LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "foo7: %s\n", "bar7");
     LogPrintLevel(BCLog::NET, BCLog::Level::Info, "foo8: %s\n", "bar8");
     LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "foo9: %s\n", "bar9");
@@ -118,11 +123,32 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup)
     std::vector<std::string> expected = {
         "foo5: bar5",
         "[net] foo6: bar6",
-        "[net:debug] foo7: bar7",
+        "[net] foo7: bar7",
         "[net:info] foo8: bar8",
         "[net:warning] foo9: bar9",
         "[net:error] foo10: bar10",
-        "[validation] foo11: bar11",
+        "[validation:info] foo11: bar11",
+    };
+    BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
+}
+
+BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup)
+{
+    LogTrace(BCLog::NET, "foo6: %s\n", "bar6"); // not logged
+    LogDebug(BCLog::NET, "foo7: %s\n", "bar7");
+    LogInfo("foo8: %s\n", "bar8");
+    LogWarning("foo9: %s\n", "bar9");
+    LogError("foo10: %s\n", "bar10");
+    std::ifstream file{tmp_log_path};
+    std::vector<std::string> log_lines;
+    for (std::string log; std::getline(file, log);) {
+        log_lines.push_back(log);
+    }
+    std::vector<std::string> expected = {
+        "[net] foo7: bar7",
+        "foo8: bar8",
+        "[warning] foo9: bar9",
+        "[error] foo10: bar10",
     };
     BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
 }
diff --git a/src/torcontrol.cpp b/src/torcontrol.cpp
index 11d13d050a..442c1c4d42 100644
--- a/src/torcontrol.cpp
+++ b/src/torcontrol.cpp
@@ -433,7 +433,7 @@ void TorController::add_onion_cb(TorControlConnection& _conn, const TorControlRe
             return;
         }
         service = LookupNumeric(std::string(service_id+".onion"), Params().GetDefaultPort());
-        LogPrintfCategory(BCLog::TOR, "Got service ID %s, advertising service %s\n", service_id, service.ToStringAddrPort());
+        LogInfo("Got tor service ID %s, advertising service %s\n", service_id, service.ToStringAddrPort());
         if (WriteBinaryFile(GetPrivateKeyFile(), private_key)) {
             LogPrint(BCLog::TOR, "Cached service private key to %s\n", fs::PathToString(GetPrivateKeyFile()));
         } else {