def test_view_change_timeout(nodeSet, looper, up, wallet1, client1): """ Check view change restarted if it is not completed in time """ m_primary_node = get_master_primary_node(list(nodeSet.nodes.values())) initial_view_no = waitForViewChange(looper, nodeSet) # Setting view change timeout to low value to make test pass quicker for node in nodeSet: node._view_change_timeout = 5 # Delaying view change messages to make first view change fail # due to timeout for node in nodeSet: node.nodeIbStasher.delay(vcd_delay(delay=50)) # Delaying preprepae messages from nodes and # sending request to force view change #for i in range(3): # delayNonPrimaries(nodeSet, instId=i, delay=10) #sendReqsToNodesAndVerifySuffReplies(looper, wallet1, client1, 4) times = {} for node in nodeSet: times[node.name] = { 'called': get_count(node, node._check_view_change_completed), 'returned_true': len(getAllReturnVals( node, node._check_view_change_completed, compare_val_to=True)) } for node in nodeSet: node.startViewChange(initial_view_no + 1) # First view change should fail, because of delayed # instance change messages. This then leads to new view change that we need. with pytest.raises(AssertionError): ensureElectionsDone(looper=looper, nodes=nodeSet, customTimeout=10) # Resetting delays to let second view change go well reset_delays_and_process_delayeds(nodeSet) # This view change should be completed with no problems ensureElectionsDone(looper=looper, nodes=nodeSet) ensure_all_nodes_have_same_data(looper, nodes=nodeSet) new_m_primary_node = get_master_primary_node(list(nodeSet.nodes.values())) assert m_primary_node.name != new_m_primary_node.name # The timeout method has been called at least once for node in nodeSet: assert get_count(node, node._check_view_change_completed) > times[node.name]['called'] assert len(getAllReturnVals(node, node._check_view_change_completed, compare_val_to=True)) > times[node.name]['returned_true'] # Multiple view changes have been initiated for node in nodeSet: assert (node.viewNo - initial_view_no) > 1 ensure_pool_functional(looper, nodeSet, wallet1, client1)
def test_view_change_after_max_catchup_rounds(txnPoolNodeSet, looper, wallet1, client1, client1Connected): """ The node should do only a fixed rounds of catchup. For this delay Prepares and Commits for 2 non-primary nodes by a large amount which is equivalent to loss of Prepares and Commits. Make sure 2 nodes have a different last prepared certificate from other two. Then do a view change, make sure view change completes and the pool does not process the request that were prepared by only a subset of the nodes """ send_reqs_batches_and_get_suff_replies(looper, wallet1, client1, 2 * 3, 3) ensure_all_nodes_have_same_data(looper, txnPoolNodeSet) ledger_summary = txnPoolNodeSet[0].elector.ledger_summary slow_nodes = [ r.node for r in getNonPrimaryReplicas(txnPoolNodeSet, 0)[-2:] ] fast_nodes = [n for n in txnPoolNodeSet if n not in slow_nodes] # Make node slow to process Prepares and Commits for node in slow_nodes: node.nodeIbStasher.delay(pDelay(120, 0)) node.nodeIbStasher.delay(cDelay(120, 0)) sendRandomRequests(wallet1, client1, 5) looper.runFor(3) ensure_view_change(looper, nodes=txnPoolNodeSet) def last_prepared(nodes): lst = [ n.master_replica.last_prepared_certificate_in_view() for n in nodes ] # All nodes have same last prepared assert check_if_all_equal_in_list(lst) return lst[0] last_prepared_slow = last_prepared(slow_nodes) last_prepared_fast = last_prepared(fast_nodes) # Check `slow_nodes` and `fast_nodes` set different last_prepared assert last_prepared_fast != last_prepared_slow # View change complete ensureElectionsDone(looper, txnPoolNodeSet) ensure_all_nodes_have_same_data(looper, txnPoolNodeSet) # The requests which were prepared by only a subset of the nodes were # not ordered assert txnPoolNodeSet[0].elector.ledger_summary == ledger_summary for node in slow_nodes: node.nodeIbStasher.reset_delays_and_process_delayeds() # Make sure pool is functional ensure_pool_functional(looper, txnPoolNodeSet, wallet1, client1) ensure_all_nodes_have_same_data(looper, txnPoolNodeSet) last_prepared(txnPoolNodeSet)
def test_different_ledger_request_interleave(tconf, looper, txnPoolNodeSet, client1, wallet1, one_node_added, client1Connected, tdirWithPoolTxns, steward1, stewardWallet, allPluginsPath): """ Send pool and domain ledger requests such that they interleave, and do view change in between and verify the pool is functional """ new_node = one_node_added sendReqsToNodesAndVerifySuffReplies(looper, wallet1, client1, 2) ensure_all_nodes_have_same_data(looper, txnPoolNodeSet) # Send domain ledger requests but don't wait for replies requests = sendRandomRequests(wallet1, client1, 2) # Add another node by sending pool ledger request _, _, new_theta = nodeThetaAdded(looper, txnPoolNodeSet, tdirWithPoolTxns, tconf, steward1, stewardWallet, allPluginsPath, name='new_theta') # Send more domain ledger requests but don't wait for replies requests.extend(sendRandomRequests(wallet1, client1, 3)) # Do view change without waiting for replies ensure_view_change(looper, nodes=txnPoolNodeSet) checkProtocolInstanceSetup(looper, txnPoolNodeSet, retryWait=1) # Make sure all requests are completed waitForSufficientRepliesForRequests(looper, client1, requests=requests) ensure_pool_functional(looper, txnPoolNodeSet, wallet1, client1) new_steward, new_steward_wallet = addNewSteward(looper, tdirWithPoolTxns, steward1, stewardWallet, 'another_ste') # Send another pool ledger request (NODE) but don't wait for completion of # request next_node_name = 'next_node' r = sendAddNewNode(tdirWithPoolTxns, next_node_name, new_steward, new_steward_wallet) node_req = r[0] # Send more domain ledger requests but don't wait for replies requests = [ node_req, *sendRandomRequests(new_steward_wallet, new_steward, 5) ] # Make sure all requests are completed waitForSufficientRepliesForRequests(looper, new_steward, requests=requests) # Make sure pool is functional ensure_pool_functional(looper, txnPoolNodeSet, wallet1, client1)
def test_genesis_nodes(looper, txnPoolNodeSet, client1, wallet1, client1Connected): assert len(txnPoolNodeSet) == nodeCount for node in txnPoolNodeSet: assertEquality(node.poolLedger.size, nodeCount) stw_count = sum(1 for _, txn in node.domainLedger.getAllTxn() if (txn[TXN_TYPE] == NYM) and (txn.get(ROLE) == STEWARD)) assertEquality(stw_count, nodeCount) ensure_pool_functional(looper, txnPoolNodeSet, wallet1, client1)
def test_no_catchup_if_got_from_3pc(looper, txnPoolNodeSet, wallet1, client1, client1Connected): """ A node is slow to receive COMMIT messages so after a view change it starts catchup. But before it can start requesting txns, the COMMITs messages are received and are ordered. The node should not request any transactions. :return: """ send_reqs_batches_and_get_suff_replies(looper, wallet1, client1, 2 * 3, 3) ensure_all_nodes_have_same_data(looper, txnPoolNodeSet) slow_node = getNonPrimaryReplicas(txnPoolNodeSet, 0)[-1].node other_nodes = [n for n in txnPoolNodeSet if n != slow_node] delay_cm = 30 delat_cp = 40 slow_node.nodeIbStasher.delay(cDelay(delay_cm)) # The slow node receives consistency proofs after some delay, this delay # gives the opportunity to deliver all 3PC messages slow_node.nodeIbStasher.delay(cpDelay(delat_cp)) # Count of `getCatchupReqs` which is called to construct the `CatchupReq` # to be sent def domain_cr_count(): return sum(1 for entry in slow_node.ledgerManager.spylog.getAll( slow_node.ledgerManager.getCatchupReqs) if entry.params['consProof'].ledgerId == DOMAIN_LEDGER_ID) old_count = domain_cr_count() sent_batches = 10 send_reqs_batches_and_get_suff_replies(looper, wallet1, client1, 2 * sent_batches, sent_batches) ensure_view_change(looper, nodes=txnPoolNodeSet) # After view change, the `slow_node` is behind waitNodeDataInequality(looper, slow_node, *other_nodes) # Unstash only COMMIT messages slow_node.nodeIbStasher.reset_delays_and_process_delayeds(Commit.__name__) looper.runFor(2) slow_node.nodeIbStasher.reset_delays_and_process_delayeds( ConsistencyProof.__name__) waitNodeDataEquality(looper, slow_node, *other_nodes) # No `CatchupReq`s constructed, hence no `CatchupReq`s could have # been sent assert domain_cr_count() == old_count # Some stashed ordered requests have been processed rv = getAllReturnVals(slow_node, slow_node.processStashedOrderedReqs) assert sent_batches in rv ensure_pool_functional(looper, txnPoolNodeSet, wallet1, client1)
def test_multiple_view_change_retries_by_timeouts(txnPoolNodeSet, looper, setup, wallet1, client1): """ Verifies that a view change is restarted each time when the previous one is timed out """ _, initial_view_no, timeout_callback_stats = setup delay_view_change_done_msg(txnPoolNodeSet) start_view_change(txnPoolNodeSet, initial_view_no + 1) def check_timeout_callback_called(times): for node in txnPoolNodeSet: assert get_count(node, node._check_view_change_completed) - \ timeout_callback_stats[node.name]['called'] == times assert len(getAllReturnVals(node, node._check_view_change_completed, compare_val_to=True)) - \ timeout_callback_stats[node.name]['returned_true'] == times # Check that the timeout method was called 3 times # during the triple view_change_timeout period plus a margin looper.run( eventually(check_timeout_callback_called, 3, retryWait=1, timeout=3 * view_change_timeout + 2)) # Check that the last view change has failed with pytest.raises(AssertionError): ensureElectionsDone(looper=looper, nodes=txnPoolNodeSet, customTimeout=1) # Reset delays to let the next view change go well reset_delays_and_process_delayeds(txnPoolNodeSet) # This view change must be completed with no problems ensureElectionsDone(looper=looper, nodes=txnPoolNodeSet) ensure_all_nodes_have_same_data(looper, nodes=txnPoolNodeSet) # 4 view changes must have been initiated (initial one + 3 retries) for node in txnPoolNodeSet: assert node.viewNo - initial_view_no == 4 ensure_pool_functional(looper, txnPoolNodeSet, wallet1, client1)
def test_view_change_min_catchup_timeout(txnPoolNodeSet, looper, wallet1, client1, tconf, viewNo): """ One of the conditions to finish catch-up during view change is to have MAX_CATCHUPS_DONE_DURING_VIEW_CHANGE rounds of catch-up without any new transactions caught up. But this should not finish very quickly. So, we should try to catch-up until MIN_TIMEOUT_CATCHUPS_DONE_DURING_VIEW_CHANGE. In the test: - Before starting view change, mock `has_ordered_till_last_prepared_certificate` so that it always returns False. - This means that the only condition on how we can finish catch-up is by MIN_TIMEOUT_CATCHUPS_DONE_DURING_VIEW_CHANGE timeout and having more than MAX_CATCHUPS_DONE_DURING_VIEW_CHANGE rounds of catch-up without new txns caught up. - Check that view change is not finished until MIN_TIMEOUT_CATCHUPS_DONE_DURING_VIEW_CHANGE - Check that view change is eventually finished after MIN_TIMEOUT_CATCHUPS_DONE_DURING_VIEW_CHANGE """ # 1. Send some txns sendReqsToNodesAndVerifySuffReplies(looper, wallet1, client1, 4) # 2. make the only condition to finish catch-up is # MIN_TIMEOUT_CATCHUPS_DONE_DURING_VIEW_CHANGE patch_has_ordered_till_last_prepared_certificate(txnPoolNodeSet) # 3. start view change expected_view_no = viewNo + 1 for node in txnPoolNodeSet: node.view_changer.startViewChange(expected_view_no) # 4. check that it's not finished till # MIN_TIMEOUT_CATCHUPS_DONE_DURING_VIEW_CHANGE no_view_chanage_timeout = tconf.MIN_TIMEOUT_CATCHUPS_DONE_DURING_VIEW_CHANGE - 1 with pytest.raises(EventuallyTimeoutException): ensureElectionsDone(looper=looper, nodes=txnPoolNodeSet, customTimeout=no_view_chanage_timeout) # 5. make sure that view change is finished eventually # (it should be finished quite soon after we waited for MIN_TIMEOUT_CATCHUPS_DONE_DURING_VIEW_CHANGE) ensureElectionsDone(looper=looper, nodes=txnPoolNodeSet, customTimeout=2) waitForViewChange(looper=looper, txnPoolNodeSet=txnPoolNodeSet, expectedViewNo=expected_view_no) ensure_all_nodes_have_same_data(looper, nodes=txnPoolNodeSet) # 6. ensure that the pool is still functional. ensure_pool_functional(looper, txnPoolNodeSet, wallet1, client1)
def test_node_request_propagates(looper, setup, txnPoolNodeSet, client1, wallet1, client1Connected, request): """ One of node lacks sufficient propagates """ faulty_node, recv_client_requests = setup old_count_recv_ppg = get_count(faulty_node, faulty_node.processPropagate) old_count_recv_req = get_count(faulty_node, faulty_node.processRequest) old_count_request_propagates = get_count(faulty_node, faulty_node.request_propagates) sent_reqs = 5 send_reqs_to_nodes_and_verify_all_replies(looper, wallet1, client1, sent_reqs) assert get_count(faulty_node, faulty_node.processPropagate) > old_count_recv_ppg if recv_client_requests: assert get_count(faulty_node, faulty_node.processRequest) > old_count_recv_req else: assert get_count(faulty_node, faulty_node.processRequest) == old_count_recv_req # Attempt to request PROPAGATEs was made twice, since the faulty node has 2 replicas assert get_count( faulty_node, faulty_node.request_propagates) - old_count_request_propagates == 2 requested_propagate_counts = getAllReturnVals( faulty_node, faulty_node.request_propagates) # The last attempt to request PROPAGATEs was not successful assert requested_propagate_counts[0] == 0 # The first attempt to request PROPAGATEs was successful as PROPAGATEs # were requested for all nodes assert requested_propagate_counts[1] == sent_reqs faulty_node.nodeIbStasher.reset_delays_and_process_delayeds() ensure_pool_functional(looper, txnPoolNodeSet, wallet1, client1, 4)
def test_view_change_retry_by_timeout(txnPoolNodeSet, looper, setup, wallet1, client1): """ Verifies that a view change is restarted if it is not completed in time """ m_primary_node, initial_view_no, timeout_callback_stats = setup delay_view_change_done_msg(txnPoolNodeSet) start_view_change(txnPoolNodeSet, initial_view_no + 1) # First view change should fail, because of delayed ViewChangeDone # messages. This then leads to new view change that we need. with pytest.raises(AssertionError): ensureElectionsDone(looper=looper, nodes=txnPoolNodeSet, customTimeout=view_change_timeout + 2) # Resetting delays to let second view change go well reset_delays_and_process_delayeds(txnPoolNodeSet) # This view change should be completed with no problems ensureElectionsDone(looper=looper, nodes=txnPoolNodeSet) ensure_all_nodes_have_same_data(looper, nodes=txnPoolNodeSet) new_m_primary_node = get_master_primary_node(list(txnPoolNodeSet)) assert m_primary_node.name != new_m_primary_node.name # The timeout method was called one time for node in txnPoolNodeSet: assert get_count(node, node._check_view_change_completed) - \ timeout_callback_stats[node.name]['called'] == 1 assert len(getAllReturnVals(node, node._check_view_change_completed, compare_val_to=True)) - \ timeout_callback_stats[node.name]['returned_true'] == 1 # 2 view changes have been initiated for node in txnPoolNodeSet: assert node.viewNo - initial_view_no == 2 ensure_pool_functional(looper, txnPoolNodeSet, wallet1, client1)
def test_view_change_timeout(nodeSet, looper, up, setup, wallet1, client1): """ Check view change restarted if it is not completed in time """ m_primary_node, initial_view_no, times = setup delay_view_change_msg(nodeSet) start_view_change(nodeSet, initial_view_no + 1) # First view change should fail, because of delayed # instance change messages. This then leads to new view change that we # need. with pytest.raises(AssertionError): ensureElectionsDone(looper=looper, nodes=nodeSet, customTimeout=10) # Resetting delays to let second view change go well reset_delays_and_process_delayeds(nodeSet) # This view change should be completed with no problems ensureElectionsDone(looper=looper, nodes=nodeSet) ensure_all_nodes_have_same_data(looper, nodes=nodeSet) new_m_primary_node = get_master_primary_node(list(nodeSet.nodes.values())) assert m_primary_node.name != new_m_primary_node.name # The timeout method has been called at least once for node in nodeSet: assert get_count( node, node._check_view_change_completed) > times[node.name]['called'] assert len( getAllReturnVals( node, node._check_view_change_completed, compare_val_to=True)) > times[node.name]['returned_true'] # Multiple view changes have been initiated for node in nodeSet: assert (node.viewNo - initial_view_no) > 1 ensure_pool_functional(looper, nodeSet, wallet1, client1)
def test_reverted_unordered(txnPoolNodeSet, looper, wallet1, client1, client1Connected): """ Before starting catchup, revert any uncommitted changes to state and ledger. This is to avoid any re-application of requests that were ordered but stashed Example scenario prepared (1, 4) startViewChange start_catchup ... .... ... committed and send Ordered (1, 2) ... .... preLedgerCatchUp force_process_ordered, take out (1,2) and stash (1, 2) now process stashed Ordered(1,2), its requests will be applied again Simulation: Delay COMMITs to a node so that it can not order requests but has prepared them. Then trigger a view change and make sure the slow node has not ordered same number of requests as others but has prepared so it can order when it receives COMMITs while view change is in progress. The slow node should revert unordered batches and but it should eventually process the ordered requests, so delay LEDGER_STATUS too so catchup is delayed """ slow_node = getNonPrimaryReplicas(txnPoolNodeSet, 0)[-1].node fast_nodes = [n for n in txnPoolNodeSet if n != slow_node] slow_node.nodeIbStasher.delay(cDelay(120, 0)) sent_batches = 5 send_reqs_batches_and_get_suff_replies(looper, wallet1, client1, 2 * sent_batches, sent_batches) # Fast nodes have same last ordered and same data last_ordered = [n.master_last_ordered_3PC for n in fast_nodes] assert check_if_all_equal_in_list(last_ordered) ensure_all_nodes_have_same_data(looper, fast_nodes) # Slow nodes have different last ordered than fast nodes assert last_ordered[0] != slow_node.master_last_ordered_3PC # Delay LEDGER_STATUS so catchup starts late slow_node.nodeIbStasher.delay(lsDelay(100)) slow_node.nodeIbStasher.delay(msg_rep_delay(100)) # slow_node has not reverted batches assert sent_batches not in getAllReturnVals( slow_node.master_replica, slow_node.master_replica.revert_unordered_batches) ensure_view_change(looper, txnPoolNodeSet) def chk1(): # slow_node reverted all batches rv = getAllReturnVals( slow_node.master_replica, slow_node.master_replica.revert_unordered_batches) assert sent_batches in rv looper.run(eventually(chk1, retryWait=1)) # After the view change slow_node has prepared same requests as the fast # nodes have ordered assert last_ordered[ 0] == slow_node.master_replica.last_prepared_before_view_change # Deliver COMMITs slow_node.nodeIbStasher.reset_delays_and_process_delayeds(COMMIT) def chk2(): # slow_node orders all requests as others have assert last_ordered[0] == slow_node.master_last_ordered_3PC looper.run(eventually(chk2, retryWait=1)) # Deliver LEDGER_STATUS so catchup can complete slow_node.nodeIbStasher.reset_delays_and_process_delayeds(LEDGER_STATUS) slow_node.nodeIbStasher.reset_delays_and_process_delayeds(MESSAGE_RESPONSE) # Ensure all nodes have same data ensure_all_nodes_have_same_data(looper, txnPoolNodeSet) ensureElectionsDone(looper, txnPoolNodeSet) def chk3(): # slow_node processed stashed Ordered requests successfully rv = getAllReturnVals(slow_node, slow_node.processStashedOrderedReqs) assert sent_batches in rv looper.run(eventually(chk3, retryWait=1)) # Ensure pool is functional ensure_pool_functional(looper, txnPoolNodeSet, wallet1, client1)