test/functional/pruning.py

   1 #!/usr/bin/env python3
   2 # Copyright (c) 2014-2016 The Bitcoin Core developers
   3 # Distributed under the MIT software license, see the accompanying
   4 # file COPYING or http://www.opensource.org/licenses/mit-license.php.
   5 """Test the pruning code.
   6
   7 WARNING:
   8 This test uses 4GB of disk space.
   9 This test takes 30 mins or more (up to 2 hours)
  10 """
  11
  12 from test_framework.test_framework import BitcoinTestFramework
  13 from test_framework.util import *
  14 import time
  15 import os
  16
  17 MIN_BLOCKS_TO_KEEP = 288
  18
  19 # Rescans start at the earliest block up to 2 hours before a key timestamp, so
  20 # the manual prune RPC avoids pruning blocks in the same window to be
  21 # compatible with pruning based on key creation time.
  22 TIMESTAMP_WINDOW = 2 * 60 * 60
  23
  24
  25 def calc_usage(blockdir):
  26     return sum(os.path.getsize(blockdir+f) for f in os.listdir(blockdir) if os.path.isfile(blockdir+f)) / (1024. * 1024.)
  27
  28 class PruneTest(BitcoinTestFramework):
  29
  30     def __init__(self):
  31         super().__init__()
  32         self.setup_clean_chain = True
  33         self.num_nodes = 6
  34
  35         # Create nodes 0 and 1 to mine.
  36         # Create node 2 to test pruning.
  37         # Create nodes 3 and 4 to test manual pruning (they will be re-started with manual pruning later)
  38         # Create nodes 5 to test wallet in prune mode, but do not connect
  39         self.extra_args = [["-maxreceivebuffer=20000", "-blockmaxsize=999000", "-checkblocks=5"],
  40                            ["-maxreceivebuffer=20000", "-blockmaxsize=999000", "-checkblocks=5"],
  41                            ["-maxreceivebuffer=20000", "-prune=550"],
  42                            ["-maxreceivebuffer=20000", "-blockmaxsize=999000"],
  43                            ["-maxreceivebuffer=20000", "-blockmaxsize=999000"],
  44                            ["-prune=550"]]
  45
  46     def setup_network(self):
  47         self.setup_nodes()
  48
  49         self.prunedir = self.options.tmpdir + "/node2/regtest/blocks/"
  50
  51         connect_nodes(self.nodes[0], 1)
  52         connect_nodes(self.nodes[1], 2)
  53         connect_nodes(self.nodes[2], 0)
  54         connect_nodes(self.nodes[0], 3)
  55         connect_nodes(self.nodes[0], 4)
  56         sync_blocks(self.nodes[0:5])
  57
  58     def create_big_chain(self):
  59         # Start by creating some coinbases we can spend later
  60         self.nodes[1].generate(200)
  61         sync_blocks(self.nodes[0:2])
  62         self.nodes[0].generate(150)
  63         # Then mine enough full blocks to create more than 550MiB of data
  64         for i in range(645):
  65             mine_large_block(self.nodes[0], self.utxo_cache_0)
  66
  67         sync_blocks(self.nodes[0:5])
  68
  69     def test_height_min(self):
  70         if not os.path.isfile(self.prunedir+"blk00000.dat"):
  71             raise AssertionError("blk00000.dat is missing, pruning too early")
  72         self.log.info("Success")
  73         self.log.info("Though we're already using more than 550MiB, current usage: %d" % calc_usage(self.prunedir))
  74         self.log.info("Mining 25 more blocks should cause the first block file to be pruned")
  75         # Pruning doesn't run until we're allocating another chunk, 20 full blocks past the height cutoff will ensure this
  76         for i in range(25):
  77             mine_large_block(self.nodes[0], self.utxo_cache_0)
  78
  79         waitstart = time.time()
  80         while os.path.isfile(self.prunedir+"blk00000.dat"):
  81             time.sleep(0.1)
  82             if time.time() - waitstart > 30:
  83                 raise AssertionError("blk00000.dat not pruned when it should be")
  84
  85         self.log.info("Success")
  86         usage = calc_usage(self.prunedir)
  87         self.log.info("Usage should be below target: %d" % usage)
  88         if (usage > 550):
  89             raise AssertionError("Pruning target not being met")
  90
  91     def create_chain_with_staleblocks(self):
  92         # Create stale blocks in manageable sized chunks
  93         self.log.info("Mine 24 (stale) blocks on Node 1, followed by 25 (main chain) block reorg from Node 0, for 12 rounds")
  94
  95         for j in range(12):
  96             # Disconnect node 0 so it can mine a longer reorg chain without knowing about node 1's soon-to-be-stale chain
  97             # Node 2 stays connected, so it hears about the stale blocks and then reorg's when node0 reconnects
  98             # Stopping node 0 also clears its mempool, so it doesn't have node1's transactions to accidentally mine
  99             self.stop_node(0)
 100             self.nodes[0]=start_node(0, self.options.tmpdir, ["-maxreceivebuffer=20000","-blockmaxsize=999000", "-checkblocks=5"], timewait=900)
 101             # Mine 24 blocks in node 1
 102             for i in range(24):
 103                 if j == 0:
 104                     mine_large_block(self.nodes[1], self.utxo_cache_1)
 105                 else:
 106                     self.nodes[1].generate(1) #tx's already in mempool from previous disconnects
 107
 108             # Reorg back with 25 block chain from node 0
 109             for i in range(25):
 110                 mine_large_block(self.nodes[0], self.utxo_cache_0)
 111
 112             # Create connections in the order so both nodes can see the reorg at the same time
 113             connect_nodes(self.nodes[1], 0)
 114             connect_nodes(self.nodes[2], 0)
 115             sync_blocks(self.nodes[0:3])
 116
 117         self.log.info("Usage can be over target because of high stale rate: %d" % calc_usage(self.prunedir))
 118
 119     def reorg_test(self):
 120         # Node 1 will mine a 300 block chain starting 287 blocks back from Node 0 and Node 2's tip
 121         # This will cause Node 2 to do a reorg requiring 288 blocks of undo data to the reorg_test chain
 122         # Reboot node 1 to clear its mempool (hopefully make the invalidate faster)
 123         # Lower the block max size so we don't keep mining all our big mempool transactions (from disconnected blocks)
 124         self.stop_node(1)
 125         self.nodes[1]=start_node(1, self.options.tmpdir, ["-maxreceivebuffer=20000","-blockmaxsize=5000", "-checkblocks=5", "-disablesafemode"], timewait=900)
 126
 127         height = self.nodes[1].getblockcount()
 128         self.log.info("Current block height: %d" % height)
 129
 130         invalidheight = height-287
 131         badhash = self.nodes[1].getblockhash(invalidheight)
 132         self.log.info("Invalidating block %s at height %d" % (badhash,invalidheight))
 133         self.nodes[1].invalidateblock(badhash)
 134
 135         # We've now switched to our previously mined-24 block fork on node 1, but thats not what we want
 136         # So invalidate that fork as well, until we're on the same chain as node 0/2 (but at an ancestor 288 blocks ago)
 137         mainchainhash = self.nodes[0].getblockhash(invalidheight - 1)
 138         curhash = self.nodes[1].getblockhash(invalidheight - 1)
 139         while curhash != mainchainhash:
 140             self.nodes[1].invalidateblock(curhash)
 141             curhash = self.nodes[1].getblockhash(invalidheight - 1)
 142
 143         assert(self.nodes[1].getblockcount() == invalidheight - 1)
 144         self.log.info("New best height: %d" % self.nodes[1].getblockcount())
 145
 146         # Reboot node1 to clear those giant tx's from mempool
 147         self.stop_node(1)
 148         self.nodes[1]=start_node(1, self.options.tmpdir, ["-maxreceivebuffer=20000","-blockmaxsize=5000", "-checkblocks=5", "-disablesafemode"], timewait=900)
 149
 150         self.log.info("Generating new longer chain of 300 more blocks")
 151         self.nodes[1].generate(300)
 152
 153         self.log.info("Reconnect nodes")
 154         connect_nodes(self.nodes[0], 1)
 155         connect_nodes(self.nodes[2], 1)
 156         sync_blocks(self.nodes[0:3], timeout=120)
 157
 158         self.log.info("Verify height on node 2: %d" % self.nodes[2].getblockcount())
 159         self.log.info("Usage possibly still high bc of stale blocks in block files: %d" % calc_usage(self.prunedir))
 160
 161         self.log.info("Mine 220 more blocks so we have requisite history (some blocks will be big and cause pruning of previous chain)")
 162         for i in range(22):
 163             # This can be slow, so do this in multiple RPC calls to avoid
 164             # RPC timeouts.
 165             self.nodes[0].generate(10) #node 0 has many large tx's in its mempool from the disconnects
 166         sync_blocks(self.nodes[0:3], timeout=300)
 167
 168         usage = calc_usage(self.prunedir)
 169         self.log.info("Usage should be below target: %d" % usage)
 170         if (usage > 550):
 171             raise AssertionError("Pruning target not being met")
 172
 173         return invalidheight,badhash
 174
 175     def reorg_back(self):
 176         # Verify that a block on the old main chain fork has been pruned away
 177         assert_raises_jsonrpc(-1, "Block not available (pruned data)", self.nodes[2].getblock, self.forkhash)
 178         self.log.info("Will need to redownload block %d" % self.forkheight)
 179
 180         # Verify that we have enough history to reorg back to the fork point
 181         # Although this is more than 288 blocks, because this chain was written more recently
 182         # and only its other 299 small and 220 large block are in the block files after it,
 183         # its expected to still be retained
 184         self.nodes[2].getblock(self.nodes[2].getblockhash(self.forkheight))
 185
 186         first_reorg_height = self.nodes[2].getblockcount()
 187         curchainhash = self.nodes[2].getblockhash(self.mainchainheight)
 188         self.nodes[2].invalidateblock(curchainhash)
 189         goalbestheight = self.mainchainheight
 190         goalbesthash = self.mainchainhash2
 191
 192         # As of 0.10 the current block download logic is not able to reorg to the original chain created in
 193         # create_chain_with_stale_blocks because it doesn't know of any peer thats on that chain from which to
 194         # redownload its missing blocks.
 195         # Invalidate the reorg_test chain in node 0 as well, it can successfully switch to the original chain
 196         # because it has all the block data.
 197         # However it must mine enough blocks to have a more work chain than the reorg_test chain in order
 198         # to trigger node 2's block download logic.
 199         # At this point node 2 is within 288 blocks of the fork point so it will preserve its ability to reorg
 200         if self.nodes[2].getblockcount() < self.mainchainheight:
 201             blocks_to_mine = first_reorg_height + 1 - self.mainchainheight
 202             self.log.info("Rewind node 0 to prev main chain to mine longer chain to trigger redownload. Blocks needed: %d" % blocks_to_mine)
 203             self.nodes[0].invalidateblock(curchainhash)
 204             assert(self.nodes[0].getblockcount() == self.mainchainheight)
 205             assert(self.nodes[0].getbestblockhash() == self.mainchainhash2)
 206             goalbesthash = self.nodes[0].generate(blocks_to_mine)[-1]
 207             goalbestheight = first_reorg_height + 1
 208
 209         self.log.info("Verify node 2 reorged back to the main chain, some blocks of which it had to redownload")
 210         waitstart = time.time()
 211         while self.nodes[2].getblockcount() < goalbestheight:
 212             time.sleep(0.1)
 213             if time.time() - waitstart > 900:
 214                 raise AssertionError("Node 2 didn't reorg to proper height")
 215         assert(self.nodes[2].getbestblockhash() == goalbesthash)
 216         # Verify we can now have the data for a block previously pruned
 217         assert(self.nodes[2].getblock(self.forkhash)["height"] == self.forkheight)
 218
 219     def manual_test(self, node_number, use_timestamp):
 220         # at this point, node has 995 blocks and has not yet run in prune mode
 221         node = self.nodes[node_number] = start_node(node_number, self.options.tmpdir, timewait=900)
 222         assert_equal(node.getblockcount(), 995)
 223         assert_raises_jsonrpc(-1, "not in prune mode", node.pruneblockchain, 500)
 224         self.stop_node(node_number)
 225
 226         # now re-start in manual pruning mode
 227         node = self.nodes[node_number] = start_node(node_number, self.options.tmpdir, ["-prune=1"], timewait=900)
 228         assert_equal(node.getblockcount(), 995)
 229
 230         def height(index):
 231             if use_timestamp:
 232                 return node.getblockheader(node.getblockhash(index))["time"] + TIMESTAMP_WINDOW
 233             else:
 234                 return index
 235
 236         def prune(index, expected_ret=None):
 237             ret = node.pruneblockchain(height(index))
 238             # Check the return value. When use_timestamp is True, just check
 239             # that the return value is less than or equal to the expected
 240             # value, because when more than one block is generated per second,
 241             # a timestamp will not be granular enough to uniquely identify an
 242             # individual block.
 243             if expected_ret is None:
 244                 expected_ret = index
 245             if use_timestamp:
 246                 assert_greater_than(ret, 0)
 247                 assert_greater_than(expected_ret + 1, ret)
 248             else:
 249                 assert_equal(ret, expected_ret)
 250
 251         def has_block(index):
 252             return os.path.isfile(self.options.tmpdir + "/node{}/regtest/blocks/blk{:05}.dat".format(node_number, index))
 253
 254         # should not prune because chain tip of node 3 (995) < PruneAfterHeight (1000)
 255         assert_raises_jsonrpc(-1, "Blockchain is too short for pruning", node.pruneblockchain, height(500))
 256
 257         # mine 6 blocks so we are at height 1001 (i.e., above PruneAfterHeight)
 258         node.generate(6)
 259         assert_equal(node.getblockchaininfo()["blocks"], 1001)
 260
 261         # negative heights should raise an exception
 262         assert_raises_jsonrpc(-8, "Negative", node.pruneblockchain, -10)
 263
 264         # height=100 too low to prune first block file so this is a no-op
 265         prune(100)
 266         if not has_block(0):
 267             raise AssertionError("blk00000.dat is missing when should still be there")
 268
 269         # Does nothing
 270         node.pruneblockchain(height(0))
 271         if not has_block(0):
 272             raise AssertionError("blk00000.dat is missing when should still be there")
 273
 274         # height=500 should prune first file
 275         prune(500)
 276         if has_block(0):
 277             raise AssertionError("blk00000.dat is still there, should be pruned by now")
 278         if not has_block(1):
 279             raise AssertionError("blk00001.dat is missing when should still be there")
 280
 281         # height=650 should prune second file
 282         prune(650)
 283         if has_block(1):
 284             raise AssertionError("blk00001.dat is still there, should be pruned by now")
 285
 286         # height=1000 should not prune anything more, because tip-288 is in blk00002.dat.
 287         prune(1000, 1001 - MIN_BLOCKS_TO_KEEP)
 288         if not has_block(2):
 289             raise AssertionError("blk00002.dat is still there, should be pruned by now")
 290
 291         # advance the tip so blk00002.dat and blk00003.dat can be pruned (the last 288 blocks should now be in blk00004.dat)
 292         node.generate(288)
 293         prune(1000)
 294         if has_block(2):
 295             raise AssertionError("blk00002.dat is still there, should be pruned by now")
 296         if has_block(3):
 297             raise AssertionError("blk00003.dat is still there, should be pruned by now")
 298
 299         # stop node, start back up with auto-prune at 550MB, make sure still runs
 300         self.stop_node(node_number)
 301         self.nodes[node_number] = start_node(node_number, self.options.tmpdir, ["-prune=550"], timewait=900)
 302
 303         self.log.info("Success")
 304
 305     def wallet_test(self):
 306         # check that the pruning node's wallet is still in good shape
 307         self.log.info("Stop and start pruning node to trigger wallet rescan")
 308         self.stop_node(2)
 309         start_node(2, self.options.tmpdir, ["-prune=550"])
 310         self.log.info("Success")
 311
 312         # check that wallet loads loads successfully when restarting a pruned node after IBD.
 313         # this was reported to fail in #7494.
 314         self.log.info("Syncing node 5 to test wallet")
 315         connect_nodes(self.nodes[0], 5)
 316         nds = [self.nodes[0], self.nodes[5]]
 317         sync_blocks(nds, wait=5, timeout=300)
 318         self.stop_node(5) #stop and start to trigger rescan
 319         start_node(5, self.options.tmpdir, ["-prune=550"])
 320         self.log.info("Success")
 321
 322     def run_test(self):
 323         self.log.info("Warning! This test requires 4GB of disk space and takes over 30 mins (up to 2 hours)")
 324         self.log.info("Mining a big blockchain of 995 blocks")
 325
 326         # Determine default relay fee
 327         self.relayfee = self.nodes[0].getnetworkinfo()["relayfee"]
 328
 329         # Cache for utxos, as the listunspent may take a long time later in the test
 330         self.utxo_cache_0 = []
 331         self.utxo_cache_1 = []
 332
 333         self.create_big_chain()
 334         # Chain diagram key:
 335         # *   blocks on main chain
 336         # +,&,$,@ blocks on other forks
 337         # X   invalidated block
 338         # N1  Node 1
 339         #
 340         # Start by mining a simple chain that all nodes have
 341         # N0=N1=N2 **...*(995)
 342
 343         # stop manual-pruning node with 995 blocks
 344         self.stop_node(3)
 345         self.stop_node(4)
 346
 347         self.log.info("Check that we haven't started pruning yet because we're below PruneAfterHeight")
 348         self.test_height_min()
 349         # Extend this chain past the PruneAfterHeight
 350         # N0=N1=N2 **...*(1020)
 351
 352         self.log.info("Check that we'll exceed disk space target if we have a very high stale block rate")
 353         self.create_chain_with_staleblocks()
 354         # Disconnect N0
 355         # And mine a 24 block chain on N1 and a separate 25 block chain on N0
 356         # N1=N2 **...*+...+(1044)
 357         # N0    **...**...**(1045)
 358         #
 359         # reconnect nodes causing reorg on N1 and N2
 360         # N1=N2 **...*(1020) *...**(1045)
 361         #                   \
 362         #                    +...+(1044)
 363         #
 364         # repeat this process until you have 12 stale forks hanging off the
 365         # main chain on N1 and N2
 366         # N0    *************************...***************************(1320)
 367         #
 368         # N1=N2 **...*(1020) *...**(1045) *..         ..**(1295) *...**(1320)
 369         #                   \            \                      \
 370         #                    +...+(1044)  &..                    $...$(1319)
 371
 372         # Save some current chain state for later use
 373         self.mainchainheight = self.nodes[2].getblockcount()   #1320
 374         self.mainchainhash2 = self.nodes[2].getblockhash(self.mainchainheight)
 375
 376         self.log.info("Check that we can survive a 288 block reorg still")
 377         (self.forkheight,self.forkhash) = self.reorg_test() #(1033, )
 378         # Now create a 288 block reorg by mining a longer chain on N1
 379         # First disconnect N1
 380         # Then invalidate 1033 on main chain and 1032 on fork so height is 1032 on main chain
 381         # N1   **...*(1020) **...**(1032)X..
 382         #                  \
 383         #                   ++...+(1031)X..
 384         #
 385         # Now mine 300 more blocks on N1
 386         # N1    **...*(1020) **...**(1032) @@...@(1332)
 387         #                 \               \
 388         #                  \               X...
 389         #                   \                 \
 390         #                    ++...+(1031)X..   ..
 391         #
 392         # Reconnect nodes and mine 220 more blocks on N1
 393         # N1    **...*(1020) **...**(1032) @@...@@@(1552)
 394         #                 \               \
 395         #                  \               X...
 396         #                   \                 \
 397         #                    ++...+(1031)X..   ..
 398         #
 399         # N2    **...*(1020) **...**(1032) @@...@@@(1552)
 400         #                 \               \
 401         #                  \               *...**(1320)
 402         #                   \                 \
 403         #                    ++...++(1044)     ..
 404         #
 405         # N0    ********************(1032) @@...@@@(1552)
 406         #                                 \
 407         #                                  *...**(1320)
 408
 409         self.log.info("Test that we can rerequest a block we previously pruned if needed for a reorg")
 410         self.reorg_back()
 411         # Verify that N2 still has block 1033 on current chain (@), but not on main chain (*)
 412         # Invalidate 1033 on current chain (@) on N2 and we should be able to reorg to
 413         # original main chain (*), but will require redownload of some blocks
 414         # In order to have a peer we think we can download from, must also perform this invalidation
 415         # on N0 and mine a new longest chain to trigger.
 416         # Final result:
 417         # N0    ********************(1032) **...****(1553)
 418         #                                 \
 419         #                                  X@...@@@(1552)
 420         #
 421         # N2    **...*(1020) **...**(1032) **...****(1553)
 422         #                 \               \
 423         #                  \               X@...@@@(1552)
 424         #                   \
 425         #                    +..
 426         #
 427         # N1 doesn't change because 1033 on main chain (*) is invalid
 428
 429         self.log.info("Test manual pruning with block indices")
 430         self.manual_test(3, use_timestamp=False)
 431
 432         self.log.info("Test manual pruning with timestamps")
 433         self.manual_test(4, use_timestamp=True)
 434
 435         self.log.info("Test wallet re-scan")
 436         self.wallet_test()
 437
 438         self.log.info("Done")
 439
 440 if __name__ == '__main__':
 441     PruneTest().main()