diff --git a/src/logging.h b/src/logging.h index fdc12c79b32..26d1becbc7e 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,37 @@ 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 { + static constexpr bool log_source{true}; + 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 +278,94 @@ 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 +//! 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 {}; } + +//! 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. This could be +//! simplified to `#define _FirstArg(arg, ...) arg` if not for a preprocessor +//! bug in Visual C++. +#define _FirstArgImpl(arg, ...) arg +#define _FirstArg(args) _FirstArgImpl args -// 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 provides the flexibility to add extra information +//! and custom formatting to log messages, or to divert log messages to a local +//! logger instead of the global logging instance, without needing to change +//! existing log statements. +#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..1fcd0850344 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -76,6 +76,161 @@ 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()); +} + +struct CustomLogSource { + static constexpr bool log_source{true}; + BCLog::LogFlags category{BCLog::VALIDATION}; + BCLog::Logger& logger{LogInstance()}; + int& m_counter; + + CustomLogSource(int& counter) : m_counter{counter} {} + + template + 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..cbb65ef703b 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))); + LogError(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)); + 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 04287581f5a..75d054b244f 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); + 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; } @@ -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 7b26cf15bd3..9b69a68a42d 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..99403f49bb8 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"); + LogError(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"); + LogError(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"); + LogError(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"); + LogError(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"); + LogError(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"); + LogError(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()); + 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)); @@ -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"); + LogError(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"); + LogError(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..9673d7bfbfd 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"); + LogError(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); + LogError(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); + LogError(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); + LogError(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); + 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) { - 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()); + 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; } } @@ -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); + 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; @@ -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"); + LogError(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()