search

btcsuite / btcd

An alternative full node bitcoin implementation written in Go (golang)
https://github.com/btcsuite/btcd/blob/master/README.md
ISC License
6.1k stars 2.31k forks source link

blockchain: don't rely on BlockHeightByHash for prune height calculations #2122

Closed kcalvinalvin closed 3 months ago

kcalvinalvin commented 4 months ago

Since BlockHeightByHash only returns the heights for blocks that are in the main chain, when a block that is stale gets pruned, this will cause an error in the block height lookup and cause an error in block processing.

Look up the node directly from the index and if the node isn't found, just skip that node. For utxoCache.lastFlushHash, if that isn't found, just force a flush.

Fixes #2121

coveralls commented 4 months ago

Pull Request Test Coverage Report for Build 8160298701

Details

Changes Missing Coverage Covered Lines Changed/Added Lines %
blockchain/utxocache.go 9 23 39.13%
<!-- Total: 9 23 39.13% -->
Files with Coverage Reduction New Missed Lines %
blockchain/utxocache.go 1 85.01%
connmgr/connmanager.go 2 86.62%
blockchain/chain.go 4 73.01%
peer/peer.go 9 73.94%
<!-- Total: 16 -->
Totals Coverage Status
Change from base Build 8117173129: -0.01%
Covered Lines: 29298
Relevant Lines: 51615
💛 - Coveralls
0xB10C commented 4 months ago

How can I help test this? Restarting with this patch?

kcalvinalvin commented 4 months ago

How can I help test this? Restarting with this patch?

I don't think we have reconsiderblock here (should push it from utreexod) so you'd have to restart syncing from scratch unfortunately

kcalvinalvin commented 4 months ago

Can we re-create the scenarios we've see in the wlid via the full block tests?

https://github.com/btcsuite/btcd/blob/13152b35e191385a874294a9dbc902e48b1d71b0/blockchain/fullblocktests/generate.go#L783-L790

https://github.com/btcsuite/btcd/blob/13152b35e191385a874294a9dbc902e48b1d71b0/blockchain/fullblocks_test.go#L132-L134

I've modified the existing TestFlushOnPrune to test for the case where stale blocks are being prunjed. Since pruning only triggers when there's at least 1.5gb of blocks, it's kinda difficult to trigger it on the full block tests so I think it's a better idea to add this test on TestFlushOnPrune as that already modifies the block file size by running the test with ffldb.TstRunWithMaxBlockFileSize().

I've verified that this error only happens when the node is pruned by running an archive node with v0.24.0 on the problematic database received from Sjors. This is reproducible by setting the pruneTarget to 0 in TestFlushOnPrune.

The error message given out in the test matches that of the logs from @0xB10C and Sjors and with the logs from when I tested it locally.

kcalvinalvin commented 4 months ago

Here's my logs for running v0.24.0 with and without pruning enabled. Full logs attached. btcd-fail.log

Without pruning:

2024-02-16 14:49:40.291 [INF] BTCD: Version 0.24.0-beta
2024-02-16 14:49:40.291 [INF] BTCD: Loading block database from '/home/calvin/.btcd/data/mainnet/blocks_ffldb'
2024-02-16 14:49:42.176 [INF] BTCD: Block database loaded
2024-02-16 14:49:42.188 [INF] INDX: Committed filter index is enabled
2024-02-16 14:49:42.188 [INF] CHAN: Pre-alloacting for 251 MiB: 
2024-02-16 14:49:42.196 [INF] CHAN: Loading block index...2024-02-16 14:49:44.246 [INF] CHAN: Chain state (height 830395, hash 00000000000000000002e3b19bd2cf690c70d6029f33a6a0a1b8cda5d9cd323a, totaltx 965476556, work 32878101565669194811673855648)
2024-02-16 14:49:46.157 [WRN] RPCS: Can't listen on 127.0.0.1:8334: listen tcp4 127.0.0.1:8334: bind: address already in use
2024-02-16 14:49:46.157 [INF] RPCS: RPC server listening on [::1]:8334
2024-02-16 14:49:46.301 [INF] AMGR: Loaded 47715 addresses from file '/home/calvin/.btcd/data/mainnet/peers.json'
2024-02-16 14:49:46.301 [INF] CMGR: Server listening on 0.0.0.0:8333
2024-02-16 14:49:46.301 [INF] CMGR: Server listening on [::]:8333
2024-02-16 14:49:46.314 [INF] CMGR: 39 addresses found from DNS seed seed.bitcoin.sipa.be
2024-02-16 14:49:46.537 [INF] CMGR: 37 addresses found from DNS seed seed.btc.petertodd.net
2024-02-16 14:49:46.662 [INF] SYNC: New valid peer 174.20.57.30:8333 (outbound) (/Satoshi:25.0.0/)
2024-02-16 14:49:46.662 [INF] SYNC: Syncing to block height 830683 from peer 174.20.57.30:8333
2024-02-16 14:49:46.720 [INF] SYNC: New valid peer 167.88.11.203:8333 (outbound) (/Satoshi:22.0.0/)
2024-02-16 14:49:46.848 [INF] CMGR: 40 addresses found from DNS seed seed.bitnodes.io
2024-02-16 14:49:46.927 [INF] CMGR: 26 addresses found from DNS seed seed.bitcoinstats.com
2024-02-16 14:49:47.100 [INF] CMGR: 31 addresses found from DNS seed dnsseed.bluematt.me
2024-02-16 14:49:47.253 [INF] CMGR: 36 addresses found from DNS seed dnsseed.bitcoin.dashjr.org
2024-02-16 14:49:47.380 [INF] SYNC: New valid peer 37.143.118.174:8333 (outbound) (/Satoshi:26.0.0/)
2024-02-16 14:49:47.405 [INF] SYNC: New valid peer 156.146.137.142:8333 (outbound) (/Satoshi:26.0.0/)
2024-02-16 14:49:47.918 [INF] SYNC: Lost peer 37.143.118.174:8333 (outbound)
2024-02-16 14:49:48.284 [INF] CMGR: 37 addresses found from DNS seed seed.bitcoin.jonasschnelli.ch
2024-02-16 14:49:48.358 [INF] SYNC: New valid peer 66.135.24.251:8333 (outbound) (/Satoshi:22.0.0/)
2024-02-16 14:49:55.098 [INF] CHAN: Flushing UTXO cache of 98 MiB with 11959 entries to disk. For large sizes, this can take up to several minutes...
2024-02-16 14:50:00.324 [INF] SYNC: Processed 2 blocks in the last 14.17s (5595 transactions, height 830397, 2024-02-14 18:12:32 +0900 KST, ~98 MiB cache)
2024-02-16 14:50:14.698 [INF] SYNC: Processed 2 blocks in the last 14.37s (3841 transactions, height 830399, 2024-02-14 18:22:37 +0900 KST, ~99 MiB cache)
2024-02-16 14:50:16.651 [INF] SYNC: New valid peer 104.13.168.146:8333 (outbound) (/Satoshi:24.0.1/)
2024-02-16 14:50:16.844 [INF] SYNC: New valid peer 212.51.136.50:8333 (outbound) (/Satoshi:24.0.1/)
2024-02-16 14:50:16.891 [INF] SYNC: New valid peer 85.214.192.204:8333 (outbound) (/Satoshi:26.0.0/)
2024-02-16 14:50:17.523 [INF] SYNC: Lost peer 85.214.192.204:8333 (outbound)
2024-02-16 14:50:17.811 [INF] SYNC: New valid peer 142.171.179.169:8333 (outbound) (/Satoshi:25.0.0/)
2024-02-16 14:50:25.692 [INF] SYNC: Processed 2 blocks in the last 10.99s (5763 transactions, height 830401, 2024-02-14 19:08:10 +0900 KST, ~101 MiB cache)
2024-02-16 14:50:37.760 [INF] SYNC: Processed 2 blocks in the last 12.06s (5254 transactions, height 830403, 2024-02-14 19:25:37 +0900 KST, ~102 MiB cache)
2024-02-16 14:50:46.912 [INF] SYNC: New valid peer 65.108.103.225:8333 (outbound) (/Satoshi:24.0.1/)
2024-02-16 14:50:47.719 [INF] SYNC: Lost peer 65.108.103.225:8333 (outbound)
2024-02-16 14:50:48.138 [INF] SYNC: New valid peer 99.29.112.187:8333 (outbound) (/Satoshi:0.20.1/)
2024-02-16 14:50:48.254 [INF] SYNC: Lost peer 99.29.112.187:8333 (outbound)
2024-02-16 14:50:48.695 [INF] SYNC: New valid peer 188.92.20.9:8333 (outbound) (/Satoshi:26.0.0/)
2024-02-16 14:50:49.508 [INF] SYNC: Processed 2 blocks in the last 11.74s (4683 transactions, height 830405, 2024-02-14 19:44:42 +0900 KST, ~103 MiB cache)
2024-02-16 14:50:50.492 [INF] SYNC: Lost peer 188.92.20.9:8333 (outbound)
2024-02-16 14:51:01.903 [INF] SYNC: Processed 2 blocks in the last 12.39s (4020 transactions, height 830407, 2024-02-14 19:54:05 +0900 KST, ~104 MiB cache)
2024-02-16 14:51:13.308 [INF] SYNC: Processed 2 blocks in the last 11.4s (5294 transactions, height 830409, 2024-02-14 20:20:38 +0900 KST, ~105 MiB cache)
2024-02-16 14:51:20.789 [INF] SYNC: New valid peer 70.181.225.218:8333 (outbound) (/Satoshi:26.0.0/)
2024-02-16 14:51:24.449 [INF] SYNC: Processed 2 blocks in the last 11.14s (5030 transactions, height 830411, 2024-02-14 20:49:50 +0900 KST, ~106 MiB cache)
2024-02-16 14:51:39.113 [INF] SYNC: Processed 2 blocks in the last 14.66s (2794 transactions, height 830413, 2024-02-14 20:51:09 +0900 KST, ~107 MiB cache)
2024-02-16 14:51:50.162 [INF] SYNC: Processed 2 blocks in the last 11.04s (4504 transactions, height 830415, 2024-02-14 21:11:52 +0900 KST, ~108 MiB cache)
2024-02-16 14:52:03.930 [INF] SYNC: Processed 2 blocks in the last 13.76s (2178 transactions, height 830417, 2024-02-14 21:15:41 +0900 KST, ~109 MiB cache)
2024-02-16 14:52:15.292 [INF] SYNC: Processed 2 blocks in the last 11.36s (5226 transactions, height 830419, 2024-02-14 21:58:03 +0900 KST, ~110 MiB cache)
2024-02-16 14:52:26.696 [INF] SYNC: Processed 2 blocks in the last 11.4s (4197 transactions, height 830421, 2024-02-14 22:15:23 +0900 KST, ~112 MiB cache)
2024-02-16 14:52:38.175 [INF] SYNC: Processed 2 blocks in the last 11.47s (4129 transactions, height 830423, 2024-02-14 22:20:58 +0900 KST, ~112 MiB cache)
2024-02-16 14:52:50.314 [INF] SYNC: Processed 2 blocks in the last 12.13s (2931 transactions, height 830425, 2024-02-14 22:27:36 +0900 KST, ~113 MiB cache)
2024-02-16 14:53:02.620 [INF] SYNC: Processed 2 blocks in the last 12.3s (4112 transactions, height 830427, 2024-02-14 22:43:15 +0900 KST, ~114 MiB cache)
2024-02-16 14:53:13.954 [INF] SYNC: Processed 2 blocks in the last 11.33s (5242 transactions, height 830429, 2024-02-14 23:10:10 +0900 KST, ~116 MiB cache)
2024-02-16 14:53:24.697 [INF] SYNC: Processed 2 blocks in the last 10.74s (5355 transactions, height 830431, 2024-02-14 23:38:04 +0900 KST, ~117 MiB cache)
2024-02-16 14:53:37.020 [INF] SYNC: Processed 2 blocks in the last 12.32s (3800 transactions, height 830433, 2024-02-14 23:50:48 +0900 KST, ~117 MiB cache)
2024-02-16 14:53:48.762 [INF] SYNC: Processed 2 blocks in the last 11.74s (5136 transactions, height 830435, 2024-02-15 00:07:13 +0900 KST, ~118 MiB cache)
2024-02-16 14:54:00.929 [INF] SYNC: Processed 2 blocks in the last 12.16s (4730 transactions, height 830437, 2024-02-15 00:22:32 +0900 KST, ~119 MiB cache)
2024-02-16 14:54:12.650 [INF] SYNC: Processed 2 blocks in the last 11.72s (5053 transactions, height 830439, 2024-02-15 00:33:22 +0900 KST, ~120 MiB cache)
2024-02-16 14:54:26.590 [INF] SYNC: Processed 3 blocks in the last 13.94s (7346 transactions, height 830442, 2024-02-15 01:47:59 +0900 KST, ~123 MiB cache)
2024-02-16 14:54:39.996 [INF] SYNC: Processed 3 blocks in the last 13.4s (7650 transactions, height 830445, 2024-02-15 02:06:03 +0900 KST, ~125 MiB cache)
2024-02-16 14:54:55.280 [INF] SYNC: Processed 3 blocks in the last 15.28s (5296 transactions, height 830448, 2024-02-15 02:08:29 +0900 KST, ~127 MiB cache)
2024-02-16 14:54:55.280 [INF] CHAN: Flushing UTXO cache of 127 MiB with 487487 entries to disk. For large sizes, this can take up to several minutes...
2024-02-16 14:55:07.136 [INF] SYNC: Processed 2 blocks in the last 11.85s (790 transactions, height 830450, 2024-02-15 02:09:15 +0900 KST, ~99 MiB cache)
2024-02-16 14:55:21.819 [INF] SYNC: Processed 3 blocks in the last 14.68s (7781 transactions, height 830453, 2024-02-15 02:21:51 +0900 KST, ~101 MiB cache)
2024-02-16 14:55:32.291 [INF] SYNC: Processed 2 blocks in the last 10.47s (5190 transactions, height 830455, 2024-02-15 02:43:22 +0900 KST, ~103 MiB cache)
2024-02-16 14:55:47.478 [INF] SYNC: Processed 3 blocks in the last 15.18s (8483 transactions, height 830458, 2024-02-15 03:01:44 +0900 KST, ~105 MiB cache)
2024-02-16 14:55:59.150 [INF] SYNC: Processed 2 blocks in the last 11.67s (3887 transactions, height 830460, 2024-02-15 03:14:05 +0900 KST, ~106 MiB cache)
2024-02-16 14:56:12.014 [INF] SYNC: Processed 2 blocks in the last 12.86s (2700 transactions, height 830462, 2024-02-15 03:17:18 +0900 KST, ~108 MiB cache)
2024-02-16 14:56:24.909 [INF] SYNC: Processed 3 blocks in the last 12.89s (10012 transactions, height 830465, 2024-02-15 04:33:09 +0900 KST, ~110 MiB cache)
2024-02-16 14:56:37.651 [INF] SYNC: Processed 3 blocks in the last 12.74s (8689 transactions, height 830468, 2024-02-15 05:08:01 +0900 KST, ~113 MiB cache)
2024-02-16 14:56:51.663 [INF] SYNC: Processed 3 blocks in the last 14.01s (7422 transactions, height 830471, 2024-02-15 05:19:50 +0900 KST, ~114 MiB cache)
2024-02-16 14:57:06.285 [INF] SYNC: Processed 3 blocks in the last 14.62s (8261 transactions, height 830474, 2024-02-15 06:07:18 +0900 KST, ~116 MiB cache)
2024-02-16 14:57:19.093 [INF] SYNC: Processed 2 blocks in the last 12.8s (3602 transactions, height 830476, 2024-02-15 06:11:31 +0900 KST, ~117 MiB cache)
2024-02-16 14:57:32.509 [INF] SYNC: Processed 3 blocks in the last 13.41s (9049 transactions, height 830479, 2024-02-15 07:21:39 +0900 KST, ~119 MiB cache)
2024-02-16 14:57:43.629 [INF] SYNC: Processed 2 blocks in the last 11.11s (5282 transactions, height 830481, 2024-02-15 07:44:52 +0900 KST, ~120 MiB cache)
2024-02-16 14:57:54.909 [INF] SYNC: Processed 2 blocks in the last 11.27s (4087 transactions, height 830483, 2024-02-15 08:09:10 +0900 KST, ~121 MiB cache)
2024-02-16 14:58:06.079 [INF] SYNC: Processed 2 blocks in the last 11.17s (5105 transactions, height 830485, 2024-02-15 08:39:49 +0900 KST, ~122 MiB cache)
2024-02-16 14:58:18.140 [INF] SYNC: Processed 2 blocks in the last 12.06s (4001 transactions, height 830487, 2024-02-15 09:03:14 +0900 KST, ~123 MiB cache)
2024-02-16 14:58:31.897 [INF] SYNC: Processed 2 blocks in the last 13.75s (3361 transactions, height 830489, 2024-02-15 09:16:51 +0900 KST, ~123 MiB cache)
2024-02-16 14:58:46.597 [INF] SYNC: Processed 2 blocks in the last 14.69s (1515 transactions, height 830491, 2024-02-15 09:20:06 +0900 KST, ~124 MiB cache)

