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)