CFilters reject and disconnect peers with a valid block hash #29655

issue djkazic openend this issue on March 14, 2024

djkazic commented at 11:09 pm on March 14, 2024: none

Is there an existing issue for this?

I have searched the existing issues

Current behaviour

For quite some time now, I’ve noticed that neutrino clients connected to my Bitcoin Core instance would have issues connecting after a while. Today, I turned on debug logging for [net] and discovered these messages (see log section). Peers were being disconnected! But strangely, it seems like even though these peers are requesting valid block hashes, Bitcoin Core is rejecting the serving of CFilters to them. No other disconnect messages for CFilters have been observed. I checked validity two ways: by checking against bitcoin-cli getblock as well as using a block explorer (mempool.space).

Expected behaviour

If a BIP-157 client requests a valid block hash as set forth by BlockRequestAllowed, it should receive a response from Bitcoin Core.

Steps to reproduce

Setup Bitcoin Core node with peerbloomfilters=1 and peerblockfilters=1, ensure port 8333 is open. Also set debug=net for debug level for networking logs.
Connect neutrino peer to Bitcoin Core node and wait.
Eventually, you will see the debug network message above.

Relevant log output

  02024-03-14T16:25:48Z [net] received: getcfheaders (37 bytes) peer=35
  12024-03-14T16:25:48Z [net] peer 35 requested invalid block hash: 0000000000000000000132006d75c39161b70fd058da1b740ab02c3f1df4470d
  22024-03-14T16:25:48Z [net] received: verack (0 bytes) peer=71
  3--
  42024-03-14T16:25:48Z [net] received: getcfheaders (37 bytes) peer=12
  52024-03-14T16:25:48Z [net] peer 12 requested invalid block hash: 0000000000000000000132006d75c39161b70fd058da1b740ab02c3f1df4470d
  62024-03-14T16:25:49Z [net] received: getdata (37 bytes) peer=37
  7--
  82024-03-14T16:25:49Z [net] received: getcfheaders (37 bytes) peer=13
  92024-03-14T16:25:49Z [net] peer 13 requested invalid block hash: 0000000000000000000132006d75c39161b70fd058da1b740ab02c3f1df4470d
 102024-03-14T16:25:49Z [net] disconnecting peer=13
 11--
 122024-03-14T16:25:58Z [net] received: getcfilters (37 bytes) peer=75
 132024-03-14T16:25:58Z [net] peer 75 requested invalid block hash: 0000000000000000000132006d75c39161b70fd058da1b740ab02c3f1df4470d
 142024-03-14T16:25:58Z [net] received: getdata (73 bytes) peer=54
 15--
 162024-03-14T16:25:58Z [net] received: getcfilters (37 bytes) peer=72
 172024-03-14T16:25:58Z [net] peer 72 requested invalid block hash: 0000000000000000000132006d75c39161b70fd058da1b740ab02c3f1df4470d
 182024-03-14T16:25:58Z [net] received: tx (372 bytes) peer=11
 19--
 202024-03-14T16:26:14Z [net] received: getcfheaders (37 bytes) peer=50
 212024-03-14T16:26:14Z [net] peer 50 requested invalid block hash: 0000000000000000000132006d75c39161b70fd058da1b740ab02c3f1df4470d
 222024-03-14T16:26:14Z [net] sending inv (37 bytes) peer=54
 23--
 242024-03-14T16:26:14Z [net] received: getcfheaders (37 bytes) peer=1
 252024-03-14T16:26:14Z [net] peer 1 requested invalid block hash: 0000000000000000000132006d75c39161b70fd058da1b740ab02c3f1df4470d
 262024-03-14T16:26:14Z [net] received: getcfheaders (37 bytes) peer=71
 272024-03-14T16:26:14Z [net] peer 71 requested invalid block hash: 0000000000000000000132006d75c39161b70fd058da1b740ab02c3f1df4470d
 282024-03-14T16:26:14Z [net] received: getcfheaders (37 bytes) peer=6
 292024-03-14T16:26:14Z [net] peer 6 requested invalid block hash: 0000000000000000000132006d75c39161b70fd058da1b740ab02c3f1df4470d
 302024-03-14T16:26:14Z [net] received: getcfheaders (37 bytes) peer=3
 312024-03-14T16:26:14Z [net] peer 3 requested invalid block hash: 0000000000000000000132006d75c39161b70fd058da1b740ab02c3f1df4470d
 322024-03-14T16:26:14Z [net] received: tx (327 bytes) peer=25
 33--
 342024-03-14T16:26:15Z [net] Cleared nodestate for peer=71
 352024-03-14T16:26:15Z [net] peer 26 requested invalid block hash: 0000000000000000000132006d75c39161b70fd058da1b740ab02c3f1df4470d
 362024-03-14T16:26:15Z [net] sending inv (109 bytes) peer=54
 37--
 382024-03-14T16:26:15Z [net] received: getcfheaders (37 bytes) peer=9
 392024-03-14T16:26:15Z [net] peer 9 requested invalid block hash: 0000000000000000000132006d75c39161b70fd058da1b740ab02c3f1df4470d
 402024-03-14T16:26:15Z [net] received: tx (345 bytes) peer=46
 41--
 422024-03-14T16:26:15Z [net] received: getcfheaders (37 bytes) peer=67
 432024-03-14T16:26:15Z [net] peer 67 requested invalid block hash: 0000000000000000000132006d75c39161b70fd058da1b740ab02c3f1df4470d
 442024-03-14T16:26:15Z [net] received: getdata (37 bytes) peer=37
 45--
 462024-03-14T16:26:24Z [net] received: getcfilters (37 bytes) peer=84
 472024-03-14T16:26:24Z [net] peer 84 requested invalid block hash: 0000000000000000000132006d75c39161b70fd058da1b740ab02c3f1df4470d
 482024-03-14T16:26:24Z [net] received: getdata (37 bytes) peer=37
 49--
 502024-03-14T16:26:24Z [net] received: getcfilters (37 bytes) peer=87
 512024-03-14T16:26:24Z [net] peer 87 requested invalid block hash: 0000000000000000000132006d75c39161b70fd058da1b740ab02c3f1df4470d
 522024-03-14T16:26:24Z [net] sending inv (577 bytes) peer=57
 53--
 542024-03-14T16:26:25Z [net] received: getcfilters (37 bytes) peer=85
 552024-03-14T16:26:25Z [net] peer 85 requested invalid block hash: 0000000000000000000132006d75c39161b70fd058da1b740ab02c3f1df4470d
 562024-03-14T16:26:25Z [net] Requesting tx c4d0491f6f1d12c2c2f7d3fef9501150b7a4e7f6346dd68308c41050567d5c64 peer=81
 57--
 582024-03-14T16:26:26Z [net] received: getcfilters (37 bytes) peer=90
 592024-03-14T16:26:26Z [net] peer 90 requested invalid block hash: 0000000000000000000132006d75c39161b70fd058da1b740ab02c3f1df4470d
 602024-03-14T16:26:26Z [net] sending inv (109 bytes) peer=68
 61--
 622024-03-14T16:26:53Z [net] received: getcfheaders (37 bytes) peer=98
 632024-03-14T16:26:53Z [net] peer 98 requested invalid block hash: 0000000000000000000132006d75c39161b70fd058da1b740ab02c3f1df4470d
 642024-03-14T16:26:53Z [net] received: ping (8 bytes) peer=28
 65--
 662024-03-14T16:29:23Z [net] received: getcfheaders (37 bytes) peer=126
 672024-03-14T16:29:23Z [net] peer 126 requested invalid block hash: 0000000000000000000132006d75c39161b70fd058da1b740ab02c3f1df4470d
 682024-03-14T16:29:23Z [net] disconnecting peer=126
 69--
 702024-03-14T16:29:51Z [net] received: getcfilters (37 bytes) peer=128
 712024-03-14T16:29:51Z [net] peer 128 requested invalid block hash: 0000000000000000000132006d75c39161b70fd058da1b740ab02c3f1df4470d
 722024-03-14T16:29:51Z [net] sending inv (541 bytes) peer=120
 73--
 742024-03-14T16:30:44Z [net] received: getcfcheckpt (33 bytes) peer=139
 752024-03-14T16:30:44Z [net] peer 139 requested invalid block hash: 0000000000000000000132006d75c39161b70fd058da1b740ab02c3f1df4470d
 762024-03-14T16:30:44Z [net] disconnecting peer=139
 77--
 782024-03-14T16:30:56Z [net] received: getcfheaders (37 bytes) peer=146
 792024-03-14T16:30:56Z [net] peer 146 requested invalid block hash: 0000000000000000000132006d75c39161b70fd058da1b740ab02c3f1df4470d
 802024-03-14T16:30:56Z [net] disconnecting peer=146
 81--
 822024-03-14T16:31:11Z [net] received: getcfheaders (37 bytes) peer=151
 832024-03-14T16:31:11Z [net] peer 151 requested invalid block hash: 0000000000000000000132006d75c39161b70fd058da1b740ab02c3f1df4470d
 842024-03-14T16:31:11Z [net] disconnecting peer=151
 85--
 862024-03-14T16:31:21Z [net] received: getcfilters (37 bytes) peer=154
 872024-03-14T16:31:21Z [net] peer 154 requested invalid block hash: 0000000000000000000132006d75c39161b70fd058da1b740ab02c3f1df4470d
 882024-03-14T16:31:21Z [net] disconnecting peer=154
 89--
 902024-03-14T16:31:39Z [net] received: getcfheaders (37 bytes) peer=153
 912024-03-14T16:31:39Z [net] peer 153 requested invalid block hash: 0000000000000000000132006d75c39161b70fd058da1b740ab02c3f1df4470d
 922024-03-14T16:31:39Z [net] disconnecting peer=153
 93--
 942024-03-14T16:40:31Z [net] received: getcfheaders (37 bytes) peer=74
 952024-03-14T16:40:31Z [net] peer 74 requested invalid block hash: 000000000000000000017ff36e3f004964cdaea7d5e397965673ec5ef9ce9337
 962024-03-14T16:40:31Z [net] disconnecting peer=74
 97--
 982024-03-14T16:40:31Z [net] received: getcfheaders (37 bytes) peer=184
 992024-03-14T16:40:31Z [net] peer 184 requested invalid block hash: 000000000000000000017ff36e3f004964cdaea7d5e397965673ec5ef9ce9337
