phantom/bitcoin
1
0
Fork 0
mirror of https://github.com/bitcoin/bitcoin.git synced 2025-01-24 18:23:26 -03:00
Code Issues Projects Releases Packages Wiki Activity Actions 1

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

Browse source 
fa2b7d8d6b Remove redundant unterminated-logprintf tidy check (MarcoFalke)
bbbb2e43ee 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 fa2b7d8d6b
  achow101:
    ACK fa2b7d8d6b
  ryanofsky:
    Code review ACK fa2b7d8d6b. Just comment and test cleanup since last review

Tree-SHA512: 10ed420f6c2fdb0f491d6c880be8dd2e8beef628f510adebadf4c3849d9f5e28906519d5cbaeb295f4c7c1b07c4c88a9905b3cfe30fee3a2c91ac9fd24ae6755
This commit is contained in:
Ava Chow 2024-10-02 19:05:34 -04:00
commit dda2613239
No known key found for this signature in database
GPG key ID: 17565732E08E5E41
9 changed files with 18 additions and 238 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

4
contrib/devtools/bitcoin-tidy/CMakeLists.txt
View file

@ -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}")

2
contrib/devtools/bitcoin-tidy/bitcoin-tidy.cpp
View file

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

108
contrib/devtools/bitcoin-tidy/example_logprintf.cpp
View file

@ -1,108 +0,0 @@
// Copyright (c) 2023 Bitcoin Developers
// Distributed under the MIT software license, see the accompanying
// file COPYING or http://www.opensource.org/licenses/mit-license.php.
#include <string>
// Test for bitcoin-unterminated-logprintf
enum LogFlags {
NONE
};
enum Level {
None
};
template <typename... Args>
static inline void LogPrintf_(const std::string& logging_function, const std::string& source_file, const int source_line, const LogFlags flag, const Level level, const char* fmt, const Args&... args)
{
}
#define LogPrintLevel_(category, level, ...) LogPrintf_(__func__, __FILE__, __LINE__, category, level, __VA_ARGS__)
#define LogPrintf(...) LogPrintLevel_(LogFlags::NONE, Level::None, __VA_ARGS__)
#define LogDebug(category, ...) \
do { \
LogPrintf(__VA_ARGS__); \
} while (0)
class CWallet
{
std::string GetDisplayName() const
{
return "default wallet";
}
public:
template <typename... Params>
void WalletLogPrintf(const char* fmt, Params... parameters) const
{
LogPrintf(("%s " + std::string{fmt}).c_str(), GetDisplayName(), parameters...);
};
};
struct ScriptPubKeyMan
{
std::string GetDisplayName() const
{
return "default wallet";
}
template <typename... Params>
void WalletLogPrintf(const char* fmt, Params... parameters) const
{
LogPrintf(("%s " + std::string{fmt}).c_str(), GetDisplayName(), parameters...);
};
};
void good_func()
{
LogPrintf("hello world!\n");
}
void good_func2()
{
CWallet wallet;
wallet.WalletLogPrintf("hi\n");
ScriptPubKeyMan spkm;
spkm.WalletLogPrintf("hi\n");
const CWallet& walletref = wallet;
walletref.WalletLogPrintf("hi\n");
auto* walletptr = new CWallet();
walletptr->WalletLogPrintf("hi\n");
delete walletptr;
}
void bad_func()
{
LogPrintf("hello world!");
}
void bad_func2()
{
LogPrintf("");
}
void bad_func3()
{
// Ending in "..." has no special meaning.
LogPrintf("hello world!...");
}
void bad_func4_ignored()
{
LogPrintf("hello world!"); // NOLINT(bitcoin-unterminated-logprintf)
}
void bad_func5()
{
CWallet wallet;
wallet.WalletLogPrintf("hi");
ScriptPubKeyMan spkm;
spkm.WalletLogPrintf("hi");
const CWallet& walletref = wallet;
walletref.WalletLogPrintf("hi");
auto* walletptr = new CWallet();
walletptr->WalletLogPrintf("hi");
delete walletptr;
}

60
contrib/devtools/bitcoin-tidy/logprintf.cpp
View file

@ -1,60 +0,0 @@
// Copyright (c) 2023 Bitcoin Developers
// Distributed under the MIT software license, see the accompanying
// file COPYING or http://www.opensource.org/licenses/mit-license.php.
#include "logprintf.h"
#include <clang/AST/ASTContext.h>
#include <clang/ASTMatchers/ASTMatchFinder.h>
namespace {
AST_MATCHER(clang::StringLiteral, unterminated)
{
size_t len = Node.getLength();
if (len > 0 && Node.getCodeUnit(len - 1) == '\n') {
return false;
}
return true;
}
} // namespace
namespace bitcoin {
void LogPrintfCheck::registerMatchers(clang::ast_matchers::MatchFinder* finder)
{
using namespace clang::ast_matchers;
/*
Logprintf(..., ..., ..., ..., ..., "foo", ...)
*/
finder->addMatcher(
callExpr(
callee(functionDecl(hasName("LogPrintf_"))),
hasArgument(5, stringLiteral(unterminated()).bind("logstring"))),
this);
/*
auto walletptr = &wallet;
wallet.WalletLogPrintf("foo");
wallet->WalletLogPrintf("foo");
*/
finder->addMatcher(
cxxMemberCallExpr(
callee(cxxMethodDecl(hasName("WalletLogPrintf"))),
hasArgument(0, stringLiteral(unterminated()).bind("logstring"))),
this);
}
void LogPrintfCheck::check(const clang::ast_matchers::MatchFinder::MatchResult& Result)
{
if (const clang::StringLiteral* lit = Result.Nodes.getNodeAs<clang::StringLiteral>("logstring")) {
const clang::ASTContext& ctx = *Result.Context;
const auto user_diag = diag(lit->getEndLoc(), "Unterminated format string used with LogPrintf");
const auto& loc = lit->getLocationOfByte(lit->getByteLength(), *Result.SourceManager, ctx.getLangOpts(), ctx.getTargetInfo());
user_diag << clang::FixItHint::CreateInsertion(loc, "\\n");
}
}
} // namespace bitcoin

29
contrib/devtools/bitcoin-tidy/logprintf.h
View file

@ -1,29 +0,0 @@
// Copyright (c) 2023 Bitcoin Developers
// Distributed under the MIT software license, see the accompanying
// file COPYING or http://www.opensource.org/licenses/mit-license.php.
#ifndef LOGPRINTF_CHECK_H
#define LOGPRINTF_CHECK_H
#include <clang-tidy/ClangTidyCheck.h>
namespace bitcoin {
// Warn about any use of LogPrintf that does not end with a newline.
class LogPrintfCheck final : public clang::tidy::ClangTidyCheck
{
public:
LogPrintfCheck(clang::StringRef Name, clang::tidy::ClangTidyContext* Context)
: clang::tidy::ClangTidyCheck(Name, Context) {}
bool isLanguageVersionSupported(const clang::LangOptions& LangOpts) const override
{
return LangOpts.CPlusPlus;
}
void registerMatchers(clang::ast_matchers::MatchFinder* Finder) override;
void check(const clang::ast_matchers::MatchFinder::MatchResult& Result) override;
};
} // namespace bitcoin
#endif // LOGPRINTF_CHECK_H

21
src/logging.cpp
View file

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

8
src/logging.h
View file

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

22
src/test/logging_tests.cpp
View file

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

2
test/lint/lint-format-strings.py
View file

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