Frequent "Timeout downloading block" with 24.1 #27705

Is there an existing issue for this?

• I have searched the existing issues

Current behaviour

After updating to 24.1 yesterday I'm seeing frequent "Timeout downloading block" on two of my four public nodes, which is pretty annoying since the timeout is 10 minutes, which means every single timeout causes a 10-minute stall on new block downloads. The other two public nodes both have a couple of timeouts, but nothing frequent. A private listen=0 tor-only node also running 24.1 does not have any timeouts at all.

Additionally, even with -logips set, the log does not include the IP of the disconnected peer. Combined with the fact that Bitcoin Core does not log incoming connections and that disconnected nodes (for obvious reasons) do not show up with getpeerinfo, this makes it hard to check for and/or block malicious activity, like say nodes that intentionally stall block uploads. Using debug logging with -debug=net does of course log this information, but this makes the logs very noisy and very large for a well-connected node.

There are no CPU starvation or general internet connectivity issues on the nodes.

Expected behaviour

Block downloads should not stall even if a particular peer is intentionally or unintentionally sending a block slowly. Additionally, if a peer is disconnected for any sort of bad behavior (especially if -logips is set), the IP of the disconnected node should be included in the log.

Steps to reproduce

No particular steps required outside of a running a public node.

Relevant log output

Node 1:

Bitcoin Core client v24.1 - server 70016/Satoshi:24.1/

ipv4 ipv6 onion total block in 92 13 14 119 out 1 3 6 10 2 total 93 16 20 129

