Improved reporting in nodeos_forked_chain_lr_test

tests/Node.py

@@ -1389,24 +1389,28 @@ def verifyAlive(self, silent=False):
         if logStatus: Utils.Print("Determined node(pid=%s) is alive" % (self.pid))
         return True
 
+    @staticmethod
+    def getBlockAttribute(block, key, blockNum, exitOnError=True):
+        value=block[key]
+
+        if value is None and exitOnError:
+            blockNumStr=" for block number %s" % (blockNum)
+            blockStr=" with block content:\n%s" % (json.dumps(block, indent=4, sort_keys=True))
+            Utils.cmdError("could not get %s%s%s" % (key, blockNumStr, blockStr))
+            Utils.errorExit("Failed to get block's %s" % (key))
+
+        return value
+
     def getBlockProducerByNum(self, blockNum, timeout=None, waitForBlock=True, exitOnError=True):
         if waitForBlock:
             self.waitForBlock(blockNum, timeout=timeout, blockType=BlockType.head)
         block=self.getBlock(blockNum, exitOnError=exitOnError)
-        blockProducer=block["producer"]
-        if blockProducer is None and exitOnError:
-            Utils.cmdError("could not get producer for block number %s" % (blockNum))
-            Utils.errorExit("Failed to get block's producer")
-        return blockProducer
+        return Node.getBlockAttribute(block, "producer", blockNum, exitOnError=exitOnError)
 
     def getBlockProducer(self, timeout=None, waitForBlock=True, exitOnError=True, blockType=BlockType.head):
         blockNum=self.getBlockNum(blockType=blockType)
         block=self.getBlock(blockNum, exitOnError=exitOnError, blockType=blockType)
-        blockProducer=block["producer"]
-        if blockProducer is None and exitOnError:
-            Utils.cmdError("could not get producer for block number %s" % (blockNum))
-            Utils.errorExit("Failed to get block's producer")
-        return blockProducer
+        return Node.getBlockAttribute(block, "producer", blockNum, exitOnError=exitOnError)
 
     def getNextCleanProductionCycle(self, trans):
         rounds=21*12*2  # max time to ensure that at least 2/3+1 of producers x blocks per producer x at least 2 times

tests/nodeos_forked_chain_test.py

@@ -1,17 +1,14 @@
 #!/usr/bin/env python3
 
 from testUtils import Utils
-import testUtils
+from datetime import datetime
 import time
 from Cluster import Cluster
+import json
 from WalletMgr import WalletMgr
-from Node import BlockType
 from Node import Node
 from TestHelper import TestHelper
 
-import decimal
-import math
-import re
 import signal
 
 ###############################################################
@@ -259,11 +256,40 @@ def getMinHeadAndLib(prodNodes):
     Print("Validating blockNum=%s, producer=%s" % (blockNum, blockProducer))
     cluster.biosNode.kill(signal.SIGTERM)
 
+    class HeadWaiter:
+        def __init__(self, node):
+            self.node=node
+            self.cachedHeadBlockNum=node.getBlockNum()
+
+        def waitIfNeeded(self, blockNum):
+            delta=self.cachedHeadBlockNum-blockNum
+            if delta >= 0:
+                return
+            previousHeadBlockNum=self.cachedHeadBlockNum
+            delta=-1*delta
+            timeout=(delta+1)/2 + 3 # round up to nearest second and 3 second extra leeway
+            self.node.waitForBlock(blockNum, timeout=timeout)
+            self.cachedHeadBlockNum=node.getBlockNum()
+            if blockNum > self.cachedHeadBlockNum:
+                Utils.errorExit("Failed to advance from block number %d to %d in %d seconds.  Only got to block number %d" % (previousHeadBlockNum, blockNum, timeout, self.cachedHeadBlockNum))
+
+        def getBlock(self, blockNum):
+            self.waitIfNeeded(blockNum)
+            return self.node.getBlock(blockNum)
+
     #advance to the next block of 12
     lastBlockProducer=blockProducer
