harmony
harmony copied to clipboard
Published
20 hours ago •
harmony-one
harmony-one
Race condition between precommit and finalcommit
In testnet, a potential race condition is spotted where precommit and finalcommit happened at the same time. This could only happen in testnet because there is less keys and the time between 2/3 commit and 100% commit can be minimal.
Solution is to add mutex on the call to InsertChain() in both preCommitAndPropose() and finalCommit() methods.
Related log on the testnet leader when the race condition happens is here:
{"level":"info","myBlock":17732590,"myViewID":17735512,"phase":"Commit","mode":"Normal","recvMsg":"[Type:COMMIT ViewID:17735512 Num:17732590 BlockHash:0xa4fe340b11bf027a471952a8df545effe701d33d33b97d2147aae84cc683223b Sender:e64eda1f4eb42916b192b36a8e3b2a396fa3d6ca8bf1e0ab0995db311443f35ddf7eebb3d655f1ccf9e7cbfd6f28e20c Leader:]","numReceivedSoFar":8,"MsgViewID":17735512,"MsgBlockNum":17732590,"caller":"/mnt/jenkins/workspace/harmony-release/harmony/consensus/leader.go:302","time":"2021-11-18T23:35:28.048764349+01:00","message":"[OnCommit] 2/3 Enough commits received"}
{"level":"info","block num":"17732590","caller":"/mnt/jenkins/workspace/harmony-release/harmony/core/state_processor.go:98","time":"2021-11-18T23:35:28.067576676+01:00","message":"result cache hit."}
{"level":"info","myBlock":17732590,"myViewID":17735512,"phase":"Commit","mode":"Normal","waitTime":"1.510448934s","caller":"/mnt/jenkins/workspace/harmony-release/harmony/consensus/leader.go:317","time":"2021-11-18T23:35:28.068571869+01:00","message":"[OnCommit] Starting Grace Period"}
{"level":"info","phase":"Commit","signer-count":11,"new-power-added":"0.150000000000000000","total-power-of-signers":"0.850000000000000000","caller":"/mnt/jenkins/workspace/harmony-release/harmony/consensus/quorum/one-node-staked-vote.go:134","time":"2021-11-18T23:35:28.07096241+01:00","message":"[AddNewVote] New Vote Added!"}
{"level":"info","phase":"Commit","signer-count":13,"new-power-added":"0.150000000000000000","total-power-of-signers":"1.000000000000000000","caller":"/mnt/jenkins/workspace/harmony-release/harmony/consensus/quorum/one-node-staked-vote.go:134","time":"2021-11-18T23:35:28.077207568+01:00","message":"[AddNewVote] New Vote Added!"}
{"level":"info","myBlock":17732590,"myViewID":17735512,"phase":"Commit","mode":"Normal","recvMsg":"[Type:COMMIT ViewID:17735512 Num:17732590 BlockHash:0xa4fe340b11bf027a471952a8df545effe701d33d33b97d2147aae84cc683223b Sender:8a211eb5e9334341fd2498fb5d6b922b4a0984d6a4ea0b5631c1904de5fe21fd6889c9c032d862546ca50a5c41294b0c;f248bd21d67f0b2cd0dd2c06446c557fc35737873857c000698ae391b607ca8ed8df00a79d9dcace1b0ce05492fc9789 Leader:]","numReceivedSoFar":11,"MsgViewID":17735512,"MsgBlockNum":17732590,"caller":"/mnt/jenkins/workspace/harmony-release/harmony/consensus/leader.go:291","time":"2021-11-18T23:35:28.077290362+01:00","message":"[OnCommit] 100% Enough commits received"}
{"level":"info","myBlock":17732590,"myViewID":17735512,"phase":"Commit","mode":"Normal","NumCommits":13,"caller":"/mnt/jenkins/workspace/harmony-release/harmony/consensus/consensus_v2.go:137","time":"2021-11-18T23:35:28.077317002+01:00","message":"[finalCommit] Finalizing Consensus"}
{"level":"info","myBlock":17732590,"myViewID":17735512,"phase":"Commit","mode":"Normal","new":"ea59422519b34d00184e29e912a6caa0a405279d280b09ee8007e2af457803fe26f5aa0f73eae3d5f6caad4f3c9c620ba6e9a44970bd01d8ba47fbf54896d8f9b0cbb2ef076d4c241f1f049e12ce1e88e7067561b65fdf88d5e072ef77df7e8cff1f","caller":"/mnt/jenkins/workspace/harmony-release/harmony/consensus/consensus_v2.go:171","time":"2021-11-18T23:35:28.093994323+01:00","message":"[finalCommit] Overriding commit signatures!!"}
{"level":"info","myBlock":17732590,"myViewID":17735512,"phase":"Commit","mode":"Normal","recvMsg":"[Type:COMMIT ViewID:17735512 Num:17732590 BlockHash:0xa4fe340b11bf027a471952a8df545effe701d33d33b97d2147aae84cc683223b Sender:e64eda1f4eb42916b192b36a8e3b2a396fa3d6ca8bf1e0ab0995db311443f35ddf7eebb3d655f1ccf9e7cbfd6f28e20c Leader:]","numReceivedSoFar":8,"MsgViewID":17735512,"MsgBlockNum":17732590,"caller":"/mnt/jenkins/workspace/harmony-release/harmony/consensus/leader.go:319","time":"2021-11-18T23:35:29.579939362+01:00","message":"[OnCommit] Commit Grace Period Ended"}
{"level":"info","hash":"0x6cf88635479f94e724ef6e48e4ce572d28f7caea5641461d6953c5a568fe1f19","from":"0xac7d2f7c00a55859a3c0041e6f613552c16c0aab","to":"0xeb1df0baf6a29b5d246cbf7072e0aa44f266555f","caller":"/mnt/jenkins/workspace/harmony-release/harmony/core/tx_pool.go:1027","time":"2021-11-18T23:35:37.659037713+01:00","message":"Pooled new future transaction"}
{"level":"info","hash":"0x6cf88635479f94e724ef6e48e4ce572d28f7caea5641461d6953c5a568fe1f19","caller":"/mnt/jenkins/workspace/harmony-release/harmony/core/tx_pool.go:1335","time":"2021-11-18T23:35:37.659194575+01:00","message":"Promoting queued transaction"}
{"level":"info","err":[null],"length of newTxs":1,"totalPending":3,"totalQueued":0,"caller":"/mnt/jenkins/workspace/harmony-release/harmony/node/node.go:220","time":"2021-11-18T23:35:37.659258725+01:00","message":"[addPendingTransactions] Adding more transactions"}
{"level":"warn","ip":"0.0.0.0","port":"9000","caller":"/mnt/jenkins/workspace/harmony-release/harmony/node/node_syncing.go:535","time":"2021-11-18T23:35:43.6553621+01:00","message":"[SYNC] peerRegistration record already exists"}
{"level":"warn","myBlock":17732590,"myViewID":17735512,"phase":"Commit","mode":"Normal","caller":"/mnt/jenkins/workspace/harmony-release/harmony/consensus/consensus_v2.go:351","time":"2021-11-18T23:35:53.133969597+01:00","message":"[ConsensusMainLoop] Ops Consensus Timeout!!!"}
{"level":"info","blockNum":17850946,"shardID":1,"caller":"/mnt/jenkins/workspace/harmony-release/harmony/core/offchain.go:165","time":"2021-11-18T23:35:54.41783258+01:00","message":"[insertChain/crosslinks] Cross Link Added to Beaconchain"}
{"level":"info","blockNum":17850947,"shardID":1,"caller":"/mnt/jenkins/workspace/harmony-release/harmony/core/offchain.go:165","time":"2021-11-18T23:35:54.417914282+01:00","message":"[insertChain/crosslinks] Cross Link Added to Beaconchain"}
{"level":"info","blockNum":17850948,"shardID":1,"caller":"/mnt/jenkins/workspace/harmony-release/harmony/core/offchain.go:165","time":"2021-11-18T23:35:54.417944949+01:00","message":"[insertChain/crosslinks] Cross Link Added to Beaconchain"}
{"level":"info","blockNum":17716718,"shardID":2,"caller":"/mnt/jenkins/workspace/harmony-release/harmony/core/offchain.go:165","time":"2021-11-18T23:35:54.417975075+01:00","message":"[insertChain/crosslinks] Cross Link Added to Beaconchain"}
{"level":"info","blockNum":17716719,"shardID":2,"caller":"/mnt/jenkins/workspace/harmony-release/harmony/core/offchain.go:165","time":"2021-11-18T23:35:54.418059974+01:00","message":"[insertChain/crosslinks] Cross Link Added to Beaconchain"}
{"level":"info","blockNum":17723167,"shardID":3,"caller":"/mnt/jenkins/workspace/harmony-release/harmony/core/offchain.go:165","time":"2021-11-18T23:35:54.418124343+01:00","message":"[insertChain/crosslinks] Cross Link Added to Beaconchain"}
{"level":"info","blockNum":17723168,"shardID":3,"caller":"/mnt/jenkins/workspace/harmony-release/harmony/core/offchain.go:165","time":"2021-11-18T23:35:54.418158266+01:00","message":"[insertChain/crosslinks] Cross Link Added to Beaconchain"}
{"level":"info","number":"17732590","hash":"0xa4fe340b11bf027a471952a8df545effe701d33d33b97d2147aae84cc683223b","uncles":0,"txs":1,"stakingTxs":0,"gas":27163,"elapsed":"26.452s","caller":"/mnt/jenkins/workspace/harmony-release/harmony/core/blockchain.go:1488","time":"2021-11-18T23:35:54.519655223+01:00","message":"Inserted new block"}
{"level":"info","blocks":1,"txs":1,"mgas":0.027163,"elapsed":"26.452s","mgasps":0.0010268608658642602,"number":"17732590","hash":"0xa4fe340b11bf027a471952a8df545effe701d33d33b97d2147aae84cc683223b","cache":"4.13 MiB","caller":"/mnt/jenkins/workspace/harmony-release/harmony/core/blockchain.go:1560","time":"2021-11-18T23:35:54.519775517+01:00","message":"Imported new chain segment"}
{"level":"info","caller":"/mnt/jenkins/workspace/harmony-release/harmony/node/node_handler.go:142","time":"2021-11-18T23:35:54.520965633+01:00","message":"broadcasting new block 17732590, group hmy/testnet/0.0.1/client/beacon"}
{"level":"info","myBlock":17732590,"myViewID":17735512,"phase":"Commit","mode":"Normal","blockHash":"0xa4fe340b11bf027a471952a8df545effe701d33d33b97d2147aae84cc683223b","blockNum":17732590,"lastCommitSig":"ab10ff89838db04eb45ba819532bd1bdc200ca863ee18390b26c2695b6576403d59d0130f9b9c898c496026484f87603748e10ff7e337f3becb2a84cfae3d20dc66d0c8dea52efe7ab8ae0eb9f6af9cc929f5e6cce19a625113b805a48c33f80331f","caller":"/mnt/jenkins/workspace/harmony-release/harmony/consensus/consensus_v2.go:579","time":"2021-11-18T23:35:54.522955067+01:00","message":"[preCommitAndPropose] Sent Committed Message"}
{"level":"info","myBlock":17732590,"myViewID":17735512,"phase":"Commit","mode":"Normal","caller":"/mnt/jenkins/workspace/harmony-release/harmony/consensus/consensus_v2.go:581","time":"2021-11-18T23:35:54.523010811+01:00","message":"[preCommitAndPropose] Start consensus timer"}
{"level":"info","myBlock":17732590,"myViewID":17735512,"phase":"Commit","mode":"Normal","caller":"/mnt/jenkins/workspace/harmony-release/harmony/consensus/consensus_v2.go:585","time":"2021-11-18T23:35:54.523057959+01:00","message":"[preCommitAndPropose] sending block proposal signal"}
{"level":"info","shardNum":4,"myShardID":0,"blockNum":17732590,"caller":"/mnt/jenkins/workspace/harmony-release/harmony/node/node_cross_shard.go:37","time":"2021-11-18T23:35:54.524451243+01:00","message":"[BroadcastCXReceipts]"}
{"level":"info","blockNum":17732590,"hash":"0xa4fe340b11bf027a471952a8df545effe701d33d33b97d2147aae84cc683223b","caller":"/mnt/jenkins/workspace/harmony-release/harmony/consensus/consensus_v2.go:677","time":"2021-11-18T23:35:54.52478798+01:00","message":"Added New Block to Blockchain!!!"}
{"level":"info","myBlock":17732591,"myViewID":17735513,"phase":"Announce","mode":"Normal","blockHash":"a4fe340b11bf027a471952a8df545effe701d33d33b97d2147aae84cc683223b","blockNum":17732591,"lastCommitSig":"ea59422519b34d00184e29e912a6caa0a405279d280b09ee8007e2af457803fe26f5aa0f73eae3d5f6caad4f3c9c620ba6e9a44970bd01d8ba47fbf54896d8f9b0cbb2ef076d4c241f1f049e12ce1e88e7067561b65fdf88d5e072ef77df7e8cff1f","caller":"/mnt/jenkins/workspace/harmony-release/harmony/consensus/consensus_v2.go:216","time":"2021-11-18T23:35:54.524865424+01:00","message":"[finalCommit] Queued Committed Message"}
{"level":"info","myBlock":17732591,"myViewID":17735513,"phase":"Announce","mode":"Normal","blockNum":17732590,"epochNum":74825,"ViewId":17735512,"blockHash":"0xa4fe340b11bf027a471952a8df545effe701d33d33b97d2147aae84cc683223b","numTxns":1,"numStakingTxns":0,"caller":"/mnt/jenkins/workspace/harmony-release/harmony/consensus/consensus_v2.go:237","time":"2021-11-18T23:35:54.524903234+01:00","message":"HOORAY!!!!!!! CONSENSUS REACHED!!!!!!!"}
{"level":"info","myBlock":17732591,"myViewID":17735513,"phase":"Announce","mode":"ViewChanging","curTimestamp":1637274954,"blockTimestamp":1637274926,"nextViewID":17735514,"stuckBlockViewID":17735513,"caller":"/mnt/jenkins/workspace/harmony-release/harmony/consensus/view_change.go:157","time":"2021-11-18T23:35:54.524965601+01:00","message":"[getNextViewID]"}
{"level":"info","myBlock":17732591,"myViewID":17735513,"phase":"Announce","mode":"ViewChanging","lastLeaderPubKey":"e7f54994bc5c02edeeb178ce2d34db276a893bab5c59ac3d7eb9f077c893f9e31171de6236ba0e21be415d8631e45b91","leaderPubKey":"e7f54994bc5c02edeeb178ce2d34db276a893bab5c59ac3d7eb9f077c893f9e31171de6236ba0e21be415d8631e45b91","gap":1,"newViewID":17735514,"myCurBlockViewID":17735513,"caller":"/mnt/jenkins/workspace/harmony-release/harmony/consensus/view_change.go:213","time":"2021-11-18T23:35:54.525026715+01:00","message":"[getNextLeaderKey] got leaderPubKey from coinbase"}
{"level":"info","myBlock":17732591,"myViewID":17735513,"phase":"Announce","mode":"ViewChanging","nextLeader":"99d0835797ca0683fb7b1d14a882879652ddcdcfe0d52385ffddf8012ee804d92e5c05a56c9d7fc663678e36a158a28c","caller":"/mnt/jenkins/workspace/harmony-release/harmony/consensus/view_change.go:227","time":"2021-11-18T23:35:54.525051681+01:00","message":"[getNextLeaderKey] next Leader"}
{"level":"warn","myBlock":17732591,"myViewID":17735513,"phase":"Announce","mode":"ViewChanging","nextViewID":17735514,"viewChangingID":17735514,"timeoutDuration":27000,"NextLeader":"99d0835797ca0683fb7b1d14a882879652ddcdcfe0d52385ffddf8012ee804d92e5c05a56c9d7fc663678e36a158a28c","caller":"/mnt/jenkins/workspace/harmony-release/harmony/consensus/view_change.go:265","time":"2021-11-18T23:35:54.525077369+01:00","message":"[startViewChange]"}
{"level":"info","context":"ViewChange","viewID":17735514,"blockNum":17732591,"caller":"/mnt/jenkins/workspace/harmony-release/harmony/consensus/view_change_construct.go:436","time":"2021-11-18T23:35:54.525131109+01:00","message":"[InitPayload] add my M2 (NIL) type messaage"}
{"level":"info","context":"ViewChange","viewID":17735514,"blockNum":17732591,"caller":"/mnt/jenkins/workspace/harmony-release/harmony/consensus/view_change_construct.go:467","time":"2021-11-18T23:35:54.52698978+01:00","message":"[InitPayload] add my M3 (ViewID) type messaage"}
{"level":"info","myBlock":17732591,"myViewID":17735513,"phase":"Announce","mode":"ViewChanging","m1Payload":"","NextLeader":"99d0835797ca0683fb7b1d14a882879652ddcdcfe0d52385ffddf8012ee804d92e5c05a56c9d7fc663678e36a158a28c","SenderPubKey":"8c95e04a4826d4d80ef16183f13aa5d14eb3c96d2755407e15c440bb4edd6e4636a82e47975385c6223ba24759561103","caller":"/mnt/jenkins/workspace/harmony-release/harmony/consensus/view_change_msg.go:76","time":"2021-11-18T23:35:54.528583326+01:00","message":"[constructViewChangeMessage]"}
{"level":"info","myBlock":17732591,"myViewID":17735513,"phase":"Announce","mode":"ViewChanging","m1Payload":"","NextLeader":"99d0835797ca0683fb7b1d14a882879652ddcdcfe0d52385ffddf8012ee804d92e5c05a56c9d7fc663678e36a158a28c","SenderPubKey":"e7f54994bc5c02edeeb178ce2d34db276a893bab5c59ac3d7eb9f077c893f9e31171de6236ba0e21be415d8631e45b91","caller":"/mnt/jenkins/workspace/harmony-release/harmony/consensus/view_change_msg.go:76","time":"2021-11-18T23:35:54.533380969+01:00","message":"[constructViewChangeMessage]"}
{"level":"info","blockNum":17732591,"asyncProposal":true,"caller":"/mnt/jenkins/workspace/harmony-release/harmony/node/node_newblock.go:57","time":"2021-11-18T23:35:54.544078176+01:00","message":"PROPOSING NEW BLOCK ------------------------------------------------"}
{"level":"error","error":"[GenerateVrfAndProof] no leader private key provided","retryCount":1,"caller":"/mnt/jenkins/workspace/harmony-release/harmony/node/node_newblock.go:113","time":"2021-11-18T23:35:54.544468963+01:00","message":"!!!!!!!!!Failed Proposing New Block!!!!!!!!!"}