2023-05-19T21:34:56Z UpdateTip: new best=000000000000000000054db4904ce0b336298268232b0ab2181d34cef56c9a60 height=790516 version=0x299bc000 log2_work=94.189904 tx=840606270 date='2023-05-19T21:34:36Z' progress=1.000000 cache=88.2MiB(660173txo) 2023-05-19T21:53:02Z Timeout downloading block 00000000000000000001fbe4a76a314e46e167682edb0042a5c262e490ff11c0 from peer=528, disconnecting 2023-05-19T21:54:18Z UpdateTip: new best=00000000000000000001fbe4a76a314e46e167682edb0042a5c262e490ff11c0 height=790517 version=0x32d78000 log2_work=94.189917 tx=840609678 date='2023-05-19T21:42:45Z' progress=0.999998 cache=89.9MiB(672511txo) 2023-05-19T22:25:35Z Timeout downloading block 000000000000000000038e06ef0ca7134739192cc3b82998a68481cad5528f24 from peer=996, disconnecting 2023-05-19T22:25:37Z UpdateTip: new best=000000000000000000038e06ef0ca7134739192cc3b82998a68481cad5528f24 height=790518 version=0x20010000 log2_work=94.189931 tx=840612320 date='2023-05-19T22:15:32Z' progress=0.999998 cache=91.8MiB(688243txo) 2023-05-19T22:25:39Z UpdateTip: new best=00000000000000000001295e20a452e428618695a831ce085516805406c3b018 height=790519 version=0x2879e000 log2_work=94.189944 tx=840615393 date='2023-05-19T22:16:56Z' progress=0.999998 cache=92.6MiB(693909txo) 2023-05-19T22:25:39Z UpdateTip: new best=0000000000000000000003adad2e1fb5c758bf7b45dd3f17e62744020e334f1a height=790520 version=0x20e00000 log2_work=94.189958 tx=840618465 date='2023-05-19T22:20:55Z' progress=0.999999 cache=93.4MiB(699848txo) 2023-05-19T22:52:47Z Timeout downloading block 000000000000000000014911b17e57ba7d201261b97e0fe5f6b952dde70dd9ac from peer=1333, disconnecting 2023-05-19T22:52:51Z UpdateTip: new best=000000000000000000014911b17e57ba7d201261b97e0fe5f6b952dde70dd9ac height=790521 version=0x286e2000 log2_work=94.189972 tx=840621159 date='2023-05-19T22:41:43Z' progress=0.999998 cache=11.0MiB(0txo) 2023-05-19T22:52:51Z UpdateTip: new best=0000000000000000000461d43123648d55faadcb39bc62ce08538540fffe3ce7 height=790522 version=0x20000000 log2_work=94.189985 tx=840623160 date='2023-05-19T22:43:45Z' progress=0.999998 cache=12.6MiB(11120txo) 2023-05-19T22:52:52Z UpdateTip: new best=0000000000000000000168b393a49306642ebafe2efa5b38d86d0165c35b8737 height=790523 version=0x304d0000 log2_work=94.189999 tx=840627385 date='2023-05-19T22:50:01Z' progress=0.999999 cache=14.0MiB(21889txo) 2023-05-19T23:04:11Z Timeout downloading block 00000000000000000003f5cdcbb70f768d5b3473586133cf4167092f968bfce4 from peer=1592, disconnecting 2023-05-19T23:07:42Z UpdateTip: new best=00000000000000000003f5cdcbb70f768d5b3473586133cf4167092f968bfce4 height=790524 version=0x2e5e4000 log2_work=94.190012 tx=840630544 date='2023-05-19T22:53:51Z' progress=0.999997 cache=15.9MiB(35889txo) 2023-05-19T23:16:10Z Timeout downloading block 0000000000000000000527be3083eda106dbb87792b553e3ad7b0d878754ab88 from peer=1717, disconnecting 2023-05-19T23:16:18Z UpdateTip: new best=0000000000000000000527be3083eda106dbb87792b553e3ad7b0d878754ab88 height=790525 version=0x29560000 log2_work=94.190026 tx=840633375 date='2023-05-19T23:05:39Z' progress=0.999998 cache=17.2MiB(45761txo) 2023-05-19T23:16:19Z UpdateTip: new best=00000000000000000004feba1ca408802ab59f5a04ae7723b8fc771d6ae28276 height=790526 version=0x2001a000 log2_work=94.190040 tx=840637107 date='2023-05-19T23:14:48Z' progress=1.000000 cache=18.2MiB(52767txo) 2023-05-19T23:27:19Z UpdateTip: new best=00000000000000000002383944d95cb6c6256666698bc7834791a015ce885766 height=790527 version=0x20800000 log2_work=94.190053 tx=840640322 date='2023-05-19T23:27:13Z' progress=1.000000 cache=19.7MiB(64515txo) 2023-05-19T23:42:49Z Timeout downloading block 000000000000000000015038841b83f36a391525c07582ae1be4f18dc9642fbc from peer=1838, disconnecting 2023-05-19T23:42:51Z UpdateTip: new best=000000000000000000015038841b83f36a391525c07582ae1be4f18dc9642fbc height=790528 version=0x25570000 log2_work=94.190067 tx=840643637 date='2023-05-19T23:33:23Z' progress=0.999998 cache=21.3MiB(75974txo) 2023-05-20T00:00:13Z UpdateTip: new best=00000000000000000000179fce05e3d2c93c9a8d4d48e7f01b36bbc59a4bdc73 height=790529 version=0x22182000 log2_work=94.190080 tx=840647227 date='2023-05-19T23:50:42Z' progress=0.999998 cache=22.9MiB(88206txo) 2023-05-20T00:59:33Z UpdateTip: new best=00000000000000000000529feb03ff753ff4e33a59a65b8515d3767b15033905 height=790530 version=0x311f2000 log2_work=94.190094 tx=840649210 date='2023-05-20T00:59:07Z' progress=1.000000 cache=27.0MiB(120827txo) 2023-05-20T01:41:31Z Timeout downloading block 00000000000000000000e1fd90fa89080b269ec81e5a40883bcc2ec6afffe123 from peer=2238, disconnecting 2023-05-20T01:41:35Z UpdateTip: new best=00000000000000000000e1fd90fa89080b269ec81e5a40883bcc2ec6afffe123 height=790531 version=0x2190e000 log2_work=94.190108 tx=840651947 date='2023-05-20T01:31:03Z' progress=0.999998 cache=29.2MiB(138000txo) 2023-05-20T01:46:03Z UpdateTip: new best=00000000000000000003bed470951558dcd621d719fc3f2acc1a2e79b086927f height=790532 version=0x32932000 log2_work=94.190121 tx=840654849 date='2023-05-20T01:45:46Z' progress=1.000000 cache=30.3MiB(146376txo) 2023-05-20T02:10:27Z Timeout downloading block 00000000000000000004765247e88780b53b239be8c37a32e90cac48e438e159 from peer=3358, disconnecting 2023-05-20T02:10:37Z UpdateTip: new best=00000000000000000004765247e88780b53b239be8c37a32e90cac48e438e159 height=790533 version=0x27254000 log2_work=94.190135 tx=840658180 date='2023-05-20T01:59:57Z' progress=0.999998 cache=32.1MiB(160585txo) 2023-05-20T02:10:45Z UpdateTip: new best=0000000000000000000104f1530223f229565760cc29670023135be476987928 height=790534 version=0x2e2a8000 log2_work=94.190148 tx=840660461 date='2023-05-20T02:06:12Z' progress=0.999999 cache=32.7MiB(165456txo) 2023-05-20T02:10:45Z UpdateTip: new best=00000000000000000002d3f7e28de73899bbcbd071e63a17df899ae42bde3958 height=790535 version=0x27ffe000 log2_work=94.190162 tx=840663087 date='2023-05-20T02:09:48Z' progress=1.000000 cache=33.5MiB(170994txo) 2023-05-20T02:21:31Z Timeout downloading block 00000000000000000000884c3c8df78e3914cff044a4367c23e511197259bfbf from peer=3637, disconnecting 2023-05-20T02:21:36Z UpdateTip: new best=00000000000000000000884c3c8df78e3914cff044a4367c23e511197259bfbf height=790536 version=0x232b2000 log2_work=94.190175 tx=840665684 date='2023-05-20T02:11:20Z' progress=0.999998 cache=34.1MiB(176019txo) 2023-05-20T02:21:36Z UpdateTip: new best=00000000000000000004437862638d8a13746fb9446ea927f92716b8a1c49440 height=790537 version=0x23f52000 log2_work=94.190189 tx=840668515 date='2023-05-20T02:19:35Z' progress=1.000000 cache=34.7MiB(180351txo) 2023-05-20T03:04:23Z Timeout downloading block 00000000000000000004503252b4a5d605be32da2e5ed2c002ab2b6f35a0eaad from peer=3744, disconnecting 2023-05-20T03:04:26Z UpdateTip: new best=00000000000000000004503252b4a5d605be32da2e5ed2c002ab2b6f35a0eaad height=790538 version=0x20006000 log2_work=94.190203 tx=840671778 date='2023-05-20T02:53:40Z' progress=0.999998 cache=36.8MiB(196605txo) 2023-05-20T03:18:08Z UpdateTip: new best=0000000000000000000575481408474f456a0831aa8f13968c0184eccb540941 height=790539 version=0x2000a000 log2_work=94.190216 tx=840674303 date='2023-05-20T03:15:11Z' progress=0.999999 cache=38.2MiB(207324txo) 2023-05-20T03:18:08Z UpdateTip: new best=0000000000000000000475caa0c227309ff3ed0cfb69fc7c9ac6717ba730e198 height=790540 version=0x20004000 log2_work=94.190230 tx=840675877 date='2023-05-20T03:17:29Z' progress=1.000000 cache=39.3MiB(215485txo) 2023-05-20T03:29:30Z Timeout downloading block 00000000000000000004100c05b266036543446601cd45d44231b8c03cae7f63 from peer=4310, disconnecting 2023-05-20T03:29:39Z UpdateTip: new best=00000000000000000004100c05b266036543446601cd45d44231b8c03cae7f63 height=790541 version=0x27260000 log2_work=94.190243 tx=840679394 date='2023-05-20T03:18:48Z' progress=0.999998 cache=40.4MiB(222857txo) 2023-05-20T03:29:42Z UpdateTip: new best=00000000000000000002411c4f32f22152c0b7add2e1562646739255d5789b53 height=790542 version=0x29a1c000 log2_work=94.190257 tx=840682729 date='2023-05-20T03:22:54Z' progress=0.999999 cache=40.8MiB(226160txo) 2023-05-20T03:29:43Z UpdateTip: new best=00000000000000000000da67581c7e1ab0243c7583eb38452c2e4637e0c85bae height=790543 version=0x20002000 log2_work=94.190271 tx=840685692 date='2023-05-20T03:25:54Z' progress=0.999999 cache=41.6MiB(231635txo) 2023-05-20T03:41:24Z Timeout downloading block 000000000000000000008aa49a59592900449f079cdccd0de6971a0a0be26f8a from peer=4422, disconnecting 2023-05-20T03:41:30Z UpdateTip: new best=000000000000000000008aa49a59592900449f079cdccd0de6971a0a0be26f8a height=790544 version=0x25cbc000 log2_work=94.190284 tx=840689566 date='2023-05-20T03:30:47Z' progress=0.999998 cache=42.6MiB(239170txo) 2023-05-20T03:41:34Z UpdateTip: new best=0000000000000000000250e67a43537ef18b95a69e3d312d25edbbd3ffa78953 height=790545 version=0x20112000 log2_work=94.190298 tx=840694197 date='2023-05-20T03:33:47Z' progress=0.999998 cache=43.4MiB(244384txo) 2023-05-20T04:09:57Z Timeout downloading block 0000000000000000000245ddb1e5f49b21d2e9b543463d45c0236a72781c442e from peer=4545, disconnecting 2023-05-20T04:09:57Z UpdateTip: new best=0000000000000000000245ddb1e5f49b21d2e9b543463d45c0236a72781c442e height=790546 version=0x29b30000 log2_work=94.190311 tx=840697341 date='2023-05-20T03:59:42Z' progress=0.999998 cache=45.6MiB(261162txo) 2023-05-20T04:23:38Z Timeout downloading block 0000000000000000000217929eefda8ff53a270b696981e6faa2ac77a98fcfc4 from peer=4827, disconnecting 2023-05-20T04:23:47Z UpdateTip: new best=0000000000000000000217929eefda8ff53a270b696981e6faa2ac77a98fcfc4 height=790547 version=0x20f36000 log2_work=94.190325 tx=840699966 date='2023-05-20T04:13:37Z' progress=0.999998 cache=46.5MiB(267581txo) 2023-05-20T04:23:54Z UpdateTip: new best=00000000000000000003bdd2634e7023b28b116f630192201354aba38e630c35 height=790548 version=0x23912000 log2_work=94.190338 tx=840703717 date='2023-05-20T04:18:25Z' progress=0.999999 cache=47.3MiB(273003txo) 2023-05-20T04:23:54Z UpdateTip: new best=0000000000000000000092674d788cb30ac843d10ee6e2c950f03c82146e72f1 height=790549 version=0x20d92000 log2_work=94.190352 tx=840707656 date='2023-05-20T04:18:46Z' progress=0.999999 cache=48.5MiB(281210txo) 2023-05-20T05:11:13Z UpdateTip: new best=00000000000000000003e0cedb9f8a2b07862f394bf3b0f2975d91df0e63eda2 height=790550 version=0x2000a000 log2_work=94.190366 tx=840711043 date='2023-05-20T05:11:02Z' progress=1.000000 cache=51.3MiB(302548txo) 2023-05-20T05:25:46Z Timeout downloading block 000000000000000000034db4134f765854fadb8e3bc8a21b698aeb73841b18aa from peer=4957, disconnecting 2023-05-20T05:25:48Z UpdateTip: new best=000000000000000000034db4134f765854fadb8e3bc8a21b698aeb73841b18aa height=790551 version=0x2000e000 log2_work=94.190379 tx=840713950 date='2023-05-20T05:15:24Z' progress=0.999998 cache=52.1MiB(309174txo) 2023-05-20T05:25:48Z UpdateTip: new best=000000000000000000057b18e4ea1b3642de481c03cb00e39435a60d2692a88b height=790552 version=0x21756004 log2_work=94.190393 tx=840715875 date='2023-05-20T05:22:30Z' progress=0.999999 cache=52.3MiB(309970txo) 2023-05-20T05:50:58Z Timeout downloading block 0000000000000000000574c26d4b484d26714502df129c5a382e6f05fac3523e from peer=5620, disconnecting 2023-05-20T05:51:00Z UpdateTip: new best=0000000000000000000574c26d4b484d26714502df129c5a382e6f05fac3523e height=790553 version=0x351c4000 log2_work=94.190406 tx=840719434 date='2023-05-20T05:40:33Z' progress=0.999998 cache=53.6MiB(319899txo) 2023-05-20T05:51:00Z UpdateTip: new best=00000000000000000004f37e8b961e3b0ecc241119df89e80635d51cc0636b99 height=790554 version=0x23214000 log2_work=94.190420 tx=840722613 date='2023-05-20T05:43:22Z' progress=0.999998 cache=53.9MiB(322501txo) 2023-05-20T05:52:27Z UpdateTip: new best=00000000000000000002c375db015a4563c2d61737baf6cc52df55097b44a83b height=790555 version=0x215e6000 log2_work=94.190434 tx=840726579 date='2023-05-20T05:52:35Z' progress=1.000000 cache=54.8MiB(328433txo) 2023-05-20T06:06:22Z Timeout downloading block 00000000000000000002f45a2aba5d821ce8aad5513960d86e31f786f13bb8c9 from peer=5863, disconnecting 2023-05-20T06:06:24Z UpdateTip: new best=00000000000000000002f45a2aba5d821ce8aad5513960d86e31f786f13bb8c9 height=790556 version=0x2f456000 log2_work=94.190447 tx=840731150 date='2023-05-20T05:56:09Z' progress=0.999998 cache=56.0MiB(337177txo)