+
+    waiter=HeadWaiter(node)
+
     while blockProducer==lastBlockProducer:
         blockNum+=1
-        blockProducer=node.getBlockProducerByNum(blockNum)
+        block=waiter.getBlock(blockNum)
+        Utils.Print("Block num: %d, block: %s" % (blockNum, json.dumps(block, indent=4, sort_keys=True)))
+        blockProducer=Node.getBlockAttribute(block, "producer", blockNum)
+
+    timestampStr=Node.getBlockAttribute(block, "timestamp", blockNum)
+    timestamp=datetime.strptime(timestampStr, Utils.TimeFmt)
 
 
     # ***   Identify what the production cycle is   ***
@@ -272,6 +298,9 @@ def getMinHeadAndLib(prodNodes):
     producerToSlot={}
     slot=-1
     inRowCountPerProducer=12
+    lastTimestamp=timestamp
+    headBlockNum=node.getBlockNum()
+    firstBlockForWindowMissedSlot=None
     while True:
         if blockProducer not in producers:
             Utils.errorExit("Producer %s was not one of the voted on producers" % blockProducer)
@@ -283,14 +312,39 @@ def getMinHeadAndLib(prodNodes):
 
         producerToSlot[blockProducer]={"slot":slot, "count":0}
         lastBlockProducer=blockProducer
+        blockSkip=[]
+        roundSkips=0
+        missedSlotAfter=[]
+        if firstBlockForWindowMissedSlot is not None:
+            missedSlotAfter.append(firstBlockForWindowMissedSlot)
+            firstBlockForWindowMissedSlot=None
         while blockProducer==lastBlockProducer:
             producerToSlot[blockProducer]["count"]+=1
             blockNum+=1
-            blockProducer=node.getBlockProducerByNum(blockNum)
+            block=waiter.getBlock(blockNum)
+            blockProducer=Node.getBlockAttribute(block, "producer", blockNum)
+            timestampStr=Node.getBlockAttribute(block, "timestamp", blockNum)
+            timestamp=datetime.strptime(timestampStr, Utils.TimeFmt)
+            timediff=timestamp-lastTimestamp
+            slotTime=0.5
+            slotsDiff=int(timediff.total_seconds() / slotTime)
+            if slotsDiff != 1:
+                slotTimeDelta=datetime.timedelta(slotTime)
+                first=lastTimestamp + slotTimeDelta
+                missed=datetime.strftime(first, Utils.TimeFmt)
+                if slotsDiff > 2:
+                    last=timestamp - slotTimeDelta
+                    missed+= " thru " + datetime.strftime(last, Utils.TimeFmt)
+                missedSlotAfter.append("%d (%s)" % (blockNum-1, missed))
+            lastTimestamp=timestamp
 
         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." %
-                            (lastBlockProducer, slot, inRowCountPerProducer, producerToSlot[lastBlockProducer]["count"], blockNum-1))
+            Utils.errorExit("Producer %s, in slot %d, expected to produce %d blocks but produced %d blocks.  At block number %d. " %
+                            (lastBlockProducer, slot, inRowCountPerProducer, producerToSlot[lastBlockProducer]["count"], blockNum-1) +
+                            "Slots were missed after the following blocks: %s" % (", ".join(missedSlotAfter)))
+        elif len(missedSlotAfter) > 0:
+            # if there was a full round, then the most recent producer missed a slot
+            firstBlockForWindowMissedSlot=missedSlotAfter[0]
 
         if blockProducer==productionCycle[0]:
             break

tests/testUtils.py

@@ -73,6 +73,8 @@ class Utils:
     DataDir="var/lib/"
     ConfigDir="etc/eosio/"
 
+    TimeFmt='%Y-%m-%dT%H:%M:%S.%f'
+
     @staticmethod
     def Print(*args, **kwargs):
         stackDepth=len(inspect.stack())-2