Fix mutliple version protocol test intermittent failure

plugins/producer_plugin/producer_plugin.cpp

@@ -963,6 +963,7 @@ void producer_plugin::handle_sighup() {
 }
 
 void producer_plugin::pause() {
+   ilog("Producer paused.")
    my->_pause_production = true;
 }
 
@@ -974,7 +975,10 @@ void producer_plugin::resume() {
    if (my->_pending_block_mode == pending_block_mode::speculating) {
       chain::controller& chain = my->chain_plug->chain();
       my->_unapplied_transactions.add_aborted( chain.abort_block() );
+      ilog("Producer resumed. Scheduling production.")
       my->schedule_production_loop();
+   } else {
+      ilog("Producer resumed.")
    }
 }
 

tests/nodeos_forked_chain_test.py

@@ -290,7 +290,7 @@ def getMinHeadAndLib(prodNodes):
 
         if producerToSlot[lastBlockProducer]["count"]!=inRowCountPerProducer:
             Utils.errorExit("Producer %s, in slot %d, expected to produce %d blocks but produced %d blocks.  At block number %d." %
-                            (blockProducer, slot, inRowCountPerProducer, producerToSlot[lastBlockProducer]["count"], blockNum))
+                            (lastBlockProducer, slot, inRowCountPerProducer, producerToSlot[lastBlockProducer]["count"], blockNum-1))
 
         if blockProducer==productionCycle[0]:
             break

tests/nodeos_multiple_version_protocol_feature_test.py

@@ -97,7 +97,8 @@ def hasBlockBecomeIrr():
                           specificExtraNodeosArgs={
                              0:"--http-max-response-time-ms 990000",
                              1:"--http-max-response-time-ms 990000",
-                             2:"--http-max-response-time-ms 990000"},
+                             2:"--http-max-response-time-ms 990000",
+                             3:"--last-block-time-offset-us -200000"},
                           onlySetProds=True,
                           pfSetupPolicy=PFSetupPolicy.NONE,
                           alternateVersionLabelsFile=alternateVersionLabelsFile,
@@ -117,10 +118,10 @@ def resumeBlockProductions():
         for node in allNodes:
             if not node.killed: node.processCurlCmd("producer", "resume", "")
 
-    def shouldNodesBeInSync(nodes:[Node]):
+    def areNodesInSync(nodes:[Node]):
         # Pause all block production to ensure the head is not moving
         pauseBlockProductions()
-        time.sleep(1) # Wait for some time to ensure all blocks are propagated
+        time.sleep(2) # Wait for some time to ensure all blocks are propagated
         headBlockIds = []
         for node in nodes:
             headBlockId = node.getInfo()["head_block_id"]
@@ -129,7 +130,7 @@ def shouldNodesBeInSync(nodes:[Node]):
         return len(set(headBlockIds)) == 1
 
     # Before everything starts, all nodes (new version and old version) should be in sync
-    assert shouldNodesBeInSync(allNodes), "Nodes are not in sync before preactivation"
+    assert areNodesInSync(allNodes), "Nodes are not in sync before preactivation"
 
     # First, we are going to test the case where:
     # - 1st node has valid earliest_allowed_activation_time
@@ -147,13 +148,13 @@ def shouldNodesBeInSync(nodes:[Node]):
     assert shouldNodeContainPreactivateFeature(newNodes[0]), "1st node should contain PREACTIVATE FEATURE"
     assert not (shouldNodeContainPreactivateFeature(newNodes[1]) or shouldNodeContainPreactivateFeature(newNodes[2])), \
            "2nd and 3rd node should not contain PREACTIVATE FEATURE"
-    assert shouldNodesBeInSync([newNodes[1], newNodes[2], oldNode]), "2nd, 3rd and 4th node should be in sync"
-    assert not shouldNodesBeInSync(allNodes), "1st node should be out of sync with the rest nodes"
+    assert areNodesInSync([newNodes[1], newNodes[2], oldNode]), "2nd, 3rd and 4th node should be in sync"
+    assert not areNodesInSync(allNodes), "1st node should be out of sync with the rest nodes"
 
     waitForOneRound()
 
     assert not shouldNodeContainPreactivateFeature(newNodes[0]), "PREACTIVATE_FEATURE should be dropped"
-    assert shouldNodesBeInSync(allNodes), "All nodes should be in sync"
+    assert areNodesInSync(allNodes), "All nodes should be in sync"
 
     # Then we set the earliest_allowed_activation_time of 2nd node and 3rd node with valid value
     # Once the 1st node activate PREACTIVATE_FEATURE, all of them should have PREACTIVATE_FEATURE activated in the next block
@@ -167,8 +168,8 @@ def shouldNodesBeInSync(nodes:[Node]):
     libBeforePreactivation = newNodes[0].getIrreversibleBlockNum()
     newNodes[0].activatePreactivateFeature()
 
-    assert shouldNodesBeInSync(newNodes), "New nodes should be in sync"
-    assert not shouldNodesBeInSync(allNodes), "Nodes should not be in sync after preactivation"
+    assert areNodesInSync(newNodes), "New nodes should be in sync"
+    assert not areNodesInSync(allNodes), "Nodes should not be in sync after preactivation"
     for node in newNodes: assert shouldNodeContainPreactivateFeature(node), "New node should contain PREACTIVATE_FEATURE"
 
     activatedBlockNum = newNodes[0].getHeadBlockNum() # The PREACTIVATE_FEATURE should have been activated before or at this block num
@@ -195,7 +196,7 @@ def shouldNodesBeInSync(nodes:[Node]):
     restartNode(oldNode, oldNodeId, chainArg="--replay", nodeosPath="programs/nodeos/nodeos")
     time.sleep(2) # Give some time to replay
 
-    assert shouldNodesBeInSync(allNodes), "All nodes should be in sync"
+    assert areNodesInSync(allNodes), "All nodes should be in sync"
     assert shouldNodeContainPreactivateFeature(oldNode), "4th node should contain PREACTIVATE_FEATURE"
 
     testSuccessful = True