validation: log CChainState::CheckBlockIndex() consistency checks #22956

jonatack commented at 1:34 PM on September 12, 2021: member

The -checkblockindex configuration option performs occasional consistency checks of the block tree, chainstate, and other validation data structures.

There is currently no logging of the checks to see when they happen and their duration.

This patch:

adds a BLOCK logging category, as the validation category is high-frequency
logs the CChainState::CheckBlockIndex() consistency checks and duration

Example (on signet, while catching up to chain tip):

$ ./src/bitcoind -signet -checkaddrman=10 -debug=lock -debug=block
...
2021-09-12T13:03:18Z [msghand] CheckBlockIndex: consistency checks started
2021-09-12T13:03:18Z [opencon] Enter: lock contention cs_main, net_processing.cpp:1152 started
2021-09-12T13:03:18Z [msghand] CheckBlockIndex: consistency checks completed (433.58ms)
2021-09-12T13:03:18Z [msghand] CheckBlockIndex: consistency checks started
2021-09-12T13:03:19Z [msghand] CheckBlockIndex: consistency checks completed (411.67ms)
2021-09-12T13:03:19Z [opencon] Enter: lock contention cs_main, net_processing.cpp:1152 completed (811929μs)

To test:

$ ./src/bitcoind -debug=block

DrahtBot added the label Validation on Sep 12, 2021

DrahtBot commented at 3:23 PM on September 12, 2021: member

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

Conflicts

Reviewers, this pull request conflicts with the following ones:

#23235 (Reduce unnecessary default logging by ajtowns)

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.

klementtan approved

klementtan commented at 7:08 AM on September 13, 2021: contributor

Code review and tested ACK 572cf0dd547b69580b7796d2192617ab4a318a5f

2021-09-13T07:01:58Z CheckBlockIndex: consistency checks started
2021-09-13T07:01:58Z CheckBlockIndex: consistency checks completed (63.12ms)
2021-09-13T07:01:58Z CheckBlockIndex: consistency checks started
2021-09-13T07:01:58Z Enter: lock contention ::cs_main, validation.cpp:4876 started
2021-09-13T07:01:58Z CheckBlockIndex: consistency checks completed (57.97ms)

in src/logging.cpp:164 in 572cf0dd54 outdated

 159 | @@ -160,6 +160,7 @@ const CLogCategoryDesc LogCategories[] =
 160 |      {BCLog::I2P, "i2p"},
 161 |      {BCLog::IPC, "ipc"},
 162 |      {BCLog::LOCK, "lock"},
 163 | +    {BCLog::BLOCK, "block"},

MarcoFalke commented at 7:27 AM on September 13, 2021:

Is there a guideline on which log category to use within validation? There is BENCH used for benchmarking validation. There is VALIDATION used for storage and validation. Now there is BLOCK used for CheckBlockIndex.

jonatack commented at 2:51 PM on September 13, 2021:

Not that I know of. I published a doc at https://github.com/jonatack/bitcoin-development/blob/master/logging.md#log-categories that is an updated version of this Bitcoin Stack Exchange answer in 2017 by @achow101 and am considering adding it to the RPC logging help.

MarcoFalke commented at 10:47 AM on September 22, 2021:

Is there a reason to not re-use the BENCH or VALIDATION category? Seems overkill to introduce a new category for a single log line that is mostly only enabled for devs/debugging.

jonatack commented at 5:02 PM on September 22, 2021:

We did that for instance with MEMPOOLREJ (1 line), QT (1 line), LOCK (1 line), PROXY (1 line), RAND (2 lines), COINDB (3 lines) and CMPCTBLOCK (3 lines), among others.

My thought was that VALIDATION is too busy and BENCH would be ok but seems not directly related to consistency checks (rename it?) We could also rename CMPCTBLOCK to BLOCK and add it to that group.

laanwj commented at 5:03 PM on September 23, 2021:

I think a BLOCK category makes sense in the sense that "block storage" is separate from "validation". We have a separate label for it too. If it is planned to be used for other messages too.

On the other hand this particular functionality is already enabled with a special option (-checkblockindex), so for this specifically I'm not sure also adding a separate category makes sense.

RAND (2 lines)

I think this one should go into a more general UTIL category at some point.

QT (1 line)

One line that captures everything from Qt's internal logging system :smile:

jonatack commented at 11:55 AM on September 29, 2021:

I think a BLOCK category makes sense in the sense that "block storage" is separate from "validation". We have a separate label for it too. If it is planned to be used for other messages too.

On the other hand this particular functionality is already enabled with a special option (-checkblockindex), so for this specifically I'm not sure also adding a separate category makes sense.

Right. It doesn't seem ideal to use BCLog::VALIDATION or BCLog::BENCH, and LogPrintf would require bitcoind to be restarted to turn off the -checkblockindex config option. Maybe rename the low-frequency BCLog::CMPCTBLOCK category to BCLog::BLOCK and use that, but it would be a bit more disruptive than the current proposal.

MarcoFalke commented at 4:09 PM on October 26, 2021:

Looks like #23235 did some of the clean-ups here?

jonatack commented at 8:44 AM on May 25, 2022:

Looks like #23235 did some of the clean-ups here?

Looked at it, but that change looks like it needs cleaning up and given how this simple change couldn't go through, I didn't attempt it.

DrahtBot added the label Needs rebase on Oct 4, 2021

log: add BLOCK logging category fbd095153a

validation: log CChainState::CheckBlockIndex() consistency checks dfca02e4cd

jonatack force-pushed on Oct 5, 2021

jonatack commented at 10:05 AM on October 5, 2021: member

Rebased following the merge of #20487, which added the UTIL logging category.

DrahtBot removed the label Needs rebase on Oct 5, 2021

DrahtBot commented at 6:19 AM on October 14, 2021: member

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

<sub>Want to unsubscribe from rebase notifications on this pull request? Just convert this pull request to a "draft".</sub>

DrahtBot added the label Needs rebase on Oct 14, 2021

laanwj commented at 7:23 PM on November 12, 2021: member

Code review ACK (but unfortunately needs rebase again)

DrahtBot commented at 12:17 PM on February 22, 2022: member

There hasn't been much activity lately and the patch still needs rebase. What is the status here?

Is it still relevant? ➡️ Please solve the conflicts to make it ready for review and to ensure the CI passes.
Is it no longer relevant? ➡️ Please close.
Did the author lose interest or time to work on this? ➡️ Please close it and mark it 'Up for grabs' with the label, so that it can be picked up in the future.

fanquake commented at 8:29 AM on May 25, 2022: member

What is the status of this?

MarcoFalke commented at 8:36 AM on May 25, 2022: member

Closing due to several months of inactivity for a "simple" logging change. Feel free to reopen this or open a new pull request.

MarcoFalke closed this on May 25, 2022

jonatack commented at 8:40 AM on May 25, 2022: member

Indeed, I thought it would be simple but no agreement on which logging category to use.

DrahtBot locked this on May 25, 2023