From d34b94a858a9bccdac951038d7f4f77169d87bc2 Mon Sep 17 00:00:00 2001 From: Sergi Delgado Date: Fri, 5 Apr 2019 19:24:45 +0100 Subject: [PATCH] Adds proper logging format --- .gitignore | 9 +++++++++ pisa-btc/pisa/api.py | 19 +++++++++++-------- pisa-btc/pisa/pisad.py | 13 +++++++++---- pisa-btc/pisa/shared.py | 8 -------- pisa-btc/pisa/watcher.py | 36 +++++++++++++++++++----------------- 5 files changed, 48 insertions(+), 37 deletions(-) delete mode 100644 pisa-btc/pisa/shared.py diff --git a/.gitignore b/.gitignore index 7694bde..f062cad 100644 --- a/.gitignore +++ b/.gitignore @@ -15,4 +15,13 @@ conf.py bitcoin.conf *__pycache__ .pending* +pisa.log +.\#* +build/ +dist/ +node_modules/ +.vscode/ +*.log +.nyc_output +logs/ diff --git a/pisa-btc/pisa/api.py b/pisa-btc/pisa/api.py index 19fd31e..c69e415 100644 --- a/pisa-btc/pisa/api.py +++ b/pisa-btc/pisa/api.py @@ -5,7 +5,7 @@ from pisa.inspector import Inspector from multiprocessing.connection import Listener -def manage_api(debug, host=HOST, port=PORT): +def manage_api(debug, logging, host=HOST, port=PORT): listener = Listener((host, port)) watcher = Watcher() inspector = Inspector() @@ -13,16 +13,18 @@ def manage_api(debug, host=HOST, port=PORT): while True: conn = listener.accept() + remote_addr, remote_port = listener.last_accepted + if debug: - print('Connection accepted from', listener.last_accepted) + logging.info('[API] connection accepted from {}:{}'.format(remote_addr, remote_port)) # Maintain metadata up to date. - t_serve = threading.Thread(target=manage_request, args=[conn, listener.last_accepted, inspector, watcher, - debug]) + t_serve = threading.Thread(target=manage_request, args=[conn, remote_addr, remote_port, inspector, watcher, + debug, logging]) t_serve.start() -def manage_request(conn, remote_addr, inspector, watcher, debug): +def manage_request(conn, remote_addr, remote_port, inspector, watcher, debug, logging): while not conn.closed: try: response = "Unknown command" @@ -35,7 +37,7 @@ def manage_request(conn, remote_addr, inspector, watcher, debug): if command == "add_appointment": appointment = inspector.inspect(msg, debug) if appointment: - appointment_added = watcher.add_appointment(appointment, debug) + appointment_added = watcher.add_appointment(appointment, debug, logging) if appointment_added: response = "Appointment accepted" @@ -46,11 +48,12 @@ def manage_request(conn, remote_addr, inspector, watcher, debug): # Send response back. Change multiprocessing.connection for an http based connection if debug: - print('Sending response and disconnecting:', response, remote_addr) + logging.info('[API] sending response and disconnecting: {} --> {}:{}'.format(response, remote_addr, + remote_port)) conn.close() except (IOError, EOFError): if debug: - print('Disconnecting from', remote_addr) + logging.info('[API] disconnecting from {}:{}'.format(remote_addr, remote_port)) conn.close() diff --git a/pisa-btc/pisa/pisad.py b/pisa-btc/pisa/pisad.py index 448761f..f43ef86 100644 --- a/pisa-btc/pisa/pisad.py +++ b/pisa-btc/pisa/pisad.py @@ -1,7 +1,8 @@ -from getopt import getopt +import logging from sys import argv +from getopt import getopt +from conf import LOG_FILE from threading import Thread -from pisa import shared from pisa.api import manage_api @@ -12,7 +13,11 @@ if __name__ == '__main__': if opt in ['-d', '--debug']: debug = True - shared.init() + # Configure logging + logging.basicConfig(format='%(asctime)s %(name)s: %(message)s', level=logging.INFO, handlers=[ + logging.FileHandler(LOG_FILE), + logging.StreamHandler() + ]) - api_thread = Thread(target=manage_api, args=[debug]) + api_thread = Thread(target=manage_api, args=[debug, logging]) api_thread.start() diff --git a/pisa-btc/pisa/shared.py b/pisa-btc/pisa/shared.py deleted file mode 100644 index 191ce8a..0000000 --- a/pisa-btc/pisa/shared.py +++ /dev/null @@ -1,8 +0,0 @@ -from queue import Queue - - -def init(): - global block_queue, registered_txs - - block_queue = Queue() - registered_txs = dict() diff --git a/pisa-btc/pisa/watcher.py b/pisa-btc/pisa/watcher.py index 9381477..d677b2c 100644 --- a/pisa-btc/pisa/watcher.py +++ b/pisa-btc/pisa/watcher.py @@ -17,7 +17,7 @@ class ZMQHandler: self.zmqSubSocket.setsockopt_string(zmq.SUBSCRIBE, "hashblock") self.zmqSubSocket.connect("%s://%s:%s" % (FEED_PROTOCOL, FEED_ADDR, FEED_PORT)) - def handle(self, block_queue, debug): + def handle(self, block_queue, debug, logging): msg = self.zmqSubSocket.recv_multipart() topic = msg[0] body = msg[1] @@ -27,7 +27,7 @@ class ZMQHandler: block_queue.put(block_hash) if debug: - print("New block received from Core ", block_hash) + logging.info("[ZMQHandler] new block received via ZMQ".format(block_hash)) class Watcher: @@ -37,7 +37,7 @@ class Watcher: self.asleep = True self.max_appointments = max_appointments - def add_appointment(self, appointment, debug): + def add_appointment(self, appointment, debug, logging): # ToDo: Discuss about validation of input data # Rationale: @@ -63,8 +63,8 @@ class Watcher: if self.asleep: self.asleep = False - zmq_subscriber = Thread(target=self.do_subscribe, args=[self.block_queue, debug]) - watcher = Thread(target=self.do_watch, args=[debug]) + zmq_subscriber = Thread(target=self.do_subscribe, args=[self.block_queue, debug, logging]) + watcher = Thread(target=self.do_watch, args=[debug, logging]) zmq_subscriber.start() watcher.start() @@ -75,11 +75,11 @@ class Watcher: return appointment_added - def do_subscribe(self, block_queue, debug): + def do_subscribe(self, block_queue, debug, logging): daemon = ZMQHandler() - daemon.handle(block_queue, debug) + daemon.handle(block_queue, debug, logging) - def do_watch(self, debug): + def do_watch(self, debug, logging): bitcoin_cli = AuthServiceProxy("http://%s:%s@%s:%d" % (BTC_RPC_USER, BTC_RPC_PASSWD, BTC_RPC_HOST, BTC_RPC_PORT)) @@ -88,13 +88,14 @@ class Watcher: try: block = bitcoin_cli.getblock(block_hash) + # ToDo: prev_block_id will be to store chain state and handle reorgs prev_block_id = block.get('previousblockhash') txs = block.get('tx') if debug: - print("New block received", block_hash) - print("Prev. block hash", prev_block_id) - print("List of transactions", txs) + logging.info("[Watcher] new block received {}".format(block_hash)) + logging.info("[Watcher] prev. block hash {}".format(prev_block_id)) + logging.info("[Watcher] list of transactions: {}".format(txs)) potential_matches = [] @@ -103,11 +104,11 @@ class Watcher: if debug: if len(potential_matches) > 0: - print("List of potential matches", potential_matches) + logging.info("[Watcher] list of potential matches: {}".format(potential_matches)) else: - print("No potential matches found") + logging.info("[Watcher] no potential matches found") - matches = self.check_potential_matches(potential_matches, bitcoin_cli) + matches = self.check_potential_matches(potential_matches, bitcoin_cli, debug, logging) # ToDo: Handle matches # ToDo: Matches will be empty list if no matches, list of matches otherwise @@ -115,10 +116,10 @@ class Watcher: # ToDo: Get rid of appointment? Set appointment to a different state (create appointment state first)? except JSONRPCException as e: - print(e) + logging.error("[Watcher] JSONRPCException. Error code {}".format(e)) continue - def check_potential_matches(self, potential_matches, bitcoin_cli): + def check_potential_matches(self, potential_matches, bitcoin_cli, debug, logging): matches = [] for locator, k in potential_matches: @@ -130,7 +131,8 @@ class Watcher: except JSONRPCException as e: # Tx decode failed returns error code -22, maybe we should be more strict here. Leaving it simple # for the POC - print(e) + if debug: + logging.error("[Watcher] JSONRPCException. Error code {}".format(e)) continue return matches