wallet, logging: Replace WalletLogPrintf() with LogInfo()

ryanofsky commented at 5:57 pm on June 26, 2024: contributor

Make new logging macros LogDebug(), LogTrace(), LogInfo(), LogWarning(), and LogError() compatible with wallet code and drop custom WalletLogPrintf() function. The new logging macros introduced in #28318 weren’t previously useful in wallet code because wallet code prefixes most log messages with the wallet names to be be able to distinguish log output from multiple wallets. Fix this by introducing a new WalletLogSource class inheriting from BCLog::Source which can include the wallet name in log messages.

This is based on #29256. The non-base commits are:

DrahtBot commented at 5:57 pm on June 26, 2024: contributor

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Code Coverage & Benchmarks

For details see: https://corecheck.dev/bitcoin/bitcoin/pulls/30343.

Reviews

See the guideline for information on the review process. A summary of reviews will appear here.

Conflicts

Reviewers, this pull request conflicts with the following ones:

#31423 (wallet: migration, don’t create spendable wallet from a watch-only legacy wallet by furszy)
#31398 (wallet: refactor: various master key encryption cleanups by theStack)
#31296 (wallet: Translate [default wallet] string in progress messages by ryanofsky)
#31061 (refactor: Check translatable format strings at compile-time by maflcko)
#30221 (wallet: Ensure best block matches wallet scan state by achow101)
#29641 (scripted-diff: Use LogInfo over LogPrintf [WIP, NOMERGE, DRAFT] by maflcko)
#29415 (Broadcast own transactions only via short-lived Tor or I2P connections by vasild)
#29136 (wallet: addhdkey RPC to add just keys to wallets via new void(KEY) descriptor by achow101)
#28710 (Remove the legacy wallet and BDB dependency by achow101)
#28333 (wallet: Construct ScriptPubKeyMans with all data rather than loaded progressively by achow101)
#25722 (refactor: Use util::Result class for wallet loading by ryanofsky)

If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first.

in src/wallet/wallet.h:448 in 5b30f17c22 outdated

444@@ -444,6 +445,8 @@ class CWallet final : public WalletStorage, public interfaces::Chain::Notificati
445      */
446     mutable RecursiveMutex cs_wallet;
447 
448+    WalletLogSource m_log;

hodlinator commented at 7:16 pm on June 26, 2024:

Why not rename GetLogSource() -> Log() here and in WalletStorage and keep m_log private? I tried and it compiles as of 5b30f17c22ade44d301aed5051a398fa38251ef7.

ryanofsky commented at 3:46 am on June 27, 2024:

re: #30343 (review)

Why not rename GetLogSource() -> Log() here and in WalletStorage and keep m_log private? I tried and it compiles as of 5b30f17.

Nice suggestion, implemented. This is much cleaner looking.

in src/wallet/walletdb.cpp:553 in 5b30f17c22 outdated

550             }
551 
552             DatabaseCursor::Status status = cursor->Next(key, value);
553             if (status != DatabaseCursor::Status::DONE) {
554-                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());
555+                LogInfo(log, "Error: Unexpected legacy entry found in descriptor wallet %s. The wallet might have been tampered with or created with malicious intent.\n", pwallet->GetName());

hodlinator commented at 7:19 pm on June 26, 2024:

Shouldn’t this be a LogError/LogWarning with removed Error: -prefix?

ryanofsky commented at 3:47 am on June 27, 2024:

re: #30343 (review)

Shouldn’t this be a LogError/LogWarning with removed Error: -prefix?

Agree that makes sense. I implemented it in a followup commit so the main commit is still a refactoring that does not change behavior.

For now I did not remove “Error:” and “Warning:” prefixes because it would be a more significant, possibly unwelcome change, since the prefixes could help messages stand out, and might be relied upon by tests. I’m also not sure if the decision to include warning and error prefixes has been discussed before somewhere else. But I’m happy to change this if there is more feedback in support of it.

in src/wallet/walletdb.cpp:987 in 5b30f17c22 outdated

