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

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 WalletLogContext class inheriting from util::log::Context which can include the wallet name in log messages.

This change makes -logsourcelocations usable with wallet code because it logs actual source locations instead of the WalletLogPrintf() location.

<!-- begin based-on -->

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

• ef93a888453 wallet, logging: Replace WalletLogPrintf() with LogInfo()
• 45ecab65d44 wallet, logging: Switch LogInfo to LogWarning/LogError<!-- end -->

<!--e57a25ab6845829454e8d69fc972939a-->

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

<!--006a51241073e994b41acfe9ec718e94-->

Code Coverage & Benchmarks

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

<!--021abf342d371248e50ceaed478a90ca-->

Reviews

See the guideline for information on the review process.

If your review is incorrectly listed, please copy-paste <code>&lt;!--meta-tag:bot-skip--&gt;</code> into the comment that the bot should ignore.

<!--174a7506f384e20aa4161008e828411d-->

Conflicts

Reviewers, this pull request conflicts with the following ones:

• #35092 (wallet: stop materializing skipped descriptor addresses after high-index detection by takeshikurosawaa)
• #34909 (wallet, refactor: modularise wallet by extracting out legacy wallet migration by rkrux)
• #34865 (logging: better use of log::Entry internally by stickies-v)
• #34778 (logging: rewrite macros to add ratelimit option, avoid unused strprintf, clarify confusing errors by ryanofsky)
• #34730 (util/log: Combine the warning/error log levels into a single alert level by ajtowns)
• #34729 (Reduce log noise by ajtowns)
• #34681 (wallet: refactor ScanForWalletTransactions by Eunovo)
• #34617 (fees: wallet: remove block policy fee estimator internals from wallet by ismaelsadeeq)
• #34514 (refactor: remove unnecessary std::move for trivially copyable types by l0rinc)
• #34502 (wallet: remove most asserts of WALLET_FLAG_DESCRIPTORS flag by rkrux)
• #34400 (wallet: parallel fast rescan (approx 5x speed up with 8 threads) by Eunovo)
• #34193 (wallet: make migration more robust against failures by furszy)
• #34075 (fees: Introduce Mempool Based Fee Estimation to reduce overestimation by ismaelsadeeq)
• #33727 (zmq: Log bind error at Error level, abort startup on init error by isrod)
• #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.

<!--5faf32d7da4f0f540f40219e4f7537a3-->

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

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.

<!--85328a0da195eb286784d51f73fa0af9-->

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

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

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 Rebased 0260cd5ccc3120102c001b3ab6c5f29dcf184b58 -> 0d49ada2b42e5b48b21bb7cb854851f09641abbb (pr/gwlog.5 -> pr/gwlog.6, compare) on top of updated base pr/bclog.20 Rebased 0d49ada2b42e5b48b21bb7cb854851f09641abbb -> f6b93a976b0127b55705dc33caf986a3344e12a4 (pr/gwlog.6 -> pr/gwlog.7, compare) due to conflict with #30485 Rebased f6b93a976b0127b55705dc33caf986a3344e12a4 -> 4c8fe044d3241664151b3727e31ac2eaa741b717 (pr/gwlog.7 -> pr/gwlog.8, compare) due to conflicts with #26619, #30659, and other PRs Rebased 4c8fe044d3241664151b3727e31ac2eaa741b717 -> e8c6095c75dead138e79a18146ce865e7fe6529a (pr/gwlog.8 -> pr/gwlog.9, compare) due to conflicts with #31061

<!-- begin push-10 -->

Rebased e8c6095c75dead138e79a18146ce865e7fe6529a -> af6f854df0d0dd72b05cda4d2e1ed0d1c2c00738 (pr/gwlog.9 -> pr/gwlog.10, compare)<!-- end -->

<!-- begin push-11 -->

Rebased af6f854df0d0dd72b05cda4d2e1ed0d1c2c00738 -> 2e4d0c3b51e2e8fbf913f28361d1a0a8d1f3e166 (pr/gwlog.10 -> pr/gwlog.11, compare)<!-- end -->

<!-- begin push-12 -->

Rebased 2e4d0c3b51e2e8fbf913f28361d1a0a8d1f3e166 -> 186b721e6107a0606be6c55edbdd8ec5d5fabd2b (pr/gwlog.11 -> pr/gwlog.12, compare)<!-- end -->

