log: improve some validation log messages to include hashPrevBlock #26487

sdulfari commented at 10:38 PM on November 10, 2022: contributor

When there is an issue with a previous block the current log messages do not indicate hashPrevBlock. Adding it makes debugging easier.

sdulfari commented at 10:39 PM on November 10, 2022: contributor

Example output from test/functional/test_runner.py --nocleanup mining_basic:

2022-11-10T21:53:32.034092Z [httpworker.1] [../../src/validation.cpp:3679] [AcceptBlockHeader] [validation] AcceptBlockHeader: 0ce2bea66a350307e512e5045a0ff1ee0de2ce47194049c962fd4c2803c6904b prev block not found: 000000000000000000000000000000000000000000000000000000000000007b

DrahtBot added the label Utils/log/libs on Nov 10, 2022

in src/validation.cpp:3679 in 1ea713e30e outdated

3675 | @@ -3676,12 +3676,12 @@ bool ChainstateManager::AcceptBlockHeader(const CBlockHeader& block, BlockValida
3676 |          CBlockIndex* pindexPrev = nullptr;
3677 |          BlockMap::iterator mi{m_blockman.m_block_index.find(block.hashPrevBlock)};
3678 |          if (mi == m_blockman.m_block_index.end()) {
3679 | -            LogPrint(BCLog::VALIDATION, "%s: %s prev block not found\n", __func__, hash.ToString());
3680 | +            LogPrint(BCLog::VALIDATION, "%s: %s prev block not found: %s\n", __func__, hash.ToString(), block.hashPrevBlock.ToString());

maflcko commented at 8:23 AM on November 11, 2022:

            LogPrint(BCLog::VALIDATION, "%s prev block not found: %s\n", hash.ToString(), block.hashPrevBlock.ToString());

It should be possible to remove __func__ here, because the LogPrint macro will inject it automatically, if the user asked for it in the settings.

sdulfari commented at 5:19 AM on November 13, 2022:

Good catch. I fixed this patch but also found more of these around the code base. Might be a good first issue to clean these up.

sdulfari commented at 5:22 AM on November 13, 2022:

New example output:

2022-11-13T05:14:21.549203Z [httpworker.3] [../../src/validation.cpp:3679] [AcceptBlockHeader] [validation] 612a289e4b1a801d7eda810841d0dce612a05f9bf3ddb7cadd28e45a6512088d prev block not found: 000000000000000000000000000000000000000000000000000000000000007b

luke-jr commented at 11:34 PM on November 14, 2022:

This might be a case where the user should be told the func even if not explicitly requesting it...

shaavan commented at 8:30 AM on November 12, 2022: contributor

Concept ACK

I think this is pretty reasonable to provide the hash of the block that is seemingly causing the error. Verified that all the LogPrint messages concerning the previous block hash now included the hash of that block as well.

sdulfari force-pushed on Nov 13, 2022

theStack commented at 5:44 PM on November 13, 2022: contributor

Concept ACK

in src/validation.cpp:3679 in 0ee27cba6e outdated

3675 | @@ -3676,12 +3676,12 @@ bool ChainstateManager::AcceptBlockHeader(const CBlockHeader& block, BlockValida
3676 |          CBlockIndex* pindexPrev = nullptr;
3677 |          BlockMap::iterator mi{m_blockman.m_block_index.find(block.hashPrevBlock)};
3678 |          if (mi == m_blockman.m_block_index.end()) {
3679 | -            LogPrint(BCLog::VALIDATION, "%s: %s prev block not found\n", __func__, hash.ToString());
3680 | +            LogPrint(BCLog::VALIDATION, "%s prev block not found: %s\n", hash.ToString(), block.hashPrevBlock.ToString());

stickies-v commented at 11:30 AM on November 14, 2022:

I'd suggest rephrasing it to remove ambiguity about which hash belongs to current/previous block, and so that the error message comes first and the detailed info only at the end:

            LogPrint(BCLog::VALIDATION, "prev block not found (current: %s, previous: %s\n", hash.ToString(), block.hashPrevBlock.ToString());

sdulfari commented at 8:10 PM on November 16, 2022:

I have clarified the relationship between the two hashes with a minimal change.

stickies-v commented at 11:31 AM on November 14, 2022: contributor

Concept ACK

sdulfari force-pushed on Nov 16, 2022

aureleoules approved

aureleoules commented at 9:26 AM on November 17, 2022: member

ACK 5cb86253316d17bfd36314d065ca5144a52ac9d7

DrahtBot commented at 9:27 AM on November 17, 2022: contributor

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

Reviews

See the guideline for information on the review process.

Type	Count	Reviewers
ACK	3	aureleoules, stickies-v, theStack
Concept ACK	1	shaavan

log: improve some validation log messages to include hashPrevBlock

When there is an issue with a previous block the current log messages do
not indicate hashPrevBlock. Adding it makes debugging easier.

ac410e6fc0

in src/validation.cpp:3725 in 5cb8625331 outdated

3721 | @@ -3722,7 +3722,7 @@ bool ChainstateManager::AcceptBlockHeader(const CBlockHeader& block, BlockValida
3722 |                          m_blockman.m_dirty_blockindex.insert(invalid_walk);
3723 |                          invalid_walk = invalid_walk->pprev;
3724 |                      }
3725 | -                    LogPrint(BCLog::VALIDATION, "%s: %s prev block invalid\n", __func__, hash.ToString());
3726 | +                    LogPrint(BCLog::VALIDATION, "%s has prev block invalid: %s\n", hash.ToString(), block.hashPrevBlock.ToString());

maflcko commented at 9:43 AM on November 17, 2022:

                    LogPrint(BCLog::VALIDATION, "header %s has prev block invalid: %s\n", hash.ToString(), block.hashPrevBlock.ToString());

Sorry for continuing to bike-shed this, but maybe instead of just printing a full hash, clarify that this is a hash of a header?

stickies-v commented at 10:53 AM on November 17, 2022:

+1. ~I'd also suggest spelling out "previous" in full, don't see the need to abbreviate. Finally, grammar could be improved a bit. All together, what about: "header %s has invalid previous block: %s\n"~ edit: bad idea, as per below

maflcko commented at 10:55 AM on November 17, 2022:

There could be a value in keeping the string "prev block invalid" the same, to allow grep "prev block invalid" ./debug.log to continue to work, no?

stickies-v commented at 11:31 AM on November 17, 2022:

Good point, hadn't considered that. Your suggestion seems optimal then.

sdulfari commented at 4:49 PM on November 17, 2022:

updated to add header clarification

sdulfari force-pushed on Nov 17, 2022

stickies-v approved

stickies-v commented at 7:41 PM on November 17, 2022: contributor

ACK ac410e6fc0fceb568d4fb3d398724ca859a8be25

aureleoules approved

aureleoules commented at 7:47 PM on November 17, 2022: member

reACK ac410e6fc0fceb568d4fb3d398724ca859a8be25

theStack approved

theStack commented at 8:51 AM on November 18, 2022: contributor

ACK ac410e6fc0fceb568d4fb3d398724ca859a8be25

maflcko merged this on Nov 18, 2022

maflcko closed this on Nov 18, 2022

sidhujag referenced this in commit 81a62c292a on Nov 18, 2022

Fabcien referenced this in commit 5c1a099852 on Nov 22, 2022

bitcoin locked this on Nov 18, 2023