validation: log which peer sent us a header

Sjors commented at 11:53 am on June 5, 2023: member

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:

02023-06-05T13:12:21Z Saw new header hash=000000000000000000045910263ef84b575ae3af151865238f1e5c619e69c330 height=792964 peer=0
12023-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)
22023-06-05T13:14:05Z Saw new cmpctblock header hash=00000000000000000003c6fd4ef2e1246a3f9e1fffab7247344f94cadb9de979 height=792965 peer=0
32023-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)
42023-06-05T13:14:41Z Saw new header hash=000000000000000000048e6d69c8399992782d08cb57f5d6cbc81a9f996c3f43 height=792966 peer=8
52023-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 commented at 11:53 am on June 5, 2023: contributor

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)
#30277 ([DO NOT MERGE] Erlay: bandwidth-efficient transaction relay protocol (Full implementation) by sr-gi)
#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.

DrahtBot added the label Validation on Jun 5, 2023

Sjors commented at 11:59 am on June 5, 2023: member

cc @jamesob, @instagibbs, @mzumsande

Sjors force-pushed on Jun 5, 2023

Sjors marked this as a draft on Jun 5, 2023

Sjors commented at 12:15 pm on June 5, 2023: member

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:

02023-06-05T11:50:30Z Saw new cmpctblock header hash=000000000000000000042a2c4e3910c5ccd48b4b2d624f08b4b5a413b98af4ea height=792960 peer=9
12023-06-05T11:50:30Z Saw new header hash=000000000000000000042a2c4e3910c5ccd48b4b2d624f08b4b5a413b98af4ea height=792960 peer=6
22023-06-05T11:50:31Z Saw new header hash=000000000000000000042a2c4e3910c5ccd48b4b2d624f08b4b5a413b98af4ea height=792960 peer=13
32023-06-05T11:50:31Z Saw new header hash=000000000000000000042a2c4e3910c5ccd48b4b2d624f08b4b5a413b98af4ea height=792960 peer=16
42023-06-05T11:50:31Z Saw new header hash=000000000000000000042a2c4e3910c5ccd48b4b2d624f08b4b5a413b98af4ea height=792960 peer=15
52023-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)
62023-06-05T11:50:31Z Saw new header hash=000000000000000000042a2c4e3910c5ccd48b4b2d624f08b4b5a413b98af4ea height=792960 peer=3

Moving to draft while I give it more thought.

Sjors force-pushed on Jun 5, 2023

Sjors commented at 12:34 pm on June 5, 2023: member

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 marked this as ready for review on Jun 5, 2023

in src/net_processing.cpp:4445 in b857d92044 outdated