Node 2:

Bitcoin Core client v24.1 - server 70016/Satoshi:24.1/

ipv4 ipv6 onion total block in 71 15 8 94 out 4 1 5 10 2 total 75 16 13 104

2023-05-20T02:09:51Z UpdateTip: new best=00000000000000000002d3f7e28de73899bbcbd071e63a17df899ae42bde3958 height=790535 version=0x27ffe000 log2_work=94.190162 tx=840663087 date='2023-05-20T02:09:48Z' progress=1.000000 cache=39.3MiB(215163txo) 2023-05-20T02:21:31Z Timeout downloading block 00000000000000000000884c3c8df78e3914cff044a4367c23e511197259bfbf from peer=4434, disconnecting 2023-05-20T02:21:38Z UpdateTip: new best=00000000000000000000884c3c8df78e3914cff044a4367c23e511197259bfbf height=790536 version=0x232b2000 log2_work=94.190175 tx=840665684 date='2023-05-20T02:11:20Z' progress=0.999998 cache=39.9MiB(219903txo) 2023-05-20T02:21:38Z UpdateTip: new best=00000000000000000004437862638d8a13746fb9446ea927f92716b8a1c49440 height=790537 version=0x23f52000 log2_work=94.190189 tx=840668515 date='2023-05-20T02:19:35Z' progress=1.000000 cache=40.5MiB(224005txo) 2023-05-20T03:04:24Z Timeout downloading block 00000000000000000004503252b4a5d605be32da2e5ed2c002ab2b6f35a0eaad from peer=7055, disconnecting 2023-05-20T03:04:30Z UpdateTip: new best=00000000000000000004503252b4a5d605be32da2e5ed2c002ab2b6f35a0eaad height=790538 version=0x20006000 log2_work=94.190203 tx=840671778 date='2023-05-20T02:53:40Z' progress=0.999998 cache=42.5MiB(239219txo) 2023-05-20T03:25:13Z Timeout downloading block 0000000000000000000575481408474f456a0831aa8f13968c0184eccb540941 from peer=7452, disconnecting 2023-05-20T03:35:14Z Timeout downloading block 0000000000000000000575481408474f456a0831aa8f13968c0184eccb540941 from peer=7070, disconnecting 2023-05-20T03:35:57Z UpdateTip: new best=0000000000000000000575481408474f456a0831aa8f13968c0184eccb540941 height=790539 version=0x2000a000 log2_work=94.190216 tx=840674303 date='2023-05-20T03:15:11Z' progress=0.999996 cache=44.2MiB(252439txo) ... 2023-05-20T03:36:04Z UpdateTip: new best=0000000000000000000250e67a43537ef18b95a69e3d312d25edbbd3ffa78953 height=790545 version=0x20112000 log2_work=94.190298 tx=840694197 date='2023-05-20T03:33:47Z' progress=1.000000 cache=48.6MiB(283897txo) 2023-05-20T04:09:57Z Timeout downloading block 0000000000000000000245ddb1e5f49b21d2e9b543463d45c0236a72781c442e from peer=7640, disconnecting 2023-05-20T04:09:57Z UpdateTip: new best=0000000000000000000245ddb1e5f49b21d2e9b543463d45c0236a72781c442e height=790546 version=0x29b30000 log2_work=94.190311 tx=840697341 date='2023-05-20T03:59:42Z' progress=0.999998 cache=50.7MiB(299836txo) ... 2023-05-20T05:40:58Z UpdateTip: new best=0000000000000000000574c26d4b484d26714502df129c5a382e6f05fac3523e height=790553 version=0x351c4000 log2_work=94.190406 tx=840719434 date='2023-05-20T05:40:33Z' progress=1.000000 cache=58.0MiB(352961txo) 2023-05-20T05:53:40Z Timeout downloading block 00000000000000000004f37e8b961e3b0ecc241119df89e80635d51cc0636b99 from peer=8096, disconnecting 2023-05-20T05:53:43Z UpdateTip: new best=00000000000000000004f37e8b961e3b0ecc241119df89e80635d51cc0636b99 height=790554 version=0x23214000 log2_work=94.190420 tx=840722613 date='2023-05-20T05:43:22Z' progress=0.999998 cache=58.6MiB(357412txo) 2023-05-20T05:53:43Z UpdateTip: new best=00000000000000000002c375db015a4563c2d61737baf6cc52df55097b44a83b height=790555 version=0x215e6000 log2_work=94.190434 tx=840726579 date='2023-05-20T05:52:35Z' progress=1.000000 cache=59.3MiB(363049txo) 2023-05-20T05:56:23Z UpdateTip: new best=00000000000000000002f45a2aba5d821ce8aad5513960d86e31f786f13bb8c9 height=790556 version=0x2f456000 log2_work=94.190447 tx=840731150 date='2023-05-20T05:56:09Z' progress=1.000000 cache=60.1MiB(367966txo) 2023-05-20T06:41:47Z Timeout downloading block 00000000000000000004240704c7da0c3aaf066d088a2e2d6d628436fe185873 from peer=9120, disconnecting 2023-05-20T06:41:52Z UpdateTip: new best=00000000000000000004240704c7da0c3aaf066d088a2e2d6d628436fe185873 height=790557 version=0x24b94000 log2_work=94.190461 tx=840734005 date='2023-05-20T06:31:27Z' progress=0.999998 cache=62.3MiB(385241txo) ... 2023-05-20T08:17:02Z UpdateTip: new best=000000000000000000051cedf2ca5d740ade80588d4fc7924daa965514d44f27 height=790566 version=0x25040000 log2_work=94.190583 tx=840762045 date='2023-05-20T08:16:22Z' progress=1.000000 cache=71.0MiB(450733txo) 2023-05-20T08:41:00Z Timeout downloading block 00000000000000000004d7a03ef3afa1d1f9ec66ae9ba1ef16999fe10d5513b4 from peer=10481, disconnecting 2023-05-20T08:43:35Z UpdateTip: new best=00000000000000000004d7a03ef3afa1d1f9ec66ae9ba1ef16999fe10d5513b4 height=790567 version=0x34760000 log2_work=94.190597 tx=840765380 date='2023-05-20T08:30:34Z' progress=0.999997 cache=72.5MiB(462134txo)

