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

fa2b7d8 Remove redundant unterminated-logprintf tidy check (MarcoFalke)
bbbb2e4 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 bitcoin/bitcoin#30386 (comment).
  * 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 fa2b7d8
  achow101:
    ACK fa2b7d8
  ryanofsky:
    Code review ACK fa2b7d8. Just comment and test cleanup since last review

Tree-SHA512: 10ed420f6c2fdb0f491d6c880be8dd2e8beef628f510adebadf4c3849d9f5e28906519d5cbaeb295f4c7c1b07c4c88a9905b3cfe30fee3a2c91ac9fd24ae6755

Author: achow101

contrib/devtools/bitcoin-tidy/CMakeLists.txt

@@ -25,7 +25,7 @@ find_program(CLANG_TIDY_EXE NAMES "clang-tidy-${LLVM_VERSION_MAJOR}" "clang-tidy
 message(STATUS "Found LLVM ${LLVM_PACKAGE_VERSION}")
 message(STATUS "Found clang-tidy: ${CLANG_TIDY_EXE}")
 
-add_library(bitcoin-tidy MODULE bitcoin-tidy.cpp logprintf.cpp nontrivial-threadlocal.cpp)
+add_library(bitcoin-tidy MODULE bitcoin-tidy.cpp nontrivial-threadlocal.cpp)
 target_include_directories(bitcoin-tidy SYSTEM PRIVATE ${LLVM_INCLUDE_DIRS})
 
 # Disable RTTI and exceptions as necessary
@@ -58,7 +58,7 @@ else()
 endif()
 
 # Create a dummy library that runs clang-tidy tests as a side-effect of building
-add_library(bitcoin-tidy-tests OBJECT EXCLUDE_FROM_ALL example_logprintf.cpp example_nontrivial-threadlocal.cpp)
+add_library(bitcoin-tidy-tests OBJECT EXCLUDE_FROM_ALL example_nontrivial-threadlocal.cpp)
 add_dependencies(bitcoin-tidy-tests bitcoin-tidy)
 
 set_target_properties(bitcoin-tidy-tests PROPERTIES CXX_CLANG_TIDY "${CLANG_TIDY_COMMAND}")

contrib/devtools/bitcoin-tidy/bitcoin-tidy.cpp

@@ -2,7 +2,6 @@
 // Distributed under the MIT software license, see the accompanying
 // file COPYING or http://www.opensource.org/licenses/mit-license.php.
 
-#include "logprintf.h"
 #include "nontrivial-threadlocal.h"
 
 #include <clang-tidy/ClangTidyModule.h>
@@ -13,7 +12,6 @@ class BitcoinModule final : public clang::tidy::ClangTidyModule
 public:
     void addCheckFactories(clang::tidy::ClangTidyCheckFactories& CheckFactories) override
     {
-        CheckFactories.registerCheck<bitcoin::LogPrintfCheck>("bitcoin-unterminated-logprintf");
         CheckFactories.registerCheck<bitcoin::NonTrivialThreadLocal>("bitcoin-nontrivial-threadlocal");
     }
 };

contrib/devtools/bitcoin-tidy/example_logprintf.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

contrib/devtools/bitcoin-tidy/logprintf.cpp

@@ -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);

contrib/devtools/bitcoin-tidy/logprintf.h

@@ -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);) {

src/logging.cpp

@@ -62,7 +62,7 @@ def main():
 
         matching_files_filtered = []
         for matching_file in matching_files:
-            if not re.search('^src/(leveldb|secp256k1|minisketch|tinyformat|test/fuzz/strprintf.cpp)|contrib/devtools/bitcoin-tidy/example_logprintf.cpp', matching_file):
+            if not re.search('^src/(leveldb|secp256k1|minisketch|tinyformat|test/fuzz/strprintf.cpp)', matching_file):
                 matching_files_filtered.append(matching_file)
         matching_files_filtered.sort()