Race in generatetoaddress? #24730
Description
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:
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:
node1 2022-03-31T22:42:56.024658Z [httpworker.2] [logging/timer.h:57] [Log] Enter: lock contention cs_main, rpc/mining.cpp:156 started
node1 2022-03-31T22:42:56.026452Z [msghand] [validationinterface.cpp:254] [NewPoWValidBlock] NewPoWValidBlock: block hash=7b7df2920d9870cb286408956ea95f6d307bb87dfd446bce18e4c35f7fe3651b
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:
[...short lock contention...]
node1 2022-03-31T22:42:56.029082Z [msghand] [logging/timer.h:57] [Log] Enter: lock contention cs_main, validation.cpp:2889 started
node1 2022-03-31T22:42:56.029188Z [httpworker.2] [node/miner.cpp:160] [CreateNewBlock] CreateNewBlock(): block weight: 892 txs: 0 fees: 0 sigops 400
node1 2022-03-31T22:42:56.029339Z [httpworker.2] [validation.cpp:1988] [ConnectBlock] - Sanity checks: 0.01ms [0.00s (0.00ms/blk)]
node1 2022-03-31T22:42:56.029411Z [httpworker.2] [validation.cpp:2087] [ConnectBlock] - Fork checks: 0.08ms [0.01s (0.08ms/blk)]
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)]
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)]
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)
node1 2022-03-31T22:42:56.029554Z [httpworker.2] [logging/timer.h:57] [Log] Enter: lock contention cs_main, rpc/mining.cpp:124 started
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.
node1 2022-03-31T22:42:56.029678Z [msghand] [validation.cpp:2617] [ConnectTip] - Load block from disk: 0.00ms [0.00s]
node1 2022-03-31T22:42:56.029743Z [msghand] [validation.cpp:1988] [ConnectBlock] - Sanity checks: 0.00ms [0.00s (0.00ms/blk)]
node1 2022-03-31T22:42:56.029823Z [msghand] [validation.cpp:2087] [ConnectBlock] - Fork checks: 0.08ms [0.01s (0.08ms/blk)]
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)]
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)]
node1 2022-03-31T22:42:56.030054Z [msghand] [validation.cpp:2204] [ConnectBlock] - Index writing: 0.14ms [0.01s (0.08ms/blk)]
node1 2022-03-31T22:42:56.030101Z [msghand] [validationinterface.cpp:249] [BlockChecked] BlockChecked: block hash=7b7df2920d9870cb286408956ea95f6d307bb87dfd446bce18e4c35f7fe3651b state=Valid
node1 2022-03-31T22:42:56.030173Z [msghand] [validation.cpp:2629] [ConnectTip] - Connect total: 0.50ms [0.05s (0.37ms/blk)]
node1 2022-03-31T22:42:56.030208Z [msghand] [validation.cpp:2634] [ConnectTip] - Flush: 0.04ms [0.00s (0.03ms/blk)]
node1 2022-03-31T22:42:56.030268Z [msghand] [validation.cpp:2640] [ConnectTip] - Writing chainstate: 0.06ms [0.01s (0.04ms/blk)]
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
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)
node1 2022-03-31T22:42:56.031851Z [msghand] [validation.cpp:2651] [ConnectTip] - Connect postprocess: 1.58ms [0.16s (1.14ms/blk)]
node1 2022-03-31T22:42:56.031877Z [msghand] [validation.cpp:2652] [ConnectTip] - Connect block: 2.18ms [0.22s (1.58ms/blk)]
node1 2022-03-31T22:42:56.031914Z [msghand] [txmempool.cpp:722] [check] Checking mempool with 0 transactions and 0 inputs
node1 2022-03-31T22:42:56.032021Z [msghand] [validationinterface.cpp:226] [BlockConnected] Enqueuing BlockConnected: block hash=7b7df2920d9870cb286408956ea95f6d307bb87dfd446bce18e4c35f7fe3651b block height=305
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:
node1 2022-03-31T22:42:56.032134Z [msghand] [logging/timer.h:57] [Log] Enter: lock contention newTaskMutex, scheduler.cpp:78 started
node1 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:
node1 2022-03-31T22:42:56.032194Z [scheduler] [validationinterface.cpp:226] [operator()] BlockConnected: block hash=7b7df2920d9870cb286408956ea95f6d307bb87dfd446bce18e4c35f7fe3651b block height=305
node1 2022-03-31T22:42:56.032261Z [scheduler] [logging/timer.h:57] [Log] Enter: lock contention cs_main, net_processing.cpp:1596 started
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.
node1 2022-03-31T22:42:56.034725Z [httpworker.2] [logging/timer.h:57] [Log] Enter: lock contention cs_main, rpc/mining.cpp:124
completed (5139μs)
Other threads do their thing:
node1 2022-03-31T22:42:56.034760Z [msghand] [logging/timer.h:57] [Log] Enter: lock contention ::cs_main, validation.cpp:5081 started
node1 2022-03-31T22:42:56.034826Z [msghand] [logging/timer.h:57] [Log] Enter: lock contention ::cs_main, validation.cpp:5081 completed (32μs)
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:
node1 2022-03-31T22:42:56.034887Z [httpworker.2] [logging/timer.h:57] [Log] Enter: lock contention cs_main, validation.cpp:3687 started
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)
node1 2022-03-31T22:42:56.035025Z [msghand] [logging/timer.h:57] [Log] Enter: lock contention ::cs_main, validation.cpp:5081 started
test 2022-03-31T22:42:56.036000Z TestFramework (ERROR): JSONRPC error
Traceback (most recent call last):
File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 132, in main
self.run_test()
File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/wallet_listreceivedby.py", line 258, in run_test
self.generatetoaddress(self.nodes[1], COINBASE_MATURITY + 1, address2, sync_fun=self.no_op)
File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 649, in generatetoaddress
blocks = generator.generatetoaddress(*args, invalid_call=False, **kwargs)
File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_node.py", line 311, in generatetoaddress
return self.__getattr__('generatetoaddress')(*args, **kwargs)
File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/coverage.py", line 49, in __call__
return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
File "/tmp/cirrus-ci-build/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/authproxy.py", line 144, in __call__
raise JSONRPCException(response['error'], status)
test_framework.authproxy.JSONRPCException: ProcessNewBlock, block not accepted (-32603)
node1 2022-03-31T22:42:56.036311Z [httpworker.2] [util/system.h:51] [error] ERROR: AcceptBlock: bad-cb-height, block height mismatch in coinbase
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
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)
node1 2022-03-31T22:42:56.036425Z [msghand] [logging/timer.h:57] [Log] Enter: lock contention ::cs_main, validation.cpp:5081 completed (1364μs)