bitcoin
validation: log which peer sent us a header
Fixes #27744
Since #27278 we log received headers. For compact blocks we also log which peer sent it (e5ce8576349d404c466b2f4cab1ca7bf920904b2), but not for regular headers. That required an additional refactor, which this PR provides.
Move the logging from validation to net_processing.
This also reduces the number of log entries (under default configuration) per compact block header from 3 to 2: one for the header and one for the connected tip.
The PR introduces a new helper method LogBlockHeader.
When receiving a compact block we call LogBlockHeader from the exact same place as where we previously logged. So that log message doesn't change. What does change is that we no longer also log from AcceptBlockHeader.
When receiving a regular header(s) message, we only log the last one. This is a change in behaviour because it was simpler to implement, but it's probably better anyway. It does mean that if a peer sends of a bunch of headers of which any is invalid, we won't log it (here).
Lastly I expanded the code comment explaining why we log this. It initially only covered selfish mining, but we also care about peers sending us headers but not following up (see e.g. #27626).
Example log:
2023-06-05T13:12:21Z Saw new header hash=000000000000000000045910263ef84b575ae3af151865238f1e5c619e69c330 height=792964 peer=0
2023-06-05T13:12:23Z UpdateTip: new best=000000000000000000045910263ef84b575ae3af151865238f1e5c619e69c330 height=792964 version=0x20000000 log2_work=94.223098 tx=848176824 date='2023-06-05T13:11:49Z' progress=1.000000 cache=6.4MiB(54615txo)
2023-06-05T13:14:05Z Saw new cmpctblock header hash=00000000000000000003c6fd4ef2e1246a3f9e1fffab7247344f94cadb9de979 height=792965 peer=0
2023-06-05T13:14:05Z UpdateTip: new best=00000000000000000003c6fd4ef2e1246a3f9e1fffab7247344f94cadb9de979 height=792965 version=0x20000000 log2_work=94.223112 tx=848179461 date='2023-06-05T13:13:58Z' progress=1.000000 cache=7.2MiB(61275txo)
2023-06-05T13:14:41Z Saw new header hash=000000000000000000048e6d69c8399992782d08cb57f5d6cbc81a9f996c3f43 height=792966 peer=8
2023-06-05T13:14:42Z UpdateTip: new best=000000000000000000048e6d69c8399992782d08cb57f5d6cbc81a9f996c3f43 height=792966 version=0x2db3c000 log2_work=94.223126 tx=848182944 date='2023-06-05T13:14:35Z' progress=1.000000 cache=8.0MiB(69837txo)
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.
| Type | Reviewers |
|---|---|
| Concept ACK | jonatack |
| Stale ACK | mzumsande, vasild |
If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.
Conflicts
Reviewers, this pull request conflicts with the following ones:
- #30342 (kernel, logging: Pass Logger instances to kernel objects by ryanofsky)
- #29641 (scripted-diff: Use LogInfo/LogDebug over LogPrintf/LogPrint by maflcko)
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.
There's various ways in which AcceptBlockHeader can return true or false early without setting state. This happens before the place where we used to log stuff. That in turn causes f25b8712c368ecfa250a6878af66f3fea3a4bcb0 to potentially log more stuff than it should (for headers that are not received via compact blocks).
It's probably why I saw so many log entries:
2023-06-05T11:50:30Z Saw new cmpctblock header hash=000000000000000000042a2c4e3910c5ccd48b4b2d624f08b4b5a413b98af4ea height=792960 peer=9
2023-06-05T11:50:30Z Saw new header hash=000000000000000000042a2c4e3910c5ccd48b4b2d624f08b4b5a413b98af4ea height=792960 peer=6
2023-06-05T11:50:31Z Saw new header hash=000000000000000000042a2c4e3910c5ccd48b4b2d624f08b4b5a413b98af4ea height=792960 peer=13
2023-06-05T11:50:31Z Saw new header hash=000000000000000000042a2c4e3910c5ccd48b4b2d624f08b4b5a413b98af4ea height=792960 peer=16
2023-06-05T11:50:31Z Saw new header hash=000000000000000000042a2c4e3910c5ccd48b4b2d624f08b4b5a413b98af4ea height=792960 peer=15
2023-06-05T11:50:31Z UpdateTip: new best=000000000000000000042a2c4e3910c5ccd48b4b2d624f08b4b5a413b98af4ea height=792960 version=0x20000000 log2_work=94.223043 tx=848167913 date='2023-06-05T11:50:20Z' progress=1.000000 cache=1194.3MiB(9437428txo)
2023-06-05T11:50:31Z Saw new header hash=000000000000000000042a2c4e3910c5ccd48b4b2d624f08b4b5a413b98af4ea height=792960 peer=3
Moving to draft while I give it more thought.
Added a check to ensure the header was valid and newly seen before we log it. That matches the behaviour from before this PR.
Rebased after #28218 (no longer needs ActiveChainstate() to get IsInitialBlockDownload()).
Added support for -logips. This lets you retrieve the IP of a node you disconnected from, without the need for -debug=net (since it's too late to ask getpeerinfo). This becomes especially useful with #27277 which removes mempool "noise" from -debug=validation, so you can e.g. see what the rejection reason was for this header (without a gigabyte of logs per day).
It turns out there's a third way that we can (and do) receive new headers: unsolicited BLOCK messages. I added two new commits that add logging for this, which also slightly refactors the first one.
Since these new changes are a bit more involved, and also touch CheckBlock(), I'll hold off on squashing pending opinions… But I do think logging these is very useful.
I get between 0 and 2 of these unsolicited blocks per day:
2023-11-07T02:19:56.507378Z Saw new header via unsolicited block hash=00000000000000000003310c8a9104bc38473171de3d2628ce608b7418384402 peer=0 peeraddr=x.x.x.x:8333
Only keeping the first commit.
I don't want to make this PR more complicated. If anyone wants to try detecting new headers that arrive via an unsolicited block, see the following dropped commits: 386febd59bd894ad9c5216eacafe0308ed314980 and 9d4e5afab754c34027daf6a533ae25408a5a5596.
Rebased to use the new logging functions LogInfo and LogDebug from #28318 (see developer-notes.md).