def verify(key, sig, message):
try:
rc = key.verify(sig, message)
return rc
except Exception as E:
_logger.error(E)
return False
def process_new_view(self, req, fd):
_logger.info(
"Node: [%s], Phase: [PROCESS NEW VIEW], Event FD: [%s], RequestInnerID: [%s]"
% (self._id, fd, req.inner.id))
# parse requests by type
m = req.inner.msg
vchange_list = []
prpr_list = []
# counter = 0
while len(m) > 0:
# counter += 1
# _logger.info("Node: [%s], Phase: [PROCESS NEW VIEW], Event FD: [%s], RequestInnerID: [%s]" % (self._id, fd, req.inner.id))
# _logger.info("COUNTER [%s]" % counter)
b = m[:4]
size = struct.unpack("!I", b)[0]
try:
r2 = request_pb2.Request()
r2.ParseFromString(m[4:size + 4])
record_pbft(self.debuglog, r2)
key = get_asymm_key(r2.inner.id, ktype="sign")
if not bool(key):
_logger.error(
"Node: [%s], ErrorMsg => {get_asymm_key(): -> returned empty key}"
% (self._id))
return
r2 = message.check(key, r2)
if r2 == None:
_logger.warn("FAILED SIG CHECK IN NEW VIEW")
return
except:
r2 = None
_logger.warn("FAILED PROTOBUF EXTRACT IN NEW VIEW")
return
if r2.inner.type == "VCHA":
vchange_list.append(r2)
if r2.inner.type == "PRPR":
prpr_list.append(r2)
m = m[size + 4:]
if not self.nvprocess_view(vchange_list):
_logger.warn("FAILED VCHANGE VALIDATION IN NEW VIEW")
return
if req.inner.view >= self.view:
self.view = req.inner.view
self.view_active = True
self.primary = self.view % self.N
self.active = {}
self.reset_message_log()
#TODO: Move this check to execute
self.client_message_log = {}
self.prepared = {}
rc2 = self.nvprocess_prpr(prpr_list)
_logger.info("Node: [%s], Msg: [New View Accepted], View: [%s]" %
(self._id, self.view))
return
def validate_keypair(i, s, v):
msg = "message" + str(i)
sig = s.sign(msg)
ver = v.verify(sig, msg)
if not ver:
_logger.error("Error while reading keypair: " % i)
return False
_logger.info("Round succeeded for keypair: " % i)
return True
def get_key_path(i, ktype):
try:
KEY_NAME = ktype + str(i) + ASYMM_FILE_FORMATS[ktype]
# _logger.info("KPATH - FETCH - %s -- %s" % (ktype, KEY_NAME))
return os.path.join(KD, KEY_NAME)
# generic catch
except Exception as E:
_logger.error(E)
return
def execute(self, req):
"""
clientbuff is used to maintain buffer for failed requests for retries
"""
seq = req.inner.seq
dig = req.inner.msg
client_req, t, fd = self.active[dig]
t.cancel()
key = get_asymm_key(self._id, ktype="sign")
if not bool(key):
_logger.error(
"Node: [%s], ErrorMsg => {get_asymm_key(): -> returned empty key}"
% (self._id))
return
#time.sleep(1)
#rc = ecdsa_sig.verify(self.ecdsa_key, self.hello_sig, "Hello world!")
#cond.acquire()
## Horrible hack...
#self.last_executed = max(seq,self.last_executed)
m = self.bank.process_request(key, self._id, seq, client_req)
client_req.inner.msg = "TRAN00000000"
#for i in range(1024):
discard = self.bank.process_request(key, self._id, seq, client_req)
#cond.release()
#if self._id == self.primary and fd in self.fdmap:
#if fd in self.fdmap:
#self.safe_send(self.fdmap[fd], m)
#self.clean(fd)
time.sleep(0.05)
# TODO: hack
retry = True
#while retry:
self.clientlock.acquire()
try:
self.send_to_client(self.clientbuff + serialize(m))
self.clientbuff = bytes()
except:
_logger.warn("failed to send, adding to client outbuff")
self.clientbuff += serialize(m)
#continue
self.clientlock.release()
#retry = False
record(self.debuglog, "EXECUTED " + str(seq))
#print("adding request with sequence number " + str(req.inner.seq) + " to queue")
if self.max_requests and seq >= self.max_requests:
maxout_msg = "max requests reached, shutting down.."
_logger.info(maxout_msg)
print(maxout_msg)
#sys.exit()
t = Timer(5, self.suicide)
t.start()
def nvprocess_view(self, vchange_list):
for r in vchange_list:
key = get_asymm_key(r.inner.id, ktype="sign")
if not bool(key):
_logger.error(
"Node: [%s], ErrorMsg => {get_asymm_key(): -> returned empty key}"
% (self._id))
return
m = message.check(key, r)
if m == None:
return False
return True
def signal_handler(event, frame):
sys.stdout.write("handling signal: %s\n" % event)
sys.stdout.flush()
_logger.error("Kill signal (%s) detected. Stopping pbft.." % event)
countdown = 3 # seconds
if event == signal.SIGINT:
print("Committing deliberate suicide in %s seconds" % countdown)
print("Active Thread Count: ", active_count())
t = Timer(countdown, suicide)
print("End time: ", datetime.now())
t.start()
print("Active Thread Count: ", active_count())
sys.exit(130) # Ctrl-C for bash
def create_request(self, req_type, seq, msg, outer_req=None):
key = get_asymm_key(self._id, ktype="sign")
if not bool(key):
_logger.error(
"Node: [%s], ErrorMsg => {get_asymm_key(): -> returned empty key}"
% (self._id))
return
# if req_type == "PRPR":
# import pdb; pdb.set_trace()
# msg = bytes(msg, encoding='utf-8')
m = message.add_sig(key, self._id, seq, self.view, req_type, msg)
if outer_req:
m.outer = outer_req.SerializeToString()
return m
def read_keys_test(n, validate=False):
if not os.path.isdir(KD):
_logger.error("Can't find key directory")
sys.exit(0)
s = []
v = []
for i in range(0, n):
secret_key = open(get_key_path(i, "sign"), "rb").read()
public_key = open(get_key_path(i, "verify"), "rb").read()
s.append(ecdsa.SigningKey.from_pem(secret_key))
v.append(ecdsa.VerifyingKey.from_pem(public_key))
if validate:
assert validate_keypair(i, s[-1], v[-1]) is True
return s, v
def vprocess_prepare(self, vprep_dict, vpre_dict, last_checkpoint):
max = 0
#[seq][id] -> req
counter = {}
for k1, v1 in vprep_dict.items():
if (not k1 in vpre_dict):
return False, 0
dig = vpre_dict[k1].inner.msg
key = get_asymm_key(vpre_dict[k1].inner.id, ktype="sign")
if not bool(key):
_logger.error(
"Node: [%s], ErrorMsg => {get_asymm_key(): -> returned empty key}"
% (self._id))
return
r = message.check(key, vpre_dict[k1])
if r == None:
return False, 0
for k2, v2 in v1.items():
# check sigs
key = get_asymm_key(v2.inner.id, ktype="sign")
if not bool(key):
_logger.error(
"Node: [%s], ErrorMsg => {get_asymm_key(): -> returned empty key}"
% (self._id))
return
r = message.check(key, v2)
if r == None:
return False, 0
#prepares need to be for the same digest
if r.inner.msg != dig:
return False
if (vpre_dict[k1].inner.id == r.inner.id):
return False, 0
if r.inner.seq < last_checkpoint:
return False, 0
if r.inner.seq > max:
max = r.inner.seq
if r.inner.seq not in counter:
counter[r.inner.seq] = 1
else:
counter[r.inner.seq] += 1
for k in counter:
if counter[k] < 2 * self.f:
return False, 0
self.add_node_history(vpre_dict[k])
return True, max
def try_client(self):
ip, port = CLIENT_ADDRESS
_logger.debug("Node: [%s], Msg: [Trying client], Target: [%s]" % \
(self._id, CLIENT_ADDRESS))
while True:
# time.sleep(5)
self.clientlock.acquire()
if len(self.clientbuff) > 0:
try:
self.send_to_client(self.clientbuff)
self.clientbuff = bytes()
except Exception as E:
_logger.error(
"Node: [%s], ErrorMsg => {while trying client, encountered: %s}"
% (self._id, E))
self.clientlock.release()
def init_server_socket(self, _id=None):
"""
triggers setup using testbed_config. Increments given server id
if that (ip, socket) from Replica List RL is already in use.
"""
global N
c = _id
while c < N:
s = None
try:
s = init_server(c)
except OSError as E:
_logger.error("%s -- Server ID: [%s]" % (E, c))
c -= 1
if s:
return s, c
def nvprocess_prpr(self, prpr_list):
for r in prpr_list:
key = get_asymm_key(r.inner.id, ktype="sign")
if not bool(key):
_logger.error(
"Node: [%s], ErrorMsg => {get_asymm_key(): -> returned empty key}"
% (self._id))
return
m = message.check(key, r)
if m == None:
return False
out = self.create_request("PREP", r.inner.seq, r.inner.msg)
self.broadcast_to_nodes(out)
#TODO: add view to node_message_log, don't broadcast here
#if self._id in self.node_message_log["COMM"][r.inner.seq]:
# out = self.create_request("COMM", r.inner.seq, r.inner.msg)
# self.broadcast_to_nodes(out)
return True
def get_asymm_key(i, ktype=None):
kpath = get_key_path(i, ktype)
found_error = False
try:
if not os.path.isfile(kpath):
result = "File Not Found: %s" % kpath
_logger.error(result)
found_error = True
else:
key_pem = open(kpath, 'rb').read()
result = ASYMM_FUNC_MAP[ktype](key_pem)
except Exception as result:
found_error = True
if found_error:
_logger.error("%s" % result)
return None
return result
def parse_request(self, request_bytes, fd):
# attempt to reconstruct the request object
# close connection and return on failure
try:
# import pdb; pdb.set_trace()
req = request_pb2.Request()
req.ParseFromString(request_bytes)
# _logger.debug(req)
_logger.info(
"Node: [%s], Phase: [PARSE REQUEST], RequestInnerID: [%s]" %
(self._id, req.inner.id))
record_pbft(self.debuglog, req)
key = get_asymm_key(req.inner.id, ktype="sign")
# if not isinstance(key, ecdsa.SigningKey):
if not bool(key):
_logger.error(
"Node: [%s], ErrorMsg => {get_asymm_key(): -> returned empty key}"
% (self._id))
return
req = message.check(key, req)
if req is None:
_logger.error(
"Node: [%s], ErrorMsg => {Failed message sig check. 'req' is empty..}"
% (self._id))
return
except Exception as E:
req = None
_logger.error(
"Node: [%s], ErrorMsg => {ERROR IN PROTOBUF TYPES: %s}" %
(self._id, E))
# raise # for debug
self.clean(fd)
return
# print(req.inner.type, len(request_bytes))
# TODO: Check for view number and view change, h/H
if req.inner.view != self.view or not self.view_active:
if req.inner.type != "VCHA" and req.inner.type != "NEVW" and \
req.inner.type != "CHKP" and req.inner.type != "REQU":
debug_msg = "TYPE: %s - ID %s - SEQ %s - VIEW - %s" % (
req.inner.type, req.inner.id, req.inner.seq,
req.inner.view)
_logger.warn("Bad view number - %s" % debug_msg)
return
if self.in_node_history(req):
_logger.warn("Duplicate node message")
# return
pass
if req.inner.type in self.request_types and not self.in_client_history(
req):
# call to actual success
self.request_types[req.inner.type](req, fd)
else:
self.clean(fd)
_logger.warn("BAD MESSAGE TYPE - %s - %s" %
(req.inner.type, req.inner.id))
def server_loop(self):
"""
call flow graph:
-> server_loop() -> parse_request() ->
self.request_types[req.inner.type]() -> [] process_client_request() ->
execute_in_order() -> execute() ->
- self.bank.process_request()
- client_sock.send()
- record()
-> suicide() when Max Requests reached..
"""
# counter = 0
# self.fdmap[s.fileno] = s
# self.p.register(s, recv_mask)
s = self.replica_map[self._id]
_logger.info("Node: [%s], Current Primary: [%s]" %
(self._id, self.primary))
_logger.info("Node: [%s], Msg: [INIT SERVER LOOP]" % (self._id))
t = Timer(5, self.try_client)
t.start()
while True:
#print(counter)
events = self.p.poll()
_logger.debug("Node: [%s], Msg: [Polling Queue], Events => {%s}" %
(self._id, events))
#cstart = time.time()
# import pdb; pdb.set_trace()
for fd, event in events:
# counter += 1
# need the flag for "Service temporarilly unavailable" exception
data = None
recv_flag = False
if fd is s.fileno():
c, addr = s.accept()
_logger.debug(
"Node: [%s], Msg: [Got Connection], Address => {%s}" %
(self._id, addr))
#print("Got connection from " + str(addr))
c.setblocking(0)
#c.setsockopt(socket.IPPROTO_TCP, socket.TCP_NODELAY, True)
self.p.register(c, recv_mask)
self.fdmap[c.fileno()] = c
self.buffmap[c.fileno()] = bytes()
self.outbuffmap[c.fileno()] = bytes()
self.connections += 1
else:
# if we have a write event
if event & send_mask != 0:
if len(self.outbuffmap[fd]) > 0:
try:
rc = self.fdmap[fd].send(self.outbuffmap[fd])
self.outbuffmap[fd] = self.outbuffmap[fd][rc:]
if len(self.outbuffmap[fd]) == 0:
self.p.modify(fd, recv_mask)
except:
#raise
self.clean(fd)
continue
if event & recv_mask != 0:
try:
data = self.fdmap[fd].recv(BUF_SIZE)
recv_flag = True
except Exception as E:
_logger.error("Node: [%s], Msg: [%s]" %
(self._id, E))
self.clean(fd)
continue
#except socket.error, serr:
#print("exception...")
#print(serr)
#self.clean(fd)
if not data and recv_flag:
try:
peer_address = ":".join(
str(i) for i in self.fdmap[fd].getpeername())
_logger.debug(
"Node: [%s], Msg: [Close Connection], Event FileNum: [%s], Address: [%s]"
% (self._id, fd, peer_address))
except Exception as E:
_logger.error(
"Node: [%s], Msg: [Close Connection], Event FileNum: [%s], ErrorMsg => {%s}"
% (self._id, fd, E))
self.clean(fd)
elif recv_flag:
_logger.debug(
"Node: [%s], ChunkLength: [%s]" %
(self._id, len(data))) # .decode('latin-1')))
self.buffmap[fd] += data # .decode('latin-1')
while (len(self.buffmap[fd]) > 3):
try:
size = struct.unpack("!I",
self.buffmap[fd][:4])[0]
except Exception as E:
_logger.error("Node: [%s], ErrorMsg => [%s]" %
(self._id, E))
break
# import pdb; pdb.set_trace()
if len(self.buffmap[fd]) >= size + 4:
self.parse_request(
self.buffmap[fd][4:size + 4], fd)
if fd not in self.buffmap:
break
self.buffmap[fd] = self.buffmap[fd][size + 4:]
else:
# TODO: check if remaining buffmap of slice
# less than size+4 as leftover crumbs
break
if self.kill_flag:
sys.exit()
def process_preprepare(self, req, fd):
_logger.info("Node: [%s], Phase: [PRE-PREPARE], Event FD: [%s]" %
(self._id, fd))
if req.inner.seq in self.node_message_log["PRPR"]:
return None
# the msg field for a preprepare should be the digest of the original client request
# TODO: make it clearer that req.outer stands for the message that the replica in subject
# is going down..
if req.outer != b'': # req.outer should be same format as req.inner (bytes)
try:
# import pdb; pdb.set_trace()
client_req = request_pb2.Request()
# client_req.ParseFromString(req.outer)
client_req.ParseFromString(req)
record_pbft(self.debuglog, client_req)
client_key = get_asymm_key(client_req.inner.id, ktype="sign")
if not bool(client_key):
_logger.error(
"Node: [%s], ErrorMsg => {get_asymm_key(): -> returned empty key}"
% (self._id))
return
client_req = message.check(client_key, client_req)
if client_req == None or req.inner.msg != client_req.dig:
_logger.warn("FAILED PRPR OUTER SIGCHECK")
return
except:
_logger.error("ERROR IN PRPR OUTER PROTOBUFF")
raise
# return
# TODO: remove replica from replica map as it has by this time probably gone down or is corrupt.
else:
client_req = None
if req.inner.msg not in self.active:
# self.active[req.inner.msg] = (client_req, Timer(self.timeout, self.handle_timeout), fd)
request_timer = Timer(self.timeout, self.handle_timeout,
[req.inner.msg, req.inner.view])
request_timer.daemon = True
request_timer.start()
self.active[req.inner.msg] = (client_req, request_timer, fd)
self.add_node_history(req)
m = self.create_request("PREP", req.inner.seq, req.inner.msg)
self.add_node_history(m)
record_pbft(self.debuglog, m)
self.inc_prep_dict(req.inner.msg)
self.broadcast_to_nodes(m)
if self.check_prepared_margin(req.inner.msg, req.inner.seq):
record(self.debuglog,
"PREPARED sequence number " + str(req.inner.seq))
m = self.create_request("COMM", req.inner.seq, req.inner.msg)
self.broadcast_to_nodes(m)
self.add_node_history(m)
self.inc_comm_dict(m.inner.msg)
record_pbft(self.debuglog, m)
self.prepared[req.inner.seq] = req.inner.msg
if self.check_committed_margin(m.inner.msg, m):
record(self.debuglog,
"COMMITTED sequence number " + str(m.inner.seq))
record_pbft(self.commitlog, m)
self.execute_in_order(m)
def process_view_change(self, req, fd):
_logger.warn(
"Node: [%s], Phase: [PROCESS VIEW CHANGE], Event FD: [%s], RequestInnerID: [%s]"
% (self._id, fd, req.inner.id))
_logger.warn("Node: [%s], RequestInnerView: [%s]" %
(self._id, req.inner.view))
self.add_node_history(req)
new_v = req.inner.view
if self._id != req.inner.view or new_v < self.view:
return
# (NEVW, v+1, V, O) where V is set of valid VCHA, O is set of PRPR
#TODO (NO PIGGYBACK)
# determine the latest stable checkpoint
checkpoint = 0
# [seq][id] -> req
# for each view change message
#for r in self.view_dict[new_v]:
vcheck_list = []
vpre_dict = {}
vprep_dict = {}
m = req.inner.msg
# for each chkp, prpr, prep message it contains
while len(m) > 0:
b = m[:4]
size = struct.unpack("!I", b)[0]
try:
#if True:
r2 = request_pb2.Request()
r2.ParseFromString(m[4:size + 4])
record_pbft(self.debuglog, r2)
key = get_asymm_key(r2.inner.id, ktype="sign")
if not bool(key):
_logger.error(
"Node: [%s], ErrorMsg => {get_asymm_key(): -> returned empty key}"
% (self._id))
return
r2 = message.check(key, r2)
if r2 is None:
print("FAILED SIG CHECK IN VIEW CHANGE")
return
except Exception as E:
#else:
r2 = None
print("FAILED PROTOBUF EXTRACT IN VIEW CHANGE: %s" % E)
raise
return
if r2.inner.type == "CHKP":
vcheck_list.append(r2)
if r2.inner.type == "PREP":
if r2.inner.seq not in vprep_dict:
vprep_dict[r2.inner.seq] = {r2.inner.id: r2}
else:
vprep_dict[r2.inner.seq][r2.inner.id] = r2
if r2.inner.type == "PRPR":
vpre_dict[r2.inner.seq] = r2
m = m[size + 4:]
rc1 = self.vprocess_checkpoints(vcheck_list, req.inner.seq)
rc2, max = self.vprocess_prepare(vprep_dict, vpre_dict, req.inner.seq)
# on success add to list
# on error do nothing and return
# request list, min, max
if rc1 and rc2:
if new_v not in self.view_dict:
self.view_dict[new_v] = ([req], 0, 0)
else:
if not self.in_view_dict(req):
self.view_dict[new_v][0].append(req)
# set min and max
if self.view_dict[new_v][1] < req.inner.seq:
#self.view_dict[new_v][1] = req.inner.seq
temp = self.view_dict[new_v]
self.view_dict[new_v] = (temp[0], req.inner.seq, temp[2])
if self.view_dict[new_v][2] < max:
#self.view_dict[new_v][2] = max
temp = self.view_dict[new_v]
self.view_dict[new_v] = (temp[0], temp[1], max)
# proccess and send the new view request
if ((not self.view_active) or new_v > self.view) and len(
self.view_dict[new_v][0]) > 2 * self.f:
msg = ""
for i in self.view_dict[new_v][0]:
msg += serialize(i)
for i in range(self.view_dict[new_v][1], self.view_dict[new_v][2]):
if i == 0:
continue
r = self.node_message_log["PRPR"][i][self.primary]
temp = self.create_request("PRPR", i, r.inner.msg)
msg += serialize(temp)
out = self.create_request("NEVW", 0, msg)
self.view_active = True
self.primary = self.view % self.N
self.active = {}
self.reset_message_log()
#TODO: MOve this check to execute
self.client_message_log = {}
self.prepared = {}
self.seq = self.view_dict[new_v][2]
self.broadcast_to_nodes(out)
print("Entering New view", self.view)
