Race in generatetoaddress?

ajtowns commented at 6:55 am on April 1, 2022: member

Test failure at https://cirrus-ci.com/task/5291668088815616?logs=ci#L3216 seems to indicate generatetoaddress has a path that doesn’t set the height in coinbase correctly.

RPC call:

0 node1 2022-03-31T22:42:56.024486Z [httpworker.2] [rpc/request.cpp:179] [parse] ThreadRPCServer method=generatetoaddress user=__cookie__

A new block immediately arrives over the network via the msghand thread:

0 node1 2022-03-31T22:42:56.024658Z [httpworker.2] [logging/timer.h:57] [Log] Enter: lock contention cs_main, rpc/mining.cpp:156 started 
1 node1 2022-03-31T22:42:56.026452Z [msghand] [validationinterface.cpp:254] [NewPoWValidBlock] NewPoWValidBlock: block hash=7b7df2920d9870cb286408956ea95f6d307bb87dfd446bce18e4c35f7fe3651b 
2 node1 2022-03-31T22:42:56.028907Z [httpworker.2] [logging/timer.h:57] [Log] Enter: lock contention cs_main, rpc/mining.cpp:156 completed (4225μs)

Then msghand gets held up in the middle of ActivateBestChain:

0[...short lock contention...]
1 node1 2022-03-31T22:42:56.029082Z [msghand] [logging/timer.h:57] [Log] Enter: lock contention cs_main, validation.cpp:2889 started 
2 node1 2022-03-31T22:42:56.029188Z [httpworker.2] [node/miner.cpp:160] [CreateNewBlock] CreateNewBlock(): block weight: 892 txs: 0 fees: 0 sigops 400 
3 node1 2022-03-31T22:42:56.029339Z [httpworker.2] [validation.cpp:1988] [ConnectBlock]     - Sanity checks: 0.01ms [0.00s (0.00ms/blk)] 
4 node1 2022-03-31T22:42:56.029411Z [httpworker.2] [validation.cpp:2087] [ConnectBlock]     - Fork checks: 0.08ms [0.01s (0.08ms/blk)] 
5 node1 2022-03-31T22:42:56.029448Z [httpworker.2] [validation.cpp:2172] [ConnectBlock]       - Connect 1 transactions: 0.04ms (0.035ms/tx, 0.000ms/txin) [0.01s (0.05ms/blk)] 
6 node1 2022-03-31T22:42:56.029486Z [httpworker.2] [validation.cpp:2185] [ConnectBlock]     - Verify 0 txins: 0.07ms (0.000ms/txin) [0.01s (0.10ms/blk)] 
7 node1 2022-03-31T22:42:56.029522Z [httpworker.2] [node/miner.cpp:175] [CreateNewBlock] CreateNewBlock() packages: 0.15ms (0 packages, 0 updated descendants), validity: 0.40ms (total 0.55ms) 
8 node1 2022-03-31T22:42:56.029554Z [httpworker.2] [logging/timer.h:57] [Log] Enter: lock contention cs_main, rpc/mining.cpp:124 started 
9 node1 2022-03-31T22:42:56.029586Z [msghand] [logging/timer.h:57] [Log] Enter: lock contention cs_main, validation.cpp:2889 completed (446μs)

At this point msghand has the ball again, and httpworker.2 is waiting before calling IncrementExtraNonce which is where the height in coinbase is set.

 0 node1 2022-03-31T22:42:56.029678Z [msghand] [validation.cpp:2617] [ConnectTip]   - Load block from disk: 0.00ms [0.00s] 
 1 node1 2022-03-31T22:42:56.029743Z [msghand] [validation.cpp:1988] [ConnectBlock]     - Sanity checks: 0.00ms [0.00s (0.00ms/blk)] 
 2 node1 2022-03-31T22:42:56.029823Z [msghand] [validation.cpp:2087] [ConnectBlock]     - Fork checks: 0.08ms [0.01s (0.08ms/blk)] 
 3 node1 2022-03-31T22:42:56.029877Z [msghand] [validation.cpp:2172] [ConnectBlock]       - Connect 1 transactions: 0.05ms (0.049ms/tx, 0.000ms/txin) [0.01s (0.05ms/blk)] 
 4 node1 2022-03-31T22:42:56.029919Z [msghand] [validation.cpp:2185] [ConnectBlock]     - Verify 0 txins: 0.09ms (0.000ms/txin) [0.01s (0.10ms/blk)] 
 5 node1 2022-03-31T22:42:56.030054Z [msghand] [validation.cpp:2204] [ConnectBlock]     - Index writing: 0.14ms [0.01s (0.08ms/blk)] 
 6 node1 2022-03-31T22:42:56.030101Z [msghand] [validationinterface.cpp:249] [BlockChecked] BlockChecked: block hash=7b7df2920d9870cb286408956ea95f6d307bb87dfd446bce18e4c35f7fe3651b state=Valid 
 7 node1 2022-03-31T22:42:56.030173Z [msghand] [validation.cpp:2629] [ConnectTip]   - Connect total: 0.50ms [0.05s (0.37ms/blk)] 
 8 node1 2022-03-31T22:42:56.030208Z [msghand] [validation.cpp:2634] [ConnectTip]   - Flush: 0.04ms [0.00s (0.03ms/blk)] 
 9 node1 2022-03-31T22:42:56.030268Z [msghand] [validation.cpp:2640] [ConnectTip]   - Writing chainstate: 0.06ms [0.01s (0.04ms/blk)] 