1002024-03-14T16:40:31Z [net] disconnecting peer=184
101--
1022024-03-14T16:40:31Z [net] received: getcfheaders (37 bytes) peer=73
1032024-03-14T16:40:31Z [net] peer 73 requested invalid block hash: 000000000000000000017ff36e3f004964cdaea7d5e397965673ec5ef9ce9337
1042024-03-14T16:40:31Z [net] disconnecting peer=73
105--
1062024-03-14T16:40:31Z [net] received: getcfheaders (37 bytes) peer=202
1072024-03-14T16:40:31Z [net] peer 202 requested invalid block hash: 000000000000000000017ff36e3f004964cdaea7d5e397965673ec5ef9ce9337
1082024-03-14T16:40:31Z [net] disconnecting peer=202
109--
1102024-03-14T16:40:32Z [net] received: getcfheaders (37 bytes) peer=78
1112024-03-14T16:40:32Z [net] peer 78 requested invalid block hash: 000000000000000000017ff36e3f004964cdaea7d5e397965673ec5ef9ce9337
1122024-03-14T16:40:32Z [net] received: getheaders (69 bytes) peer=222
113--
1142024-03-14T16:40:32Z [net] received: getcfheaders (37 bytes) peer=229
1152024-03-14T16:40:32Z [net] peer 229 requested invalid block hash: 000000000000000000017ff36e3f004964cdaea7d5e397965673ec5ef9ce9337
1162024-03-14T16:40:32Z [net] socket closed for peer=192
117--
1182024-03-14T16:40:32Z [net] received: getcfheaders (37 bytes) peer=77
1192024-03-14T16:40:32Z [net] peer 77 requested invalid block hash: 000000000000000000017ff36e3f004964cdaea7d5e397965673ec5ef9ce9337
1202024-03-14T16:40:32Z [net] disconnecting peer=77
121--
1222024-03-14T16:46:29Z [net] received: getcfheaders (37 bytes) peer=259
1232024-03-14T16:46:29Z [net] peer 259 requested invalid block hash: 00000000000000000001a680cb297921d300dadaab79df9876303b6c0bd9dd69
1242024-03-14T16:46:29Z [net] disconnecting peer=259
125--
1262024-03-14T16:46:29Z [net] received: getcfheaders (37 bytes) peer=241
1272024-03-14T16:46:29Z [net] peer 241 requested invalid block hash: 00000000000000000001a680cb297921d300dadaab79df9876303b6c0bd9dd69
1282024-03-14T16:46:29Z [net] sending inv (37 bytes) peer=265
129--
1302024-03-14T17:01:49Z [net] received: getcfheaders (37 bytes) peer=400
1312024-03-14T17:01:49Z [net] peer 400 requested invalid block hash: 0000000000000000000026ebf8f613a1ce69849f12e2c5f8fd9867c2402e60fc
1322024-03-14T17:01:49Z [net] disconnecting peer=400
133--
1342024-03-14T17:01:49Z [net] received: getcfheaders (37 bytes) peer=303
1352024-03-14T17:01:49Z [net] peer 303 requested invalid block hash: 0000000000000000000026ebf8f613a1ce69849f12e2c5f8fd9867c2402e60fc
1362024-03-14T17:01:50Z [net] disconnecting peer=303
137--
1382024-03-14T17:01:50Z [net] received: getcfheaders (37 bytes) peer=337
1392024-03-14T17:01:50Z [net] peer 337 requested invalid block hash: 0000000000000000000026ebf8f613a1ce69849f12e2c5f8fd9867c2402e60fc
1402024-03-14T17:01:50Z [net] disconnecting peer=337
141--
1422024-03-14T17:01:50Z [net] received: getcfheaders (37 bytes) peer=391
1432024-03-14T17:01:50Z [net] peer 391 requested invalid block hash: 0000000000000000000026ebf8f613a1ce69849f12e2c5f8fd9867c2402e60fc
1442024-03-14T17:01:50Z [net] disconnecting peer=391
145--
1462024-03-14T18:02:26Z [net] received: getcfheaders (37 bytes) peer=828
1472024-03-14T18:02:26Z [net] peer 828 requested invalid block hash: 000000000000000000032b3666aa4da769d272e90a3b95819433ef1ad8cf0f91
1482024-03-14T18:02:26Z [net] disconnecting peer=828
149--
1502024-03-14T18:02:26Z [net] received: getcfheaders (37 bytes) peer=500
1512024-03-14T18:02:26Z [net] peer 500 requested invalid block hash: 000000000000000000032b3666aa4da769d272e90a3b95819433ef1ad8cf0f91
1522024-03-14T18:02:26Z [net] disconnecting peer=500
153--
1542024-03-14T18:02:27Z [net] received: getcfheaders (37 bytes) peer=426
1552024-03-14T18:02:27Z [net] peer 426 requested invalid block hash: 000000000000000000032b3666aa4da769d272e90a3b95819433ef1ad8cf0f91
1562024-03-14T18:02:27Z [net] disconnecting peer=426
1572024-03-14T18:02:27Z [net] received: getcfheaders (37 bytes) peer=606
1582024-03-14T18:02:27Z [net] peer 606 requested invalid block hash: 000000000000000000032b3666aa4da769d272e90a3b95819433ef1ad8cf0f91
1592024-03-14T18:02:27Z [net] disconnecting peer=606
160--
1612024-03-14T18:02:27Z [net] received: getcfheaders (37 bytes) peer=429
1622024-03-14T18:02:27Z [net] peer 429 requested invalid block hash: 000000000000000000032b3666aa4da769d272e90a3b95819433ef1ad8cf0f91
1632024-03-14T18:02:27Z [net] disconnecting peer=429
164--
1652024-03-14T18:02:27Z [net] received: getcfheaders (37 bytes) peer=425
1662024-03-14T18:02:27Z [net] peer 425 requested invalid block hash: 000000000000000000032b3666aa4da769d272e90a3b95819433ef1ad8cf0f91
1672024-03-14T18:02:27Z [net] disconnecting peer=425
168--
1692024-03-14T18:26:18Z [net] received: getcfheaders (37 bytes) peer=905
1702024-03-14T18:26:18Z [net] peer 905 requested invalid block hash: 000000000000000000003b869494f4d6e7de0436d5ecd1b9e897728cdf5ca940
1712024-03-14T18:26:18Z [net] disconnecting peer=905
172--
1732024-03-14T18:26:18Z [net] received: getcfheaders (37 bytes) peer=1003
1742024-03-14T18:26:18Z [net] peer 1003 requested invalid block hash: 000000000000000000003b869494f4d6e7de0436d5ecd1b9e897728cdf5ca940
1752024-03-14T18:26:18Z [net] disconnecting peer=1003
176--
1772024-03-14T19:08:54Z [net] received: getcfheaders (37 bytes) peer=1363
1782024-03-14T19:08:54Z [net] peer 1363 requested invalid block hash: 000000000000000000014e6470d64f5f9e9c370325adaa8628841feb07a62ad0
1792024-03-14T19:08:54Z [net] disconnecting peer=1363
180--
1812024-03-14T19:16:00Z [net] received: getcfheaders (37 bytes) peer=1244
1822024-03-14T19:16:00Z [net] peer 1244 requested invalid block hash: 0000000000000000000262970ea32768668aba73aba631b9a17871fbe988b6c5
1832024-03-14T19:16:00Z [net] disconnecting peer=1244
184--
1852024-03-14T19:47:31Z [net] received: getcfheaders (37 bytes) peer=942
1862024-03-14T19:47:31Z [net] peer 942 requested invalid block hash: 0000000000000000000197ca35169bbd71bacab0258d773398720a23d0fb4a58
1872024-03-14T19:47:31Z [net] disconnecting peer=942
188--
1892024-03-14T19:47:31Z [net] received: getcfheaders (37 bytes) peer=1066
1902024-03-14T19:47:31Z [net] peer 1066 requested invalid block hash: 0000000000000000000197ca35169bbd71bacab0258d773398720a23d0fb4a58
1912024-03-14T19:47:31Z [net] disconnecting peer=1066
192--
1932024-03-14T19:47:31Z [net] received: getcfheaders (37 bytes) peer=907
1942024-03-14T19:47:31Z [net] peer 907 requested invalid block hash: 0000000000000000000197ca35169bbd71bacab0258d773398720a23d0fb4a58
1952024-03-14T19:47:31Z [net] disconnecting peer=907
196--
1972024-03-14T19:47:31Z [net] received: getcfheaders (37 bytes) peer=906
1982024-03-14T19:47:31Z [net] peer 906 requested invalid block hash: 0000000000000000000197ca35169bbd71bacab0258d773398720a23d0fb4a58
1992024-03-14T19:47:31Z [net] sending inv (181 bytes) peer=114
200--
2012024-03-14T19:51:17Z [net] received: getcfheaders (37 bytes) peer=1822
2022024-03-14T19:51:17Z [net] peer 1822 requested invalid block hash: 00000000000000000000c855dc4e0cc69918aed13ed048d38018b63e7b9b071c
2032024-03-14T19:51:17Z [net] disconnecting peer=1822
204--
2052024-03-14T19:51:17Z [net] received: getcfheaders (37 bytes) peer=1798
2062024-03-14T19:51:17Z [net] peer 1798 requested invalid block hash: 00000000000000000000c855dc4e0cc69918aed13ed048d38018b63e7b9b071c
2072024-03-14T19:51:17Z [net] disconnecting peer=1798
208--
2092024-03-14T19:51:58Z [net] received: getcfheaders (37 bytes) peer=1836
2102024-03-14T19:51:58Z [net] peer 1836 requested invalid block hash: 0000000000000000000170d2609f1b73735872a2242789f2190d846f585bddda
2112024-03-14T19:51:58Z [net] disconnecting peer=1836
212--
2132024-03-14T20:03:34Z [net] received: getcfheaders (37 bytes) peer=1841
2142024-03-14T20:03:34Z [net] peer 1841 requested invalid block hash: 0000000000000000000219dfc58b29fbf268e0d2c3b0bbf164e34527e3c03c3b
2152024-03-14T20:03:34Z [net] sending inv (253 bytes) peer=25
216--
2172024-03-14T20:03:34Z [net] received: getcfheaders (37 bytes) peer=1875
2182024-03-14T20:03:34Z [net] peer 1875 requested invalid block hash: 0000000000000000000219dfc58b29fbf268e0d2c3b0bbf164e34527e3c03c3b
2192024-03-14T20:03:34Z [net] disconnecting peer=1875
220--
2212024-03-14T20:11:27Z [net] received: getcfheaders (37 bytes) peer=1837
2222024-03-14T20:11:27Z [net] peer 1837 requested invalid block hash: 00000000000000000000292964b4b00d1d414583bd18d1ebea7a8041d4409c6d
2232024-03-14T20:11:27Z [net] disconnecting peer=1837
224--
2252024-03-14T21:06:43Z [net] received: getcfheaders (37 bytes) peer=2002
2262024-03-14T21:06:43Z [net] peer 2002 requested invalid block hash: 00000000000000000001b224ba634525a3263cda1f8cac13209f7c52b800a275
2272024-03-14T21:06:43Z [net] disconnecting peer=2002
228--
2292024-03-14T22:51:15Z [net] received: getcfheaders (37 bytes) peer=1842
2302024-03-14T22:51:15Z [net] peer 1842 requested invalid block hash: 0000000000000000000069998432cdfe3f87dda9bcd1d33c239fa775fbdfaed4
2312024-03-14T22:51:15Z [net] disconnecting peer=1842