How did you obtain Bitcoin Core

Pre-built binaries

What version of Bitcoin Core are you using?

v24.1

Operating system and version

Rocky Linux 8.7, Kernel 4.18.0-425.19.2.el8_7.x86_64

Machine specifications

Two servers hosted at different data centers with Xeon server CPUs, SSD disks and gigabit uplinks.

@ArmchairCryptologist Thanks for reporting. This is an issue we are aware of. To avoid any confusion, and make it clear you're seeing the issue with v24.1, I've edited your post slightly.

For what it's worth, I ran the node with debug logging for a bit, and while it seems to be mostly (but not exclusively) the same peer causing the stall, it also doesn't necessarily seem malicious, just slow, since it does successfully transfer some blocks. The client seems to really like requesting blocks from the peer in question, so I'm guessing it get blocks earlier than most other peers, and possibly gets overloaded because of it. In some cases it even looks to be requesting another block from it while it is already downloading one - and in some cases it seems to successfully download the second block then timeout on the first? See block 00000000000000000001a50acdf7b30c8f1b127ab6c105b69a4f6c24f72ab9eb in the second segment below.

2023-05-20T13:24:00Z [net] receive version message: /Satoshi:0.19.0.1/: version 70015, blocks=0, us=0.0.0.0:0, txrelay=0, peer=2605, peeraddr=3.20.y.z:46930
2023-05-20T13:24:00Z [net] send version message: version 70016, blocks=790585, them=3.20.y.z:46930, txrelay=1, peer=2605
2023-05-20T13:45:59Z [net] Requesting block 000000000000000000041c3004e9f638d5355f26701c424606365e94db5c94ce from  peer=2605
2023-05-20T13:45:59Z UpdateTip: new best=000000000000000000041c3004e9f638d5355f26701c424606365e94db5c94ce height=790587 version=0x24bea000 log2_work=94.190868 tx=840839324 date='2023-05-20T13:45:38Z' progress=1.000000 cache=94.6MiB(705910txo)
2023-05-20T14:00:13Z [net] Requesting block 00000000000000000001b274dbd40480fd3ab8ffbc1dcd9daa4667c76077c88a from  peer=2605
2023-05-20T14:01:02Z [net] Requesting block 00000000000000000001e9f4462968ba404af8e9286c197d9ae3650a5165cac6 from  peer=2605
2023-05-20T14:10:13Z Timeout downloading block 00000000000000000001b274dbd40480fd3ab8ffbc1dcd9daa4667c76077c88a from peer=2605, disconnecting
2023-05-20T14:10:13Z [net] Requesting block 00000000000000000001b274dbd40480fd3ab8ffbc1dcd9daa4667c76077c88a (790588) peer=0
2023-05-20T14:10:13Z [net] Requesting block 00000000000000000001e9f4462968ba404af8e9286c197d9ae3650a5165cac6 (790589) peer=0
2023-05-20T14:10:14Z [net] received block 00000000000000000001b274dbd40480fd3ab8ffbc1dcd9daa4667c76077c88a peer=0
2023-05-20T14:10:14Z UpdateTip: new best=00000000000000000001b274dbd40480fd3ab8ffbc1dcd9daa4667c76077c88a height=790588 version=0x2dfbc000 log2_work=94.190882 tx=840843696 date='2023-05-20T13:59:44Z' progress=0.999998 cache=93.6MiB(696440txo)
2023-05-20T14:10:14Z [net] received block 00000000000000000001e9f4462968ba404af8e9286c197d9ae3650a5165cac6 peer=0
2023-05-20T14:10:14Z UpdateTip: new best=00000000000000000001e9f4462968ba404af8e9286c197d9ae3650a5165cac6 height=790589 version=0x20e8c000 log2_work=94.190895 tx=840848460 date='2023-05-20T14:00:34Z' progress=0.999998 cache=94.5MiB(702207txo)

