Merge bitcoin/bitcoin#30929: log: Enforce trailing newline

fa2b7d8d6b3f8d53199921e1e542072441b26fab Remove redundant unterminated-logprintf tidy check (MarcoFalke)
bbbb2e43ee95c9a8866aa1f65e3f001f752dfed2 log: Enforce trailing newline, Remove redundant m_started_new_line (MarcoFalke)

Pull request description:

  There are many problems around missing a trailing newline while logging:

  * All log lines are currently terminated by a trailing newline. This means any runtime code trying to handle a "missing" newline is currently dead code.
  * Leaving a line unterminated is racy and can cause content corruption by mixing log lines from different sources.
  * It requires extra code like `m_started_new_line` to keep track of, which is annoying and pointless to maintain, because it is currently dead code, see https://github.com/bitcoin/bitcoin/pull/30386#discussion_r1684380835.
  * It requires a standalone `unterminated-logprintf` clang-tidy plugin, which is unmaintained (no one updated it for the new log function names), probably harder to maintain than normal C++ code (because it requires clang AST matcher knowledge), brittle (it can fail to detect issues at any time, if it goes out-of-sync, or be explicitly disabled via `NOLINT`), and annoying for devs (it is slow and intricate to run locally and thus only effectively run on CI or via the CI scripts).

  Fix all issues by enforcing the trailing newline in logs directly in the code. Then remove all the other stuff.

  This refactor does not change behavior.

ACKs for top commit:
  stickies-v:
    re-ACK fa2b7d8d6b3f8d53199921e1e542072441b26fab
  achow101:
    ACK fa2b7d8d6b3f8d53199921e1e542072441b26fab
  ryanofsky:
    Code review ACK fa2b7d8d6b3f8d53199921e1e542072441b26fab. Just comment and test cleanup since last review

Tree-SHA512: 10ed420f6c2fdb0f491d6c880be8dd2e8beef628f510adebadf4c3849d9f5e28906519d5cbaeb295f4c7c1b07c4c88a9905b3cfe30fee3a2c91ac9fd24ae6755

3 files changed, 15 insertions, 36 deletions

diff --git a/src/logging.cpp b/src/logging.cpp
index d04db767e6..5f055566ef 100644
--- a/src/logging.cpp
+++ b/src/logging.cpp
@@ -5,6 +5,7 @@
 
 #include <logging.h>
 #include <memusage.h>
+#include <util/check.h>
 #include <util/fs.h>
 #include <util/string.h>
 #include <util/threadnames.h>