4294@@ -4268,8 +4295,8 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
4295         }
4296 
4297         if (received_new_header) {

Sjors commented at 1:56 pm on June 5, 2023:

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

mzumsande commented at 6:45 pm on June 20, 2023:

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.

vasild commented at 2:46 pm on October 6, 2023:

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:

0if (received_new_header && pindex != nullptr) {

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

Sjors commented at 4:37 pm on October 6, 2023:

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

mzumsande commented at 6:55 pm on June 20, 2023: contributor

Tested ACK b857d920444241f1598b6be509796d1d8e14dbbb

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

DrahtBot added the label Needs rebase on Jun 24, 2023

Sjors commented at 10:57 am on July 28, 2023: member

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

Sjors force-pushed on Aug 1, 2023

Sjors commented at 1:35 pm on August 1, 2023: member

Rebased! (after #26969)

DrahtBot removed the label Needs rebase on Aug 1, 2023

jonatack commented at 10:19 pm on August 1, 2023: contributor

Concept ACK

Sjors commented at 10:41 am on August 21, 2023: member

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

Sjors force-pushed on Aug 21, 2023

Sjors force-pushed on Aug 31, 2023

Sjors commented at 8:40 am on August 31, 2023: member

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 force-pushed on Sep 28, 2023

Sjors commented at 1:18 pm on September 28, 2023: member

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.

Sjors force-pushed on Sep 28, 2023

DrahtBot added the label CI failed on Sep 28, 2023

DrahtBot removed the label CI failed on Sep 28, 2023

DrahtBot added the label Needs rebase on Oct 5, 2023

Sjors commented at 2:45 pm on October 5, 2023: member

Rebased.

Sjors force-pushed on Oct 5, 2023

DrahtBot removed the label Needs rebase on Oct 5, 2023

in src/net_processing.cpp:1068 in a0edbded5f outdated

1063@@ -1058,6 +1064,8 @@ class PeerManagerImpl final : public PeerManager
1064 
1065     void AddAddressKnown(Peer& peer, const CAddress& addr) EXCLUSIVE_LOCKS_REQUIRED(g_msgproc_mutex);
1066     void PushAddress(Peer& peer, const CAddress& addr) EXCLUSIVE_LOCKS_REQUIRED(g_msgproc_mutex);
1067+
1068+    void LogBlockHeader(uint256 block_hash, std::optional<int> height, const CNode& peer, const bool via_compact_block = false, const bool via_unsolicited_block = false);

vasild commented at 2:24 pm on October 6, 2023:

nit: There is no point in qualifying by value parameters with const.

0    void LogBlockHeader(uint256 block_hash, std::optional<int> height, const CNode& peer, const bool via_compact_block = false, bool via_unsolicited_block = false);

Sjors commented at 4:55 pm on October 6, 2023:

Fixed

in src/net_processing.cpp:3358 in a0edbded5f outdated

3363+    // To prevent log spam, this function should only be called after it was determined that a
3364+    // header is both new and valid.
3365+    //
3366+    // These messages are valuable for detecting potential selfish mining behavior;
3367+    // if multiple displacing headers are seen near simultaneously across many
3368+    // nodes in the network, this might be an indication of selfish mining.

vasild commented at 2:31 pm on October 6, 2023:

What is selfish mining? Miners are expected to be selfish and that is ok, no?

Sjors commented at 4:24 pm on October 6, 2023:

I’m not sure if it’s precisely defined anywhere, but the term is used to describe a situation where a miner intentionally doesn’t broadcast their new block and instead waits for a competitor to mine at the same height, hoping that the network picks their side of the fork. When @jamesob first opened an earlier version of this PR, there were rumors of such an attack happening, but this may have been a misunderstanding based on our block connection logging. https://bitcoin.stackexchange.com/questions/tagged/selfish-mining

in src/net_processing.cpp:3369 in a0edbded5f outdated

3375+        via_compact_block ? "cmpctblock " : "",
3376+        via_unsolicited_block ? " via unsolicited block" : "",
3377+        hash.ToString(),
3378+        height ? strprintf(" height=%d", height.value()) : "",
3379+        peer.GetId(),
3380+        fLogIPs ? strprintf(" peeraddr=%s", peer.addr.ToStringAddrPort()) : ""

vasild commented at 2:33 pm on October 6, 2023:

To avoid double space between the hash and the height and between the peer id and address:

0        "Saw new %sheader%s hash=%s%s peer=%d%s",
1        via_compact_block ? "cmpctblock " : "",
2        via_unsolicited_block ? " via unsolicited block" : "",
3        hash.ToString(),
4        height ? strprintf(" height=%d", height.value()) : "",
5        peer.GetId(),
6        fLogIPs ? strprintf(" peeraddr=%s", peer.addr.ToStringAddrPort()) : ""

Sjors commented at 4:55 pm on October 6, 2023:

Fixed

in src/validation.cpp:4001 in a0edbded5f outdated

3989-        LogPrintLevel(BCLog::VALIDATION, BCLog::Level::Debug, "%s\n", msg);
3990-    } else {
3991-        LogPrintf("%s\n", msg);
3992-    }
3993-
3994     return true;

vasild commented at 3:06 pm on October 6, 2023:

In master this logs if AcceptBlockHeader() returns true. This PR removes the log from here and moves it to the callers.

The call chains are like this: ProcessHeadersMessage() -> ProcessNewBlockHeaders() -> AcceptBlockHeader() (has the log) ProcessMessage() -> ProcessNewBlockHeaders() -> AcceptBlockHeader() (has the log) submitheader() -> ProcessNewBlockHeaders() -> AcceptBlockHeader() (omits the log) AcceptBlock() -> AcceptBlockHeader() (omits the log)

are the two log omissions intentional?

Sjors commented at 4:50 pm on October 6, 2023:

They’re not intentional, but I believe it’s fine:

submitheader() is only used for mining, for which this log isn’t relevant, so it’s fine to omit.
AcceptBlock() -> AcceptBlockHeader(): this is called in the following ways:
- in LoadExternalBlockFile(): not relevant for this log
- from ProcessNewBlock() called from:
  - the kernel demo utility bitcoin-chainstate.cpp: not relevant
  - GenerateBlock(): (mining / tests)
  - ProcessBlock() in net_processing.cpp:
    - when receiving CMPCTBLOCK and in ProcessCompactBlockTxns(): part of compact block processing, we’ve already logged the new header for that earlier
when receiving a BLOCK directly: handled in the third commit

mzumsande commented at 7:30 pm on December 1, 2023:

I looked at this independently (tracing the call chains before reading this thread), and I came to the same conclusion as Sjors, except for the case of a direct BLOCK, which has an issue that I mentioned below.

in src/net_processing.cpp:1070 in a0edbded5f outdated

1063@@ -1058,6 +1064,8 @@ class PeerManagerImpl final : public PeerManager
1064 
1065     void AddAddressKnown(Peer& peer, const CAddress& addr) EXCLUSIVE_LOCKS_REQUIRED(g_msgproc_mutex);
1066     void PushAddress(Peer& peer, const CAddress& addr) EXCLUSIVE_LOCKS_REQUIRED(g_msgproc_mutex);
1067+

vasild commented at 3:14 pm on October 6, 2023:

In the commit message of a0edbded5f validation: log new header from unsolicited block: s/only only/only/

in src/net_processing.cpp:964 in a0edbded5f outdated

951+     * @param[in]   block               The block
952+     * @param[in]   force_processing    Bypass some of our anti-DoS protections
953+     * @param[in]   min_pow_checked     The header is known to be part of a sufficiently high-work chain (anti-dos check)
954+     * @return                          True if this is a new block
955+     */
956+    bool ProcessBlock(CNode& node, const std::shared_ptr<const CBlock>& block, bool force_processing, bool min_pow_checked);

vasild commented at 3:15 pm on October 6, 2023:

Would be nice to wrap the long lines in the commit message of 1a5b9d4a09 validation: log which peer sent us a header to something like 70-80 columns.

vasild commented at 3:24 pm on October 6, 2023: contributor

Approach ACK a0edbded5f998c7efb005c8f9a8f9aba9c7bbda9

Sjors force-pushed on Oct 6, 2023

Sjors commented at 4:55 pm on October 6, 2023: member

Rebased and addressed @vasild’s feedback.

vasild approved

vasild commented at 9:09 am on October 9, 2023: contributor

ACK a460dea70a4fb1b6e82534de27b13a4a1f4f06f7

Would be nice if other reviewers assess #27826 (review). I am new to this area of the code.

DrahtBot requested review from mzumsande on Oct 9, 2023

DrahtBot requested review from jonatack on Oct 9, 2023

Sjors commented at 2:25 am on November 7, 2023: member

I get between 0 and 2 of these unsolicited blocks per day:

02023-11-07T02:19:56.507378Z Saw new header via unsolicited block hash=00000000000000000003310c8a9104bc38473171de3d2628ce608b7418384402 peer=0 peeraddr=x.x.x.x:8333

DrahtBot added the label Needs rebase on Nov 28, 2023

Sjors force-pushed on Nov 28, 2023

Sjors commented at 1:19 pm on November 28, 2023: member

Trivial rebase after #28892’s fa79a881ce0537e1d74da296a7513730438d2a02.

Sjors commented at 1:20 pm on November 28, 2023: member

@mzumsande can you take another look?

DrahtBot removed the label Needs rebase on Nov 28, 2023

vasild approved

vasild commented at 7:50 am on December 1, 2023: contributor

ACK 708600f3b7df4cf166a2fcdfd3c0dc70b70812f0

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

in src/net_processing.cpp:3374 in 708600f3b7 outdated

3368@@ -3369,10 +3369,11 @@ void PeerManagerImpl::LogBlockHeader(const CBlockIndex& index, const CNode& peer
3369     // Having this log by default when not in IBD ensures broad availability of
3370     // this data in case investigation is merited.
3371     const auto msg = strprintf(
3372-        "Saw new %sheader hash=%s height=%d peer=%d%s",
3373+        "Saw new %sheader%s hash=%s%s peer=%d%s",
3374         via_compact_block ? "cmpctblock " : "",
3375-        index.GetBlockHash().ToString(),
3376-        index.nHeight,
3377+        via_unsolicited_block ? " via unsolicited block" : "",

mzumsande commented at 7:16 pm on December 1, 2023:

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

Sjors commented at 7:41 pm on December 1, 2023:

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

Sjors commented at 12:53 pm on December 4, 2023:

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.

Sjors commented at 2:02 pm on December 4, 2023:

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:

 02023-12-04T13:47:10Z Synchronizing blockheaders, height: 819750 (~100.00%)
 12023-12-04T13:47:10Z [validation:debug] Saw new header hash=00000000000000000002d311ad8da2e7551130798984e20c87b8156c3d27d261 height=819750 peer=1
 22023-12-04T13:47:10Z [net] sending sendheaders (0 bytes) peer=1
 32023-12-04T13:47:10Z [net] Requesting block 00000000000000000000cb25399b73ca8d7233d889d6f593185d2d9d8c1c12a4 (819343) peer=1
 4...
 52023-12-04T13:47:10Z [net] Requesting block 00000000000000000000f2a44776f015e8d0fed852974feaa3a4fef29db93863 (819346) peer=1
 6…
 72023-12-04T13:47:11Z [net] received: block (1659646 bytes) peer=1
 82023-12-04T13:47:11Z [net] received block 00000000000000000000f2a44776f015e8d0fed852974feaa3a4fef29db93863 peer=1
 92023-12-04T13:47:12Z [validation] Pre-allocating up to position 0x900000 in rev03971.dat
102023-12-04T13:47:12Z [validation] BlockChecked: block hash=00000000000000000000f2a44776f015e8d0fed852974feaa3a4fef29db93863 state=Valid
112023-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)
122023-12-04T13:47:12Z [validation] Enqueuing BlockConnected: block hash=00000000000000000000f2a44776f015e8d0fed852974feaa3a4fef29db93863 block height=819346
132023-12-04T13:47:12Z [validation] Enqueuing UpdatedBlockTip: new block hash=00000000000000000000f2a44776f015e8d0fed852974feaa3a4fef29db93863 fork block hash=000000000000000000016a22934809aba22dda98fe8a0ee1582b43fe109aebe8 (in IBD=true)
142023-12-04T13:47:12Z [validation:debug] Saw new header hash=00000000000000000000f2a44776f015e8d0fed852974feaa3a4fef29db93863 peer=1
15…
162023-12-04T13:47:12Z [validation] BlockConnected: block hash=00000000000000000000f2a44776f015e8d0fed852974feaa3a4fef29db93863 block height=819346
172023-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 386febd59bd894ad9c5216eacafe0308ed314980 anyway.

Sjors commented at 2:11 pm on December 4, 2023:

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.

DrahtBot requested review from mzumsande on Dec 1, 2023

Sjors force-pushed on Dec 4, 2023

Sjors commented at 2:24 pm on December 4, 2023: member

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.

Sjors force-pushed on Dec 4, 2023

DrahtBot added the label Needs rebase on Jan 10, 2024

validation: log which peer sent us a header

Supports -logips

Since 2c3a90f663a61ee147d785167a2902494d81d34d 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 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.

e3f752982b

Sjors force-pushed on Jan 18, 2024

Sjors commented at 9:51 am on January 18, 2024: member

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

DrahtBot added the label CI failed on Jan 18, 2024

DrahtBot removed the label Needs rebase on Jan 18, 2024

DrahtBot removed the label CI failed on Jan 23, 2024

DrahtBot added the label CI failed on Feb 27, 2024

DrahtBot removed the label CI failed on Mar 3, 2024

Sjors commented at 10:25 am on March 5, 2024: member

@0xB10C you may also find this interesting.

validation: log which peer sent us a header #27826

Code Coverage

Reviews

Conflicts