2023-05-20T14:11:13Z [net] send version message: version 70016, blocks=790590, them=3.20.y.z:60848, txrelay=1, peer=3072
2023-05-20T14:11:13Z [net] receive version message: /Satoshi:0.19.0.1/: version 70015, blocks=0, us=0.0.0.0:0, txrelay=0, peer=3072, peeraddr=3.20.y.z:60848
2023-05-20T15:08:09Z [net] Requesting block 00000000000000000001cfd7b99787a52f2933f0d73d2d0c4805c2b25b17d166 from  peer=3072
2023-05-20T15:16:40Z [net] received block 00000000000000000001a50acdf7b30c8f1b127ab6c105b69a4f6c24f72ab9eb peer=3072
2023-05-20T15:18:09Z Timeout downloading block 00000000000000000001cfd7b99787a52f2933f0d73d2d0c4805c2b25b17d166 from peer=3072, disconnecting
2023-05-20T15:18:09Z [net] Requesting block 00000000000000000001cfd7b99787a52f2933f0d73d2d0c4805c2b25b17d166 (790595) peer=2136
2023-05-20T15:18:20Z [net] received block 00000000000000000001cfd7b99787a52f2933f0d73d2d0c4805c2b25b17d166 peer=2136
2023-05-20T15:18:20Z UpdateTip: new best=00000000000000000001cfd7b99787a52f2933f0d73d2d0c4805c2b25b17d166 height=790595 version=0x37ffe000 log2_work=94.190977 tx=840874538 date='2023-05-20T15:07:57Z' progress=0.999998 cache=107.4MiB(755884txo)
2023-05-20T15:18:20Z UpdateTip: new best=00000000000000000001a50acdf7b30c8f1b127ab6c105b69a4f6c24f72ab9eb height=790596 version=0x24d10000 log2_work=94.190990 tx=840876894 date='2023-05-20T15:16:19Z' progress=1.000000 cache=108.8MiB(766732txo)

