From 12d97dbdcbb73cb4a68ca4b52591bc9c7649d3cf Mon Sep 17 00:00:00 2001 From: Ryan Ofsky Date: Fri, 12 Jan 2024 16:52:05 -0500 Subject: [PATCH 1/5] logging: Improve new LogDebug/Trace/Info/Warning/Error Macros Improve new LogDebug(), LogTrace(), LogInfo(), LogWarning(), LogError() macros introduced in #28318: - Make them always accept log categories to make it possible to only log messages from a particular component. - Make them not rely on a global LogInstance, to provide better control of logging in controlled environments, such as unit tests that want to selectively capture log output, or libbitcoinkernel applications that want to have multiple instances of validation objects without mixing their log output. - Make them consistent, now all accepting the same parameters. - Make them less verbose by not requiring BCLog category constants to be specified in individual log prints --- src/logging.h | 148 ++++++++++++++++++++++++++++--------- src/test/logging_tests.cpp | 117 +++++++++++++++++++++++++++++ 2 files changed, 229 insertions(+), 36 deletions(-) diff --git a/src/logging.h b/src/logging.h index fdc12c79b32..07be8e23b6d 100644 --- a/src/logging.h +++ b/src/logging.h @@ -6,6 +6,7 @@ #ifndef BITCOIN_LOGGING_H #define BITCOIN_LOGGING_H +#include #include #include #include @@ -21,6 +22,12 @@ #include #include +namespace BCLog { +class Logger; +} // namespace BCLog + +BCLog::Logger& LogInstance(); + static const bool DEFAULT_LOGTIMEMICROS = false; static const bool DEFAULT_LOGIPS = false; static const bool DEFAULT_LOGTIMESTAMPS = true; @@ -73,6 +80,11 @@ namespace BCLog { TXPACKAGES = (CategoryMask{1} << 28), ALL = ~NONE, }; + //! Log level constants. Most code will not need to use these directly and + //! can use LogTrace, LogDebug, LogInfo, LogWarning, and LogError macros + //! defined below for less verbosity and more efficiency (by not evaluating + //! unused format arguments). See macro definitions below or "Logging" + //! section in developer-notes.md for more detailed information. enum class Level { Trace = 0, // High-volume or detailed logging for development/debugging Debug, // Reasonably noisy logging, but still usable in production @@ -225,9 +237,36 @@ namespace BCLog { bool DefaultShrinkDebugFile() const; }; + //! Object representing a particular source of log messages. Holds a logging + //! category, a reference to the logger object to output to, and a + //! formatting hook. + struct Source { + LogFlags category; + Logger& logger; + + //! Constructor. Implicit so can be constructed from category constants passed to Log macros below. + Source(LogFlags category = LogFlags::ALL, Logger& logger = LogInstance()) : category{category}, logger{logger} {} + + template + std::string Format(util::ConstevalFormatString fmt, const Args&... args) const + { + std::string log_msg; + try { + log_msg = tfm::format(fmt, args...); + } catch (tinyformat::format_error& fmterr) { + log_msg = "Error \"" + std::string{fmterr.what()} + "\" while formatting log message: " + fmt.fmt; + } + return log_msg; + } + }; } // namespace BCLog -BCLog::Logger& LogInstance(); +//! Determine whether logging is enabled from a source at the specified level. +template +static inline bool LogEnabled(const Source& source, BCLog::Level level) +{ + return source.logger.WillLogCategoryLevel(source.category, level) && source.logger.Enabled(); +} /** Return true if log accepts specified category, at the specified level. */ static inline bool LogAcceptCategory(BCLog::LogFlags category, BCLog::Level level) @@ -238,46 +277,83 @@ static inline bool LogAcceptCategory(BCLog::LogFlags category, BCLog::Level leve /** Return true if str parses as a log category and set the flag */ bool GetLogCategory(BCLog::LogFlags& flag, std::string_view str); -template -inline void LogPrintFormatInternal(std::string_view logging_function, std::string_view source_file, const int source_line, const BCLog::LogFlags flag, const BCLog::Level level, util::ConstevalFormatString fmt, const Args&... args) +//! Internal helper to get log source object from macro argument, if argument is +//! BCLog::Source object or a category constant that BCLog::Source can be +//! constructed from. +static inline const BCLog::Source& _LogSource(const BCLog::Source& source LIFETIMEBOUND) { return source; } + +//! Internal helper to get log source object from macro argument, if argument is +//! just a format string and no source or category was provided. +static inline BCLog::Source _LogSource(std::string_view fmt) { return {}; } + +//! Internal helper to format log arguments and call a logging function. +template +requires (!std::is_convertible_v) +void _LogFormat(LogFn&& log, Source&& source, SourceArg&&, util::ConstevalFormatString fmt, const Args&... args) { - if (LogInstance().Enabled()) { - std::string log_msg; - try { - log_msg = tfm::format(fmt, args...); - } catch (tinyformat::format_error& fmterr) { - 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); - } + log(source, source.Format(fmt, args...)); +} +template +void _LogFormat(LogFn&& log, Source&& source, util::ConstevalFormatString fmt, const Args&... args) +{ + log(source, source.Format(fmt, args...)); } -#define LogPrintLevel_(category, level, ...) LogPrintFormatInternal(__func__, __FILE__, __LINE__, category, level, __VA_ARGS__) +//! Internal helper to return first arg in a __VA_ARGS__ pack. +#define _FirstArg(arg, ...) arg -// Log unconditionally. -// Be conservative when using functions that unconditionally log to debug.log! -// It should not be the case that an inbound peer can fill up a user's storage -// with debug.log entries. -#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__) - -// Deprecated unconditional logging. -#define LogPrintf(...) LogInfo(__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 and severity level. -#define LogPrintLevel(category, level, ...) \ - do { \ - if (LogAcceptCategory((category), (level))) { \ - LogPrintLevel_(category, level, __VA_ARGS__); \ - } \ +//! Internal helper to check level and log. Avoids evaluating arguments if not logging. +#define _LogPrint(level, ...) \ + do { \ + if (LogEnabled(_LogSource(_FirstArg(__VA_ARGS__)), (level))) { \ + const auto& func = __func__; \ + _LogFormat([&](auto&& source, auto&& message) { \ + source.logger.LogPrintStr(message, func, __FILE__, \ + __LINE__, source.category, (level)); \ + }, _LogSource(_FirstArg(__VA_ARGS__)), __VA_ARGS__); \ + } \ } 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__) +//! Logging macros which output log messages at the specified levels, and avoid +//! evaluating their arguments if logging is not enabled for the level. The +//! macros accept an optional log source parameter followed by a printf-style +//! format string and arguments. +//! +//! - LogError(), LogWarning(), and LogInfo() are all enabled by default, so +//! they should be called infrequently, in cases where they will not spam the +//! log and take up disk space. +//! +//! - LogDebug() is enabled when debug logging is enabled, and should be used to +//! show messages that can help users troubleshoot issues. +//! +//! - LogTrace() is enabled when both debug logging AND tracing are enabled, and +//! should be used for fine-grained traces that will be helpful to developers. +//! +//! For more information about log levels, see the -debug and -loglevel +//! documentation, or the "Logging" section of developer notes. +//! +//! A source argument specifying a category can be specified as a first argument to +//! all log macros, but it is optional: +//! +//! LogDebug(BCLog::TXRECONCILIATION, "Forget txreconciliation state of peer=%d\n", peer_id); +//! LogInfo("Uncategorizable log information.\n"); +//! +//! Source objects can also be declared to avoid repeating category constants: +//! +//! const BCLog::Source m_log{BCLog::TXRECONCILIATION}; +//! ... +//! LogDebug(m_log, "Forget txreconciliation state of peer=%d\n", peer_id); +//! +//! Using source objects also allows diverting log messages to a local logger +//! instead of the global logging instance. +#define LogError(...) _LogPrint(BCLog::Level::Error, __VA_ARGS__) +#define LogWarning(...) _LogPrint(BCLog::Level::Warning, __VA_ARGS__) +#define LogInfo(...) _LogPrint(BCLog::Level::Info, __VA_ARGS__) +#define LogDebug(...) _LogPrint(BCLog::Level::Debug, __VA_ARGS__) +#define LogTrace(...) _LogPrint(BCLog::Level::Trace, __VA_ARGS__) +#define LogPrintLevel(source, level, ...) _LogPrint(level, source, __VA_ARGS__) + +//! Deprecated macros. +#define LogPrintf(...) LogInfo(__VA_ARGS__) #endif // BITCOIN_LOGGING_H diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index 77ec81e5977..74a676a9e95 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -76,6 +76,123 @@ struct LogSetup : public BasicTestingSetup { } }; +//! Test logging to local logger. +BOOST_AUTO_TEST_CASE(logging_local_logger) +{ + BCLog::Logger logger; + logger.m_log_timestamps = false; + logger.EnableCategory(BCLog::LogFlags::ALL); + logger.SetLogLevel(BCLog::Level::Trace); + logger.StartLogging(); + + std::vector messages; + logger.PushBackCallback([&](const std::string& s) { messages.push_back(s); }); + + BCLog::Source log{BCLog::NET, logger}; + LogError(log, "error %s\n", "arg"); + LogWarning(log, "warning %s\n", "arg"); + LogInfo(log, "info %s\n", "arg"); + LogDebug(log, "debug %s\n", "arg"); + LogTrace(log, "trace %s\n", "arg"); + + constexpr auto expected{std::to_array({ + "[net:error] error arg\n", + "[net:warning] warning arg\n", + "[net:info] info arg\n", + "[net] debug arg\n", + "[net:trace] trace arg\n", + })}; + BOOST_CHECK_EQUAL_COLLECTIONS(messages.begin(), messages.end(), expected.begin(), expected.end()); +} + +//! Test logging to global logger with different types of source arguments. +BOOST_FIXTURE_TEST_CASE(logging_source_args, LogSetup) +{ + LogInstance().EnableCategory(BCLog::LogFlags::ALL); + LogInstance().SetLogLevel(BCLog::Level::Trace); + + // Test logging with no source arguments. + LogError("error\n"); + LogWarning("warning\n"); + LogInfo("info\n"); + LogDebug("debug\n"); + LogTrace("trace\n"); + LogError("error %s\n", "arg"); + LogWarning("warning %s\n", "arg"); + LogInfo("info %s\n", "arg"); + LogDebug("debug %s\n", "arg"); + LogTrace("trace %s\n", "arg"); + + // Test logging with category arguments. + LogError(BCLog::NET, "error\n"); + LogWarning(BCLog::NET, "warning\n"); + LogInfo(BCLog::NET, "info\n"); + LogDebug(BCLog::NET, "debug\n"); + LogTrace(BCLog::NET, "trace\n"); + LogError(BCLog::NET, "error %s\n", "arg"); + LogWarning(BCLog::NET, "warning %s\n", "arg"); + LogInfo(BCLog::NET, "info %s\n", "arg"); + LogDebug(BCLog::NET, "debug %s\n", "arg"); + LogTrace(BCLog::NET, "trace %s\n", "arg"); + + // Test logging with source object. + BCLog::Source log{BCLog::TOR}; + LogError(log, "error\n"); + LogWarning(log, "warning\n"); + LogInfo(log, "info\n"); + LogDebug(log, "debug\n"); + LogTrace(log, "trace\n"); + LogError(log, "error %s\n", "arg"); + LogWarning(log, "warning %s\n", "arg"); + LogInfo(log, "info %s\n", "arg"); + LogDebug(log, "debug %s\n", "arg"); + LogTrace(log, "trace %s\n", "arg"); + + constexpr auto expected{std::to_array({ + "[error] error", + "[warning] warning", + "info", + "[debug] debug", + "[trace] trace", + + "[error] error arg", + "[warning] warning arg", + "info arg", + "[debug] debug arg", + "[trace] trace arg", + + "[net:error] error", + "[net:warning] warning", + "[net:info] info", + "[net] debug", + "[net:trace] trace", + + "[net:error] error arg", + "[net:warning] warning arg", + "[net:info] info arg", + "[net] debug arg", + "[net:trace] trace arg", + + "[tor:error] error", + "[tor:warning] warning", + "[tor:info] info", + "[tor] debug", + "[tor:trace] trace", + + "[tor:error] error arg", + "[tor:warning] warning arg", + "[tor:info] info arg", + "[tor] debug arg", + "[tor:trace] trace arg", + })}; + std::ifstream file{tmp_log_path}; + std::vector log_lines; + for (std::string log; std::getline(file, log);) { + log_lines.push_back(log); + } + BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end()); +} + BOOST_AUTO_TEST_CASE(logging_timer) { auto micro_timer = BCLog::Timer("tests", "end_msg"); From 5db1958e60aef9d3604448c21e1f397e561480ee Mon Sep 17 00:00:00 2001 From: Ryan Ofsky Date: Tue, 27 Feb 2024 20:45:00 -0500 Subject: [PATCH 2/5] logging: Add preprocessor workaround for MSVC Needed to fix errors like: const Source &_LogSource(const Source &)': expects 1 arguments - 3 provided const Source &_LogSource(const Source &)': expects 1 arguments - 3 provided due to a compiler bug: https://stackoverflow.com/questions/5134523/msvc-doesnt-expand-va-args-correctly/5134656#5134656 Example CI failure: https://github.com/bitcoin/bitcoin/actions/runs/8072891468/job/22055528830?pr=29256 --- src/logging.h | 11 +++++++---- 1 file changed, 7 insertions(+), 4 deletions(-) diff --git a/src/logging.h b/src/logging.h index 07be8e23b6d..224453474f3 100644 --- a/src/logging.h +++ b/src/logging.h @@ -299,18 +299,21 @@ void _LogFormat(LogFn&& log, Source&& source, util::ConstevalFormatString Date: Tue, 27 Feb 2024 16:30:24 -0500 Subject: [PATCH 3/5] wallet, logging: Replace WalletLogPrintf() with LogInfo() Make new logging macros LogDebug(), LogTrace(), LogInfo(), LogWarning(), and LogError() compatible with wallet code and drop custom WalletLogPrintf() function. The new logging macros introduced in #28318 weren't previously useful in wallet code because wallet code prefixes most log messages with the wallet names to be be able to distinguish log output from multiple wallets. Fix this by introducing a new WalletLogSource class inheriting from BCLog::Source which can include the wallet name in log messages --- src/logging.h | 13 +- src/test/logging_tests.cpp | 38 ++++ src/wallet/dump.cpp | 2 +- src/wallet/logging.h | 29 +++ src/wallet/receive.cpp | 3 +- src/wallet/rpc/backup.cpp | 7 +- src/wallet/scriptpubkeyman.cpp | 41 ++-- src/wallet/scriptpubkeyman.h | 14 +- src/wallet/spend.cpp | 8 +- src/wallet/wallet.cpp | 89 ++++---- src/wallet/wallet.h | 13 +- src/wallet/walletdb.cpp | 43 ++-- src/wallet/wallettool.cpp | 2 +- test/lint/run-lint-format-strings.py | 297 +++++++++++++++++++++++++++ 14 files changed, 491 insertions(+), 108 deletions(-) create mode 100644 src/wallet/logging.h create mode 100755 test/lint/run-lint-format-strings.py diff --git a/src/logging.h b/src/logging.h index 224453474f3..26d1becbc7e 100644 --- a/src/logging.h +++ b/src/logging.h @@ -241,6 +241,7 @@ namespace BCLog { //! category, a reference to the logger object to output to, and a //! formatting hook. struct Source { + static constexpr bool log_source{true}; LogFlags category; Logger& logger; @@ -282,6 +283,12 @@ bool GetLogCategory(BCLog::LogFlags& flag, std::string_view str); //! constructed from. static inline const BCLog::Source& _LogSource(const BCLog::Source& source LIFETIMEBOUND) { return source; } +//! Internal helper to get log source object from macro argument, if argument is +//! a custom log source with a log_source member. +template +requires (Source::log_source) +static inline const Source& _LogSource(const Source& source LIFETIMEBOUND) { return source; } + //! Internal helper to get log source object from macro argument, if argument is //! just a format string and no source or category was provided. static inline BCLog::Source _LogSource(std::string_view fmt) { return {}; } @@ -347,8 +354,10 @@ void _LogFormat(LogFn&& log, Source&& source, util::ConstevalFormatString + std::string Format(util::ConstevalFormatString fmt, const Args&... args) const + { + return tfm::format("Custom #%d %s", ++m_counter, tfm::format(fmt, args...)); + } +}; + +BOOST_FIXTURE_TEST_CASE(logging_CustomSource, LogSetup) +{ + int counter{0}; + CustomLogSource log{counter}; + LogTrace(log, "foo0: %s\n", "bar0"); // not logged + LogDebug(log, "foo1: %s\n", "bar1"); + LogInfo(log, "foo2: %s\n", "bar2"); + LogWarning(log, "foo3: %s\n", "bar3"); + LogError(log, "foo4: %s\n", "bar4"); + std::ifstream file{tmp_log_path}; + std::vector log_lines; + for (std::string log; std::getline(file, log);) { + log_lines.push_back(log); + } + constexpr auto expected{std::to_array({ + "[validation] Custom #1 foo1: bar1", + "[validation:info] Custom #2 foo2: bar2", + "[validation:warning] Custom #3 foo3: bar3", + "[validation:error] Custom #4 foo4: bar4", + })}; + BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end()); +} + BOOST_AUTO_TEST_CASE(logging_timer) { auto micro_timer = BCLog::Timer("tests", "end_msg"); diff --git a/src/wallet/dump.cpp b/src/wallet/dump.cpp index db2756e0ca8..662a6ddccfb 100644 --- a/src/wallet/dump.cpp +++ b/src/wallet/dump.cpp @@ -114,7 +114,7 @@ bool DumpWallet(const ArgsManager& args, WalletDatabase& db, bilingual_str& erro // deleter here. static void WalletToolReleaseWallet(CWallet* wallet) { - wallet->WalletLogPrintf("Releasing wallet\n"); + LogInfo(wallet->Log(), "Releasing wallet\n"); wallet->Close(); delete wallet; } diff --git a/src/wallet/logging.h b/src/wallet/logging.h new file mode 100644 index 00000000000..a237cf098d8 --- /dev/null +++ b/src/wallet/logging.h @@ -0,0 +1,29 @@ +// Copyright (c) 2024 The Bitcoin Core developers +// Distributed under the MIT software license, see the accompanying +// file COPYING or http://www.opensource.org/licenses/mit-license.php. + +#ifndef BITCOIN_WALLET_LOGGING_H +#define BITCOIN_WALLET_LOGGING_H + +#include + +#include + +namespace wallet { +/** Prepends the wallet name in logging output to ease debugging in multi-wallet use cases */ +class WalletLogSource : public BCLog::Source +{ + std::string m_display_name; + +public: + WalletLogSource(std::string display_name) : BCLog::Source{BCLog::ALL}, m_display_name{std::move(display_name)} {} + + template + std::string Format(util::ConstevalFormatString fmt, const Args&... args) const + { + return m_display_name + " " + BCLog::Source::Format(fmt, args...); + } +}; +} // namespace wallet + +#endif // BITCOIN_WALLET_LOGGING_H diff --git a/src/wallet/receive.cpp b/src/wallet/receive.cpp index c164266f80b..28282dcb8a5 100644 --- a/src/wallet/receive.cpp +++ b/src/wallet/receive.cpp @@ -196,6 +196,7 @@ void CachedTxGetAmounts(const CWallet& wallet, const CWalletTx& wtx, std::list& listSent, CAmount& nFee, const isminefilter& filter, bool include_change) { + const BCLog::Source& log{wallet.Log()}; nFee = 0; listReceived.clear(); listSent.clear(); @@ -230,7 +231,7 @@ void CachedTxGetAmounts(const CWallet& wallet, const CWalletTx& wtx, if (!ExtractDestination(txout.scriptPubKey, address) && !txout.scriptPubKey.IsUnspendable()) { - wallet.WalletLogPrintf("CWalletTx::GetAmounts: Unknown transaction type found, txid %s\n", + LogInfo(log, "CWalletTx::GetAmounts: Unknown transaction type found, txid %s\n", wtx.GetHash().ToString()); address = CNoDestination(); } diff --git a/src/wallet/rpc/backup.cpp b/src/wallet/rpc/backup.cpp index ac23b092d40..80ae7a0bec5 100644 --- a/src/wallet/rpc/backup.cpp +++ b/src/wallet/rpc/backup.cpp @@ -508,6 +508,7 @@ RPCHelpMan importwallet() std::shared_ptr const pwallet = GetWalletForJSONRPCRequest(request); if (!pwallet) return UniValue::VNULL; + const auto& log{pwallet->Log()}; EnsureLegacyScriptPubKeyMan(*pwallet, true); WalletRescanReserver reserver(*pwallet); @@ -594,10 +595,10 @@ RPCHelpMan importwallet() CHECK_NONFATAL(key.VerifyPubKey(pubkey)); CKeyID keyid = pubkey.GetID(); - pwallet->WalletLogPrintf("Importing %s...\n", EncodeDestination(PKHash(keyid))); + LogInfo(log, "Importing %s...\n", EncodeDestination(PKHash(keyid))); if (!pwallet->ImportPrivKeys({{keyid, key}}, time)) { - pwallet->WalletLogPrintf("Error importing key for %s\n", EncodeDestination(PKHash(keyid))); + LogInfo(log, "Error importing key for %s\n", EncodeDestination(PKHash(keyid))); fGood = false; continue; } @@ -612,7 +613,7 @@ RPCHelpMan importwallet() int64_t time = script_pair.second; if (!pwallet->ImportScripts({script}, time)) { - pwallet->WalletLogPrintf("Error importing script %s\n", HexStr(script)); + LogInfo(log, "Error importing script %s\n", HexStr(script)); fGood = false; continue; } diff --git a/src/wallet/scriptpubkeyman.cpp b/src/wallet/scriptpubkeyman.cpp index 04287581f5a..1dfd3d07005 100644 --- a/src/wallet/scriptpubkeyman.cpp +++ b/src/wallet/scriptpubkeyman.cpp @@ -17,6 +17,7 @@ #include #include #include +#include #include #include @@ -354,7 +355,7 @@ std::vector LegacyScriptPubKeyMan::MarkUnusedAddresses(const for (const auto& keyid : GetAffectedKeys(script, *this)) { std::map::const_iterator mi = m_pool_key_to_index.find(keyid); if (mi != m_pool_key_to_index.end()) { - WalletLogPrintf("%s: Detected a used keypool key, mark all keypool keys up to this key as used\n", __func__); + LogInfo(m_log, "%s: Detected a used keypool key, mark all keypool keys up to this key as used\n", __func__); for (const auto& keypool : MarkReserveKeysAsUsed(mi->second)) { // derive all possible destinations as any of them could have been used for (const auto& type : LEGACY_OUTPUT_TYPES) { @@ -364,7 +365,7 @@ std::vector LegacyScriptPubKeyMan::MarkUnusedAddresses(const } if (!TopUp()) { - WalletLogPrintf("%s: Topping up keypool failed (locked wallet)\n", __func__); + LogInfo(m_log, "%s: Topping up keypool failed (locked wallet)\n", __func__); } } @@ -378,12 +379,12 @@ std::vector LegacyScriptPubKeyMan::MarkUnusedAddresses(const if (meta.has_key_origin) { path = meta.key_origin.path; } else if (!ParseHDKeypath(meta.hdKeypath, path)) { - WalletLogPrintf("%s: Adding inactive seed keys failed, invalid hdKeypath: %s\n", + LogInfo(m_log, "%s: Adding inactive seed keys failed, invalid hdKeypath: %s\n", __func__, meta.hdKeypath); } if (path.size() != 3) { - WalletLogPrintf("%s: Adding inactive seed keys failed, invalid path size: %d, has_key_origin: %s\n", + LogInfo(m_log, "%s: Adding inactive seed keys failed, invalid path size: %d, has_key_origin: %s\n", __func__, path.size(), meta.has_key_origin); @@ -392,7 +393,7 @@ std::vector LegacyScriptPubKeyMan::MarkUnusedAddresses(const int64_t index = path[2] & ~BIP32_HARDENED_KEY_LIMIT; if (!TopUpInactiveHDChain(meta.hd_seed_id, index, internal)) { - WalletLogPrintf("%s: Adding inactive seed keys failed\n", __func__); + LogInfo(m_log, "%s: Adding inactive seed keys failed\n", __func__); } } } @@ -484,7 +485,7 @@ bool LegacyScriptPubKeyMan::Upgrade(int prev_version, int new_version, bilingual bool hd_upgrade = false; bool split_upgrade = false; if (IsFeatureSupported(new_version, FEATURE_HD) && !IsHDEnabled()) { - WalletLogPrintf("Upgrading wallet to HD\n"); + LogInfo(m_log, "Upgrading wallet to HD\n"); m_storage.SetMinVersion(FEATURE_HD); // generate a new master key @@ -494,7 +495,7 @@ bool LegacyScriptPubKeyMan::Upgrade(int prev_version, int new_version, bilingual } // Upgrade to HD chain split if necessary if (!IsFeatureSupported(prev_version, FEATURE_HD_SPLIT) && IsFeatureSupported(new_version, FEATURE_HD_SPLIT)) { - WalletLogPrintf("Upgrading wallet to use HD chain split\n"); + LogInfo(m_log, "Upgrading wallet to use HD chain split\n"); m_storage.SetMinVersion(FEATURE_PRE_SPLIT_KEYPOOL); split_upgrade = FEATURE_HD_SPLIT > prev_version; // Upgrade the HDChain @@ -788,7 +789,7 @@ bool LegacyDataSPKM::LoadCScript(const CScript& redeemScript) if (redeemScript.size() > MAX_SCRIPT_ELEMENT_SIZE) { std::string strAddr = EncodeDestination(ScriptHash(redeemScript)); - WalletLogPrintf("%s: Warning: This wallet contains a redeemScript of size %i which exceeds maximum size %i thus can never be redeemed. Do not use address %s.\n", __func__, redeemScript.size(), MAX_SCRIPT_ELEMENT_SIZE, strAddr); + LogInfo(m_log, "%s: Warning: This wallet contains a redeemScript of size %i which exceeds maximum size %i thus can never be redeemed. Do not use address %s.\n", __func__, redeemScript.size(), MAX_SCRIPT_ELEMENT_SIZE, strAddr); return true; } @@ -1296,7 +1297,7 @@ bool LegacyScriptPubKeyMan::NewKeyPool() if (!TopUp()) { return false; } - WalletLogPrintf("LegacyScriptPubKeyMan::NewKeyPool rewrote keypool\n"); + LogInfo(m_log, "LegacyScriptPubKeyMan::NewKeyPool rewrote keypool\n"); } return true; } @@ -1369,9 +1370,9 @@ bool LegacyScriptPubKeyMan::TopUpChain(WalletBatch& batch, CHDChain& chain, unsi } if (missingInternal + missingExternal > 0) { if (chain == m_hd_chain) { - WalletLogPrintf("keypool added %d keys (%d internal), size=%u (%u internal)\n", missingInternal + missingExternal, missingInternal, setInternalKeyPool.size() + setExternalKeyPool.size() + set_pre_split_keypool.size(), setInternalKeyPool.size()); + LogInfo(m_log, "keypool added %d keys (%d internal), size=%u (%u internal)\n", missingInternal + missingExternal, missingInternal, setInternalKeyPool.size() + setExternalKeyPool.size() + set_pre_split_keypool.size(), setInternalKeyPool.size()); } else { - WalletLogPrintf("inactive seed with id %s added %d external keys, %d internal keys\n", HexStr(chain.seed_id), missingExternal, missingInternal); + LogInfo(m_log, "inactive seed with id %s added %d external keys, %d internal keys\n", HexStr(chain.seed_id), missingExternal, missingInternal); } } return true; @@ -1404,7 +1405,7 @@ void LegacyScriptPubKeyMan::KeepDestination(int64_t nIndex, const OutputType& ty assert(have_pk); LearnRelatedScripts(pubkey, type); m_index_to_reserved_key.erase(nIndex); - WalletLogPrintf("keypool keep %d\n", nIndex); + LogInfo(m_log, "keypool keep %d\n", nIndex); } void LegacyScriptPubKeyMan::ReturnDestination(int64_t nIndex, bool fInternal, const CTxDestination&) @@ -1424,7 +1425,7 @@ void LegacyScriptPubKeyMan::ReturnDestination(int64_t nIndex, bool fInternal, co m_index_to_reserved_key.erase(nIndex); NotifyCanGetAddressesChanged(); } - WalletLogPrintf("keypool return %d\n", nIndex); + LogInfo(m_log, "keypool return %d\n", nIndex); } bool LegacyScriptPubKeyMan::GetKeyFromPool(CPubKey& result, const OutputType type) @@ -1490,7 +1491,7 @@ bool LegacyScriptPubKeyMan::ReserveKeyFromKeyPool(int64_t& nIndex, CKeyPool& key assert(m_index_to_reserved_key.count(nIndex) == 0); m_index_to_reserved_key[nIndex] = keypool.vchPubKey.GetID(); m_pool_key_to_index.erase(keypool.vchPubKey.GetID()); - WalletLogPrintf("keypool reserve %d\n", nIndex); + LogInfo(m_log, "keypool reserve %d\n", nIndex); } NotifyCanGetAddressesChanged(); return true; @@ -1535,7 +1536,7 @@ std::vector LegacyScriptPubKeyMan::MarkReserveKeysAsUsed(int64_t keypo } LearnAllRelatedScripts(keypool.vchPubKey); batch.ErasePool(index); - WalletLogPrintf("keypool index %d removed\n", index); + LogInfo(m_log, "keypool index %d removed\n", index); it = setKeyPool->erase(it); result.push_back(std::move(keypool)); } @@ -1607,7 +1608,7 @@ bool LegacyScriptPubKeyMan::ImportScripts(const std::set scripts, int64 for (const auto& entry : scripts) { CScriptID id(entry); if (HaveCScript(id)) { - WalletLogPrintf("Already have script %s, skipping\n", HexStr(entry)); + LogInfo(m_log, "Already have script %s, skipping\n", HexStr(entry)); continue; } if (!AddCScriptWithDB(batch, entry)) { @@ -1635,7 +1636,7 @@ bool LegacyScriptPubKeyMan::ImportPrivKeys(const std::map& privkey assert(key.VerifyPubKey(pubkey)); // Skip if we already have the key if (HaveKey(id)) { - WalletLogPrintf("Already have key with pubkey %s, skipping\n", HexStr(pubkey)); + LogInfo(m_log, "Already have key with pubkey %s, skipping\n", HexStr(pubkey)); continue; } mapKeyMetadata[id].nCreateTime = timestamp; @@ -1663,7 +1664,7 @@ bool LegacyScriptPubKeyMan::ImportPubKeys(const std::vector DescriptorScriptPubKeyMan::MarkUnusedAddresses(co if (IsMine(script)) { int32_t index = m_map_script_pub_keys[script]; if (index >= m_wallet_descriptor.next_index) { - WalletLogPrintf("%s: Detected a used keypool item at index %d, mark all keypool items up to this item as used\n", __func__, index); + LogInfo(m_log, "%s: Detected a used keypool item at index %d, mark all keypool items up to this item as used\n", __func__, index); auto out_keys = std::make_unique(); std::vector scripts_temp; while (index >= m_wallet_descriptor.next_index) { @@ -2340,7 +2341,7 @@ std::vector DescriptorScriptPubKeyMan::MarkUnusedAddresses(co } } if (!TopUp()) { - WalletLogPrintf("%s: Topping up keypool failed (locked wallet)\n", __func__); + LogInfo(m_log, "%s: Topping up keypool failed (locked wallet)\n", __func__); } } diff --git a/src/wallet/scriptpubkeyman.h b/src/wallet/scriptpubkeyman.h index 4dbb2838d71..9a7a1a8c8ed 100644 --- a/src/wallet/scriptpubkeyman.h +++ b/src/wallet/scriptpubkeyman.h @@ -31,8 +31,9 @@ enum class OutputType; namespace wallet { -struct MigrationData; class ScriptPubKeyMan; +class WalletLogSource; +struct MigrationData; // Wallet storage things that ScriptPubKeyMans need in order to be able to store things to the wallet database. // It provides access to things that are part of the entire wallet and not specific to a ScriptPubKeyMan such as @@ -44,6 +45,7 @@ class WalletStorage public: virtual ~WalletStorage() = default; virtual std::string GetDisplayName() const = 0; + virtual const WalletLogSource& Log() const = 0; virtual WalletDatabase& GetDatabase() const = 0; virtual bool IsWalletFlagSet(uint64_t) const = 0; virtual void UnsetBlankWalletFlag(WalletBatch&) = 0; @@ -174,10 +176,11 @@ struct WalletDestination class ScriptPubKeyMan { protected: + const WalletLogSource& m_log; WalletStorage& m_storage; public: - explicit ScriptPubKeyMan(WalletStorage& storage) : m_storage(storage) {} + explicit ScriptPubKeyMan(WalletStorage& storage) : m_log{storage.Log()}, m_storage(storage) {} virtual ~ScriptPubKeyMan() = default; virtual util::Result GetNewDestination(const OutputType type) { return util::Error{Untranslated("Not supported")}; } virtual isminetype IsMine(const CScript& script) const { return ISMINE_NO; } @@ -253,13 +256,6 @@ public: /** Returns a set of all the scriptPubKeys that this ScriptPubKeyMan watches */ virtual std::unordered_set GetScriptPubKeys() const { return {}; }; - /** Prepends the wallet name in logging output to ease debugging in multi-wallet use cases */ - template - void WalletLogPrintf(util::ConstevalFormatString wallet_fmt, const Params&... params) const - { - LogInfo("%s %s", m_storage.GetDisplayName(), tfm::format(wallet_fmt, params...)); - }; - /** Watch-only address added */ boost::signals2::signal NotifyWatchonlyChanged; diff --git a/src/wallet/spend.cpp b/src/wallet/spend.cpp index f45db1c16f3..b9831cb3082 100644 --- a/src/wallet/spend.cpp +++ b/src/wallet/spend.cpp @@ -1014,6 +1014,7 @@ static util::Result CreateTransactionInternal( const CCoinControl& coin_control, bool sign) EXCLUSIVE_LOCKS_REQUIRED(wallet.cs_wallet) { + const auto& log{wallet.Log()}; AssertLockHeld(wallet.cs_wallet); FastRandomContext rng_fast; @@ -1355,8 +1356,8 @@ static util::Result CreateTransactionInternal( // accidental reuse. reservedest.KeepDestination(); - wallet.WalletLogPrintf("Coin Selection: Algorithm:%s, Waste Metric Score:%d\n", GetAlgorithmName(result.GetAlgo()), result.GetWaste()); - wallet.WalletLogPrintf("Fee Calculation: Fee:%d Bytes:%u Tgt:%d (requested %d) Reason:\"%s\" Decay %.5f: Estimation: (%g - %g) %.2f%% %.1f/(%.1f %d mem %.1f out) Fail: (%g - %g) %.2f%% %.1f/(%.1f %d mem %.1f out)\n", + LogInfo(log, "Coin Selection: Algorithm:%s, Waste Metric Score:%d\n", GetAlgorithmName(result.GetAlgo()), result.GetWaste()); + LogInfo(log, "Fee Calculation: Fee:%d Bytes:%u Tgt:%d (requested %d) Reason:\"%s\" Decay %.5f: Estimation: (%g - %g) %.2f%% %.1f/(%.1f %d mem %.1f out) Fail: (%g - %g) %.2f%% %.1f/(%.1f %d mem %.1f out)\n", current_fee, nBytes, feeCalc.returnedTarget, feeCalc.desiredTarget, StringForFeeReason(feeCalc.reason), feeCalc.est.decay, feeCalc.est.pass.start, feeCalc.est.pass.end, (feeCalc.est.pass.totalConfirmed + feeCalc.est.pass.inMempool + feeCalc.est.pass.leftMempool) > 0.0 ? 100 * feeCalc.est.pass.withinTarget / (feeCalc.est.pass.totalConfirmed + feeCalc.est.pass.inMempool + feeCalc.est.pass.leftMempool) : 0.0, @@ -1374,6 +1375,7 @@ util::Result CreateTransaction( const CCoinControl& coin_control, bool sign) { + const auto& log{wallet.Log()}; if (vecSend.empty()) { return util::Error{_("Transaction must have at least one recipient")}; } @@ -1413,7 +1415,7 @@ util::Result CreateTransaction( txr_grouped.has_value() ? txr_grouped->fee : 0, txr_grouped.has_value() && txr_grouped->change_pos.has_value() ? int32_t(*txr_grouped->change_pos) : -1); if (txr_grouped) { - wallet.WalletLogPrintf("Fee non-grouped = %lld, grouped = %lld, using %s\n", + LogInfo(log, "Fee non-grouped = %lld, grouped = %lld, using %s\n", txr_ungrouped.fee, txr_grouped->fee, use_aps ? "grouped" : "non-grouped"); if (use_aps) return txr_grouped; } diff --git a/src/wallet/wallet.cpp b/src/wallet/wallet.cpp index 7abd17d31e9..d263aae62b1 100644 --- a/src/wallet/wallet.cpp +++ b/src/wallet/wallet.cpp @@ -235,7 +235,7 @@ static std::set g_unloading_wallet_set GUARDED_BY(g_wallet_release_ static void FlushAndDeleteWallet(CWallet* wallet) { const std::string name = wallet->GetName(); - wallet->WalletLogPrintf("Releasing wallet %s..\n", name); + LogInfo(wallet->Log(), "Releasing wallet\n"); wallet->Flush(); delete wallet; // Wallet is now released, notify WaitForDeleteWallet, if any. @@ -631,7 +631,7 @@ bool CWallet::ChangeWalletPassphrase(const SecureString& strOldWalletPassphrase, if (pMasterKey.second.nDeriveIterations < 25000) pMasterKey.second.nDeriveIterations = 25000; - WalletLogPrintf("Wallet passphrase changed to an nDeriveIterations of %i\n", pMasterKey.second.nDeriveIterations); + LogInfo(m_log, "Wallet passphrase changed to an nDeriveIterations of %i\n", pMasterKey.second.nDeriveIterations); if (!crypter.SetKeyFromPassphrase(strNewWalletPassphrase, pMasterKey.second.vchSalt, pMasterKey.second.nDeriveIterations, pMasterKey.second.nDerivationMethod)) return false; @@ -664,7 +664,7 @@ void CWallet::SetMinVersion(enum WalletFeature nVersion, WalletBatch* batch_in) LOCK(cs_wallet); if (nWalletVersion >= nVersion) return; - WalletLogPrintf("Setting minversion to %d\n", nVersion); + LogInfo(m_log, "Setting minversion to %d\n", nVersion); nWalletVersion = nVersion; { @@ -835,7 +835,7 @@ bool CWallet::EncryptWallet(const SecureString& strWalletPassphrase) if (kMasterKey.nDeriveIterations < 25000) kMasterKey.nDeriveIterations = 25000; - WalletLogPrintf("Encrypting Wallet with an nDeriveIterations of %i\n", kMasterKey.nDeriveIterations); + LogInfo(m_log, "Encrypting Wallet with an nDeriveIterations of %i\n", kMasterKey.nDeriveIterations); if (!crypter.SetKeyFromPassphrase(strWalletPassphrase, kMasterKey.vchSalt, kMasterKey.nDeriveIterations, kMasterKey.nDerivationMethod)) return false; @@ -1011,7 +1011,7 @@ bool CWallet::MarkReplaced(const uint256& originalHash, const uint256& newHash) bool success = true; if (!batch.WriteTx(wtx)) { - WalletLogPrintf("%s: Updating batch tx %s failed\n", __func__, wtx.GetHash().ToString()); + LogInfo(m_log, "%s: Updating batch tx %s failed\n", __func__, wtx.GetHash().ToString()); success = false; } @@ -1153,7 +1153,7 @@ CWalletTx* CWallet::AddToWallet(CTransactionRef tx, const TxState& state, const } //// debug print - WalletLogPrintf("AddToWallet %s %s%s %s\n", hash.ToString(), (fInsertedNew ? "new" : ""), (fUpdated ? "update" : ""), TxStateString(state)); + LogInfo(m_log, "AddToWallet %s %s%s %s\n", hash.ToString(), (fInsertedNew ? "new" : ""), (fUpdated ? "update" : ""), TxStateString(state)); // Write to disk if (fInsertedNew || fUpdated) @@ -1240,7 +1240,7 @@ bool CWallet::AddToWalletIfInvolvingMe(const CTransactionRef& ptx, const SyncTxS std::pair range = mapTxSpends.equal_range(txin.prevout); while (range.first != range.second) { if (range.first->second != tx.GetHash()) { - WalletLogPrintf("Transaction %s (in block %s) conflicts with wallet transaction %s (both spend %s:%i)\n", tx.GetHash().ToString(), conf->confirmed_block_hash.ToString(), range.first->second.ToString(), range.first->first.hash.ToString(), range.first->first.n); + LogInfo(m_log, "Transaction %s (in block %s) conflicts with wallet transaction %s (both spend %s:%i)\n", tx.GetHash().ToString(), conf->confirmed_block_hash.ToString(), range.first->second.ToString(), range.first->first.hash.ToString(), range.first->first.n); MarkConflicted(conf->confirmed_block_hash, conf->confirmed_block_height, range.first->second); } range.first++; @@ -1852,7 +1852,7 @@ int64_t CWallet::RescanFromTime(int64_t startTime, const WalletRescanReserver& r int start_height = 0; uint256 start_block; bool start = chain().findFirstBlockWithTimeAndHeight(startTime - TIMESTAMP_WINDOW, 0, FoundBlock().hash(start_block).height(start_height)); - WalletLogPrintf("%s: Rescanning last %i blocks\n", __func__, start ? WITH_LOCK(cs_wallet, return GetLastBlockHeight()) - start_height + 1 : 0); + LogInfo(m_log, "%s: Rescanning last %i blocks\n", __func__, start ? WITH_LOCK(cs_wallet, return GetLastBlockHeight()) - start_height + 1 : 0); if (start) { // TODO: this should take into account failure by ScanResult::USER_ABORT @@ -1902,7 +1902,7 @@ CWallet::ScanResult CWallet::ScanForWalletTransactions(const uint256& start_bloc std::unique_ptr fast_rescan_filter; if (!IsLegacy() && chain().hasBlockFilterIndex(BlockFilterType::BASIC)) fast_rescan_filter = std::make_unique(*this); - WalletLogPrintf("Rescan started from block %s... (%s)\n", start_block.ToString(), + LogInfo(m_log, "Rescan started from block %s... (%s)\n", start_block.ToString(), fast_rescan_filter ? "fast variant using block filters" : "slow variant inspecting all blocks"); fAbortRescan = false; @@ -1927,7 +1927,7 @@ CWallet::ScanResult CWallet::ScanForWalletTransactions(const uint256& start_bloc bool next_interval = reserver.now() >= current_time + INTERVAL_TIME; if (next_interval) { current_time = reserver.now(); - WalletLogPrintf("Still rescanning. At block %d. Progress=%f\n", block_height, progress_current); + LogInfo(m_log, "Still rescanning. At block %d. Progress=%f\n", block_height, progress_current); } bool fetch_block{true}; @@ -1979,7 +1979,7 @@ CWallet::ScanResult CWallet::ScanForWalletTransactions(const uint256& start_bloc CBlockLocator loc = m_chain->getActiveChainLocator(block_hash); if (!loc.IsNull()) { - WalletLogPrintf("Saving scan progress %d.\n", block_height); + LogInfo(m_log, "Saving scan progress %d.\n", block_height); WalletBatch batch(GetDatabase()); batch.WriteBestBlock(loc); } @@ -2023,18 +2023,18 @@ CWallet::ScanResult CWallet::ScanForWalletTransactions(const uint256& start_bloc } } if (!max_height) { - WalletLogPrintf("Scanning current mempool transactions.\n"); + LogInfo(m_log, "Scanning current mempool transactions.\n"); WITH_LOCK(cs_wallet, chain().requestMempoolTransactions(*this)); } ShowProgress(strprintf("%s %s", GetDisplayName(), _("Rescanning…")), 100); // hide progress dialog in GUI if (block_height && fAbortRescan) { - WalletLogPrintf("Rescan aborted at block %d. Progress=%f\n", block_height, progress_current); + LogInfo(m_log, "Rescan aborted at block %d. Progress=%f\n", block_height, progress_current); result.status = ScanResult::USER_ABORT; } else if (block_height && chain().shutdownRequested()) { - WalletLogPrintf("Rescan interrupted by shutdown request at block %d. Progress=%f\n", block_height, progress_current); + LogInfo(m_log, "Rescan interrupted by shutdown request at block %d. Progress=%f\n", block_height, progress_current); result.status = ScanResult::USER_ABORT; } else { - WalletLogPrintf("Rescan completed in %15dms\n", Ticks(reserver.now() - start_time)); + LogInfo(m_log, "Rescan completed in %15dms\n", Ticks(reserver.now() - start_time)); } return result; } @@ -2054,7 +2054,7 @@ bool CWallet::SubmitTxMemoryPoolAndRelay(CWalletTx& wtx, std::string& err_string if (GetTxDepthInMainChain(wtx) != 0) return false; // Submit transaction to mempool for relay - WalletLogPrintf("Submitting wtx %s to mempool for relay\n", wtx.GetHash().ToString()); + LogInfo(m_log, "Submitting wtx %s to mempool for relay\n", wtx.GetHash().ToString()); // We must set TxStateInMempool here. Even though it will also be set later by the // entered-mempool callback, if we did not there would be a race where a // user could call sendmoney in a loop and hit spurious out of funds errors @@ -2153,7 +2153,7 @@ void CWallet::ResubmitWalletTransactions(bool relay, bool force) } // cs_wallet if (submitted_tx_count > 0) { - WalletLogPrintf("%s: resubmit %u unconfirmed transactions\n", __func__, submitted_tx_count); + LogInfo(m_log, "%s: resubmit %u unconfirmed transactions\n", __func__, submitted_tx_count); } } @@ -2339,7 +2339,7 @@ OutputType CWallet::TransactionChangeType(const std::optional& chang void CWallet::CommitTransaction(CTransactionRef tx, mapValue_t mapValue, std::vector> orderForm) { LOCK(cs_wallet); - WalletLogPrintf("CommitTransaction:\n%s\n", util::RemoveSuffixView(tx->ToString(), "\n")); + LogInfo(m_log, "CommitTransaction:\n%s\n", util::RemoveSuffixView(tx->ToString(), "\n")); // Add tx to wallet, because if it has change it's also ours, // otherwise just for transaction history. @@ -2372,7 +2372,7 @@ void CWallet::CommitTransaction(CTransactionRef tx, mapValue_t mapValue, std::ve std::string err_string; if (!SubmitTxMemoryPoolAndRelay(*wtx, err_string, true)) { - WalletLogPrintf("CommitTransaction(): Transaction cannot be broadcast immediately, %s\n", err_string); + LogInfo(m_log, "CommitTransaction(): Transaction cannot be broadcast immediately, %s\n", err_string); // TODO: if we expect the failure to be long term or permanent, instead delete wtx from the wallet and return failure. } } @@ -2475,11 +2475,11 @@ bool CWallet::SetAddressBookWithDB(WalletBatch& batch, const CTxDestination& add const std::string& encoded_dest = EncodeDestination(address); if (new_purpose && !batch.WritePurpose(encoded_dest, PurposeToString(*new_purpose))) { - WalletLogPrintf("Error: fail to write address book 'purpose' entry\n"); + LogInfo(m_log, "Error: fail to write address book 'purpose' entry\n"); return false; } if (!batch.WriteName(encoded_dest, strName)) { - WalletLogPrintf("Error: fail to write address book 'name' entry\n"); + LogInfo(m_log, "Error: fail to write address book 'name' entry\n"); return false; } @@ -2512,24 +2512,24 @@ bool CWallet::DelAddressBookWithDB(WalletBatch& batch, const CTxDestination& add // NOTE: This isn't a problem for sending addresses because they don't have any data that needs to be kept. // When adding new address data, it should be considered here whether to retain or delete it. if (IsMine(address)) { - WalletLogPrintf("%s called with IsMine address, NOT SUPPORTED. Please report this bug! %s\n", __func__, CLIENT_BUGREPORT); + LogInfo(m_log, "%s called with IsMine address, NOT SUPPORTED. Please report this bug! %s\n", __func__, CLIENT_BUGREPORT); return false; } // Delete data rows associated with this address if (!batch.EraseAddressData(address)) { - WalletLogPrintf("Error: cannot erase address book entry data\n"); + LogInfo(m_log, "Error: cannot erase address book entry data\n"); return false; } // Delete purpose entry if (!batch.ErasePurpose(dest)) { - WalletLogPrintf("Error: cannot erase address book entry purpose\n"); + LogInfo(m_log, "Error: cannot erase address book entry purpose\n"); return false; } // Delete name entry if (!batch.EraseName(dest)) { - WalletLogPrintf("Error: cannot erase address book entry name\n"); + LogInfo(m_log, "Error: cannot erase address book entry name\n"); return false; } @@ -2903,7 +2903,7 @@ unsigned int CWallet::ComputeTimeSmart(const CWalletTx& wtx, bool rescanning_old nTimeSmart = std::max(latestEntry, std::min(blocktime, latestNow)); } } else { - WalletLogPrintf("%s: found %s in block %s not in index\n", __func__, wtx.GetHash().ToString(), block_hash->ToString()); + LogInfo(m_log, "%s: found %s in block %s not in index\n", __func__, wtx.GetHash().ToString(), block_hash->ToString()); } } return nTimeSmart; @@ -3011,6 +3011,7 @@ std::shared_ptr CWallet::Create(WalletContext& context, const std::stri walletInstance->m_notify_tx_changed_script = args.GetArg("-walletnotify", ""); // Load wallet + const auto& log{walletInstance->Log()}; bool rescan_required = false; DBErrors nLoadWalletRet = walletInstance->LoadWallet(); if (nLoadWalletRet != DBErrors::LOAD_OK) { @@ -3232,7 +3233,7 @@ std::shared_ptr CWallet::Create(WalletContext& context, const std::stri walletInstance->m_spend_zero_conf_change = args.GetBoolArg("-spendzeroconfchange", DEFAULT_SPEND_ZEROCONF_CHANGE); walletInstance->m_signal_rbf = args.GetBoolArg("-walletrbf", DEFAULT_WALLET_RBF); - walletInstance->WalletLogPrintf("Wallet completed loading in %15dms\n", Ticks(SteadyClock::now() - start)); + LogInfo(log, "Wallet completed loading in %15dms\n", Ticks(SteadyClock::now() - start)); // Try to top up keypool. No-op if the wallet is locked. walletInstance->TopUpKeyPool(); @@ -3253,9 +3254,9 @@ std::shared_ptr CWallet::Create(WalletContext& context, const std::stri { LOCK(walletInstance->cs_wallet); walletInstance->SetBroadcastTransactions(args.GetBoolArg("-walletbroadcast", DEFAULT_WALLETBROADCAST)); - walletInstance->WalletLogPrintf("setKeyPool.size() = %u\n", walletInstance->GetKeyPoolSize()); - walletInstance->WalletLogPrintf("mapWallet.size() = %u\n", walletInstance->mapWallet.size()); - walletInstance->WalletLogPrintf("m_address_book.size() = %u\n", walletInstance->m_address_book.size()); + LogInfo(log, "setKeyPool.size() = %u\n", walletInstance->GetKeyPoolSize()); + LogInfo(log, "mapWallet.size() = %u\n", walletInstance->mapWallet.size()); + LogInfo(log, "m_address_book.size() = %u\n", walletInstance->m_address_book.size()); } return walletInstance; @@ -3263,6 +3264,7 @@ std::shared_ptr CWallet::Create(WalletContext& context, const std::stri bool CWallet::AttachChain(const std::shared_ptr& walletInstance, interfaces::Chain& chain, const bool rescan_required, bilingual_str& error, std::vector& warnings) { + const auto& log{walletInstance->Log()}; LOCK(walletInstance->cs_wallet); // allow setting the chain if it hasn't been set already but prevent changing it assert(!walletInstance->m_chain || walletInstance->m_chain == &chain); @@ -3365,7 +3367,7 @@ bool CWallet::AttachChain(const std::shared_ptr& walletInstance, interf } chain.initMessage(_("Rescanning…")); - walletInstance->WalletLogPrintf("Rescanning last %i blocks (from block %i)...\n", *tip_height - rescan_height, rescan_height); + LogInfo(log, "Rescanning last %i blocks (from block %i)...\n", *tip_height - rescan_height, rescan_height); { WalletRescanReserver reserver(*walletInstance); @@ -3397,10 +3399,10 @@ bool CWallet::UpgradeWallet(int version, bilingual_str& error) { int prev_version = GetVersion(); if (version == 0) { - WalletLogPrintf("Performing wallet upgrade to %i\n", FEATURE_LATEST); + LogInfo(m_log, "Performing wallet upgrade to %i\n", FEATURE_LATEST); version = FEATURE_LATEST; } else { - WalletLogPrintf("Allowing wallet upgrade up to %i\n", version); + LogInfo(m_log, "Allowing wallet upgrade up to %i\n", version); } if (version < prev_version) { error = strprintf(_("Cannot downgrade wallet from version %i to version %i. Wallet version unchanged."), prev_version, version); @@ -3868,7 +3870,7 @@ void CWallet::LoadActiveScriptPubKeyMan(uint256 id, OutputType type, bool intern // Legacy wallets have only one ScriptPubKeyManager and it's active for all output and change types. Assert(IsWalletFlagSet(WALLET_FLAG_DESCRIPTORS)); - WalletLogPrintf("Setting spkMan to active: id = %s, type = %s, internal = %s\n", id.ToString(), FormatOutputType(type), internal ? "true" : "false"); + LogInfo(m_log, "Setting spkMan to active: id = %s, type = %s, internal = %s\n", id.ToString(), FormatOutputType(type), internal ? "true" : "false"); auto& spk_mans = internal ? m_internal_spk_managers : m_external_spk_managers; auto& spk_mans_other = internal ? m_external_spk_managers : m_internal_spk_managers; auto spk_man = m_spk_managers.at(id).get(); @@ -3886,7 +3888,7 @@ void CWallet::DeactivateScriptPubKeyMan(uint256 id, OutputType type, bool intern { auto spk_man = GetScriptPubKeyMan(type, internal); if (spk_man != nullptr && spk_man->GetID() == id) { - WalletLogPrintf("Deactivate spkMan: id = %s, type = %s, internal = %s\n", id.ToString(), FormatOutputType(type), internal ? "true" : "false"); + LogInfo(m_log, "Deactivate spkMan: id = %s, type = %s, internal = %s\n", id.ToString(), FormatOutputType(type), internal ? "true" : "false"); WalletBatch batch(GetDatabase()); if (!batch.EraseActiveScriptPubKeyMan(static_cast(type), internal)) { throw std::runtime_error(std::string(__func__) + ": erasing active ScriptPubKeyMan id failed"); @@ -3946,13 +3948,13 @@ ScriptPubKeyMan* CWallet::AddWalletDescriptor(WalletDescriptor& desc, const Flat AssertLockHeld(cs_wallet); if (!IsWalletFlagSet(WALLET_FLAG_DESCRIPTORS)) { - WalletLogPrintf("Cannot add WalletDescriptor to a non-descriptor wallet\n"); + LogInfo(m_log, "Cannot add WalletDescriptor to a non-descriptor wallet\n"); return nullptr; } auto spk_man = GetDescriptorScriptPubKeyMan(desc); if (spk_man) { - WalletLogPrintf("Update existing descriptor: %s\n", desc.descriptor->ToString()); + LogInfo(m_log, "Update existing descriptor: %s\n", desc.descriptor->ToString()); spk_man->UpdateWalletDescriptor(desc); } else { auto new_spk_man = std::unique_ptr(new DescriptorScriptPubKeyMan(*this, desc, m_keypool_size)); @@ -3971,7 +3973,7 @@ ScriptPubKeyMan* CWallet::AddWalletDescriptor(WalletDescriptor& desc, const Flat // Top up key pool, the manager will generate new scriptPubKeys internally if (!spk_man->TopUp()) { - WalletLogPrintf("Could not top up scriptPubKeys\n"); + LogInfo(m_log, "Could not top up scriptPubKeys\n"); return nullptr; } @@ -3980,7 +3982,7 @@ ScriptPubKeyMan* CWallet::AddWalletDescriptor(WalletDescriptor& desc, const Flat if (!desc.descriptor->IsRange()) { auto script_pub_keys = spk_man->GetScriptPubKeys(); if (script_pub_keys.empty()) { - WalletLogPrintf("Could not generate scriptPubKeys (cache is empty)\n"); + LogInfo(m_log, "Could not generate scriptPubKeys (cache is empty)\n"); return nullptr; } @@ -4004,7 +4006,7 @@ bool CWallet::MigrateToSQLite(bilingual_str& error) { AssertLockHeld(cs_wallet); - WalletLogPrintf("Migrating wallet storage database from BerkeleyDB to SQLite.\n"); + LogInfo(m_log, "Migrating wallet storage database from BerkeleyDB to SQLite.\n"); if (m_database->Format() == "sqlite") { error = _("Error: This wallet already uses SQLite"); @@ -4296,6 +4298,7 @@ bool CWallet::CanGrindR() const bool DoMigration(CWallet& wallet, WalletContext& context, bilingual_str& error, MigrationResult& res) EXCLUSIVE_LOCKS_REQUIRED(wallet.cs_wallet) { + const auto& log{wallet.Log()}; AssertLockHeld(wallet.cs_wallet); // Get all of the descriptors from the legacy wallet @@ -4321,7 +4324,7 @@ bool DoMigration(CWallet& wallet, WalletContext& context, bilingual_str& error, options.create_flags |= WALLET_FLAG_KEY_ORIGIN_METADATA; } if (data->watch_descs.size() > 0) { - wallet.WalletLogPrintf("Making a new watchonly wallet containing the watched scripts\n"); + LogInfo(log, "Making a new watchonly wallet containing the watched scripts\n"); DatabaseStatus status; std::vector warnings; @@ -4358,7 +4361,7 @@ bool DoMigration(CWallet& wallet, WalletContext& context, bilingual_str& error, UpdateWalletSetting(*context.chain, wallet_name, /*load_on_startup=*/true, warnings); } if (data->solvable_descs.size() > 0) { - wallet.WalletLogPrintf("Making a new watchonly wallet containing the unwatched solvable scripts\n"); + LogInfo(log, "Making a new watchonly wallet containing the unwatched solvable scripts\n"); DatabaseStatus status; std::vector warnings; @@ -4402,7 +4405,7 @@ bool DoMigration(CWallet& wallet, WalletContext& context, bilingual_str& error, error = util::ErrorString(res_migration); return false; } - wallet.WalletLogPrintf("Wallet migration complete.\n"); + LogInfo(log, "Wallet migration complete.\n"); return true; }); } diff --git a/src/wallet/wallet.h b/src/wallet/wallet.h index c475718eb94..a02380964ca 100644 --- a/src/wallet/wallet.h +++ b/src/wallet/wallet.h @@ -29,6 +29,7 @@ #include #include #include +#include #include #include #include @@ -389,6 +390,9 @@ private: /** Wallet name: relative directory name or "" for default wallet. */ std::string m_name; + /** Custom log source which adds the wallet name to all log messages */ + WalletLogSource m_log; + /** Internal database handle. */ std::unique_ptr m_database; @@ -462,6 +466,7 @@ public: CWallet(interfaces::Chain* chain, const std::string& name, std::unique_ptr database) : m_chain(chain), m_name(name), + m_log{GetDisplayName()}, m_database(std::move(database)) { } @@ -929,13 +934,7 @@ public: std::string wallet_name = GetName().length() == 0 ? "default wallet" : GetName(); return strprintf("[%s]", wallet_name); }; - - /** Prepends the wallet name in logging output to ease debugging in multi-wallet use cases */ - template - void WalletLogPrintf(util::ConstevalFormatString wallet_fmt, const Params&... params) const - { - LogInfo("%s %s", GetDisplayName(), tfm::format(wallet_fmt, params...)); - }; + const WalletLogSource& Log() const override { return m_log; } /** Upgrade the wallet */ bool UpgradeWallet(int version, bilingual_str& error); diff --git a/src/wallet/walletdb.cpp b/src/wallet/walletdb.cpp index c939ebb1fd4..d165210e10f 100644 --- a/src/wallet/walletdb.cpp +++ b/src/wallet/walletdb.cpp @@ -480,11 +480,12 @@ static DBErrors LoadMinVersion(CWallet* pwallet, DatabaseBatch& batch) EXCLUSIVE static DBErrors LoadWalletFlags(CWallet* pwallet, DatabaseBatch& batch) EXCLUSIVE_LOCKS_REQUIRED(pwallet->cs_wallet) { + const auto& log{pwallet->Log()}; AssertLockHeld(pwallet->cs_wallet); uint64_t flags; if (batch.Read(DBKeys::FLAGS, flags)) { if (!pwallet->LoadWalletFlags(flags)) { - pwallet->WalletLogPrintf("Error reading wallet database: Unknown non-tolerable wallet flags found\n"); + LogInfo(log, "Error reading wallet database: Unknown non-tolerable wallet flags found\n"); return DBErrors::TOO_NEW; } } @@ -504,10 +505,11 @@ static LoadResult LoadRecords(CWallet* pwallet, DatabaseBatch& batch, const std: DataStream ssKey; DataStream ssValue{}; + const auto& log{Assert(pwallet)->Log()}; Assume(!prefix.empty()); std::unique_ptr cursor = batch.GetNewPrefixCursor(prefix); if (!cursor) { - pwallet->WalletLogPrintf("Error getting database cursor for '%s' records\n", key); + LogInfo(log, "Error getting database cursor for '%s' records\n", key); result.m_result = DBErrors::CORRUPT; return result; } @@ -517,7 +519,7 @@ static LoadResult LoadRecords(CWallet* pwallet, DatabaseBatch& batch, const std: if (status == DatabaseCursor::Status::DONE) { break; } else if (status == DatabaseCursor::Status::FAIL) { - pwallet->WalletLogPrintf("Error reading next '%s' record for wallet database\n", key); + LogInfo(log, "Error reading next '%s' record for wallet database\n", key); result.m_result = DBErrors::CORRUPT; return result; } @@ -527,7 +529,7 @@ static LoadResult LoadRecords(CWallet* pwallet, DatabaseBatch& batch, const std: std::string error; DBErrors record_res = load_func(pwallet, ssKey, ssValue, error); if (record_res != DBErrors::LOAD_OK) { - pwallet->WalletLogPrintf("%s\n", error); + LogInfo(log, "%s\n", error); } result.m_result = std::max(result.m_result, record_res); ++result.m_records; @@ -544,6 +546,7 @@ static LoadResult LoadRecords(CWallet* pwallet, DatabaseBatch& batch, const std: static DBErrors LoadLegacyWalletRecords(CWallet* pwallet, DatabaseBatch& batch, int last_client) EXCLUSIVE_LOCKS_REQUIRED(pwallet->cs_wallet) { + const auto& log{pwallet->Log()}; AssertLockHeld(pwallet->cs_wallet); DBErrors result = DBErrors::LOAD_OK; @@ -557,13 +560,13 @@ static DBErrors LoadLegacyWalletRecords(CWallet* pwallet, DatabaseBatch& batch, prefix << type; std::unique_ptr cursor = batch.GetNewPrefixCursor(prefix); if (!cursor) { - pwallet->WalletLogPrintf("Error getting database cursor for '%s' records\n", type); + LogInfo(log, "Error getting database cursor for '%s' records\n", type); return DBErrors::CORRUPT; } DatabaseCursor::Status status = cursor->Next(key, value); if (status != DatabaseCursor::Status::DONE) { - pwallet->WalletLogPrintf("Error: Unexpected legacy entry found in descriptor wallet %s. The wallet might have been tampered with or created with malicious intent.\n", pwallet->GetName()); + LogInfo(log, "Error: Unexpected legacy entry found in descriptor wallet %s. The wallet might have been tampered with or created with malicious intent.\n", pwallet->GetName()); return DBErrors::UNEXPECTED_LEGACY_ENTRY; } } @@ -698,7 +701,7 @@ static DBErrors LoadLegacyWalletRecords(CWallet* pwallet, DatabaseBatch& batch, } } } else { - pwallet->WalletLogPrintf("Inactive HD Chains found but no Legacy ScriptPubKeyMan\n"); + LogInfo(log, "Inactive HD Chains found but no Legacy ScriptPubKeyMan\n"); result = DBErrors::CORRUPT; } } @@ -774,7 +777,7 @@ static DBErrors LoadLegacyWalletRecords(CWallet* pwallet, DatabaseBatch& batch, if (result <= DBErrors::NONCRITICAL_ERROR) { // Only do logging and time first key update if there were no critical errors - pwallet->WalletLogPrintf("Legacy Wallet Keys: %u plaintext, %u encrypted, %u w/ metadata, %u total.\n", + LogInfo(log, "Legacy Wallet Keys: %u plaintext, %u encrypted, %u w/ metadata, %u total.\n", key_res.m_records, ckey_res.m_records, keymeta_res.m_records, key_res.m_records + ckey_res.m_records); // nTimeFirstKey is only reliable if all keys have metadata @@ -800,6 +803,7 @@ static DataStream PrefixStream(const Args&... args) static DBErrors LoadDescriptorWalletRecords(CWallet* pwallet, DatabaseBatch& batch, int last_client) EXCLUSIVE_LOCKS_REQUIRED(pwallet->cs_wallet) { + const auto& log{pwallet->Log()}; AssertLockHeld(pwallet->cs_wallet); // Load descriptor record @@ -962,7 +966,7 @@ static DBErrors LoadDescriptorWalletRecords(CWallet* pwallet, DatabaseBatch& bat if (desc_res.m_result <= DBErrors::NONCRITICAL_ERROR) { // Only log if there are no critical errors - pwallet->WalletLogPrintf("Descriptors: %u, Descriptor Keys: %u plaintext, %u encrypted, %u total.\n", + LogInfo(log, "Descriptors: %u, Descriptor Keys: %u plaintext, %u encrypted, %u total.\n", desc_res.m_records, num_keys, num_ckeys, num_keys + num_ckeys); } @@ -971,6 +975,7 @@ static DBErrors LoadDescriptorWalletRecords(CWallet* pwallet, DatabaseBatch& bat static DBErrors LoadAddressBookRecords(CWallet* pwallet, DatabaseBatch& batch) EXCLUSIVE_LOCKS_REQUIRED(pwallet->cs_wallet) { + const auto& log{pwallet->Log()}; AssertLockHeld(pwallet->cs_wallet); DBErrors result = DBErrors::LOAD_OK; @@ -988,14 +993,14 @@ static DBErrors LoadAddressBookRecords(CWallet* pwallet, DatabaseBatch& batch) E // Load purpose record LoadResult purpose_res = LoadRecords(pwallet, batch, DBKeys::PURPOSE, - [] (CWallet* pwallet, DataStream& key, DataStream& value, std::string& err) EXCLUSIVE_LOCKS_REQUIRED(pwallet->cs_wallet) { + [&] (CWallet* pwallet, DataStream& key, DataStream& value, std::string& err) EXCLUSIVE_LOCKS_REQUIRED(pwallet->cs_wallet) { std::string strAddress; key >> strAddress; std::string purpose_str; value >> purpose_str; std::optional purpose{PurposeFromString(purpose_str)}; if (!purpose) { - pwallet->WalletLogPrintf("Warning: nonstandard purpose string '%s' for address '%s'\n", purpose_str, strAddress); + LogInfo(log, "Warning: nonstandard purpose string '%s' for address '%s'\n", purpose_str, strAddress); } pwallet->m_address_book[DecodeDestination(strAddress)].purpose = purpose; return DBErrors::LOAD_OK; @@ -1032,13 +1037,14 @@ static DBErrors LoadAddressBookRecords(CWallet* pwallet, DatabaseBatch& batch) E static DBErrors LoadTxRecords(CWallet* pwallet, DatabaseBatch& batch, std::vector& upgraded_txs, bool& any_unordered) EXCLUSIVE_LOCKS_REQUIRED(pwallet->cs_wallet) { + const auto& log{pwallet->Log()}; AssertLockHeld(pwallet->cs_wallet); DBErrors result = DBErrors::LOAD_OK; // Load tx record any_unordered = false; LoadResult tx_res = LoadRecords(pwallet, batch, DBKeys::TX, - [&any_unordered, &upgraded_txs] (CWallet* pwallet, DataStream& key, DataStream& value, std::string& err) EXCLUSIVE_LOCKS_REQUIRED(pwallet->cs_wallet) { + [&any_unordered, &upgraded_txs, &log] (CWallet* pwallet, DataStream& key, DataStream& value, std::string& err) EXCLUSIVE_LOCKS_REQUIRED(pwallet->cs_wallet) { DBErrors result = DBErrors::LOAD_OK; uint256 hash; key >> hash; @@ -1064,13 +1070,13 @@ static DBErrors LoadTxRecords(CWallet* pwallet, DatabaseBatch& batch, std::vecto uint8_t fUnused; std::string unused_string; value >> fTmp >> fUnused >> unused_string; - pwallet->WalletLogPrintf("LoadWallet() upgrading tx ver=%d %d %s\n", + LogInfo(log, "LoadWallet() upgrading tx ver=%d %d %s\n", wtx.fTimeReceivedIsTxTime, fTmp, hash.ToString()); wtx.fTimeReceivedIsTxTime = fTmp; } else { - pwallet->WalletLogPrintf("LoadWallet() repairing tx ver=%d %s\n", wtx.fTimeReceivedIsTxTime, hash.ToString()); + LogInfo(log, "LoadWallet() repairing tx ver=%d %s\n", wtx.fTimeReceivedIsTxTime, hash.ToString()); wtx.fTimeReceivedIsTxTime = 0; } upgraded_txs.push_back(hash); @@ -1176,12 +1182,13 @@ DBErrors WalletBatch::LoadWallet(CWallet* pwallet) bool any_unordered = false; std::vector upgraded_txs; + const auto& log{pwallet->Log()}; LOCK(pwallet->cs_wallet); // Last client version to open this wallet int last_client = CLIENT_VERSION; bool has_last_client = m_batch->Read(DBKeys::VERSION, last_client); - pwallet->WalletLogPrintf("Wallet file version = %d, last client version = %d\n", pwallet->GetVersion(), last_client); + LogInfo(log, "Wallet file version = %d, last client version = %d\n", pwallet->GetVersion(), last_client); try { if ((result = LoadMinVersion(pwallet, *m_batch)) != DBErrors::LOAD_OK) return result; @@ -1192,7 +1199,7 @@ DBErrors WalletBatch::LoadWallet(CWallet* pwallet) #ifndef ENABLE_EXTERNAL_SIGNER if (pwallet->IsWalletFlagSet(WALLET_FLAG_EXTERNAL_SIGNER)) { - pwallet->WalletLogPrintf("Error: External signer wallet being loaded without external signer support compiled\n"); + LogInfo(log, "Error: External signer wallet being loaded without external signer support compiled\n"); return DBErrors::EXTERNAL_SIGNER_SUPPORT_REQUIRED; } #endif @@ -1259,10 +1266,10 @@ DBErrors WalletBatch::LoadWallet(CWallet* pwallet) // Although wallets without private keys should not have *ckey records, we should double check that. // Removing the mkey records is only safe if there are no *ckey records. if (pwallet->IsWalletFlagSet(WALLET_FLAG_DISABLE_PRIVATE_KEYS) && pwallet->HasEncryptionKeys() && !pwallet->HaveCryptedKeys()) { - pwallet->WalletLogPrintf("Detected extraneous encryption keys in this wallet without private keys. Removing extraneous encryption keys.\n"); + LogInfo(log, "Detected extraneous encryption keys in this wallet without private keys. Removing extraneous encryption keys.\n"); for (const auto& [id, _] : pwallet->mapMasterKeys) { if (!EraseMasterKey(id)) { - pwallet->WalletLogPrintf("Error: Unable to remove extraneous encryption key '%u'. Wallet corrupt.\n", id); + LogInfo(log, "Error: Unable to remove extraneous encryption key '%u'. Wallet corrupt.\n", id); return DBErrors::CORRUPT; } } diff --git a/src/wallet/wallettool.cpp b/src/wallet/wallettool.cpp index f7e7b74fc36..52fff34f9a2 100644 --- a/src/wallet/wallettool.cpp +++ b/src/wallet/wallettool.cpp @@ -22,7 +22,7 @@ namespace WalletTool { // deleter here. static void WalletToolReleaseWallet(CWallet* wallet) { - wallet->WalletLogPrintf("Releasing wallet\n"); + LogInfo(wallet->Log(), "Releasing wallet\n"); wallet->Close(); delete wallet; } diff --git a/test/lint/run-lint-format-strings.py b/test/lint/run-lint-format-strings.py new file mode 100755 index 00000000000..74bd5592fbc --- /dev/null +++ b/test/lint/run-lint-format-strings.py @@ -0,0 +1,297 @@ +#!/usr/bin/env python3 +# +# Copyright (c) 2018-2022 The Bitcoin Core developers +# Distributed under the MIT software license, see the accompanying +# file COPYING or http://www.opensource.org/licenses/mit-license.php. +# +# Lint format strings: This program checks that the number of arguments passed +# to a variadic format string function matches the number of format specifiers +# in the format string. + +import argparse +import re +import sys + +FALSE_POSITIVES = [ + ("src/clientversion.cpp", "strprintf(_(COPYRIGHT_HOLDERS), COPYRIGHT_HOLDERS_SUBSTITUTION)"), + ("src/test/logging_tests.cpp", 'tfm::format("Custom #%d %s", ++m_counter, tfm::format(fmt, args...))'), + ("src/test/translation_tests.cpp", "strprintf(format, arg)"), +] + + +def parse_function_calls(function_name, source_code): + """Return an array with all calls to function function_name in string source_code. + Preprocessor directives and C++ style comments ("//") in source_code are removed. + + >>> len(parse_function_calls("foo", "foo();bar();foo();bar();")) + 2 + >>> parse_function_calls("foo", "foo(1);bar(1);foo(2);bar(2);")[0].startswith("foo(1);") + True + >>> parse_function_calls("foo", "foo(1);bar(1);foo(2);bar(2);")[1].startswith("foo(2);") + True + >>> len(parse_function_calls("foo", "foo();bar();// foo();bar();")) + 1 + >>> len(parse_function_calls("foo", "#define FOO foo();")) + 0 + """ + assert type(function_name) is str and type(source_code) is str and function_name + lines = [re.sub("// .*", " ", line).strip() + for line in source_code.split("\n") + if not line.strip().startswith("#")] + return re.findall(r"[^a-zA-Z_](?=({}\(.*).*)".format(function_name), " " + " ".join(lines)) + + +def normalize(s): + """Return a normalized version of string s with newlines, tabs and C style comments ("/* ... */") + replaced with spaces. Multiple spaces are replaced with a single space. + + >>> normalize(" /* nothing */ foo\tfoo /* bar */ foo ") + 'foo foo foo' + """ + assert type(s) is str + s = s.replace("\n", " ") + s = s.replace("\t", " ") + s = re.sub(r"/\*.*?\*/", " ", s) + s = re.sub(" {2,}", " ", s) + return s.strip() + + +ESCAPE_MAP = { + r"\n": "[escaped-newline]", + r"\t": "[escaped-tab]", + r'\"': "[escaped-quote]", +} + + +def escape(s): + """Return the escaped version of string s with "\\\"", "\\n" and "\\t" escaped as + "[escaped-backslash]", "[escaped-newline]" and "[escaped-tab]". + + >>> unescape(escape("foo")) == "foo" + True + >>> escape(r'foo \\t foo \\n foo \\\\ foo \\ foo \\"bar\\"') + 'foo [escaped-tab] foo [escaped-newline] foo \\\\\\\\ foo \\\\ foo [escaped-quote]bar[escaped-quote]' + """ + assert type(s) is str + for raw_value, escaped_value in ESCAPE_MAP.items(): + s = s.replace(raw_value, escaped_value) + return s + + +def unescape(s): + """Return the unescaped version of escaped string s. + Reverses the replacements made in function escape(s). + + >>> unescape(escape("bar")) + 'bar' + >>> unescape("foo [escaped-tab] foo [escaped-newline] foo \\\\\\\\ foo \\\\ foo [escaped-quote]bar[escaped-quote]") + 'foo \\\\t foo \\\\n foo \\\\\\\\ foo \\\\ foo \\\\"bar\\\\"' + """ + assert type(s) is str + for raw_value, escaped_value in ESCAPE_MAP.items(): + s = s.replace(escaped_value, raw_value) + return s + + +def parse_function_call_and_arguments(function_name, function_call): + """Split string function_call into an array of strings consisting of: + * the string function_call followed by "(" + * the function call argument #1 + * ... + * the function call argument #n + * a trailing ");" + + The strings returned are in escaped form. See escape(...). + + >>> parse_function_call_and_arguments("foo", 'foo("%s", "foo");') + ['foo(', '"%s",', ' "foo"', ')'] + >>> parse_function_call_and_arguments("foo", 'foo("%s", "foo");') + ['foo(', '"%s",', ' "foo"', ')'] + >>> parse_function_call_and_arguments("foo", 'foo("%s %s", "foo", "bar");') + ['foo(', '"%s %s",', ' "foo",', ' "bar"', ')'] + >>> parse_function_call_and_arguments("fooprintf", 'fooprintf("%050d", i);') + ['fooprintf(', '"%050d",', ' i', ')'] + >>> parse_function_call_and_arguments("foo", 'foo(bar(foobar(barfoo("foo"))), foobar); barfoo') + ['foo(', 'bar(foobar(barfoo("foo"))),', ' foobar', ')'] + >>> parse_function_call_and_arguments("foo", "foo()") + ['foo(', '', ')'] + >>> parse_function_call_and_arguments("foo", "foo(123)") + ['foo(', '123', ')'] + >>> parse_function_call_and_arguments("foo", 'foo("foo")') + ['foo(', '"foo"', ')'] + >>> parse_function_call_and_arguments("strprintf", 'strprintf("%s (%d)", std::wstring_convert,wchar_t>().to_bytes(buf), err);') + ['strprintf(', '"%s (%d)",', ' std::wstring_convert,wchar_t>().to_bytes(buf),', ' err', ')'] + >>> parse_function_call_and_arguments("strprintf", 'strprintf("%s (%d)", foo().to_bytes(buf), err);') + ['strprintf(', '"%s (%d)",', ' foo().to_bytes(buf),', ' err', ')'] + >>> parse_function_call_and_arguments("strprintf", 'strprintf("%s (%d)", foo().to_bytes(buf), err);') + ['strprintf(', '"%s (%d)",', ' foo().to_bytes(buf),', ' err', ')'] + >>> parse_function_call_and_arguments("strprintf", 'strprintf("%s (%d)", foo << 1, err);') + ['strprintf(', '"%s (%d)",', ' foo << 1,', ' err', ')'] + >>> parse_function_call_and_arguments("strprintf", 'strprintf("%s (%d)", foo() >> 1, err);') + ['strprintf(', '"%s (%d)",', ' foo() >> 1,', ' err', ')'] + >>> parse_function_call_and_arguments("strprintf", 'strprintf("%s (%d)", foo < 1 ? bar : foobar, err);') + ['strprintf(', '"%s (%d)",', ' foo < 1 ? bar : foobar,', ' err', ')'] + >>> parse_function_call_and_arguments("strprintf", 'strprintf("%s (%d)", foo < 1, err);') + ['strprintf(', '"%s (%d)",', ' foo < 1,', ' err', ')'] + >>> parse_function_call_and_arguments("strprintf", 'strprintf("%s (%d)", foo > 1 ? bar : foobar, err);') + ['strprintf(', '"%s (%d)",', ' foo > 1 ? bar : foobar,', ' err', ')'] + >>> parse_function_call_and_arguments("strprintf", 'strprintf("%s (%d)", foo > 1, err);') + ['strprintf(', '"%s (%d)",', ' foo > 1,', ' err', ')'] + >>> parse_function_call_and_arguments("strprintf", 'strprintf("%s (%d)", foo <= 1, err);') + ['strprintf(', '"%s (%d)",', ' foo <= 1,', ' err', ')'] + >>> parse_function_call_and_arguments("strprintf", 'strprintf("%s (%d)", foo <= bar<1, 2>(1, 2), err);') + ['strprintf(', '"%s (%d)",', ' foo <= bar<1, 2>(1, 2),', ' err', ')'] + >>> parse_function_call_and_arguments("strprintf", 'strprintf("%s (%d)", foo>foo<1,2>(1,2)?bar:foobar,err)'); + ['strprintf(', '"%s (%d)",', ' foo>foo<1,2>(1,2)?bar:foobar,', 'err', ')'] + >>> parse_function_call_and_arguments("strprintf", 'strprintf("%s (%d)", foo>foo<1,2>(1,2),err)'); + ['strprintf(', '"%s (%d)",', ' foo>foo<1,2>(1,2),', 'err', ')'] + """ + assert type(function_name) is str and type(function_call) is str and function_name + remaining = normalize(escape(function_call)) + expected_function_call = "{}(".format(function_name) + assert remaining.startswith(expected_function_call) + parts = [expected_function_call] + remaining = remaining[len(expected_function_call):] + open_parentheses = 1 + open_template_arguments = 0 + in_string = False + parts.append("") + for i, char in enumerate(remaining): + parts.append(parts.pop() + char) + if char == "\"": + in_string = not in_string + continue + if in_string: + continue + if char == "(": + open_parentheses += 1 + continue + if char == ")": + open_parentheses -= 1 + if open_parentheses > 1: + continue + if open_parentheses == 0: + parts.append(parts.pop()[:-1]) + parts.append(char) + break + prev_char = remaining[i - 1] if i - 1 >= 0 else None + next_char = remaining[i + 1] if i + 1 <= len(remaining) - 1 else None + if char == "<" and next_char not in [" ", "<", "="] and prev_char not in [" ", "<"]: + open_template_arguments += 1 + continue + if char == ">" and next_char not in [" ", ">", "="] and prev_char not in [" ", ">"] and open_template_arguments > 0: + open_template_arguments -= 1 + if open_template_arguments > 0: + continue + if char == ",": + parts.append("") + return parts + + +def parse_string_content(argument): + """Return the text within quotes in string argument. + + >>> parse_string_content('1 "foo %d bar" 2') + 'foo %d bar' + >>> parse_string_content('1 foobar 2') + '' + >>> parse_string_content('1 "bar" 2') + 'bar' + >>> parse_string_content('1 "foo" 2 "bar" 3') + 'foobar' + >>> parse_string_content('1 "foo" 2 " " "bar" 3') + 'foo bar' + >>> parse_string_content('""') + '' + >>> parse_string_content('') + '' + >>> parse_string_content('1 2 3') + '' + """ + assert type(argument) is str + string_content = "" + in_string = False + for char in normalize(escape(argument)): + if char == "\"": + in_string = not in_string + elif in_string: + string_content += char + return string_content + + +def count_format_specifiers(format_string): + """Return the number of format specifiers in string format_string. + + >>> count_format_specifiers("foo bar foo") + 0 + >>> count_format_specifiers("foo %d bar foo") + 1 + >>> count_format_specifiers("foo %d bar %i foo") + 2 + >>> count_format_specifiers("foo %d bar %i foo %% foo") + 2 + >>> count_format_specifiers("foo %d bar %i foo %% foo %d foo") + 3 + >>> count_format_specifiers("foo %d bar %i foo %% foo %*d foo") + 4 + >>> count_format_specifiers("foo %5$d") + 5 + >>> count_format_specifiers("foo %5$*7$d") + 7 + """ + assert type(format_string) is str + format_string = format_string.replace('%%', 'X') + n = max_pos = 0 + for m in re.finditer("%(.*?)[aAcdeEfFgGinopsuxX]", format_string, re.DOTALL): + # Increase the max position if the argument has a position number like + # "5$", otherwise increment the argument count. + pos_num, = re.match(r"(?:(^\d+)\$)?", m.group(1)).groups() + if pos_num is not None: + max_pos = max(max_pos, int(pos_num)) + else: + n += 1 + + # Increase the max position if there is a "*" width argument with a + # position like "*7$", and increment the argument count if there is a + # "*" width argument with no position. + star, star_pos_num = re.match(r"(?:.*?(\*(?:(\d+)\$)?)|)", m.group(1)).groups() + if star_pos_num is not None: + max_pos = max(max_pos, int(star_pos_num)) + elif star is not None: + n += 1 + return max(n, max_pos) + + +def main(): + parser = argparse.ArgumentParser(description="This program checks that the number of arguments passed " + "to a variadic format string function matches the number of format " + "specifiers in the format string.") + parser.add_argument("--skip-arguments", type=int, help="number of arguments before the format string " + "argument (e.g. 1 in the case of fprintf)", default=0) + parser.add_argument("function_name", help="function name (e.g. fprintf)", default=None) + parser.add_argument("file", nargs="*", help="C++ source code file (e.g. foo.cpp)") + args = parser.parse_args() + exit_code = 0 + for filename in args.file: + with open(filename, "r", encoding="utf-8") as f: + for function_call_str in parse_function_calls(args.function_name, f.read()): + parts = parse_function_call_and_arguments(args.function_name, function_call_str) + relevant_function_call_str = unescape("".join(parts))[:512] + if (f.name, relevant_function_call_str) in FALSE_POSITIVES: + continue + if len(parts) < 3 + args.skip_arguments: + exit_code = 1 + print("{}: Could not parse function call string \"{}(...)\": {}".format(f.name, args.function_name, relevant_function_call_str)) + continue + argument_count = len(parts) - 3 - args.skip_arguments + format_str = parse_string_content(parts[1 + args.skip_arguments]) + format_specifier_count = count_format_specifiers(format_str) + if format_specifier_count != argument_count: + exit_code = 1 + print("{}: Expected {} argument(s) after format string but found {} argument(s): {}".format(f.name, format_specifier_count, argument_count, relevant_function_call_str)) + continue + sys.exit(exit_code) + + +if __name__ == "__main__": + main() From b7e37883da1357694a9dd762e9b29b16e9e2db4e Mon Sep 17 00:00:00 2001 From: Ryan Ofsky Date: Wed, 26 Jun 2024 21:55:34 -0400 Subject: [PATCH 4/5] wallet, logging: Switch LogInfo to LogWarning/LogError Switch to LogWarning / LogError in obvious places where wallet code is clearly outputting warnings and errors. Suggested by hodlinator in https://github.com/bitcoin/bitcoin/pull/30343#discussion_r1655406670 https://github.com/bitcoin/bitcoin/pull/30343#discussion_r1655407301 https://github.com/bitcoin/bitcoin/pull/30343#discussion_r1655436010 --- src/wallet/rpc/backup.cpp | 4 ++-- src/wallet/scriptpubkeyman.cpp | 2 +- src/wallet/wallet.cpp | 10 +++++----- src/wallet/walletdb.cpp | 16 ++++++++-------- 4 files changed, 16 insertions(+), 16 deletions(-) diff --git a/src/wallet/rpc/backup.cpp b/src/wallet/rpc/backup.cpp index 80ae7a0bec5..cbb65ef703b 100644 --- a/src/wallet/rpc/backup.cpp +++ b/src/wallet/rpc/backup.cpp @@ -598,7 +598,7 @@ RPCHelpMan importwallet() LogInfo(log, "Importing %s...\n", EncodeDestination(PKHash(keyid))); if (!pwallet->ImportPrivKeys({{keyid, key}}, time)) { - LogInfo(log, "Error importing key for %s\n", EncodeDestination(PKHash(keyid))); + LogError(log, "Error importing key for %s\n", EncodeDestination(PKHash(keyid))); fGood = false; continue; } @@ -613,7 +613,7 @@ RPCHelpMan importwallet() int64_t time = script_pair.second; if (!pwallet->ImportScripts({script}, time)) { - LogInfo(log, "Error importing script %s\n", HexStr(script)); + LogError(log, "Error importing script %s\n", HexStr(script)); fGood = false; continue; } diff --git a/src/wallet/scriptpubkeyman.cpp b/src/wallet/scriptpubkeyman.cpp index 1dfd3d07005..75d054b244f 100644 --- a/src/wallet/scriptpubkeyman.cpp +++ b/src/wallet/scriptpubkeyman.cpp @@ -789,7 +789,7 @@ bool LegacyDataSPKM::LoadCScript(const CScript& redeemScript) if (redeemScript.size() > MAX_SCRIPT_ELEMENT_SIZE) { std::string strAddr = EncodeDestination(ScriptHash(redeemScript)); - LogInfo(m_log, "%s: Warning: This wallet contains a redeemScript of size %i which exceeds maximum size %i thus can never be redeemed. Do not use address %s.\n", __func__, redeemScript.size(), MAX_SCRIPT_ELEMENT_SIZE, strAddr); + LogWarning(m_log, "%s: Warning: This wallet contains a redeemScript of size %i which exceeds maximum size %i thus can never be redeemed. Do not use address %s.\n", __func__, redeemScript.size(), MAX_SCRIPT_ELEMENT_SIZE, strAddr); return true; } diff --git a/src/wallet/wallet.cpp b/src/wallet/wallet.cpp index d263aae62b1..0b43b2089dd 100644 --- a/src/wallet/wallet.cpp +++ b/src/wallet/wallet.cpp @@ -2475,11 +2475,11 @@ bool CWallet::SetAddressBookWithDB(WalletBatch& batch, const CTxDestination& add const std::string& encoded_dest = EncodeDestination(address); if (new_purpose && !batch.WritePurpose(encoded_dest, PurposeToString(*new_purpose))) { - LogInfo(m_log, "Error: fail to write address book 'purpose' entry\n"); + LogError(m_log, "Error: fail to write address book 'purpose' entry\n"); return false; } if (!batch.WriteName(encoded_dest, strName)) { - LogInfo(m_log, "Error: fail to write address book 'name' entry\n"); + LogError(m_log, "Error: fail to write address book 'name' entry\n"); return false; } @@ -2517,19 +2517,19 @@ bool CWallet::DelAddressBookWithDB(WalletBatch& batch, const CTxDestination& add } // Delete data rows associated with this address if (!batch.EraseAddressData(address)) { - LogInfo(m_log, "Error: cannot erase address book entry data\n"); + LogError(m_log, "Error: cannot erase address book entry data\n"); return false; } // Delete purpose entry if (!batch.ErasePurpose(dest)) { - LogInfo(m_log, "Error: cannot erase address book entry purpose\n"); + LogError(m_log, "Error: cannot erase address book entry purpose\n"); return false; } // Delete name entry if (!batch.EraseName(dest)) { - LogInfo(m_log, "Error: cannot erase address book entry name\n"); + LogError(m_log, "Error: cannot erase address book entry name\n"); return false; } diff --git a/src/wallet/walletdb.cpp b/src/wallet/walletdb.cpp index d165210e10f..9673d7bfbfd 100644 --- a/src/wallet/walletdb.cpp +++ b/src/wallet/walletdb.cpp @@ -485,7 +485,7 @@ static DBErrors LoadWalletFlags(CWallet* pwallet, DatabaseBatch& batch) EXCLUSIV uint64_t flags; if (batch.Read(DBKeys::FLAGS, flags)) { if (!pwallet->LoadWalletFlags(flags)) { - LogInfo(log, "Error reading wallet database: Unknown non-tolerable wallet flags found\n"); + LogError(log, "Error reading wallet database: Unknown non-tolerable wallet flags found\n"); return DBErrors::TOO_NEW; } } @@ -509,7 +509,7 @@ static LoadResult LoadRecords(CWallet* pwallet, DatabaseBatch& batch, const std: Assume(!prefix.empty()); std::unique_ptr cursor = batch.GetNewPrefixCursor(prefix); if (!cursor) { - LogInfo(log, "Error getting database cursor for '%s' records\n", key); + LogError(log, "Error getting database cursor for '%s' records\n", key); result.m_result = DBErrors::CORRUPT; return result; } @@ -519,7 +519,7 @@ static LoadResult LoadRecords(CWallet* pwallet, DatabaseBatch& batch, const std: if (status == DatabaseCursor::Status::DONE) { break; } else if (status == DatabaseCursor::Status::FAIL) { - LogInfo(log, "Error reading next '%s' record for wallet database\n", key); + LogError(log, "Error reading next '%s' record for wallet database\n", key); result.m_result = DBErrors::CORRUPT; return result; } @@ -529,7 +529,7 @@ static LoadResult LoadRecords(CWallet* pwallet, DatabaseBatch& batch, const std: std::string error; DBErrors record_res = load_func(pwallet, ssKey, ssValue, error); if (record_res != DBErrors::LOAD_OK) { - LogInfo(log, "%s\n", error); + LogError(log, "%s\n", error); } result.m_result = std::max(result.m_result, record_res); ++result.m_records; @@ -560,13 +560,13 @@ static DBErrors LoadLegacyWalletRecords(CWallet* pwallet, DatabaseBatch& batch, prefix << type; std::unique_ptr cursor = batch.GetNewPrefixCursor(prefix); if (!cursor) { - LogInfo(log, "Error getting database cursor for '%s' records\n", type); + LogError(log, "Error getting database cursor for '%s' records\n", type); return DBErrors::CORRUPT; } DatabaseCursor::Status status = cursor->Next(key, value); if (status != DatabaseCursor::Status::DONE) { - LogInfo(log, "Error: Unexpected legacy entry found in descriptor wallet %s. The wallet might have been tampered with or created with malicious intent.\n", pwallet->GetName()); + LogError(log, "Error: Unexpected legacy entry found in descriptor wallet %s. The wallet might have been tampered with or created with malicious intent.\n", pwallet->GetName()); return DBErrors::UNEXPECTED_LEGACY_ENTRY; } } @@ -1000,7 +1000,7 @@ static DBErrors LoadAddressBookRecords(CWallet* pwallet, DatabaseBatch& batch) E value >> purpose_str; std::optional purpose{PurposeFromString(purpose_str)}; if (!purpose) { - LogInfo(log, "Warning: nonstandard purpose string '%s' for address '%s'\n", purpose_str, strAddress); + LogWarning(log, "Warning: nonstandard purpose string '%s' for address '%s'\n", purpose_str, strAddress); } pwallet->m_address_book[DecodeDestination(strAddress)].purpose = purpose; return DBErrors::LOAD_OK; @@ -1199,7 +1199,7 @@ DBErrors WalletBatch::LoadWallet(CWallet* pwallet) #ifndef ENABLE_EXTERNAL_SIGNER if (pwallet->IsWalletFlagSet(WALLET_FLAG_EXTERNAL_SIGNER)) { - LogInfo(log, "Error: External signer wallet being loaded without external signer support compiled\n"); + LogError(log, "Error: External signer wallet being loaded without external signer support compiled\n"); return DBErrors::EXTERNAL_SIGNER_SUPPORT_REQUIRED; } #endif From e8c6095c75dead138e79a18146ce865e7fe6529a Mon Sep 17 00:00:00 2001 From: Ryan Ofsky Date: Wed, 26 Jun 2024 22:18:07 -0400 Subject: [PATCH 5/5] wallet, logging: Switch LogInfo to LogError in AddWalletDescriptor Seems like all of these cases are treated as errors, so it makes sense to use the corresponding log level. Change suggested by hodlinator in https://github.com/bitcoin/bitcoin/pull/30343#discussion_r1655434943 --- src/wallet/wallet.cpp | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/wallet/wallet.cpp b/src/wallet/wallet.cpp index 0b43b2089dd..99403f49bb8 100644 --- a/src/wallet/wallet.cpp +++ b/src/wallet/wallet.cpp @@ -3948,13 +3948,13 @@ ScriptPubKeyMan* CWallet::AddWalletDescriptor(WalletDescriptor& desc, const Flat AssertLockHeld(cs_wallet); if (!IsWalletFlagSet(WALLET_FLAG_DESCRIPTORS)) { - LogInfo(m_log, "Cannot add WalletDescriptor to a non-descriptor wallet\n"); + LogError(m_log, "Cannot add WalletDescriptor to a non-descriptor wallet\n"); return nullptr; } auto spk_man = GetDescriptorScriptPubKeyMan(desc); if (spk_man) { - LogInfo(m_log, "Update existing descriptor: %s\n", desc.descriptor->ToString()); + LogError(m_log, "Update existing descriptor: %s\n", desc.descriptor->ToString()); spk_man->UpdateWalletDescriptor(desc); } else { auto new_spk_man = std::unique_ptr(new DescriptorScriptPubKeyMan(*this, desc, m_keypool_size)); @@ -3973,7 +3973,7 @@ ScriptPubKeyMan* CWallet::AddWalletDescriptor(WalletDescriptor& desc, const Flat // Top up key pool, the manager will generate new scriptPubKeys internally if (!spk_man->TopUp()) { - LogInfo(m_log, "Could not top up scriptPubKeys\n"); + LogError(m_log, "Could not top up scriptPubKeys\n"); return nullptr; } @@ -3982,7 +3982,7 @@ ScriptPubKeyMan* CWallet::AddWalletDescriptor(WalletDescriptor& desc, const Flat if (!desc.descriptor->IsRange()) { auto script_pub_keys = spk_man->GetScriptPubKeys(); if (script_pub_keys.empty()) { - LogInfo(m_log, "Could not generate scriptPubKeys (cache is empty)\n"); + LogError(m_log, "Could not generate scriptPubKeys (cache is empty)\n"); return nullptr; }