log: Add validation interface logging

[jkczyz]

Add logging of CValidationInterface callbacks using a new VALIDATION log flag (see #12994). A separate flag is desirable as the logging can be noisy and thus may need to be disabled without affecting other logging.

This could help debug issues where there may be race conditions at play, such as #12978.

[DrahtBot]

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

Conflicts

Reviewers, this pull request conflicts with the following ones:

• #17562 (WIP: Validation: Remove ConnectTrace and PerBlockConnectTrace by jnewbery)
• #17477 (Remove the mempool's NotifyEntryAdded and NotifyEntryRemoved signals by jnewbery)
• #17399 (validation: Templatize ValidationState instead of subclassing by jkczyz)
• #16365 (Log RPC parameters (arguments) if -debug=rpcparams 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.

[ariard]

Tested validationinterface log flag with both cli option and logging RPC. Worked as expected.

Nice to have more logging around the validation callbacks, order of events may be so confusing!

[jnewbery]

Concept ACK

[jkczyz]

Addressed all comments and add correct formatting for valid CValidationState in b303865.

Also updated CValidationState accessors in 3ff8755 to return strings by constant reference to avoid copying. Although this means the references are only valid for the lifetime of the object, which should be okay.

[jnewbery]

I've partially reviewed and left a few comments inline. I intend to finish review and test this week.

[jnewbery]

I did some light testing and this looks good. If you wanted to add automated tests, take a look at assert_debug_log() in the TestNode object. That allows you to test that specific strings have been written to the debug log.

updated CValidationState accessors in 3ff8755 to return strings by constant reference to avoid copying.

Was this required for the PR? Those accessors aren't used very much, so performance isn't critical. I'd suggest not changing them in this PR.

[jkczyz]

I did some light testing and this looks good. If you wanted to add automated tests, take a look at assert_debug_log() in the TestNode object. That allows you to test that specific strings have been written to the debug log.

I would be hesitant to add a functional test only to check for informational logging. Is there an existing a test where all these events are exercised? Not sure if it is worth adding regardless.

updated CValidationState accessors in 3ff8755 to return strings by constant reference to avoid copying.

Was this required for the PR? Those accessors aren't used very much, so performance isn't critical. I'd suggest not changing them in this PR.

Yeah, commit 72c6e50 calls those methods in such a way that not returning references would have incurred excessive copies. Would it be better if the two commits were merged?

[jkczyz]

@jnewbery I have some concerns about this additional logging. Since #14209 was merged, all log function arguments are evaluated regardless of whether logging is enabled for the given category. This was not the case prior to that PR since a macro was used for logging.

Given the heavy amount of logging added in this PR, should the function vs macro approach for logging be revisited? Typically, the use of macros in logging libraries is to avoid such argument evaluation if I understand correctly.

[maflcko]

Since #14209 was merged, all log function arguments are evaluated regardless of whether logging is enabled for the given category.

Huh? They were passed to strprintf before and after that change, but strprintf was only called when logging was enabled. I don't see how that pull changed anything.

[jkczyz]

Since #14209 was merged, all log function arguments are evaluated regardless of whether logging is enabled for the given category.

Huh? They were passed to strprintf before and after that change, but strprintf was only called when logging was enabled. I don't see how that pull changed anything.

By evaluation I mean at the call site of LogPrint. While this doesn't make a difference when passing variables, it does matter when the arguments are calls to other functions. Prior to #14209, the latter would be textually included when used and thus not evaluated if logging was not enabled for the given category.

[maflcko]

Ah, right

[hebasto]

IMO, 6c730c3 commit is outside the original PR goal.
Also string (i.e., basic_string<char>) offers move semantics; so it can be efficiently return by value.

[jkczyz]

IMO, 6c730c3 commit is outside the original PR goal.
Also string (i.e., basic_string<char>) offers move semantics; so it can be efficiently return by value.

I removed the commit. But I don't believe move semantics apply here as the function is returning a member variable.

[jnewbery]

I removed the commit. (6c730c3)

Thanks!

I've tested this and it works great. I think we need to resolve this question: #16688 (comment) before merging this PR. It seems reasonable to me to change logging back to using a macro for the reasons you suggest. Adding a GetHash() call to every validation interface call, even when logging is disabled, seems a shame. I'd be happy to review a PR that does that.

Rename CMainSignals::MempoolEntryRemoved to TransactionRemovedFromMempool and Format CValidationState properly in all cases could be pulled out into their own PR while we're waiting for that, although note that Format CValidationState properly in all cases conflicts with 0053e16.

[jkczyz]

I've tested this and it works great. I think we need to resolve this question: #16688 (comment) before merging this PR. It seems reasonable to me to change logging back to using a macro for the reasons you suggest. Adding a GetHash() call to every validation interface call, even when logging is disabled, seems a shame. I'd be happy to review a PR that does that.

@jnewbery Will do.

@MarcoFalke I'm not sure I follow the part about "unnecessary branches are not analyzed" in #14209. If I were to make LogPrint (but not LogPrintf) a macro again, will I need to define it conditionally based on USE_COVERAGE as was done in c8914b9?

[maflcko]

If you revert #14209, please make it as slim as possible (without the USE_COVERAGE guard, which mostly did only harm)

[jnewbery]

I would be hesitant to add a functional test only to check for informational logging. Is there an existing a test where all these events are exercised? Not sure if it is worth adding regardless.

Yeah, I agree that this isn't necessary.

[jkczyz]

@hebasto @ryanofsky Thanks for the review! I've addressed all comments.

[jnewbery]

ACK f9abf4a

[hebasto]

ACK f9abf4a

[ariard]

ACK f9abf4a, only changes since 0cadb12 are replacing log indication VALIDATIONINTERFACE by VALIDATION and avoiding a forward declaration with a new include

[ryanofsky]

Code review ACK f9abf4a. Just suggested changes since last review (thanks!)

[jonatack]

ACK e7f8450 posthumous code review and manual tests.

Usage listed here for visitor convenience (the PR description was not updated from validationinterface to validation):

• bitcoind -help | grep -B6 ", validation"

  -debug=<category>
       Output debugging information (default: -nodebug, supplying <category> is
       optional). If <category> is not supplied or if <category> = 1,
       output all debugging information. <category> can be: net, tor,
       mempool, http, bench, zmq, walletdb, rpc, estimatefee, addrman,
       selectcoins, reindex, cmpctblock, rand, prune, proxy, mempoolrej,
       libevent, coindb, qt, leveldb, validation.

• bitcoind -debug=validation (launch bitcoind with validation logging)
• bitcoin-cli help logging
• bitcoin-cli logging [] '["validation"]' (toggle validation logging off)
• bitcoin-cli logging '["validation"]' (toggle validation logging on)