@@ -368,6 +369,8 @@ static size_t MemUsage(const BCLog::Logger::BufferedLog& buflog)
 
 void BCLog::Logger::FormatLogStrInPlace(std::string& str, BCLog::LogFlags category, BCLog::Level level, std::string_view source_file, int source_line, std::string_view logging_function, std::string_view threadname, SystemClock::time_point now, std::chrono::seconds mocktime) const
 {
+    if (!str.ends_with('\n')) str.push_back('\n');
+
     str.insert(0, GetLogPrefix(category, level));
 
     if (m_log_sourcelocations) {
@@ -391,21 +394,7 @@ void BCLog::Logger::LogPrintStr_(std::string_view str, std::string_view logging_
 {
     std::string str_prefixed = LogEscapeMessage(str);
 
-    const bool starts_new_line = m_started_new_line;
-    m_started_new_line = !str.empty() && str[str.size()-1] == '\n';
-
     if (m_buffering) {
-        if (!starts_new_line) {
-            if (!m_msgs_before_open.empty()) {
-                m_msgs_before_open.back().str += str_prefixed;
-                m_cur_buffer_memusage += str_prefixed.size();
-                return;
-            } else {
-                // unlikely edge case; add a marker that something was trimmed
-                str_prefixed.insert(0, "[...] ");
-            }
-        }
-
         {
             BufferedLog buf{
                 .now=SystemClock::now(),
@@ -435,9 +424,7 @@ void BCLog::Logger::LogPrintStr_(std::string_view str, std::string_view logging_
         return;
     }
 
-    if (starts_new_line) {
-        FormatLogStrInPlace(str_prefixed, category, level, source_file, source_line, logging_function, util::ThreadGetInternalName(), SystemClock::now(), GetMockTime());
-    }
+    FormatLogStrInPlace(str_prefixed, category, level, source_file, source_line, logging_function, util::ThreadGetInternalName(), SystemClock::now(), GetMockTime());
 
     if (m_print_to_console) {
         // print to console
diff --git a/src/logging.h b/src/logging.h
index 8605c8cd64..fdc12c79b3 100644
--- a/src/logging.h
+++ b/src/logging.h
@@ -105,13 +105,6 @@ namespace BCLog {
         size_t m_cur_buffer_memusage GUARDED_BY(m_cs){0};
         size_t m_buffer_lines_discarded GUARDED_BY(m_cs){0};
 
-        /**
-         * m_started_new_line is a state variable that will suppress printing of
-         * the timestamp when multiple calls are made that don't end in a
-         * newline.
-         */
-        std::atomic_bool m_started_new_line{true};
-
         //! Category-specific log level. Overrides `m_log_level`.
         std::unordered_map<LogFlags, Level> m_category_log_levels GUARDED_BY(m_cs);
 
@@ -253,7 +246,6 @@ inline void LogPrintFormatInternal(std::string_view logging_function, std::strin
         try {
             log_msg = tfm::format(fmt, args...);
         } catch (tinyformat::format_error& fmterr) {
-            /* Original format string will have newline so don't add one here */
             log_msg = "Error \"" + std::string{fmterr.what()} + "\" while formatting log message: " + fmt.fmt;
         }
         LogInstance().LogPrintStr(log_msg, logging_function, source_file, source_line, flag, level);
diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp
index 8217a2385c..77ec81e597 100644
--- a/src/test/logging_tests.cpp
+++ b/src/test/logging_tests.cpp
@@ -86,12 +86,12 @@ BOOST_AUTO_TEST_CASE(logging_timer)
 BOOST_FIXTURE_TEST_CASE(logging_LogPrintStr, LogSetup)
 {
     LogInstance().m_log_sourcelocations = true;
-    LogInstance().LogPrintStr("foo1: bar1\n", "fn1", "src1", 1, BCLog::LogFlags::NET, BCLog::Level::Debug);
-    LogInstance().LogPrintStr("foo2: bar2\n", "fn2", "src2", 2, BCLog::LogFlags::NET, BCLog::Level::Info);
-    LogInstance().LogPrintStr("foo3: bar3\n", "fn3", "src3", 3, BCLog::LogFlags::ALL, BCLog::Level::Debug);
-    LogInstance().LogPrintStr("foo4: bar4\n", "fn4", "src4", 4, BCLog::LogFlags::ALL, BCLog::Level::Info);
-    LogInstance().LogPrintStr("foo5: bar5\n", "fn5", "src5", 5, BCLog::LogFlags::NONE, BCLog::Level::Debug);
-    LogInstance().LogPrintStr("foo6: bar6\n", "fn6", "src6", 6, BCLog::LogFlags::NONE, BCLog::Level::Info);
+    LogInstance().LogPrintStr("foo1: bar1", "fn1", "src1", 1, BCLog::LogFlags::NET, BCLog::Level::Debug);
+    LogInstance().LogPrintStr("foo2: bar2", "fn2", "src2", 2, BCLog::LogFlags::NET, BCLog::Level::Info);
+    LogInstance().LogPrintStr("foo3: bar3", "fn3", "src3", 3, BCLog::LogFlags::ALL, BCLog::Level::Debug);
+    LogInstance().LogPrintStr("foo4: bar4", "fn4", "src4", 4, BCLog::LogFlags::ALL, BCLog::Level::Info);
+    LogInstance().LogPrintStr("foo5: bar5", "fn5", "src5", 5, BCLog::LogFlags::NONE, BCLog::Level::Debug);
+    LogInstance().LogPrintStr("foo6: bar6", "fn6", "src6", 6, BCLog::LogFlags::NONE, BCLog::Level::Info);
     std::ifstream file{tmp_log_path};
     std::vector<std::string> log_lines;
     for (std::string log; std::getline(file, log);) {
@@ -133,11 +133,11 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacrosDeprecated, LogSetup)
 
 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");
+    LogTrace(BCLog::NET, "foo6: %s", "bar6"); // not logged
+    LogDebug(BCLog::NET, "foo7: %s", "bar7");
+    LogInfo("foo8: %s", "bar8");
+    LogWarning("foo9: %s", "bar9");
+    LogError("foo10: %s", "bar10");
     std::ifstream file{tmp_log_path};
     std::vector<std::string> log_lines;
     for (std::string log; std::getline(file, log);) {