2023-05-20T15:16:17Z [net] send version message: version 70016, blocks=790594, them=8.28.y.z:58268, txrelay=1, peer=3718
2023-05-20T15:16:17Z [net] receive version message: /Satoshi:24.99.0/: version 70016, blocks=790595, us=x.x.x.x:8333, txrelay=0, peer=3718, peeraddr=8.28.y.z:58268
2023-05-20T15:19:09Z [net] send version message: version 70016, blocks=790597, them=3.20.y.z:52650, txrelay=1, peer=3744
2023-05-20T15:19:09Z [net] receive version message: /Satoshi:0.19.0.1/: version 70015, blocks=0, us=0.0.0.0:0, txrelay=0, peer=3744, peeraddr=3.20.y.z:52650
2023-05-20T15:19:33Z [net] Requesting block 00000000000000000002008400350c042c72251789c6b00dc972e70904ccf994 from  peer=3744
2023-05-20T15:29:33Z Timeout downloading block 00000000000000000002008400350c042c72251789c6b00dc972e70904ccf994 from peer=3744, disconnecting
2023-05-20T15:29:33Z [net] Requesting block 00000000000000000002008400350c042c72251789c6b00dc972e70904ccf994 (790598) peer=3718
2023-05-20T15:39:33Z Timeout downloading block 00000000000000000002008400350c042c72251789c6b00dc972e70904ccf994 from peer=3718, disconnecting
2023-05-20T15:39:33Z [net] Requesting block 00000000000000000002008400350c042c72251789c6b00dc972e70904ccf994 (790598) peer=2547
2023-05-20T15:39:34Z [net] received block 00000000000000000002008400350c042c72251789c6b00dc972e70904ccf994 peer=2547
2023-05-20T15:39:34Z UpdateTip: new best=00000000000000000002008400350c042c72251789c6b00dc972e70904ccf994 height=790598 version=0x332ec000 log2_work=94.191018 tx=840884128 date='2023-05-20T15:18:58Z' progress=0.999996 cache=110.8MiB(781253txo)