984         std::string purpose_str;
985         value >> purpose_str;
986         std::optional<AddressPurpose> purpose{PurposeFromString(purpose_str)};
987         if (!purpose) {
988-            pwallet->WalletLogPrintf("Warning: nonstandard purpose string '%s' for address '%s'\n", purpose_str, strAddress);
989+            LogInfo(log, "Warning: nonstandard purpose string '%s' for address '%s'\n", purpose_str, strAddress);

hodlinator commented at 7:20 pm on June 26, 2024:

LogWarning?

ryanofsky commented at 3:47 am on June 27, 2024:

re: #30343 (review)

LogWarning?

Thanks, done in a new commit (see earlier comment)

in src/wallet/scriptpubkeyman.h:36 in 5b30f17c22 outdated

30@@ -31,6 +31,7 @@
31 enum class OutputType;
32 
33 namespace wallet {
34+class WalletLogSource;
35 struct MigrationData;
36 class ScriptPubKeyMan;

hodlinator commented at 7:25 pm on June 26, 2024:

nit: Should strive for alphabetical ordering?

ryanofsky commented at 3:46 am on June 27, 2024:

re: #30343 (review)

nit: Should strive for alphabetical ordering?

Yes, now piped these through sort

in src/wallet/wallet.cpp:3871 in 5b30f17c22 outdated

3867@@ -3866,13 +3868,13 @@ ScriptPubKeyMan* CWallet::AddWalletDescriptor(WalletDescriptor& desc, const Flat
3868     AssertLockHeld(cs_wallet);
3869 
3870     if (!IsWalletFlagSet(WALLET_FLAG_DESCRIPTORS)) {
3871-        WalletLogPrintf("Cannot add WalletDescriptor to a non-descriptor wallet\n");
3872+        LogInfo(m_log, "Cannot add WalletDescriptor to a non-descriptor wallet\n");

hodlinator commented at 7:48 pm on June 26, 2024:

Should maybe have been a warning all along?

ryanofsky commented at 3:46 am on June 27, 2024:

re: #30343 (review)

Should maybe have been a warning all along?

Good catch. It actually looks to me like all of the log prints in this function should be errors. I changed them to use LogError in a new commit. It’s a separate commit because the level change is a minor change in behavior, and is less obvious than other level changes.

maflcko commented at 5:41 am on June 27, 2024:

Are you sure that LogError is the right level? It should only be used for fatal errors where the node needs to shut down, according to the docs. This seems like a warning here, as suggested above.

Some wallet code can probably use Result and pass errors up, possibly here as well. And the caller can decide whether to log as a warning or return over RPC (or something else).

ryanofsky commented at 6:51 am on June 27, 2024:

Are you sure that LogError is the right level? It should only be used for fatal errors where the node needs to shut down, according to the docs. This seems like a warning here, as suggested above.

Oh, that is interesting. The descriptions of those log levels in https://github.com/bitcoin/bitcoin/blob/b27afb7fb774809c9c075d56e44657e0b607a00c/doc/developer-notes.md#logging are much more severe than I would have expected. Based on those descriptions I would expect LogError to be called LogFatal and LogWarning to be called LogCritical. I would have expected LogError to be used for normal errors, and LogWarning to be used for normal warnings.

Maybe the naming would be worth following up on, but I don’t think it would be good to do in this PR. It actually seems like LogInfo is the right log level to use here, not LogWarning. Or do you disagree? Should I just drop the last two commits in this PR?

in src/wallet/wallet.cpp:2491 in 5b30f17c22 outdated

2489         }
2490 
2491         // Delete purpose entry
2492         if (!batch.ErasePurpose(dest)) {
2493-            WalletLogPrintf("Error: cannot erase address book entry purpose\n");
2494+            LogInfo(m_log, "Error: cannot erase address book entry purpose\n");

hodlinator commented at 7:50 pm on June 26, 2024:

LogInfo(m_log, "Error: -> LogError( here and in other places?

ryanofsky commented at 3:46 am on June 27, 2024:

re: #30343 (review)

LogInfo(m_log, "Error: -> LogError( here and in other places?

Thanks, done in a new commit (see earlier comment)

hodlinator commented at 10:17 pm on June 26, 2024: contributor

Went through this and the parent PR together. It was helpful to see how that other PR’s changes were used in this one.

ryanofsky referenced this in commit 8de95b3b5d on Jun 27, 2024

ryanofsky referenced this in commit 5a629a60c4 on Jun 27, 2024

ryanofsky force-pushed on Jun 27, 2024

ryanofsky commented at 4:13 am on June 27, 2024: contributor

Thanks for the review! The suggestions are a big improvement and make the logging code more succinct and clean.

Rebased 5b30f17c22ade44d301aed5051a398fa38251ef7 -> 5a629a60c4739b94383596f9d040502b7b2c8b69 (pr/gwlog.1 -> pr/gwlog.2, compare) on top of the updated parent PR implementing review suggestions.

ryanofsky referenced this in commit 1ac3f01fe5 on Jun 27, 2024

ryanofsky referenced this in commit db8c6fc2ca on Jun 27, 2024

ryanofsky force-pushed on Jun 27, 2024

DrahtBot added the label CI failed on Jun 27, 2024

DrahtBot commented at 4:35 am on June 27, 2024: contributor

🚧 At least one of the CI tasks failed. Make sure to run all tests locally, according to the documentation.

Possibly this is due to a silent merge conflict (the changes in this pull request being incompatible with the current code in the target branch). If so, make sure to rebase on the latest commit of the target branch.

Leave a comment here, if you need help tracking down a confusing failure.

Debug: https://github.com/bitcoin/bitcoin/runs/26740126920

ryanofsky commented at 4:36 am on June 27, 2024: contributor

Updated 5a629a60c4739b94383596f9d040502b7b2c8b69 -> db8c6fc2ca5e1ad99aeda741e3b453f1f7bf7955 (pr/gwlog.2 -> pr/gwlog.3, compare) fixing initialization order bug in last push

DrahtBot removed the label CI failed on Jun 27, 2024

ryanofsky referenced this in commit 6b5b2354c6 on Jun 28, 2024

ryanofsky referenced this in commit d486e49b54 on Jun 28, 2024

ryanofsky referenced this in commit b0c2f8203d on Jun 28, 2024

ryanofsky referenced this in commit 29eaec25af on Jun 28, 2024

ryanofsky force-pushed on Jun 28, 2024

ryanofsky commented at 2:27 pm on June 28, 2024: contributor

Updated and rebased db8c6fc2ca5e1ad99aeda741e3b453f1f7bf7955 -> 29eaec25af32e543df3cff091938c3cb8f7cce17 (pr/gwlog.3 -> pr/gwlog.4, compare) with suggestion to use constexpr Rebased 29eaec25af32e543df3cff091938c3cb8f7cce17 -> 0260cd5ccc3120102c001b3ab6c5f29dcf184b58 (pr/gwlog.4 -> pr/gwlog.5, compare) due to conflict with #30406

glozow added the label Wallet on Jul 2, 2024

DrahtBot added the label Needs rebase on Jul 11, 2024

ryanofsky referenced this in commit 5cec69a56e on Jul 17, 2024

ryanofsky referenced this in commit 57346e0dea on Jul 17, 2024

ryanofsky referenced this in commit b9a3715858 on Jul 17, 2024

ryanofsky referenced this in commit 0260cd5ccc on Jul 17, 2024

ryanofsky force-pushed on Jul 17, 2024

DrahtBot removed the label Needs rebase on Jul 17, 2024

DrahtBot commented at 10:41 am on July 22, 2024: contributor

🚧 At least one of the CI tasks failed. Debug: https://github.com/bitcoin/bitcoin/runs/27589923083

Make sure to run all tests locally, according to the documentation.

The failure may happen due to a number of reasons, for example:

Possibly due to a silent merge conflict (the changes in this pull request being incompatible with the current code in the target branch). If so, make sure to rebase on the latest commit of the target branch.
A sanitizer issue, which can only be found by compiling with the sanitizer and running the affected test.
An intermittent issue.

Leave a comment here, if you need help tracking down a confusing failure.

DrahtBot added the label CI failed on Jul 22, 2024

DrahtBot removed the label CI failed on Jul 22, 2024

DrahtBot added the label Needs rebase on Jul 26, 2024

ryanofsky referenced this in commit c75687736a on Aug 7, 2024

ryanofsky referenced this in commit 0d51d583aa on Aug 7, 2024

ryanofsky force-pushed on Aug 7, 2024

ryanofsky referenced this in commit f16a846d79 on Aug 7, 2024

ryanofsky referenced this in commit 0d49ada2b4 on Aug 7, 2024

ryanofsky referenced this in commit 989f2ea404 on Aug 7, 2024

ryanofsky referenced this in commit f6b93a976b on Aug 7, 2024

ryanofsky referenced this in commit 5f6750a543 on Aug 7, 2024

ryanofsky referenced this in commit 517a4f1c0f on Aug 7, 2024

ryanofsky force-pushed on Aug 7, 2024

DrahtBot removed the label Needs rebase on Aug 7, 2024

DrahtBot added the label Needs rebase on Aug 15, 2024

logging: Improve new LogDebug/Trace/Info/Warning/Error Macros

Improve new LogDebug(), LogTrace(), LogInfo(),  LogWarning(), LogError() macros
introduced in #28318:

- Make them always accept log categories to make it possible to only log
  messages from a particular component.
- Make them not rely on a global LogInstance, to provide better control of
  logging in controlled environments, such as unit tests that want to
  selectively capture log output, or libbitcoinkernel applications that want to
  have multiple instances of validation objects without mixing their log output.
- Make them consistent, now all accepting the same parameters.
- Make them less verbose by not requiring BCLog category constants to be
  specified in individual log prints

12d97dbdcb

logging: Add preprocessor workaround for MSVC

Needed to fix errors like:

const Source &_LogSource(const Source &)': expects 1 arguments - 3 provided
const Source &_LogSource(const Source &)': expects 1 arguments - 3 provided

due to a compiler bug:

https://stackoverflow.com/questions/5134523/msvc-doesnt-expand-va-args-correctly/5134656#5134656

Example CI failure:

https://github.com/bitcoin/bitcoin/actions/runs/8072891468/job/22055528830?pr=29256

5db1958e60

Merge remote-tracking branch 'origin/pull/29256/head' 0b4bccfa87

wallet, logging: Replace WalletLogPrintf() with LogInfo()

Make new logging macros LogDebug(), LogTrace(), LogInfo(), LogWarning(), and
LogError() compatible with wallet code and drop custom WalletLogPrintf()
function. The new logging macros introduced in #28318 weren't previously useful
in wallet code because wallet code prefixes most log messages with the wallet
names to be be able to distinguish log output from multiple wallets. Fix this
by introducing a new WalletLogSource class inheriting from BCLog::Source which
can include the wallet name in log messages

d1bbeac66e

wallet, logging: Switch LogInfo to LogWarning/LogError

Switch to LogWarning / LogError in obvious places where wallet code is clearly outputting warnings and errors.

Suggested by hodlinator in
https://github.com/bitcoin/bitcoin/pull/30343#discussion_r1655406670
https://github.com/bitcoin/bitcoin/pull/30343#discussion_r1655407301
https://github.com/bitcoin/bitcoin/pull/30343#discussion_r1655436010

8e9e7b90cd

wallet, logging: Switch LogInfo to LogError in AddWalletDescriptor

Seems like all of these cases are treated as errors, so it makes sense to use
the corresponding log level.

Change suggested by hodlinator in https://github.com/bitcoin/bitcoin/pull/30343#discussion_r1655434943

4c8fe044d3

ryanofsky referenced this in commit 980a494f6c on Dec 9, 2024

ryanofsky referenced this in commit 09fcfffd48 on Dec 9, 2024

ryanofsky force-pushed on Dec 9, 2024

DrahtBot removed the label Needs rebase on Dec 9, 2024

wallet, logging: Replace WalletLogPrintf() with LogInfo() #30343

Code Coverage & Benchmarks

Reviews

Conflicts