def init_replica_map(self, socket_obj):
self.fdmap[socket_obj.fileno()] = socket_obj
self.p.register(socket_obj, recv_mask)
self.replica_map[self._id] = socket_obj
#self.replica_map = {}
#for i in range(self._id+1, self.N)[::-1]:
# TODO:
# make this dynamic / event responsibe upon request of addition of new node (from BFT committee)
# Also, this should trigger check margin for valid minimum number of nodes to be present
# to achieve BFT fault tolerance (N-1/3)
for i in range(self.N):
if i == self._id:
continue
# r = socket.socket()
# import pdb; pdb.set_trace()
remote_ip, remote_port = RL[i]
_logger.debug(
"Node: [%s], Msg: [Attempt Connection], Replica List => %s" %
(self._id, RL))
retry = True
# retry = False
count = 0
while retry: # re-trying will not cause a deadlock.
count += 1
try:
r = socks.socksocket()
# import pdb; pdb.set_trace()
# r.setproxy(socks.PROXY_TYPE_SOCKS5, "127.0.0.1", config.TOR_SOCKSPORT[self._id], True)
# r.setblocking(0)
r.connect((remote_ip, remote_port))
_logger.info(
"Node: [%s], Msg: [Connection Established], Target: [%s:%s]"
% (self._id, remote_ip, remote_port))
except Exception as e:
time.sleep(0.5)
r.close()
_logger.debug(
"Node: [%s], Msg: [Connection Retry], Count: [%s], Target: [%s:%d], Cause => {%s}"
% (self._id, count, remote_ip, remote_port, str(e)))
#if count == 10000:
# raise
continue
retry = False
#r.setsockopt(socket.IPPROTO_TCP, socket.TCP_NODELAY, True)
self.replica_map[i] = r
self.fdmap[r.fileno()] = r
self.buffmap[r.fileno()] = bytes()
self.outbuffmap[r.fileno()] = bytes()
self.p.register(r, recv_mask)
#m = message.add_sig(K, "INIT " + str(ID), ID)
#m = add_sig(0,"INIT",str(ID))
#r.send(m.SerializeToString())
m = self.create_request("INIT", 0, str(self._id).encode("utf-8"))
self.safe_send(r, m)
msg = "init connection to replica " + str(i) + " on fd " + str(
r.fileno())
_logger.info(
"Node: [%s], Phase: [INIT], Msg: [Connected to Replica %d], Event FD: [%s]"
% (self._id, i, str(r.fileno())))
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 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 process_commit(self, req, fd):
_logger.info("Node: [%s], Phase: [COMMIT], Event DF: [%s]" %
(self._id, fd))
self.add_node_history(req)
self.inc_comm_dict(req.inner.msg)
if self.check_committed_margin(req.inner.msg, req):
record(self.debuglog,
"COMMITTED sequence number " + str(req.inner.seq))
record_pbft(self.commitlog, req)
self.execute_in_order(req)
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 send_to_client(self, msg):
ip, port = CLIENT_ADDRESS
client_sock = socks.socksocket() # socket.socket()
# import pdb; pdb.set_trace()
client_sock.setproxy(socks.PROXY_TYPE_SOCKS5, "127.0.0.1",
config.TOR_SOCKSPORT[self._id], True)
_logger.info("Node: [%s], Msg: [Dialing Client], Target: [%s:%s]" %
(self._id, ip, port))
client_sock.connect((ip, port))
client_sock.send(msg)
client_sock.close()
def write_new_keys(n):
if not os.path.isdir(KD):
os.mkdir(KD)
for i in range(0, n):
s_file = open(get_key_path(i, "sign"), 'wb')
v_file = open(get_key_path(i, "verify"), 'wb')
sk, vk = generate_keys()
s_file.write(sk.to_pem())
v_file.write(vk.to_pem())
s_file.close()
v_file.close()
msg = "written new keys to %s" % KD
_logger.info(msg)
return msg
def process_prepare(self, req, fd):
_logger.info("Node: [%s], Phase: [PREPARE], Event FD: [%s]" %
(self._id, fd))
self.add_node_history(req)
self.inc_prep_dict(req.inner.msg)
# import pdb; pdb.set_trace()
# TODO: this turns out to be false always
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_client_request(self, req, fd):
_logger.info(
"Node: [%s], Phase: [PROCESS CLIENT REQ], Event FD: [%s]" %
(self._id, fd))
if req.inner.timestamp == 0:
pass
#print(req.inner.msg)
if req.dig in self.active:
client_req, t, fd = self.active[req.dig]
if client_req is None:
self.active[req.dig] = (req, t, fd)
if req.dig in self.comm_dict and self.comm_dict[
req.dig].prepared:
m = self.comm_dict[req.dig].req
self.execute_in_order(m)
return
self.lock.acquire()
if self.view_active:
view = self.view
else:
self.lock.release()
return
self.add_client_history(req)
request_timer = Timer(self.timeout, self.handle_timeout,
[req.dig, req.inner.view])
request_timer.daemon = True
request_timer.start()
self.active[req.dig] = (req, request_timer, fd)
self.lock.release()
if self.primary == self._id:
self.seq = self.seq + 1
#m = self.create_request("PRPR", self.seq, req.dig, req)
m = self.create_request("PRPR", self.seq, req.dig)
self.add_node_history(m)
record_pbft(self.debuglog, m)
self.broadcast_to_nodes(m)
def call_to_viewchange(self, context):
"""
complains to snailchain, init viewchange
"""
start = time.time()
response = None
total = 0
# TODO: derive timer logic from node.py
# request_timer = Timer(self.timeout, self.handle_timeout, [req.dig, req.inner.view])
# request_timer.daemon = True
# TODO: handle timeout
while True:
response = self.wait_for_reply(start, context)
# TODO: something like go routine to handle_timeout()
if response is False:
return False
else:
total = time.time() - start
_logger.info("Total time taken for view change: %s" % total)
return True
if self.handle_timeout(start, self.timeout_viewchange):
break
return
def record_pbft(file, request):
msg = "Req Type: [%s], Seq: [%d], Received From: [%d], In View: [%d]" % (
request.inner.type, request.inner.seq, request.inner.id,
request.inner.view)
_logger.info("Node: [%s], %s" % (self._id, msg))
record(file, msg)
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 debug_print_bank(self):
_logger.info("Node: [%s], Wait Queue Length: [%s]" %
(self._id, len(self.waiting)))
_logger.info("Node: [%s], Last Executed: [%s]" %
(self._id, self.last_executed))
self.bank.print_balances()
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()