validation: log which peer sent us a header #27826

Sjors · 2023-06-05T11:53:28Z

Since #27278 we log received headers. For compact blocks we also log which peer sent it (e5ce857), 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)

DrahtBot · 2023-06-05T11:53:31Z

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:

#29415 (Broadcast own transactions only via short-lived Tor or I2P connections by vasild)

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.

Sjors · 2023-06-05T11:59:04Z

cc @jamesob, @instagibbs, @mzumsande

Sjors · 2023-06-05T12:15:45Z

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 f25b871 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.

Sjors · 2023-06-05T12:34:58Z

Added a check to ensure the header was valid and newly seen before we log it. That matches the behaviour from before this PR.

Sjors · 2023-06-05T13:56:28Z

src/net_processing.cpp

@@ -4268,8 +4295,8 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
        }

        if (received_new_header) {


Since it's possible for ProcessNewBlockHeaders to return false without us returning, I wonder if we should only log if it returned true (as we do above).

I don't think this is possible though?
The call structure is ProcessNewBlockHeaders() -> AcceptBlockHeader() -> {CheckBlockHeader() / ContextualCheckBlockHeader()}, and the latter two functions return either true or state.Invalid(...). As a result, ProcessNewBlockHeaders() would always return the invalid state of the first header that fails, and net_processing would abort.

I think the assert() however is too strong. Relying on the chain described by @mzumsande above looks to fragile to me. To assert in such a way, IMO ProcessNewBlockHeaders() should clearly document that it will always set the pointer when it returns true and if it returns false, then the state is invalid. Then the code above should be changed from if (!ProcessNewBlockHeaders...) { if (state.IsInvalid... to maybe assert that the state is invalid or no checking the state at all.

It looks safer to me to remove assert(pindex); and change the condition to:

if (received_new_header && pindex != nullptr) {

Edit: now I see that assert(pindex); existed before this PR and this PR just moves it upwards.

1a5b9d4: I'd like to leave dealing with the assert to a (up for grabs) followup.

mzumsande

Tested ACK b857d92

I like that this makes logging less verbose (by logging one less entry, and by only logging the last header when multiple headers arrive at the same time).

mzumsande · 2023-06-20T18:45:43Z

src/net_processing.cpp

@@ -4268,8 +4295,8 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
        }

        if (received_new_header) {


I don't think this is possible though?
The call structure is ProcessNewBlockHeaders() -> AcceptBlockHeader() -> {CheckBlockHeader() / ContextualCheckBlockHeader()}, and the latter two functions return either true or state.Invalid(...). As a result, ProcessNewBlockHeaders() would always return the invalid state of the first header that fails, and net_processing would abort.

Sjors · 2023-07-28T10:57:59Z

I still have to rebase this, will do soon(tm).

Sjors · 2023-08-01T13:35:56Z

Rebased! (after #26969)

jonatack · 2023-08-01T22:19:58Z

Concept ACK

Sjors · 2023-08-21T10:41:49Z

Rebased after #28218 (no longer needs ActiveChainstate() to get IsInitialBlockDownload()).

Sjors · 2023-08-31T08:40:47Z

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).

Sjors · 2023-11-07T02:25:55Z

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

Sjors · 2023-11-28T13:19:22Z

Trivial rebase after #28892's fa79a88.

Sjors · 2023-11-28T13:20:21Z

@mzumsande can you take another look?

vasild

ACK 708600f

As with the previous ACK: would be nice if other reviewers assess #27826 (comment).

mzumsande · 2023-12-01T19:16:02Z

src/net_processing.cpp

        via_compact_block ? "cmpctblock " : "",
-        index.GetBlockHash().ToString(),
-        index.nHeight,
+        via_unsolicited_block ? " via unsolicited block" : "",


I like the first commit, but the second/third commit are not ideal, because there is a difference between a new block and a new header:
I started up this branch on mainnet while being a few blocks behind (but not that far such that I'd be in IBD so that the log messages would go to BCLog::VALIDATION).
Then, the log entries I'd get for each downloaded block ("Saw new header via unsolicited block") are wrong in two ways:
The header is not new (only the block), plus the block is not unsolicited (we asked for it with a getdata message).

That indeed sounds like two bugs, will try to reproduce.

I can reproduce the issue. When the nodes catches up, for a small fraction of blocks it says "Saw new header via unsolicited block". The header refers to a block that was already connected, sometimes more than 25 blocks ago.

I solved the second issue by setting /*via_unsolicited_block=*/!is_block_requested (renamed forceProcessing). I'll push that in a bit.

I'm still debugging the first issue. E.g an example log during IBD, with -debug=net -debug=validation -loglevel=validation:debug:

2023-12-04T13:47:10Z Synchronizing blockheaders, height: 819750 (~100.00%) 2023-12-04T13:47:10Z [validation:debug] Saw new header hash=00000000000000000002d311ad8da2e7551130798984e20c87b8156c3d27d261 height=819750 peer=1 2023-12-04T13:47:10Z [net] sending sendheaders (0 bytes) peer=1 2023-12-04T13:47:10Z [net] Requesting block 00000000000000000000cb25399b73ca8d7233d889d6f593185d2d9d8c1c12a4 (819343) peer=1 ... 2023-12-04T13:47:10Z [net] Requesting block 00000000000000000000f2a44776f015e8d0fed852974feaa3a4fef29db93863 (819346) peer=1 … 2023-12-04T13:47:11Z [net] received: block (1659646 bytes) peer=1 2023-12-04T13:47:11Z [net] received block 00000000000000000000f2a44776f015e8d0fed852974feaa3a4fef29db93863 peer=1 2023-12-04T13:47:12Z [validation] Pre-allocating up to position 0x900000 in rev03971.dat 2023-12-04T13:47:12Z [validation] BlockChecked: block hash=00000000000000000000f2a44776f015e8d0fed852974feaa3a4fef29db93863 state=Valid 2023-12-04T13:47:12Z UpdateTip: new best=00000000000000000000f2a44776f015e8d0fed852974feaa3a4fef29db93863 height=819346 version=0x32000000 log2_work=94.574638 tx=928820934 date='2023-12-01T22:28:26Z' progress=0.998647 cache=153.7MiB(1297209txo) 2023-12-04T13:47:12Z [validation] Enqueuing BlockConnected: block hash=00000000000000000000f2a44776f015e8d0fed852974feaa3a4fef29db93863 block height=819346 2023-12-04T13:47:12Z [validation] Enqueuing UpdatedBlockTip: new block hash=00000000000000000000f2a44776f015e8d0fed852974feaa3a4fef29db93863 fork block hash=000000000000000000016a22934809aba22dda98fe8a0ee1582b43fe109aebe8 (in IBD=true) 2023-12-04T13:47:12Z [validation:debug] Saw new header hash=00000000000000000000f2a44776f015e8d0fed852974feaa3a4fef29db93863 peer=1 … 2023-12-04T13:47:12Z [validation] BlockConnected: block hash=00000000000000000000f2a44776f015e8d0fed852974feaa3a4fef29db93863 block height=819346 2023-12-04T13:47:12Z [validation] UpdatedBlockTip: new block hash=00000000000000000000f2a44776f015e8d0fed852974feaa3a4fef29db93863 fork block hash=000000000000000000016a22934809aba22dda98fe8a0ee1582b43fe109aebe8 (in IBD=true)

So we already this header from an earlier header sync, yet ProcessBlock returns true which it should only do if the header is new.

Well, according to the documentation that I added myself in the second commit 386febd anyway.

Ah, but that documentation is ~~wrong~~ ambiguous. ProcessBlock only tells us if the block is new, not if the header is new. The latter is checked by AcceptBlockHeader, but not returned.

Sjors · 2023-12-04T14:24:09Z

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: 386febd and 9d4e5af.

Supports -logips Since 2c3a90f we log received headers. For compact blocks we also log which peer sent it (e5ce857), but not for regular headers. That required an additional refactor, which this commit provides, to 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.

Sjors · 2024-01-18T09:51:40Z

Rebased to use the new logging functions LogInfo and LogDebug from #28318 (see developer-notes.md).

Sjors · 2024-03-05T10:25:54Z

@0xB10C you may also find this interesting.

DrahtBot added the Validation label Jun 5, 2023

Sjors force-pushed the 2023/05/saw-header branch from b1637f3 to f25b871 Compare June 5, 2023 12:00

Sjors marked this pull request as draft June 5, 2023 12:11

Sjors force-pushed the 2023/05/saw-header branch from f25b871 to b857d92 Compare June 5, 2023 12:33

Sjors marked this pull request as ready for review June 5, 2023 13:23

Sjors commented Jun 5, 2023

View reviewed changes

This was referenced Jun 5, 2023

Relay own transactions only via short-lived Tor or I2P connections #27509

Closed

net, refactor: net_processing, add ProcessCompactBlockTxns #26969

Merged

Sjors mentioned this pull request Jun 16, 2023

p2p: Log addresses of stalling peers #27761

Merged

DrahtBot mentioned this pull request Jun 17, 2023

Rework validation logic for assumeutxo #27746

Merged

mzumsande reviewed Jun 20, 2023

View reviewed changes

DrahtBot added the Needs rebase label Jun 24, 2023

Sjors force-pushed the 2023/05/saw-header branch from b857d92 to deef9d3 Compare August 1, 2023 13:35

DrahtBot removed the Needs rebase label Aug 1, 2023

DrahtBot mentioned this pull request Aug 5, 2023

refactor: Make IsInitialBlockDownload & NotifyHeaderTip not require a Chainstate #28218

Merged

Sjors force-pushed the 2023/05/saw-header branch from deef9d3 to 050c345 Compare August 21, 2023 10:41

DrahtBot mentioned this pull request Aug 22, 2023

logging: Simplify API for level based logging #28318

Merged

Sjors mentioned this pull request Aug 30, 2023

Move log messages: tx enqueue to mempool, allocation to blockstorage #27277

Draft

Sjors force-pushed the 2023/05/saw-header branch from 050c345 to fe62a60 Compare August 31, 2023 08:36

Sjors mentioned this pull request Aug 31, 2023

Frequent "Timeout downloading block" with 24.1 #27705

Closed

1 task

Sjors mentioned this pull request Sep 7, 2023

BIP324 connection support #28196

Merged

DrahtBot mentioned this pull request Nov 16, 2023

refactor: P2P transport without serialize version and type #28892

Merged

This was referenced Nov 27, 2023

refactor: VectorWriter and SpanReader without nVersion #28912

Merged

refactor: Remove unused SER_DISK, SER_NETWORK, CDataStream #28451

Merged

DrahtBot added the Needs rebase label Nov 28, 2023

Sjors force-pushed the 2023/05/saw-header branch from a460dea to 708600f Compare November 28, 2023 13:19

DrahtBot removed the Needs rebase label Nov 28, 2023

vasild approved these changes Dec 1, 2023

View reviewed changes

mzumsande reviewed Dec 1, 2023

View reviewed changes

DrahtBot requested a review from mzumsande December 1, 2023 19:18

Sjors force-pushed the 2023/05/saw-header branch from 708600f to 9d4e5af Compare December 4, 2023 14:21

Sjors force-pushed the 2023/05/saw-header branch from 9d4e5af to 516b547 Compare December 4, 2023 14:25

DrahtBot mentioned this pull request Dec 20, 2023

p2p: adaptive connections services flags #28170

Merged

DrahtBot added the Needs rebase label Jan 10, 2024

Sjors force-pushed the 2023/05/saw-header branch from 516b547 to e3f7529 Compare January 18, 2024 09:45

DrahtBot added CI failed and removed Needs rebase labels Jan 18, 2024

This was referenced Jan 18, 2024

Improve new LogDebug/Trace/Info/Warning/Error Macros #29256

Open

logging: Update to new logging API #29231

Closed

DrahtBot removed the CI failed label Jan 23, 2024

DrahtBot mentioned this pull request Feb 9, 2024

Broadcast own transactions only via short-lived Tor or I2P connections #29415

Open

DrahtBot added CI failed and removed CI failed labels Feb 27, 2024

DrahtBot mentioned this pull request Mar 13, 2024

scripted-diff: Use LogInfo/LogDebug over LogPrintf/LogPrint #29641

Draft

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

validation: log which peer sent us a header #27826

validation: log which peer sent us a header #27826

Sjors commented Jun 5, 2023 •

edited

DrahtBot commented Jun 5, 2023 •

edited

Sjors commented Jun 5, 2023

Sjors commented Jun 5, 2023 •

edited

Sjors commented Jun 5, 2023 •

edited

Sjors Jun 5, 2023

mzumsande Jun 20, 2023

vasild Oct 6, 2023

Sjors Oct 6, 2023

mzumsande left a comment

mzumsande Jun 20, 2023

Sjors commented Jul 28, 2023

Sjors commented Aug 1, 2023 •

edited

jonatack commented Aug 1, 2023

Sjors commented Aug 21, 2023

Sjors commented Aug 31, 2023 •

edited

Sjors commented Nov 7, 2023

Sjors commented Nov 28, 2023

Sjors commented Nov 28, 2023

vasild left a comment •

edited

mzumsande Dec 1, 2023 •

edited

Sjors Dec 1, 2023

Sjors Dec 4, 2023

Sjors Dec 4, 2023 •

edited

Sjors Dec 4, 2023 •

edited

Sjors commented Dec 4, 2023 •

edited

Sjors commented Jan 18, 2024

Sjors commented Mar 5, 2024

		@@ -4268,8 +4295,8 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
		}

		if (received_new_header) {

validation: log which peer sent us a header #27826

Are you sure you want to change the base?

validation: log which peer sent us a header #27826

Conversation

Sjors commented Jun 5, 2023 • edited

DrahtBot commented Jun 5, 2023 • edited

Code Coverage

Reviews

Conflicts

Sjors commented Jun 5, 2023

Sjors commented Jun 5, 2023 • edited

Sjors commented Jun 5, 2023 • edited

Sjors Jun 5, 2023

Choose a reason for hiding this comment

mzumsande Jun 20, 2023

Choose a reason for hiding this comment

vasild Oct 6, 2023

Choose a reason for hiding this comment

Sjors Oct 6, 2023

Choose a reason for hiding this comment

mzumsande left a comment

Choose a reason for hiding this comment

mzumsande Jun 20, 2023

Choose a reason for hiding this comment

Sjors commented Jul 28, 2023

Sjors commented Aug 1, 2023 • edited

jonatack commented Aug 1, 2023

Sjors commented Aug 21, 2023

Sjors commented Aug 31, 2023 • edited

Sjors commented Nov 7, 2023

Sjors commented Nov 28, 2023

Sjors commented Nov 28, 2023

vasild left a comment • edited

Choose a reason for hiding this comment

mzumsande Dec 1, 2023 • edited

Choose a reason for hiding this comment

Sjors Dec 1, 2023

Choose a reason for hiding this comment

Sjors Dec 4, 2023

Choose a reason for hiding this comment

Sjors Dec 4, 2023 • edited

Choose a reason for hiding this comment

Sjors Dec 4, 2023 • edited

Choose a reason for hiding this comment

Sjors commented Dec 4, 2023 • edited

Sjors commented Jan 18, 2024

Sjors commented Mar 5, 2024

Sjors commented Jun 5, 2023 •

edited

DrahtBot commented Jun 5, 2023 •

edited

Sjors commented Jun 5, 2023 •

edited

Sjors commented Jun 5, 2023 •

edited

Sjors commented Aug 1, 2023 •

edited

Sjors commented Aug 31, 2023 •

edited

vasild left a comment •

edited

mzumsande Dec 1, 2023 •

edited

Sjors Dec 4, 2023 •

edited

Sjors Dec 4, 2023 •

edited

Sjors commented Dec 4, 2023 •

edited