2023-05-20T15:30:33Z [net] send version message: version 70016, blocks=790597, them=3.20.y.z:56230, txrelay=1, peer=3854
2023-05-20T15:30:33Z [net] receive version message: /Satoshi:0.19.0.1/: version 70015, blocks=0, us=0.0.0.0:0, txrelay=0, peer=3854, peeraddr=3.20.y.z:56230
2023-05-20T15:51:11Z [net] Requesting block 0000000000000000000035ea85540fe9071a16424a087c1d4f12ee544fb21994 from  peer=3854
2023-05-20T15:53:57Z [net] Requesting block 0000000000000000000266ed1b962d5866ecbd8535fd6aaa51a0dd0b80606ba7 from  peer=3854
2023-05-20T16:01:11Z Timeout downloading block 0000000000000000000035ea85540fe9071a16424a087c1d4f12ee544fb21994 from peer=3854, disconnecting
2023-05-20T16:01:11Z [net] Requesting block 0000000000000000000035ea85540fe9071a16424a087c1d4f12ee544fb21994 (790600) peer=2136
2023-05-20T16:01:11Z [net] Requesting block 0000000000000000000266ed1b962d5866ecbd8535fd6aaa51a0dd0b80606ba7 (790601) peer=2136
2023-05-20T16:01:21Z [net] received block 0000000000000000000035ea85540fe9071a16424a087c1d4f12ee544fb21994 peer=2136
2023-05-20T16:01:21Z UpdateTip: new best=0000000000000000000035ea85540fe9071a16424a087c1d4f12ee544fb21994 height=790600 version=0x20000000 log2_work=94.191045 tx=840891903 date='2023-05-20T15:51:07Z' progress=0.999998 cache=113.7MiB(804127txo)
2023-05-20T16:01:31Z [net] received block 0000000000000000000266ed1b962d5866ecbd8535fd6aaa51a0dd0b80606ba7 peer=2136
2023-05-20T16:01:31Z UpdateTip: new best=0000000000000000000266ed1b962d5866ecbd8535fd6aaa51a0dd0b80606ba7 height=790601 version=0x2667e000 log2_work=94.191058 tx=840895519 date='2023-05-20T15:53:36Z' progress=0.999998 cache=114.5MiB(809732txo)