10 node1 2022-03-31T22:42:56.031702Z [msghand] [policy/fees.cpp:654] [processBlock] Blockpolicy estimates updated by 0 of 0 block txs, since last block 0 of 0 tracked, mempool map size 0, max target 51 from current 
11 node1 2022-03-31T22:42:56.031821Z [msghand] [validation.cpp:2433] [UpdateTipLog] UpdateTip: new best=7b7df2920d9870cb286408956ea95f6d307bb87dfd446bce18e4c35f7fe3651b height=305 version=0x30000000 log2_work=9.257388 tx=310 date='2022-03-31T22:43:07Z' progress=1.000000 cache=0.0MiB(112txo) 
12 node1 2022-03-31T22:42:56.031851Z [msghand] [validation.cpp:2651] [ConnectTip]   - Connect postprocess: 1.58ms [0.16s (1.14ms/blk)] 
13 node1 2022-03-31T22:42:56.031877Z [msghand] [validation.cpp:2652] [ConnectTip] - Connect block: 2.18ms [0.22s (1.58ms/blk)] 
14 node1 2022-03-31T22:42:56.031914Z [msghand] [txmempool.cpp:722] [check] Checking mempool with 0 transactions and 0 inputs 
15 node1 2022-03-31T22:42:56.032021Z [msghand] [validationinterface.cpp:226] [BlockConnected] Enqueuing BlockConnected: block hash=7b7df2920d9870cb286408956ea95f6d307bb87dfd446bce18e4c35f7fe3651b block height=305 
16 node1 2022-03-31T22:42:56.032089Z [msghand] [validationinterface.cpp:199] [UpdatedBlockTip] Enqueuing UpdatedBlockTip: new block hash=7b7df2920d9870cb286408956ea95f6d307bb87dfd446bce18e4c35f7fe3651b fork block hash=7b0602dccb1e34108167e32238ec6011d29eae6da3f9e4430165bc0ecd5283d7 (in IBD=false)

Now the tip has been updated. Looks like msghand releases the lock, but manages to reacquire it before any other thread:

0node1 2022-03-31T22:42:56.032134Z [msghand] [logging/timer.h:57] [Log] Enter: lock contention newTaskMutex, scheduler.cpp:78 started 
1node1 2022-03-31T22:42:56.032167Z [msghand] [logging/timer.h:57] [Log] Enter: lock contention newTaskMutex, scheduler.cpp:78 completed (3μs)

The scheduler thread seems to get the lock next:

0 node1 2022-03-31T22:42:56.032194Z [scheduler] [validationinterface.cpp:226] [operator()] BlockConnected: block hash=7b7df2920d9870cb286408956ea95f6d307bb87dfd446bce18e4c35f7fe3651b block height=305 
1 node1 2022-03-31T22:42:56.032261Z [scheduler] [logging/timer.h:57] [Log] Enter: lock contention cs_main, net_processing.cpp:1596 started 
2 node1 2022-03-31T22:42:56.034681Z [scheduler] [logging/timer.h:57] [Log] Enter: lock contention cs_main, net_processing.cpp:1596 completed (2398μs)

And finally httpworker.2 gets it, incrementing the extra nonce, and presumably updating to the new block.

0 node1 2022-03-31T22:42:56.034725Z [httpworker.2] [logging/timer.h:57] [Log] Enter: lock contention cs_main, rpc/mining.cpp:124 
1completed (5139μs)

Other threads do their thing:

0 node1 2022-03-31T22:42:56.034760Z [msghand] [logging/timer.h:57] [Log] Enter: lock contention ::cs_main, validation.cpp:5081 started 
1 node1 2022-03-31T22:42:56.034826Z [msghand] [logging/timer.h:57] [Log] Enter: lock contention ::cs_main, validation.cpp:5081 completed (32μs) 
2 node1 2022-03-31T22:42:56.034855Z [scheduler] [validationinterface.cpp:199] [operator()] UpdatedBlockTip: new block hash=7b7df2920d9870cb286408956ea95f6d307bb87dfd446bce18e4c35f7fe3651b fork block hash=7b0602dccb1e34108167e32238ec6011d29eae6da3f9e4430165bc0ecd5283d7 (in IBD=false)

Then httpworker.2 is calling ProcessNewblock and everything falls apart:

 0 node1 2022-03-31T22:42:56.034887Z [httpworker.2] [logging/timer.h:57] [Log] Enter: lock contention cs_main, validation.cpp:3687 started 
 1 node1 2022-03-31T22:42:56.034970Z [httpworker.2] [logging/timer.h:57] [Log] Enter: lock contention cs_main, validation.cpp:3687 completed (58μs) 
 2 node1 2022-03-31T22:42:56.035025Z [msghand] [logging/timer.h:57] [Log] Enter: lock contention ::cs_main, validation.cpp:5081 started 
 3 test  2022-03-31T22:42:56.036000Z TestFramework (ERROR): JSONRPC error 
 4                                   Traceback (most recent call last):
 5                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 132, in main
 6                                       self.run_test()
 7                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/wallet_listreceivedby.py", line 258, in run_test
 8                                       self.generatetoaddress(self.nodes[1], COINBASE_MATURITY + 1, address2, sync_fun=self.no_op)
 9                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 649, in generatetoaddress
10                                       blocks = generator.generatetoaddress(*args, invalid_call=False, **kwargs)
11                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_node.py", line 311, in generatetoaddress
12                                       return self.__getattr__('generatetoaddress')(*args, **kwargs)
13                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/coverage.py", line 49, in __call__
14                                       return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
15                                     File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/authproxy.py", line 144, in __call__
16                                       raise JSONRPCException(response['error'], status)
17                                   test_framework.authproxy.JSONRPCException: ProcessNewBlock, block not accepted (-32603)
18 node1 2022-03-31T22:42:56.036311Z [httpworker.2] [util/system.h:51] [error] ERROR: AcceptBlock: bad-cb-height, block height mismatch in coinbase 
19 node1 2022-03-31T22:42:56.036345Z [httpworker.2] [validationinterface.cpp:249] [BlockChecked] BlockChecked: block hash=2f267e107b619688b165b81e220b7012a48537ec711c044b19a9527ae7615421 state=bad-cb-height, block height mismatch in coinbase 
20 node1 2022-03-31T22:42:56.036381Z [httpworker.2] [util/system.h:51] [error] ERROR: ProcessNewBlock: AcceptBlock FAILED (bad-cb-height, block height mismatch in coinbase) 
21 node1 2022-03-31T22:42:56.036425Z [msghand] [logging/timer.h:57] [Log] Enter: lock contention ::cs_main, validation.cpp:5081 completed (1364μs)

ajtowns added the label Bug on Apr 1, 2022

MarcoFalke commented at 8:19 am on April 1, 2022: member

IncrementExtraNonce uses the wrong block height. If the block was created with CNB at an earlier height, it is wrong to just use the height of the tip when updating the extra nonce.

I think you are reporting two bugs:

A race in the tests, as the functional tests shouldn’t compete for the tip block in normal operation?
A race in IncrementExtraNonce

I think the bug in IncrementExtraNonce can be fixed by removing the function. Not sure about test bug.

ajtowns commented at 10:57 am on April 1, 2022: member

Ahh, I think static hashPrevBlock should be replaced by pindexPrev->GetBlockHash() if it were worth keeping.

Yes, the race in the test was what I originally thought was buggy, but I couldn’t see what was going on in IncExtraNonce to result in that particular error.

MarcoFalke commented at 1:23 pm on April 1, 2022: member

Fixed both issues in #https://github.com/bitcoin/bitcoin/pull/24732 and https://github.com/bitcoin/bitcoin/pull/24739

MarcoFalke referenced this in commit 79bf1a0fa2 on Apr 6, 2022

MarcoFalke referenced this in commit f58c1f1a44 on Apr 27, 2022

sidhujag referenced this in commit 0b6f2ffe8c on Apr 29, 2022

jamesob commented at 5:06 pm on June 6, 2022: member

Issue can be closed?

MarcoFalke closed this on Jun 7, 2022

DrahtBot locked this on Jun 7, 2023

Race in generatetoaddress? #24730