With pruning:

2024-02-16 16:20:42.635 [INF] BTCD: Version 0.24.0-beta
2024-02-16 16:20:42.635 [INF] BTCD: Loading block database from '/home/calvin/.btcd/data/mainnet/blocks_ffldb'
2024-02-16 16:20:43.087 [INF] BTCD: Block database loaded
2024-02-16 16:20:43.098 [INF] INDX: Committed filter index is enabled
2024-02-16 16:20:43.098 [INF] CHAN: Pre-alloacting for 251 MiB: 
2024-02-16 16:20:43.102 [INF] CHAN: Loading block index...
2024-02-16 16:20:45.186 [INF] CHAN: Chain state (height 830687, hash 0000000000000000000037d512b01992e7b0109ff269e13edd5b3950f8c6bf6e, totaltx 966077512, work 32975358517829526424473523104)
2024-02-16 16:20:46.963 [WRN] RPCS: Can't listen on 127.0.0.1:8334: listen tcp4 127.0.0.1:8334: bind: address already in use
2024-02-16 16:20:46.963 [INF] RPCS: RPC server listening on [::1]:8334
2024-02-16 16:20:47.106 [INF] AMGR: Loaded 47768 addresses from file '/home/calvin/.btcd/data/mainnet/peers.json'
2024-02-16 16:20:47.110 [INF] CMGR: Server listening on 0.0.0.0:8333
2024-02-16 16:20:47.110 [INF] CMGR: Server listening on [::]:8333
2024-02-16 16:20:47.363 [INF] SYNC: New valid peer 65.0.3.156:8333 (outbound) (/Satoshi:0.21.1/)
2024-02-16 16:20:47.363 [INF] SYNC: Syncing to block height 830687 from peer 65.0.3.156:8333
2024-02-16 16:20:47.493 [INF] SYNC: New valid peer 66.58.243.215:8333 (outbound) (/Satoshi:23.0.0/)
2024-02-16 16:20:47.521 [INF] SYNC: New valid peer 165.22.229.88:8333 (outbound) (/Satoshi:0.20.1/)
2024-02-16 16:20:47.560 [INF] CMGR: 37 addresses found from DNS seed seed.btc.petertodd.net
2024-02-16 16:20:47.615 [INF] SYNC: Lost peer 66.58.243.215:8333 (outbound)
2024-02-16 16:20:47.663 [INF] SYNC: New valid peer 188.68.53.44:8333 (outbound) (/Satoshi:22.0.0/)
2024-02-16 16:20:47.720 [INF] CMGR: 26 addresses found from DNS seed seed.bitcoinstats.com
2024-02-16 16:20:47.734 [INF] SYNC: New valid peer 82.66.53.98:8333 (outbound) (/Satoshi:26.0.0/)
2024-02-16 16:20:47.785 [INF] CMGR: 40 addresses found from DNS seed seed.bitnodes.io
2024-02-16 16:20:47.905 [INF] CMGR: 31 addresses found from DNS seed dnsseed.bluematt.me
2024-02-16 16:20:47.967 [INF] SYNC: New valid peer 164.132.200.159:8333 (outbound) (/Satoshi:24.0.1/)
2024-02-16 16:20:48.117 [INF] SYNC: Lost peer 164.132.200.159:8333 (outbound)
2024-02-16 16:20:48.343 [INF] SYNC: New valid peer 193.169.245.118:8333 (outbound) (/Satoshi:24.99.0/)
2024-02-16 16:20:48.492 [INF] CMGR: 37 addresses found from DNS seed seed.bitcoin.jonasschnelli.ch
2024-02-16 16:20:48.662 [INF] SYNC: New valid peer 65.108.122.251:8333 (outbound) (/Satoshi:25.1.0/)
2024-02-16 16:20:48.729 [INF] SYNC: Lost peer 65.108.122.251:8333 (outbound)
2024-02-16 16:20:48.991 [INF] CMGR: 36 addresses found from DNS seed dnsseed.bitcoin.dashjr.org
2024-02-16 16:20:49.674 [INF] SYNC: New valid peer 86.215.168.115:8333 (outbound) (/Satoshi:26.0.0/)
2024-02-16 16:20:51.605 [INF] CMGR: 39 addresses found from DNS seed seed.bitcoin.sipa.be
2024-02-16 16:21:17.364 [INF] SYNC: Lost peer 65.0.3.156:8333 (outbound)
2024-02-16 16:21:17.364 [INF] SYNC: Syncing to block height 830688 from peer 188.68.53.44:8333
2024-02-16 16:21:17.911 [INF] SYNC: New valid peer 159.224.238.145:8333 (outbound) (/Satoshi:24.0.1/)
2024-02-16 16:21:21.123 [ERR] SYNC: Failed to process block 0000000000000000000051a4d8fe6aa337190ab387fb73da51ccdc0c45e20b93: block 000000000000000000032956cbfd8721abe0572d81542e75e38e6185312bee09 is not in the main chain
2024-02-16 16:21:22.706 [INF] BTCD: Received signal (interrupt).  Shutting down...
2024-02-16 16:21:22.706 [INF] BTCD: Gracefully shutting down the server...
2024-02-16 16:21:22.706 [WRN] SRVR: Server shutting down
2024-02-16 16:21:22.706 [WRN] RPCS: RPC server shutting down
2024-02-16 16:21:22.706 [INF] RPCS: RPC server shutdown complete
2024-02-16 16:21:24.734 [INF] SRVR: New peer 88.17.82.14:8333 (outbound) ignored - server is shutting down
2024-02-16 16:21:24.734 [WRN] SYNC: Received done peer message for unknown peer 88.17.82.14:8333 (outbound)
2024-02-16 16:21:36.464 [INF] SYNC: Lost peer 159.224.238.145:8333 (outbound)
0xB10C commented 4 months ago

I don't think we have reconsiderblock here (should push it from utreexod) so you'd have to restart syncing from scratch unfortunately

Alright, done that. I still have a copy of the old datadir in-case anyone needs it for testing or further debugging. I'll re-add the btcd v0.24 to fork-observer once it's synced. I also made sure to add an RSS feed for lagging nodes.

kcalvinalvin commented 4 months ago

Added additional comments in the new code