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:

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

37f555a752

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

1592e5a12a

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

For detailed information about the code coverage, see the test coverage report.

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:

#30364 (logging: Replace LogError and LogWarning with LogAlert by ryanofsky)
#30221 (wallet: Ensure best block matches wallet scan state by achow101)
#29418 (rpc: provide per message stats for global traffic via new RPC ‘getnetmsgstats’ by vasild)
#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)
#28574 (wallet: optimize migration process, batch db transactions by furszy)
#28333 (wallet: Construct ScriptPubKeyMans with all data rather than loaded progressively by achow101)
#26697 (logging: use bitset for categories by LarryRuane)

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: none

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

test: Clean up LogPrintf_ test to check LogPrintStr directly

Change was suggested by hodlinator in https://github.com/bitcoin/bitcoin/pull/29256#discussion_r1655562082

681b21f7ca

Merge remote-tracking branch 'origin/pull/29256/head' d2ed5cdbea

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

c47747b325

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

b0c2f8203d

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

29eaec25af

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 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

glozow added the label Wallet on Jul 2, 2024

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

Code Coverage

Reviews

Conflicts