<!-- begin push-13 -->

Rebased 186b721e6107a0606be6c55edbdd8ec5d5fabd2b -> df507121593d4a1cd58c80e5e63735c115c728c5 (pr/gwlog.12 -> pr/gwlog.13, compare)<!-- end --> on updated base PR to fix CI errors (https://github.com/bitcoin/bitcoin/actions/runs/18514132530?pr=30343), also fixing wallet name formatting causing wallet_tests/CreateWallet to fail

<!-- begin push-14 -->

Rebased df507121593d4a1cd58c80e5e63735c115c728c5 -> e84bd31c04751e968a0936b93d6cc7e639ac4409 (pr/gwlog.13 -> pr/gwlog.14, compare)<!-- end -->

<!-- begin push-15 -->

Rebased e84bd31c04751e968a0936b93d6cc7e639ac4409 -> 75042af2053485badea67b1ff9b38bc820f3f24c (pr/gwlog.14 -> pr/gwlog.15, compare)<!-- end -->

<!-- begin push-16 -->

Rebased 75042af2053485badea67b1ff9b38bc820f3f24c -> 74bb399dfa1f0823f26fc3bfa7917f5f4fa36668 (pr/gwlog.15 -> pr/gwlog.16, compare)<!-- end -->

<!-- begin push-17 -->

Rebased 74bb399dfa1f0823f26fc3bfa7917f5f4fa36668 -> a08c9bc808ef19accc90335fb115f791a66e0158 (pr/gwlog.16 -> pr/gwlog.17, compare)<!-- end --> on top of #29256 pr/bclog.34

<!-- begin push-18 -->

Rebased a08c9bc808ef19accc90335fb115f791a66e0158 -> aac55f94938aa7ac727b840a9766adb848e998ab (pr/gwlog.17 -> pr/gwlog.18, compare)<!-- end --> on top of #29256 pr/bclog.36

<!-- begin push-19 -->

Rebased aac55f94938aa7ac727b840a9766adb848e998ab -> 7fc95e7cbb3ee3cae14df02602ac51a3d910945c (pr/gwlog.18 -> pr/gwlog.19, compare)<!-- end --> on top of #29256 pr/bclog.37 with review suggestions

<!-- begin push-20 -->

Rebased 7fc95e7cbb3ee3cae14df02602ac51a3d910945c -> 524c5b8ef547700e4b5a234bf6bebd4d775d98e5 (pr/gwlog.19 -> pr/gwlog.20, compare)<!-- end --> on top of #29256 pr/bclog.39

<!-- begin push-21 -->

Rebased 524c5b8ef547700e4b5a234bf6bebd4d775d98e5 -> 45ecab65d4434aebafa23195c3571b833faf47ca (pr/gwlog.20 -> pr/gwlog.21, compare)<!-- end --> on top of #29256 pr/bclog.40

<!--85328a0da195eb286784d51f73fa0af9-->

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

<details><summary>Hints</summary>

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.

</details>

<!--85328a0da195eb286784d51f73fa0af9-->

🚧 At least one of the CI tasks failed. _{Debug: https://github.com/bitcoin/bitcoin/runs/39937553048}

<details><summary>Hints</summary>

Try to run the tests locally, according to the documentation. However, a CI failure may still 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.

</details>

I wanted to push a simple scripted diff to rename WalletLogPrintf, to LogInfo, but noticed this pR already does that (in a more elaborate way). Is it a draft because it's based on #29256 which should be reviewed first? That one has two nacks, can you make a version of this that simply renames the leftover LogPrintf reference or is that just a demonstration for the usefulness of log contexts?

Would be curious about your scripted-diff. I don't think we want to only replace WalletLogPrintf calls with LogInfo calls, because the point of WalletLogPrintf is to include wallet names in log messages, and it would bad to lose these, and awkward to have to specify them in every log call. I think this PR takes a nice approach of allowing Loginfo and other logging macros to work in wallet code including wallet names as part of the log context.

This PR is ready to review and has had some review, but is a draft because is based on another PR and should not be merged before that one. The other PR has nacks because originally it allowed LogInfo calls to accept category constants, and there was a debate about whether it was harmful to log category information, but I eventually gave in and removed it, so I don't think the nacks are still relevant.

Reviewed and tested aac55f94938a.

I found an issue, at log.h LogPrint_ , rvalue source arguments can be bound by reference and used after their lifetime ends. I tried to solve this in a few ways, but I think the most elegant simple one is to block rvalues at compile time by deleting the overload. I failed to find any rvalue usage that exists today. Solution suggested in inline comments.

I used the following test to confirm the lifetime issue (for demo of the issue only; we don't need it if we block rvalues at compile time):

struct LifetimeCheckedSource : public util::log::Source {
    LifetimeCheckedSource(int& counter, BCLog::Logger& logger, bool& alive)
        : Source{BCLog::VALIDATION, &logger}, m_counter{counter}, m_alive{alive}
    {
        m_alive = true;
    }
    ~LifetimeCheckedSource()
    {
        m_alive = false;
    }
    template <typename... Args>
    std::string Format(util::ConstevalFormatString<sizeof...(Args)> fmt, const Args&... args) const
    {
        CHECK_NONFATAL(m_alive);
        return tfm::format("Custom #%d %s", ++m_counter, tfm::format(fmt, args...));
    }
    int& m_counter;
    bool& m_alive;
};

BOOST_AUTO_TEST_CASE(logging_temporary_source_lifetime)
{
    BCLog::Logger logger;
    logger.m_log_timestamps = false;
    logger.EnableCategory(BCLog::LogFlags::ALL);
    logger.SetLogLevel(BCLog::Level::Debug);
    logger.StartLogging();

    std::vector<std::string> messages;
    logger.PushBackCallback([&](const std::string& s) { messages.push_back(s); });

    int counter{0};
    bool alive{false};
    auto make_source = [&counter, &logger, &alive]() {
        return LifetimeCheckedSource{counter, logger, alive};
    };
    LogDebug(make_source(), "temporary %s", "source");

    BOOST_REQUIRE_EQUAL(messages.size(), 1U);
    BOOST_CHECK_EQUAL(messages[0], "[validation] Custom [#1](/bitcoin-bitcoin/1/) temporary source\n");
    BOOST_CHECK_EQUAL(counter, 1);
}

Run build/bin/test_bitcoin --run_test=logging_tests/logging_temporary_source_lifetime to see it fail.

Reviewe and test 7fc95e7cbb3e after the rebase.

Concept ACK except this issue

Thanks for the reviews @adyshimony! Note that most of your comments apply to #29256 which this is based on (#29256 is subset of this PR), so you may be interested in reviewing that directly. Some of your comments are now addressed in recent updates to both PRs.

re: #30343#pullrequestreview-3871171023

I found an issue, at log.h LogPrint_ , rvalue source arguments can be bound by reference and used after their lifetime ends.

I think this issue is already handled by the LIFETIMEBOUND annotation in GetSource().

When I build your test, the compiler shows warning: temporary bound to local reference '_source' will be destroyed at the end of the full-expression [-Wdangling] on line LogDebug(make_source(), "temporary %s", "source");.

So I think any code written in that unsafe style should be caught locally or by CI, and not be an issue. Your suggestion #30343 (review) to restrict GetSource() overloading so it can't bind to lvalues could also make sense if LIFETIMEBOUND warning isn't sufficient, but I feel like just using LIFETIMEBOUND avoids unnecessary complexity and provides a better diagnostic.

Ohhh, I didn’t catch this earlier because I was building with GCC!

After switching to Clang, I can see it. This is Clang only flag, so reviewers using only GCC may miss it...

I still think the cleaner approach is to reject temporary sources directly at compile time by deleting the rvalue overload, so it clearly says "this usage is not allowed".

Given the existing lvalue overload, the additional deleted overload can be simple:

template <bool take_category, typename Source>
requires (Source::log_source)
const Source& GetSource(const Source&&) = delete;

In any case, with either approach, ACK on https://github.com/bitcoin/bitcoin/commit/7fc95e7cbb3ee3cae14df02602ac51a3d910945c.

<!--cf906140f33d8803c4a75a2196329ecb-->

🐙 This pull request conflicts with the target branch and needs rebase.