Can you block this peer?

I did block the peer right after I posted the latest logs four days ago, and after that the block timeouts dropped to 2-3 per day, but like I mentioned in the bug report, since Core doesn't normally log the IP of disconnected incoming peers you pretty much have to enable debug=net logging to find the IP of the misbehaving peer. Which on this particular node is ~1GB of logs per 2-3 hours.

I did block the peer right after I posted the latest logs four days ago, and after that the block timeouts dropped to 2-3 per day, but like I mentioned in the bug report, since Core doesn't normally log the IP of disconnected incoming peers you pretty much have to enable debug=net logging to find the IP of the misbehaving peer. Which on this particular node is ~1GB of logs per 2-3 hours.

The reason why connections/disconnections aren't logged for inbound peers is that these events are remotely triggerable at almost no cost. If we'd log these by default, that would make us susceptible to disk-exhaustion attacks where an attacker tries to fill up our logs over time by triggering the log repeatedly. This doesn't apply to special-category logs like debug=net because users who activate those are expected to monitor their node more closely. There have been mitigations suggested (e.g. #21603) but none of those have made it in so far. That being said, I agree that debug=net is quite messy and could use different levels of verbosity.

The reason why connections/disconnections aren't logged for inbound peers is that these events are remotely triggerable at almost no cost. If we'd log these by default, that would make us susceptible to disk-exhaustion attacks where an attacker tries to fill up our logs over time by triggering the log repeatedly.

I see, that makes sense in general. But when a connection is closed due to a block download timeout, you already generate a log entry Timeout downloading block x from peer=y, disconnecting with the default logging level. As such it shouldn't add any risk of such attacks if the remote address was simply added to this line, something like peer=x addr=x.x.x.x?

As such it shouldn't add any risk of such attacks if the remote address was simply added to this line, something like peer=x addr=x.x.x.x?

I agree, with addr=x.x.x.x being conditional on -logips. That could make sense in some more spots as well, I could open a PR to suggest it unless you want to.

I agree, with addr=x.x.x.x being conditional on -logips. That could make sense in some more spots as well, I could open a PR to suggest it unless you want to.

By all means, please do. I expect reworking the block downloading logic would be fair from trivial, but at least with this it will be easy to just block any peers that repeatedly cause the node to stall.

I'd love to see the addition of addr too!

By all means, please do.

see #27761

I expect reworking the block downloading logic would be fair from trivial

While that's certainly true, #27626 just made it into master and will help a lot with this! (not part of 25.0 though, it will need a bit more testing)

Which on this particular node is ~1GB of logs per 2-3 hours.

Another annoying way to find it is detect when node is stalled, then do getpeerinfo and see who has a block "inflight", then ban them.

That said, this should not happen regularly post #27626

I agree, with addr=x.x.x.x being conditional on -logips. That could make sense in some more spots as well, I could open a PR to suggest it unless you want to.

I added it in #27826 (to see which peer sent a header).

We assume that this is fixed by #27626 please feel free to ask for this to be reopened if it reocurrs