How did you obtain Bitcoin Core

Pre-built binaries

What version of Bitcoin Core are you using?

v26.0.0

Operating system and version

Ubuntu 20.04 LTS

Machine specifications

No response

mzumsande commented at 0:03 am on March 15, 2024: contributor

Comparing the timestamps to those when my node received the respective blocks, it looks to me like these filters are requested immediately after the block was newly found in the network, but at a time when the block hash wasn’t validated and connected yet at your node. Is it possible that the disconnected clients didn’t adhere to this part from BIP157, where they are expected to wait for a headers message before sending the request? StopHash MUST be known to belong to a block accepted by the receiving peer. This is the case if the peer had previously sent a headers or inv message with that block or any descendents. A node that receives getcfilters with an unknown StopHash SHOULD NOT respond.
maflcko commented at 7:14 am on March 15, 2024: member

IIRC the filters are built in a background thread, which is not waited on, so this may happen even if the remote knows that the block was connected already.
djkazic commented at 12:18 pm on March 15, 2024: none

OK sounds like this is normal behavior. I’ll take a look at the neutrino side of things.

Thanks for taking a look @maflcko and @mzumsande!
mzumsande commented at 2:41 pm on March 15, 2024: contributor

IIRC the filters are built in a background thread, which is not waited on, so this may happen even if the remote knows that the block was connected already.

Yes, I think so too. Though in that case (if we had connected the tip but not constructed the filter yet) there should be a different error message (“Failed to find block filter in index”) and we wouldn’t disconnect but ignore the request, so it likely didn’t happen here.

OK sounds like this is normal behavior.

I would agree that it’s normal to not answer the request (if we really haven’t connected and advertised the block - would be good to double-check that in the log) - but maybe it could still be better to just not answer if the requested blockfilter is 1 above the current tip instead of disconnecting.
bitcoin deleted a comment on Mar 19, 2024
willcl-ark added the label P2P on Mar 20, 2024

Contributors
djkazic mzumsande maflcko

Labels
P2P