Test: Late blocks to producer

plugins/net_plugin/net_plugin.cpp

@@ -2713,7 +2713,7 @@ namespace eosio {
 
    // thread safe
    void dispatch_manager::bcast_block(const signed_block_ptr& b, const block_id_type& id) {
-      fc_dlog( p2p_blk_log, "bcast block ${b}", ("b", b->block_num()) );
+      fc_dlog( p2p_blk_log, "bcast block ${b}:${id}", ("b", b->block_num())("id", id.str().substr(8,16)) );
 
       if(my_impl->sync_master->syncing_from_peer() ) return;
 

tests/CMakeLists.txt

@@ -43,6 +43,8 @@ configure_file(${CMAKE_CURRENT_SOURCE_DIR}/nodeos_chainbase_allocation_test.py $
 configure_file(${CMAKE_CURRENT_SOURCE_DIR}/nodeos_protocol_feature_test.py ${CMAKE_CURRENT_BINARY_DIR}/nodeos_protocol_feature_test.py COPYONLY)
 configure_file(${CMAKE_CURRENT_SOURCE_DIR}/nodeos_multiple_version_protocol_feature_test.py ${CMAKE_CURRENT_BINARY_DIR}/nodeos_multiple_version_protocol_feature_test.py COPYONLY)
 configure_file(${CMAKE_CURRENT_SOURCE_DIR}/nodeos_extra_packed_data_test.py ${CMAKE_CURRENT_BINARY_DIR}/nodeos_extra_packed_data_test.py COPYONLY)
+configure_file(${CMAKE_CURRENT_SOURCE_DIR}/nodeos_late_block_test.py ${CMAKE_CURRENT_BINARY_DIR}/nodeos_late_block_test.py COPYONLY)
+configure_file(${CMAKE_CURRENT_SOURCE_DIR}/nodeos_late_block_test_shape.json ${CMAKE_CURRENT_BINARY_DIR}/nodeos_late_block_test_shape.json COPYONLY)
 configure_file(${CMAKE_CURRENT_SOURCE_DIR}/validate-dirty-db.py ${CMAKE_CURRENT_BINARY_DIR}/validate-dirty-db.py COPYONLY)
 configure_file(${CMAKE_CURRENT_SOURCE_DIR}/keosd_auto_launch_test.py ${CMAKE_CURRENT_BINARY_DIR}/keosd_auto_launch_test.py COPYONLY)
 configure_file(${CMAKE_CURRENT_SOURCE_DIR}/db_modes_test.sh ${CMAKE_CURRENT_BINARY_DIR}/db_modes_test.sh COPYONLY)
@@ -206,6 +208,7 @@ add_np_test(NAME nodeos_snapshot_diff_test COMMAND tests/nodeos_snapshot_diff_te
 add_np_test(NAME nodeos_snapshot_diff_if_test COMMAND tests/nodeos_snapshot_diff_test.py -v --activate-if ${UNSHARE})
 add_np_test(NAME nodeos_snapshot_forked_test COMMAND tests/nodeos_snapshot_forked_test.py -v ${UNSHARE})
 add_np_test(NAME nodeos_snapshot_forked_if_test COMMAND tests/nodeos_snapshot_forked_test.py -v --activate-if ${UNSHARE})
+add_np_test(NAME nodeos_late_block_test COMMAND tests/nodeos_late_block_test.py -v ${UNSHARE})
 
 add_np_test(NAME trx_finality_status_test COMMAND tests/trx_finality_status_test.py -v ${UNSHARE})
 add_np_test(NAME trx_finality_status_if_test COMMAND tests/trx_finality_status_test.py -v --activate-if ${UNSHARE})

tests/TestHarness/Node.py

@@ -676,21 +676,23 @@ def findStderrFiles(path):
     def findInLog(self, searchStr):
         dataDir=Utils.getNodeDataDir(self.nodeId)
         files=Node.findStderrFiles(dataDir)
+        pattern = re.compile(searchStr)
         for file in files:
             with open(file, 'r') as f:
                 for line in f:
-                    if searchStr in line:
+                    if pattern.search(line):
                         return True
         return False
 
     def linesInLog(self, searchStr):
         dataDir=Utils.getNodeDataDir(self.nodeId)
         files=Node.findStderrFiles(dataDir)
+        pattern = re.compile(searchStr)
         lines=[]
         for file in files:
             with open(file, 'r') as f:
                 for line in f:
-                    if searchStr in line:
+                    if pattern.search(line):
                         lines.append(line)
         return lines
 

tests/nodeos_late_block_test.py

@@ -0,0 +1,109 @@
+#!/usr/bin/env python3
+import os
+import shutil
+import signal
+import time
+from TestHarness import Cluster, TestHelper, Utils, WalletMgr
+from TestHarness.Node import BlockType
+
+###############################################################
+# nodeos_late_block_test
+#
+# Set up a cluster of 4 producer nodes so that 3 can reach consensus.
+# Node_00 - defproducera,b,c
+# Node_01 - defproducerd,e,f
+# Node_02 - defproducerg,h,i
+#  Node_04 - bridge between 2 & 3
+# Node_03 - defproducerj,k,l
+#
+# When Node_02 is producing shutdown Node_04 and bring it back up when Node_03 is producing.
+# Verify that Node_03 realizes it should switch over to fork other nodes have chosen.
+###############################################################
+
+Print=Utils.Print
+errorExit=Utils.errorExit
+
+args=TestHelper.parse_args({"-d","--keep-logs","--dump-error-details","-v","--leave-running","--unshared"})
+pnodes=4
+total_nodes=pnodes + 1
+delay=args.d
+debug=args.v
+dumpErrorDetails=args.dump_error_details
+
+Utils.Debug=debug
+testSuccessful=False
+
+cluster=Cluster(unshared=args.unshared, keepRunning=args.leave_running, keepLogs=args.keep_logs)
+walletMgr=WalletMgr(True, keepRunning=args.leave_running, keepLogs=args.keep_logs)
+
+try:
+    TestHelper.printSystemInfo("BEGIN")
+    cluster.setWalletMgr(walletMgr)
+
+    Print(f'producing nodes: {pnodes}, delay between nodes launch: {delay} second{"s" if delay != 1 else ""}')
+
+    Print("Stand up cluster")
+    # do not allow pause production to interfere with late block test
+    extraNodeosArgs=" --production-pause-vote-timeout-ms 0 "
+
+    if cluster.launch(pnodes=pnodes, totalNodes=total_nodes, extraNodeosArgs=extraNodeosArgs,
+                      topo="./tests/nodeos_late_block_test_shape.json", delay=delay, loadSystemContract=False,
+                      activateIF=True, signatureProviderForNonProducer=True) is False:
+        errorExit("Failed to stand up eos cluster.")
+
+    assert cluster.biosNode.getInfo(exitOnError=True)["head_block_producer"] != "eosio", "launch should have waited for production to change"
+    cluster.biosNode.kill(signal.SIGTERM)
+    cluster.waitOnClusterSync(blockAdvancing=5)
+
+    node3 = cluster.getNode(3)
+    node4 = cluster.getNode(4) # bridge between 2 & 3
+
+    Print("Wait for producer before j")
+    node3.waitForAnyProducer("defproducerh", exitOnError=True)
+    node3.waitForAnyProducer("defproduceri", exitOnError=True)
+    iProdBlockNum = node3.getHeadBlockNum()
+
+    node4.kill(signal.SIGTERM)
+    assert not node4.verifyAlive(), "Node4 did not shutdown"
+
+    Print("Wait until Node_03 starts to produce its second round ")
+    node3.waitForProducer("defproducerk", exitOnError=True)
+
+    Print("Relaunch bridge to connection Node_02 and Node_03")
+    node4.relaunch()
+
+    Print("Verify Node_03 fork switches even though it is producing")
+    node3.waitForProducer("defproduceri", exitOnError=True)
+    Print("Verify fork switch")
+    assert node3.findInLog("switching forks .* defproducerk"), "Expected to find 'switching forks' in node_03 log"
+
+    Print("Wait until Node_00 to produce")
+    node3.waitForProducer("defproducera")
+
+    # verify the LIB blocks of defproduceri made it into the canonical chain
+    # defproducerk has produced at least one block, but possibly more by time of relaunch, so verify only some of the round
+    for i in range(9):
+        defprod=node3.getBlockProducerByNum(iProdBlockNum + i)
+        assert defprod == "defproduceri", f"expected defproduceri for block {iProdBlockNum + i}, instead: {defprod}"
+
+    # verify that defproducerk blocks made it into the canonical chain as well
+    # It can take a while to resolve the fork, but should have at least one defproducerk block unless defproducerl
+    # wins the fork in which case there will be another fork switch
+    expectedProd = "defproducerk"
+    if node3.findInLog("switching forks .* defproducerl"):
+        expectedProd = "defproducera"
+    iProdBlockNum += 12 # into the next set of blocks
+    found_defproducer = False
+    for i in range(12):
+        defprod=node3.getBlockProducerByNum(iProdBlockNum + i)
+        if defprod == expectedProd:
+            found_defproducer = True
+
+    assert found_defproducer, f"expected {expectedProd} in blocks {iProdBlockNum}-{iProdBlockNum+12}"
+
+    testSuccessful=True
+finally:
+    TestHelper.shutdown(cluster, walletMgr, testSuccessful=testSuccessful, dumpErrorDetails=dumpErrorDetails)
+
+exitCode = 0 if testSuccessful else 1
+exit(exitCode)

tests/nodeos_late_block_test_shape.json

@@ -0,0 +1,122 @@
+{
+  "name": "testnet_",
+  "nodes": {
+      "bios":{
+        "name": "bios",
+        "keys": [
+          {
+            "privkey":"5KQwrPbwdL6PhXujxW37FSSQZ1JiwsST4cqQzDeyXtP79zkvFD3",
+            "pubkey":"EOS6MRyAjQq8ud7hVNYcfnVPJqcVpscN5So8BhtHuGYqET5GDW5CV"
+          }
+        ],
+        "peers": [
+          "testnet_01",
+          "testnet_02"
+        ],
+        "producers": [
+          "eosio"
+        ],
+        "dont_start": false
+      },
+      "testnet_00":{
+        "name": "testnet_00",
+        "keys": [
+          {
+            "privkey":"5K3h9XiAmrx9EuqD8CRxHgQwEVDaWpqrhrnpdvwHtVzwJFMhNmE",
+            "pubkey":"EOS7K5pQCk22ojetRdyumrqp6nJX6eiQiTWWcGkZAMGhoBxgcsxhK",
+            "blspubkey":"PUB_BLS_kGOCEX1MM5Xl928OOvGLyNo3_GpV8av1HnoaCEGOD8bAu3MDvazu0gCZGA1G7msTh1ZTPMEMVdXMuRVS0tv_9bW9Ohz9XvgtjgbPpxxc_NaeENkGg4uDBOro0Rk8DCEW4ToLKA",
+            "blsprivkey":"PVT_BLS_EnQXObGKvYqfubrKjxpCqNkHeLlkQg7LERjDGm1RKjgyFZnk",
+            "blspop":"SIG_BLS_bXrzPVc-ahxOCWrcl-iWIMuS8ego54iz7vi38A8h_ViqtxklH9O3A2z0eiw5j40M08ejiTm7JbCY_GOwulv1oXb9SaLYQkCTZjzCVssDkghLBRTVCZW2oJmU9WbZXikNw6nkygTs5sUTtCda2a_M5jqY_Rw92_NWmbolgBNkFvMcAgSHexdETA-b7QgJX_oYBWkyP0Pt8LzO6bJueZSjH8wZ8VuPc9o8taY85mt_qgdOTbXVBG2m5ud0eAUps2UHAHt-Ig"
+          }
+        ],
+        "peers": [
+          "testnet_01",
+          "testnet_02"
+        ],
+        "producers": [
+          "defproducera",
+          "defproducerb",
+          "defproducerc"
+        ],
+        "dont_start": false
+      },
+      "testnet_01":{
+        "name": "testnet_01",
+        "keys": [
+          {
+            "privkey":"5HviUPkTEtvF2B1nm8aZUnjma2TzgpKRjuXjwHyy3FME4xDbkZF",
+            "pubkey":"EOS5CbcTDgbks2ptTxvyCbT9HFbzX7PDHUY2wN4DDnVBhhQr2ZNDE",
+            "blspubkey":"PUB_BLS_Y8ndNvnrEpnzJcNUg49ncWDiDGRgR7WUmRRDR9yMURoS6zF14sPnbb-DsTGp0cEM628a4CmG6KXMhPJMqGZvb7RM_MGIwgbEhVaENL8rXeYLOuFDS375KHFgXxs2P5sZuaN7aA",
+            "blsprivkey":"PVT_BLS_A1Mifu5xyaxiveyjnZ-qN2zOt-5_KLMpjTrDI9udcQNV1NBR",
+            "blspop":"SIG_BLS_7D0OUU1h7E0AKkAmqV4v3Ot9oSPWJBOss4yDejr2x1g5G31cSSAYIAtqZOYC-ioNzddY7zkvTcbhKgBzv5a-G1HmV1pOCXXPJ5TL0iqU8Ks5abeEWCdhArGATmRQiSMYNcj9rMQcm3H6Z0pOlOdbDdt8Cg-SY_H4jEGmAY2ZqudAH_U8gS19aydJU-2uQq0SPIr2Okl-WNbc-q3NVQw6Y0sAHAwN4BOIHup2MJyDDDIbpSEkBchRp3zna1XJf6oBuUzpqQ"
+          }
+        ],
+        "peers": [
+          "testnet_00",
+          "testnet_01"
+        ],
+        "producers": [
+          "defproducerd",
+          "defproducere",
+          "defproducerf"
+        ],
+        "dont_start": false
+      },
+      "testnet_02":{
+        "name": "testnet_02",
+        "keys": [
+          {
+            "privkey":"5KkQbdxFHr8Pg1N3DEMDdU7emFgUTwQvh99FDJrodFhUbbsAtQT",
+            "pubkey":"EOS6Tkpf8kcDfa32WA9B4nTcEJ64ZdDMSNioDcaL6rzdMwnpzaWJB",
+            "blspubkey":"PUB_BLS_Wf_O_QeyVhekDXS5q3qBxTyj_qxSrX_uiCY4z8ClpW0X2jrAVgAVHOQ9IR2H40QTWveD8QIGhhSbmSFPa0zFbs5k3yfnjfuuwpA7T1O13_LSdtxT19ehYiE4chZX6SUMJ09JFA",
+            "blsprivkey":"PVT_BLS_1ZLWim0k80ssXswSZp1T3ydHO9U3gLnKKlEBIDy8927XDLLj",
+            "blspop":"SIG_BLS_EL09aI3w-qCgarLM2Z5-T6sisSHBN0J4vMZxtGQklkOcAxgnCaPPXe0roxY4W0gVe2y6T01YrklmT_qZu2tAwqiNrVJcScY8QKvRSeczGBBab1MgnHvaAOuf6bA4JPAELIu2iPWfsS6-oLyLbNP5xtZpMXPHu3yaSJssXNOb5rcVs1KXaIUEagJeAlBBQEcKmFWfeAsJ_R8JDw4i9gSNmROzUjm6LVBpvB7vrnPDPFRA0BQ19H4FED6PtuFPShwJGVz4dg"
+          }
+        ],
+        "peers": [
+          "testnet_00",
+          "testnet_01",
+          "testnet_04"
+        ],
+        "producers": [
+          "defproducerg",
+          "defproducerh",
+          "defproduceri"
+        ],
+        "dont_start": false
+      },
+      "testnet_03":{
+        "name": "testnet_03",
+        "keys": [
+          {
+            "privkey":"5JxTJJegQBpEL1p77TzkN1ompMB9gDwAfjM9chPzFCB4chxmwrE",
+            "pubkey":"EOS52ntDHqA2qj4xVo7KmxdezMRhvvBqpZBuKYJCsgihisxmywpAx",
+            "blspubkey":"PUB_BLS_C-FprIiry6X-8dlLYH7xUAhIuKXBQv56zJPgtcdmKeHf8AAy750eRrOYBtKG0-QEIN5l_yl9dTLvAYmOios6Q5t3ybWBUVVQ2WWcbZLVxzwBftLwYvo1zPXH7LHEE_sAgP1i7g",
+            "blsprivkey":"PVT_BLS_ubElmjajfsYP_9HRSpmV-Fi_IPWKTyJS4XFSWrU8ezMZ_mL_",
+            "blspop":"SIG_BLS_k3wrhVl2GUG_lGsPr9io-zoamPw7eiaxMDExk-yOqcpXtu0zALHoUWJRh0WOerAS1-_RQNhbi4q-BWO9IbiNWRKP9CYIhNIL6ochGHHy4aBmZ-IzEjfBrDt7inDtFTYY0Gl372e5OqPXAwi6J3GeHipXuzAiw7SV8XdWFefthxId4meKX6vw5_RWx4XQ4ScRYoCG7UQtIZkQPEsu1SfJGL6z-cfTTSq-naKbzp0QQYfqtQkFfmL7qQUH1iohnb0HbTbRbQ"
+          }
+        ],
+        "peers": [
+          "testnet_04"
+        ],
+        "producers": [
+          "defproducerj",
+          "defproducerk",
+          "defproducerl"
+        ],
+        "dont_start": false
+      },
+      "testnet_04":{
+        "name": "testnet_04",
+        "keys": [
+        ],
+        "peers": [
+          "testnet_02",
+          "testnet_03"
+        ],
+        "producers": [
+        ],
+        "dont_start": false
+      }
+  }
+}