After multiple wallets became supported, wallet-related log messages became ambiguous as to which wallet they were being emitted by.
This pull request adds a CWallet::WalletLogPrintf function to be used when logging wallet-specific events. This function prepends the wallet’s name to the log message and forwards it to LogPrintf
fixes #11317
Thank you @dooglus for bringing attention to this in #11317 and opening #11320.
This is #11320 with the following changes:
rpcdump.cpp’s importwallet functionIn #11320 @promag and @luke-jr suggested approaches to reducing the repetition of "[%s]" GetName() boilerplate. @jimpo, in the context of #12954, what are your thoughts?
This is outside of the scope of this PR and may be controversial, but I do think we would benefit from automated testing of log messages. This could either be done by checking the debug.log of nodes in existing tests, or as a separate test script.
Open questions:
There are logging calls in two WalletBatch methods where it’s not immediately apparent to me how to get the wallet’s name: WalletBatch::FindWalletTx and WalletBatch::RecoverKeysOnlyFilter. Is there something I’m not seeing? If the only solution is refactoring then I’ll leave them alone in this PR.
CWallet’s m_name defaults to an empty string, so we end up with lots of empty square brackets in the log messages. Should we have a default wallet name?
I luke-jr’s suggestion of CWallet::LogPrintf. The main benefit is not even reducing boilerplate, it’s to reduce the amount of refactoring required if someone decides that there is a better way of presenting the wallet info on the log line. Also, I think it’ll be more obvious that way when people add new log statements in wallet files as compared to noticing the extra log argument and having to realize that it’s a standard.
With regards to #12954, I don’t see any issues. Won’t even be a git conflict, I don’t think.
This is an example of a case where structured logging might be useful (being able to tag log statments with key-value pairs in a not-ad-hoc way). I know the Bitcoin ABC team is thinking about this.
CWallet::LogPrintf instead.
553@@ -554,7 +554,7 @@ UniValue importwallet(const JSONRPCRequest& request)
554
555 // Use uiInterface.ShowProgress instead of pwallet.ShowProgress because pwallet.ShowProgress has a cancel button tied to AbortRescan which
556 // we don't want for this progress bar shoing the import progress. uiInterface.ShowProgress does not have a cancel button.
557- uiInterface.ShowProgress(_("Importing..."), 0, false); // show progress dialog in GUI
558+ uiInterface.ShowProgress(strprintf(_("[%s] Importing..."), pwallet->GetName()), 0, false); // show progress dialog in GUI
_("Importing...") and do the string manipulation afterward
CWallet::LogPrintf would be useful.
Unfortunately CWallet::LogPrintf doesn’t play nice with the LogPrintf macro so I created a CWallet::WalletLogPrintf function, using a variadic template to forward args to the macro. Creative solutions to avoid the double namespacing are welcome
https://github.com/PierreRochard/bitcoin/commit/45343a251306000501654d1dc015dd88501e271d → https://github.com/PierreRochard/bitcoin/commit/77152113c9939d4ba7b6e8f22ec4d07703d1891b force push diff here
1197@@ -1198,6 +1198,11 @@ class CWallet final : public CCryptoKeyStore, public CValidationInterface
1198
1199 /** Whether a given output is spendable by this wallet */
1200 bool OutputEligibleForSpending(const COutput& output, const CoinEligibilityFilter& eligibility_filter) const;
1201+
1202+ template<typename... Params>
1203+ void WalletLogPrintf(std::string fmt, Params... parameters) const {
1204+ LogPrintf(("[" + GetName() + "] " + fmt).c_str(), parameters...);
This results in empty brackets at the start of the log if the default is being used, eg:
02018-06-21T14:12:32.172374Z init message: [] Loading wallet...
12018-06-21T14:12:32.174733Z [] nFileVersion = 169900
22018-06-21T14:12:32.174776Z [] Keys: 0 plaintext, 0 encrypted, 0 w/ metadata, 0 total. Unknown wallet records: 0
32018-06-21T14:12:32.175201Z [] Performing wallet upgrade to 169900
Any thoughts about only adding the prefix if the wallet name is non-empty?
default wallet there instead, so that it’s explicit.
4055@@ -4057,7 +4056,7 @@ std::shared_ptr<CWallet> CWallet::CreateWalletFromFile(const std::string& name,
4056 }
4057 }
4058
4059- uiInterface.InitMessage(_("Loading wallet..."));
4060+ uiInterface.InitMessage(strprintf(_("[%s] Loading wallet..."), walletFile));
nit: This looks a bit weird in the logs compared to the other messages:
02018-06-21T14:12:32.894599Z init message: [w1] Loading wallet...
(ie the [<wallet_name>] prefix is not at the start of the log). Maybe just change to:
0 uiInterface.InitMessage(strprintf(_("Loading wallet %s ..."), walletFile));
4105 else
4106- LogPrintf("Allowing wallet upgrade up to %i\n", nMaxVersion);
4107+ walletInstance->WalletLogPrintf("Allowing wallet upgrade up to %i\n", nMaxVersion);
4108 if (nMaxVersion < walletInstance->GetVersion())
4109 {
4110 InitError(_("Cannot downgrade wallet"));
There are a couple of logs lower down that you’ve missed:
LogPrintf("Upgrading wallet to HD\n"); (L4131) LogPrintf("Upgrading wallet to use HD chain split\n"); (L4143)
194@@ -195,7 +195,7 @@ Result CreateTransaction(const CWallet* wallet, const uint256& txid, const CCoin
195 // If the output would become dust, discard it (converting the dust to fee)
196 poutput->nValue -= nDelta;
197 if (poutput->nValue <= GetDustThreshold(*poutput, GetDiscardRate(*wallet, ::feeEstimator))) {
198- LogPrint(BCLog::RPC, "Bumping fee and discarding dust output\n");
199+ LogPrint(BCLog::RPC, "[%s] Bumping fee and discarding dust output\n", wallet->GetName());
WalletLogPrintf. I don’t think this needs to be in the RPC category.
Tested ACK 77152113c9939d4ba7b6e8f22ec4d07703d1891b.
A few nits inline.
The log format conflicts slightly with #13168, which prefixes the log with [<thread_name>]. It’ll make the logic a little more tricky for log parsing tools to deal with the possibility of one or two bracketed prefixes, but it’s probably not that big a deal.
I agree with @jimpo that structured logging could be a good way to go in future. That’d obviously be a separate PR.
Thanks for the review John, I’ve addressed your nits, and I agree re: structured logging
https://github.com/PierreRochard/bitcoin/commit/77152113c9939d4ba7b6e8f22ec4d07703d1891b → https://github.com/PierreRochard/bitcoin/commit/553b1a7f815ec39dc30c65f22aa2f9f6cae41c25 force push diff here
1197@@ -1198,6 +1198,11 @@ class CWallet final : public CCryptoKeyStore, public CValidationInterface
1198
1199 /** Whether a given output is spendable by this wallet */
1200 bool OutputEligibleForSpending(const COutput& output, const CoinEligibilityFilter& eligibility_filter) const;
1201+
1202+ template<typename... Params>
WalletLogPrintf as a non-member function; or (ii) implementing a CWallet::GetDebugString(...)-like method that returns the debug string, which can be passed to the LogPrintf macro.
CWallet::DisplayName is called for - the concept is used in e.g. https://github.com/bitcoin/bitcoin/blob/88a15ebc8d317a6fd4851adb344ff944d497284c/src/qt/bitcoingui.cpp#L509
LogPrintf and not have to think about the context - the macro or some other magic would automatically add the wallet name if it’s available in that context. Ultimately I think that kind of improvement would be part of a wider (structured) logging refactoring.
@Empact agree, I’ve factored out a CWallet::GetDisplayName and added calls to it in relevant parts
Thanks @PierreRochard, yeah you’re absolutely right about that.
I was thinking about something more straightforward.
The gist of my suggestion was to just extract (or remove) WalletLogPrintf from the wallet for the advantages that this may provide.
When extracted the signature of WalletLogPrintf could look something like this:
0template<typename... Params>
1void WalletLogPrintf(const CWallet* wallet, const std::string& fmt, const Params&... parameters) {
2 ...
3};
and would be used like:
0WalletLogPrintf(pWallet, "#reckless");
Imo WalletLogPrintf meets the recommendation: “A function that can be simply, elegantly, and efficiently implemented as a freestanding function (that is, as a nonmember function) should be implemented outside the class. ” from Stroustrup.
Anyway, this comment is just to clarify what I meant. It is not critical and it’s probably best to ignore it :)
559@@ -560,7 +560,7 @@ UniValue importwallet(const JSONRPCRequest& request)
560
561 // Use uiInterface.ShowProgress instead of pwallet.ShowProgress because pwallet.ShowProgress has a cancel button tied to AbortRescan which
562 // we don't want for this progress bar showing the import progress. uiInterface.ShowProgress does not have a cancel button.
563- uiInterface.ShowProgress(_("Importing..."), 0, false); // show progress dialog in GUI
564+ uiInterface.ShowProgress(strprintf(_("[%s] Importing..."), pwallet->GetName()), 0, false); // show progress dialog in GUI
GetDisplayName here.
1667@@ -1669,8 +1668,8 @@ void CWalletTx::GetAmounts(std::list<COutputEntry>& listReceived,
1668
1669 if (!ExtractDestination(txout.scriptPubKey, address) && !txout.scriptPubKey.IsUnspendable())
1670 {
1671- LogPrintf("CWalletTx::GetAmounts: Unknown transaction type found, txid %s\n",
1672- this->GetHash().ToString());
1673+ pwallet->WalletLogPrintf("CWalletTx::GetAmounts: Unknown transaction type found, txid %s\n",
1674+ this->GetHash().ToString());
1184@@ -1185,6 +1185,15 @@ class CWallet final : public CCryptoKeyStore, public CValidationInterface
1185
1186 /** Whether a given output is spendable by this wallet */
1187 bool OutputEligibleForSpending(const COutput& output, const CoinEligibilityFilter& eligibility_filter) const;
1188+
Thank you for the reviews and comments @empact, @251Labs, and @achow101.
https://github.com/PierreRochard/bitcoin/commit/553b1a7f815ec39dc30c65f22aa2f9f6cae41c25 → https://github.com/PierreRochard/bitcoin/commit/fb71743dbbd188ec3796f6e489f0a73e328bb7cb force push diff here
git diff $pre_force_push_commit $new_commit locally (after fetching the objects)
1213+ };
1214+
1215+ /** Prepends the wallet name in logging output to ease debugging in multi-wallet use cases */
1216+ template<typename... Params>
1217+ void WalletLogPrintf(std::string fmt, Params... parameters) const {
1218+ LogPrintf((GetDisplayName() + " " + fmt).c_str(), parameters...);
sanitize inputs please :)
0/home/ubuntu/bitcoin
1→ bcli createwallet "a%ib"
2{
3 "name": "a%ib",
4 "warning": ""
5}
6/home/ubuntu/bitcoin
7→ tail -30 ../.bitcoin/regtest/debug.log
82018-07-27T14:36:38Z tor: Not connected to Tor control port 127.0.0.1:9051, trying to reconnect
92018-07-27T14:36:40Z tor: Error connecting to Tor control socket
102018-07-27T14:36:40Z tor: Not connected to Tor control port 127.0.0.1:9051, trying to reconnect
112018-07-27T14:36:44Z tor: Error connecting to Tor control socket
122018-07-27T14:36:44Z tor: Not connected to Tor control port 127.0.0.1:9051, trying to reconnect
132018-07-27T14:36:45Z Received a POST request for / from 127.0.0.1:59554
142018-07-27T14:36:45Z ThreadRPCServer method=createwallet user=bitcoinrpc
152018-07-27T14:36:45Z Using BerkeleyDB version Berkeley DB 4.8.30: (April 9, 2010)
162018-07-27T14:36:45Z Using wallet wallet.dat
172018-07-27T14:36:45Z BerkeleyEnvironment::Open: LogDir=/home/ubuntu/.bitcoin/regtest/wallets/a%ib/database ErrorFile=/home/ubuntu/.bitcoin/regtest/wallets/a%ib/db.log
182018-07-27T14:36:45Z init message: Loading wallet a%ib...
192018-07-27T14:36:45Z Error "tinyformat: Too many conversion specifiers in format string" while formatting log message: [a%ib] nFileVersion = %d
202018-07-27T14:36:45Z Error "tinyformat: Too many conversion specifiers in format string" while formatting log message: [a%ib] Keys: %u plaintext, %u encrypted, %u w/ metadata, %u total. Unknown wallet records: %u
212018-07-27T14:36:45Z Error "tinyformat: Too many conversion specifiers in format string" while formatting log message: [a%ib] Performing wallet upgrade to %i
222018-07-27T14:36:46Z Error "tinyformat: Too many conversion specifiers in format string" while formatting log message: [a%ib] keypool added %d keys (%d internal), size=%u (%u internal)
232018-07-27T14:36:46Z Error "tinyformat: Too many conversion specifiers in format string" while formatting log message: [a%ib] wallet %15dms
242018-07-27T14:36:46Z Error "tinyformat: Too many conversion specifiers in format string" while formatting log message: [a%ib] setKeyPool.size() = %u
252018-07-27T14:36:46Z Error "tinyformat: Too many conversion specifiers in format string" while formatting log message: [a%ib] mapWallet.size() = %u
262018-07-27T14:36:46Z Error "tinyformat: Too many conversion specifiers in format string" while formatting log message: [a%ib] mapAddressBook.size() = %u
272018-07-27T14:36:49Z Flushing wallet.dat
282018-07-27T14:36:49Z Flushed wallet.dat 4ms
292018-07-27T14:36:49Z tor: Error connecting to Tor control socket
302018-07-27T14:36:49Z tor: Not connected to Tor control port 127.0.0.1:9051, trying to reconnect
312018-07-27T14:36:56Z tor: Error connecting to Tor control socket
322018-07-27T14:36:56Z tor: Not connected to Tor control port 127.0.0.1:9051, trying to reconnect
332018-07-27T14:37:08Z tor: Error connecting to Tor control socket
342018-07-27T14:37:08Z tor: Not connected to Tor control port 127.0.0.1:9051, trying to reconnect
352018-07-27T14:37:25Z tor: Error connecting to Tor control socket
362018-07-27T14:37:25Z tor: Not connected to Tor control port 127.0.0.1:9051, trying to reconnect
372018-07-27T14:37:36Z Adding fixed seed nodes as DNS doesn't seem to be available.
Rather than adding an escape fn another option is to just
0LogPrintf("%s " + fmt, GetDisplayName(), parameters...)
Thank you for catching that @jnewbery!
https://github.com/PierreRochard/bitcoin/commit/dd67b82bbeba948823224d9ab6c2aa2d24730e21 → https://github.com/PierreRochard/bitcoin/commit/237a0f87c9841c46276b04b1f947db9fcd10221d force push diff here
There might be some more instances after you rebase on master:
0git grep LogPrint ./src/wallet ':(exclude)src/wallet/db.cpp' ':(exclude)src/wallet/init.cpp' ':(exclude)src/wallet/walletdb.cpp' ':(exclude)src/wallet/crypter.cpp' |grep -v WalletLogPrintf| grep -v GetDisplayName
559@@ -560,7 +560,7 @@ UniValue importwallet(const JSONRPCRequest& request)
560
561 // Use uiInterface.ShowProgress instead of pwallet.ShowProgress because pwallet.ShowProgress has a cancel button tied to AbortRescan which
562 // we don't want for this progress bar showing the import progress. uiInterface.ShowProgress does not have a cancel button.
563- uiInterface.ShowProgress(_("Importing..."), 0, false); // show progress dialog in GUI
564+ uiInterface.ShowProgress(strprintf(_("%s Importing..."), pwallet->GetDisplayName()), 0, false); // show progress dialog in GUI
strprintf("%s " + _("Imp...
1731+ if (pindex) WalletLogPrintf("Rescan started from block %d...\n", pindex->nHeight);
1732
1733 {
1734 fAbortRescan = false;
1735- ShowProgress(_("Rescanning..."), 0); // show rescan progress in GUI as dialog or on splashscreen, if -rescan on startup
1736+ ShowProgress(strprintf(_("%s Rescanning..."), GetDisplayName()), 0); // show rescan progress in GUI as dialog or on splashscreen, if -rescan on startup
After multiple wallets became supported, wallet-related log messages
became ambiguous as to which wallet they were being emitted by.
fixes #11317
@MarcoFalke Thanks, I found one more after rebasing on to master.
I avoided changing the InitError related strings as many already have the wallet name. I could fix the one you pointed out which does not - but that would change the translation string and prevent this from being merged into 0.17.0. I’ll create a follow up PR to standardize the formatting of the InitError messages.
Force push diff here
4004@@ -4006,7 +4005,7 @@ std::shared_ptr<CWallet> CWallet::CreateWalletFromFile(const std::string& name,
4005 }
4006 }
4007
4008- uiInterface.InitMessage(_("Loading wallet..."));
4009+ uiInterface.InitMessage(strprintf(_("Loading wallet %s..."), walletFile));
InitMessage, InitWarning, and InitError messages
4216@@ -4218,7 +4217,7 @@ std::shared_ptr<CWallet> CWallet::CreateWalletFromFile(const std::string& name,
4217 walletInstance->m_spend_zero_conf_change = gArgs.GetBoolArg("-spendzeroconfchange", DEFAULT_SPEND_ZEROCONF_CHANGE);
4218 walletInstance->m_signal_rbf = gArgs.GetBoolArg("-walletrbf", DEFAULT_WALLET_RBF);
4219
4220- LogPrintf(" wallet %15dms\n", GetTimeMillis() - nStart);
4221+ walletInstance->WalletLogPrintf("wallet %15dms\n", GetTimeMillis() - nStart);
Since the format of this log is being changed in this PR, does it make sense to make the log a bit clearer. Something like:
0"wallet completed loading in %15dms\n", GetTimeMillis() - nStart
4269@@ -4271,7 +4270,7 @@ std::shared_ptr<CWallet> CWallet::CreateWalletFromFile(const std::string& name,
4270 }
4271 walletInstance->ScanForWalletTransactions(pindexRescan, nullptr, reserver, true);
4272 }
4273- LogPrintf(" rescan %15dms\n", GetTimeMillis() - nStart);
4274+ walletInstance->WalletLogPrintf("rescan %15dms\n", GetTimeMillis() - nStart);
Again, this log could be made clearer as part of this or a follow-up PR:
0"rescan completed in %15dms\n", GetTimeMillis() - nStart