mirrors/bitcoin
1
0
Fork 0
mirror of https://github.com/bitcoin/bitcoin.git synced 2025-03-13 11:35:20 +01:00
Code Issues Projects Releases Wiki Activity

Merge e8c6095c75 into a50af6e4c4

Browse source
This commit is contained in:
Ryan Ofsky 2025-03-13 02:03:54 +01:00 • committed by GitHub
commit 93f1ab145f
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
14 changed files with 721 additions and 142 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

154
src/logging.h
View file

@ -6,6 +6,7 @@
#ifndef BITCOIN_LOGGING_H
#define BITCOIN_LOGGING_H
#include <attributes.h>
#include <threadsafety.h>
#include <tinyformat.h>
#include <util/fs.h>
@ -21,6 +22,12 @@
#include <unordered_map>
#include <vector>
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 <typename... Args>
std::string Format(util::ConstevalFormatString<sizeof...(Args)> 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 <typename Source>
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 <typename... Args>
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<sizeof...(Args)> 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 <typename Source>
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 <typename LogFn, typename Source, typename SourceArg, typename... Args>
requires (!std::is_convertible_v<SourceArg, std::string_view>)
void _LogFormat(LogFn&& log, Source&& source, SourceArg&&, util::ConstevalFormatString<sizeof...(Args)> 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 <typename LogFn, typename Source, typename... Args>
void _LogFormat(LogFn&& log, Source&& source, util::ConstevalFormatString<sizeof...(Args)> 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, ...) \
//! Internal helper to check level and log. Avoids evaluating arguments if not logging.
#define _LogPrint(level, ...) \
do { \
if (LogAcceptCategory((category), (level))) { \
LogPrintLevel_(category, level, __VA_ARGS__); \
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

155
src/test/logging_tests.cpp
View file

@ -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<std::string> 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<std::string> 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 <typename... Args>
std::string Format(util::ConstevalFormatString<sizeof...(Args)> 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<std::string> 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<std::chrono::microseconds>("tests", "end_msg");

2
src/wallet/dump.cpp
View file

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

29
src/wallet/logging.h Normal file
View file

@ -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 <logging.h>
#include <string>
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 <typename... Args>
std::string Format(util::ConstevalFormatString<sizeof...(Args)> fmt, const Args&... args) const
{
return m_display_name + " " + BCLog::Source::Format(fmt, args...);
}
};
} // namespace wallet
#endif // BITCOIN_WALLET_LOGGING_H

3
src/wallet/receive.cpp
View file

@ -196,6 +196,7 @@ void CachedTxGetAmounts(const CWallet& wallet, const CWalletTx& wtx,
std::list<COutputEntry>& 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();
}

7
src/wallet/rpc/backup.cpp
View file

@ -508,6 +508,7 @@ RPCHelpMan importwallet()
std::shared_ptr<CWallet> 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;
}

41
src/wallet/scriptpubkeyman.cpp
View file

@ -17,6 +17,7 @@
#include <util/string.h>
#include <util/time.h>
#include <util/translation.h>
#include <wallet/logging.h>
#include <wallet/scriptpubkeyman.h>
#include <optional>
@ -354,7 +355,7 @@ std::vector<WalletDestination> LegacyScriptPubKeyMan::MarkUnusedAddresses(const
for (const auto& keyid : GetAffectedKeys(script, *this)) {
std::map<CKeyID, int64_t>::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<WalletDestination> 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<WalletDestination> 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<WalletDestination> 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<CKeyPool> 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<CScript> 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<CKeyID, CKey>& 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<std::pair<CKeyID, bo
CPubKey temp;
if (GetPubKey(id, temp)) {
// Already have pubkey, skipping
WalletLogPrintf("Already have pubkey %s, skipping\n", HexStr(temp));
LogInfo(m_log, "Already have pubkey %s, skipping\n", HexStr(temp));
continue;
}
if (!AddWatchOnlyWithDB(batch, GetScriptForRawPubKey(pubkey), timestamp)) {
@ -2326,7 +2327,7 @@ std::vector<WalletDestination> 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<FlatSigningProvider>();
std::vector<CScript> scripts_temp;
while (index >= m_wallet_descriptor.next_index) {
@ -2340,7 +2341,7 @@ std::vector<WalletDestination> 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__);
}
}

14
src/wallet/scriptpubkeyman.h
View file

@ -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<CTxDestination> 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<CScript, SaltedSipHasher> GetScriptPubKeys() const { return {}; };
/** Prepends the wallet name in logging output to ease debugging in multi-wallet use cases */
template <typename... Params>
void WalletLogPrintf(util::ConstevalFormatString<sizeof...(Params)> wallet_fmt, const Params&... params) const
{
LogInfo("%s %s", m_storage.GetDisplayName(), tfm::format(wallet_fmt, params...));
};
/** Watch-only address added */
boost::signals2::signal<void (bool fHaveWatchOnly)> NotifyWatchonlyChanged;

8
src/wallet/spend.cpp
View file

@ -1014,6 +1014,7 @@ static util::Result<CreatedTransactionResult> 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<CreatedTransactionResult> 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<CreatedTransactionResult> 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<CreatedTransactionResult> 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;
}

89
src/wallet/wallet.cpp
View file

@ -235,7 +235,7 @@ static std::set<std::string> 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<TxSpends::const_iterator, TxSpends::const_iterator> 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<FastWalletRescanFilter> fast_rescan_filter;
if (!IsLegacy() && chain().hasBlockFilterIndex(BlockFilterType::BASIC)) fast_rescan_filter = std::make_unique<FastWalletRescanFilter>(*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<std::chrono::milliseconds>(reserver.now() - start_time));
LogInfo(m_log, "Rescan completed in %15dms\n", Ticks<std::chrono::milliseconds>(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<OutputType>& chang
void CWallet::CommitTransaction(CTransactionRef tx, mapValue_t mapValue, std::vector<std::pair<std::string, std::string>> 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> 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> 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<std::chrono::milliseconds>(SteadyClock::now() - start));
LogInfo(log, "Wallet completed loading in %15dms\n", Ticks<std::chrono::milliseconds>(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> 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> CWallet::Create(WalletContext& context, const std::stri
bool CWallet::AttachChain(const std::shared_ptr<CWallet>& walletInstance, interfaces::Chain& chain, const bool rescan_required, bilingual_str& error, std::vector<bilingual_str>& 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<CWallet>& 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<uint8_t>(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<DescriptorScriptPubKeyMan>(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<bilingual_str> 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<bilingual_str> 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;
});
}

13
src/wallet/wallet.h
View file

@ -29,6 +29,7 @@
#include <util/ui_change_type.h>
#include <wallet/crypter.h>
#include <wallet/db.h>
#include <wallet/logging.h>
#include <wallet/scriptpubkeyman.h>
#include <wallet/transaction.h>
#include <wallet/types.h>
@ -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<WalletDatabase> m_database;
@ -462,6 +466,7 @@ public:
CWallet(interfaces::Chain* chain, const std::string& name, std::unique_ptr<WalletDatabase> 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 <typename... Params>
void WalletLogPrintf(util::ConstevalFormatString<sizeof...(Params)> 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);

43
src/wallet/walletdb.cpp
View file

@ -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<DatabaseCursor> 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<DatabaseCursor> 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<AddressPurpose> 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<uint256>& 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<uint256> 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;
}
}

2
src/wallet/wallettool.cpp
View file

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

297
test/lint/run-lint-format-strings.py Executable file
View file

@ -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<std::codecvt_utf8_utf16<wchar_t>,wchar_t>().to_bytes(buf), err);')
['strprintf(', '"%s (%d)",', ' std::wstring_convert<std::codecvt_utf8_utf16<wchar_t>,wchar_t>().to_bytes(buf),', ' err', ')']
>>> parse_function_call_and_arguments("strprintf", 'strprintf("%s (%d)", foo<wchar_t>().to_bytes(buf), err);')
['strprintf(', '"%s (%d)",', ' foo<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 << 1, err);')
['strprintf(', '"%s (%d)",', ' foo << 1,', ' err', ')']
>>> parse_function_call_and_arguments("strprintf", 'strprintf("%s (%d)", foo<bar>() >> 1, err);')
['strprintf(', '"%s (%d)",', ' foo<bar>() >> 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()