2019-04-26 18:27:27 +03:00
|
|
|
# Copyright (c) Microsoft Corporation. All rights reserved.
|
|
|
|
# Licensed under the Apache 2.0 License.
|
|
|
|
import time
|
|
|
|
import math
|
|
|
|
import infra.ccf
|
|
|
|
import infra.proc
|
2020-01-29 18:09:28 +03:00
|
|
|
import infra.e2e_args
|
2020-05-01 15:55:20 +03:00
|
|
|
import http
|
2019-04-26 18:27:27 +03:00
|
|
|
|
2020-05-01 15:55:20 +03:00
|
|
|
from infra.tx_status import TxStatus
|
2019-04-26 18:27:27 +03:00
|
|
|
from loguru import logger as LOG
|
|
|
|
|
|
|
|
# This test starts from a given number of nodes (hosts), commits
|
2019-08-15 19:52:43 +03:00
|
|
|
# a transaction, stops the current primary, waits for an election and repeats
|
|
|
|
# this process until no progress can be made (i.e. no primary can be elected
|
2019-04-26 18:27:27 +03:00
|
|
|
# as F > N/2).
|
|
|
|
|
|
|
|
|
2020-05-22 16:56:21 +03:00
|
|
|
def wait_for_seqno_to_commit(seqno, view, nodes):
|
2019-04-26 18:27:27 +03:00
|
|
|
"""
|
2020-05-22 16:56:21 +03:00
|
|
|
Wait for a specific seqno at a specific view to be committed on all nodes.
|
2019-04-26 18:27:27 +03:00
|
|
|
"""
|
2020-03-26 18:30:06 +03:00
|
|
|
for _ in range(infra.ccf.Network.replication_delay * 10):
|
2019-04-26 18:27:27 +03:00
|
|
|
up_to_date_f = []
|
|
|
|
for f in nodes:
|
2019-10-01 18:17:14 +03:00
|
|
|
with f.node_client() as c:
|
2020-05-22 16:56:21 +03:00
|
|
|
r = c.get("tx", {"view": view, "seqno": seqno})
|
2020-05-01 15:55:20 +03:00
|
|
|
assert (
|
|
|
|
r.status == http.HTTPStatus.OK
|
|
|
|
), f"tx request returned HTTP status {r.status}"
|
|
|
|
status = TxStatus(r.result["status"])
|
|
|
|
if status == TxStatus.Committed:
|
2019-04-26 18:27:27 +03:00
|
|
|
up_to_date_f.append(f.node_id)
|
2020-05-01 15:55:20 +03:00
|
|
|
elif status == TxStatus.Invalid:
|
|
|
|
raise RuntimeError(
|
2020-05-22 16:56:21 +03:00
|
|
|
f"Node {f.node_id} reports transaction ID {view}.{seqno} is invalid and will never be committed"
|
2020-05-01 15:55:20 +03:00
|
|
|
)
|
|
|
|
else:
|
|
|
|
pass
|
2019-04-26 18:27:27 +03:00
|
|
|
if len(up_to_date_f) == len(nodes):
|
|
|
|
break
|
2020-03-26 18:30:06 +03:00
|
|
|
time.sleep(0.1)
|
2019-04-26 18:27:27 +03:00
|
|
|
assert len(up_to_date_f) == len(
|
|
|
|
nodes
|
2020-05-01 15:55:20 +03:00
|
|
|
), "Only {} out of {} nodes are up to date".format(len(up_to_date_f), len(nodes))
|
2019-04-26 18:27:27 +03:00
|
|
|
|
|
|
|
|
|
|
|
def run(args):
|
|
|
|
# Three nodes minimum to make sure that the raft network can still make progress
|
|
|
|
# if one node stops
|
2020-01-27 16:53:23 +03:00
|
|
|
hosts = ["localhost"] * (4 if args.consensus == "pbft" else 3)
|
2019-04-26 18:27:27 +03:00
|
|
|
|
|
|
|
with infra.ccf.network(
|
2020-02-06 18:27:18 +03:00
|
|
|
hosts, args.binary_dir, args.debug_nodes, args.perf_nodes, pdb=args.pdb
|
2019-04-26 18:27:27 +03:00
|
|
|
) as network:
|
2020-03-23 13:53:05 +03:00
|
|
|
check = infra.checker.Checker()
|
2019-04-26 18:27:27 +03:00
|
|
|
|
2019-11-08 12:33:47 +03:00
|
|
|
network.start_and_join(args)
|
2020-05-22 16:56:21 +03:00
|
|
|
current_view = None
|
2019-04-26 18:27:27 +03:00
|
|
|
|
|
|
|
# Time before an election completes
|
2020-03-09 15:52:43 +03:00
|
|
|
max_election_duration = (
|
2020-03-31 16:42:19 +03:00
|
|
|
args.pbft_view_change_timeout * 2 / 1000
|
2020-03-09 15:52:43 +03:00
|
|
|
if args.consensus == "pbft"
|
2020-03-31 16:42:19 +03:00
|
|
|
else args.raft_election_timeout * 2 / 1000
|
2020-03-09 15:52:43 +03:00
|
|
|
)
|
2019-04-26 18:27:27 +03:00
|
|
|
|
|
|
|
# Number of nodes F to stop until network cannot make progress
|
|
|
|
nodes_to_stop = math.ceil(len(hosts) / 2)
|
2019-11-25 19:52:04 +03:00
|
|
|
if args.consensus == "pbft":
|
|
|
|
nodes_to_stop = math.ceil(len(hosts) / 3)
|
2019-04-26 18:27:27 +03:00
|
|
|
|
|
|
|
for _ in range(nodes_to_stop):
|
2019-08-15 19:52:43 +03:00
|
|
|
# Note that for the first iteration, the primary is known in advance anyway
|
|
|
|
LOG.debug("Find freshly elected primary")
|
2020-01-27 16:53:23 +03:00
|
|
|
# After a view change in pbft, finding the new primary takes longer
|
2020-05-22 16:56:21 +03:00
|
|
|
primary, current_view = network.find_primary(
|
2020-01-27 16:53:23 +03:00
|
|
|
request_timeout=(30 if args.consensus == "pbft" else 3)
|
|
|
|
)
|
2019-04-26 18:27:27 +03:00
|
|
|
|
2019-11-25 19:52:04 +03:00
|
|
|
LOG.debug(
|
2020-05-22 16:56:21 +03:00
|
|
|
"Commit new transactions, primary:{}, current_view:{}".format(
|
|
|
|
primary.node_id, current_view
|
2019-11-25 19:52:04 +03:00
|
|
|
)
|
|
|
|
)
|
2020-02-19 20:08:06 +03:00
|
|
|
with primary.user_client() as c:
|
2020-03-23 13:53:05 +03:00
|
|
|
res = c.rpc(
|
2019-04-26 18:27:27 +03:00
|
|
|
"LOG_record",
|
|
|
|
{
|
2020-05-22 16:56:21 +03:00
|
|
|
"id": current_view,
|
|
|
|
"msg": "This log is committed in view {}".format(current_view),
|
2019-04-26 18:27:27 +03:00
|
|
|
},
|
2019-10-07 17:18:10 +03:00
|
|
|
readonly_hint=None,
|
2019-04-26 18:27:27 +03:00
|
|
|
)
|
2020-03-23 13:53:05 +03:00
|
|
|
check(res, result=True)
|
2020-05-22 16:56:21 +03:00
|
|
|
seqno = res.seqno
|
2019-04-26 18:27:27 +03:00
|
|
|
|
|
|
|
LOG.debug("Waiting for transaction to be committed by all nodes")
|
2020-05-22 16:56:21 +03:00
|
|
|
wait_for_seqno_to_commit(seqno, current_view, network.get_joined_nodes())
|
2019-04-26 18:27:27 +03:00
|
|
|
|
2019-08-15 19:52:43 +03:00
|
|
|
LOG.debug("Stopping primary")
|
|
|
|
primary.stop()
|
2019-04-26 18:27:27 +03:00
|
|
|
|
2020-03-31 16:42:19 +03:00
|
|
|
LOG.debug(
|
|
|
|
f"Waiting {max_election_duration} for a new primary to be elected..."
|
|
|
|
)
|
2019-04-26 18:27:27 +03:00
|
|
|
time.sleep(max_election_duration)
|
|
|
|
|
|
|
|
# More than F nodes have been stopped, trying to commit any message
|
|
|
|
LOG.debug(
|
|
|
|
"No progress can be made as more than {} nodes have stopped".format(
|
|
|
|
nodes_to_stop
|
|
|
|
)
|
|
|
|
)
|
2019-05-20 13:45:53 +03:00
|
|
|
try:
|
2020-01-27 16:53:23 +03:00
|
|
|
primary, _ = network.find_primary()
|
2019-08-15 19:52:43 +03:00
|
|
|
assert False, "Primary should not be found"
|
2020-01-27 16:53:23 +03:00
|
|
|
except infra.ccf.PrimaryNotFound:
|
|
|
|
pass
|
2019-11-25 19:52:04 +03:00
|
|
|
|
|
|
|
LOG.info(
|
|
|
|
"As expected, primary could not be found after election timeout. Test ended successfully."
|
|
|
|
)
|
2019-04-26 18:27:27 +03:00
|
|
|
|
|
|
|
|
|
|
|
if __name__ == "__main__":
|
|
|
|
|
2020-01-29 18:09:28 +03:00
|
|
|
args = infra.e2e_args.cli_args()
|
2020-01-28 17:06:12 +03:00
|
|
|
args.package = "liblogging"
|
2019-04-26 18:27:27 +03:00
|
|
|
run(args)
|