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()