From 1184b4648aa4a4cf9ac21aaf1e446bc13a18caa2 Mon Sep 17 00:00:00 2001 From: Sergi Delgado Segura Date: Mon, 16 Dec 2019 19:45:30 +0100 Subject: [PATCH] Fixes logs and removes redundant tailing dots --- apps/cli/pisa_cli.py | 64 ++++++++++++++++++++++------------------- common/cryptographer.py | 22 +++++++------- pisa/block_processor.py | 6 ++-- pisa/carrier.py | 4 +-- pisa/cleaner.py | 10 +++---- pisa/responder.py | 14 ++++----- pisa/watcher.py | 10 +++---- 7 files changed, 68 insertions(+), 62 deletions(-) diff --git a/apps/cli/pisa_cli.py b/apps/cli/pisa_cli.py index 4d45414..c793b96 100644 --- a/apps/cli/pisa_cli.py +++ b/apps/cli/pisa_cli.py @@ -3,6 +3,7 @@ import sys import json import requests import time +import binascii from sys import argv from getopt import getopt, GetoptError from requests import ConnectTimeout, ConnectionError @@ -84,7 +85,7 @@ def save_signed_appointment(appointment, signature): def add_appointment(args): appointment_data = None - use_help = "Use 'help add_appointment' for help of how to use the command." + use_help = "Use 'help add_appointment' for help of how to use the command" if not args: logger.error("No appointment data provided. " + use_help) @@ -99,7 +100,7 @@ def add_appointment(args): if arg_opt in ["-f", "--file"]: fin = args.pop(0) if not os.path.isfile(fin): - logger.error("Can't find file " + fin) + logger.error("Can't find file", filename=fin) return False try: @@ -107,7 +108,7 @@ def add_appointment(args): appointment_data = json.load(f) except IOError as e: - logger.error("I/O error({}): {}".format(e.errno, e.strerror)) + logger.error("I/O error", errno=e.errno, error=e.strerror) return False else: appointment_data = json.loads(arg_opt) @@ -117,13 +118,13 @@ def add_appointment(args): return False if not appointment_data: - logger.error("The provided JSON is empty.") + logger.error("The provided JSON is empty") return False valid_locator = check_sha256_hex_format(appointment_data.get("tx_id")) if not valid_locator: - logger.error("The provided locator is not valid.") + logger.error("The provided locator is not valid") return False add_appointment_endpoint = "http://{}:{}".format(pisa_api_server, pisa_api_port) @@ -140,31 +141,34 @@ def add_appointment(args): cli_sk = Cryptographer.load_private_key_der(sk_der) except ValueError: - logger.error("Failed to deserialize the public key. It might be in an unsupported format.") + logger.error("Failed to deserialize the public key. It might be in an unsupported format") return False except FileNotFoundError: - logger.error("Client's private key file not found. Please check your settings.") + logger.error("Client's private key file not found. Please check your settings") return False except IOError as e: - logger.error("I/O error({}): {}".format(e.errno, e.strerror)) + logger.error("I/O error", errno=e.errno, error=e.strerror) return False signature = Cryptographer.sign(Cryptographer.signature_format(appointment), cli_sk) try: cli_pk_der = load_key_file_data(CLI_PUBLIC_KEY) + hex_pk_der = binascii.hexlify(cli_pk_der) except FileNotFoundError: - logger.error("Client's public key file not found. Please check your settings.") + logger.error("Client's public key file not found. Please check your settings") return False except IOError as e: - logger.error("I/O error({}): {}".format(e.errno, e.strerror)) + logger.error("I/O error", errno=e.errno, error=e.strerror) return False - data = {"appointment": appointment, "signature": signature, "public_key": cli_pk_der.decode("utf-8")} + # FIXME: Exceptions for hexlify need to be covered + + data = {"appointment": appointment, "signature": signature, "public_key": hex_pk_der.decode("utf-8")} appointment_json = json.dumps(data, sort_keys=True, separators=(",", ":")) @@ -176,29 +180,31 @@ def add_appointment(args): response_json = r.json() except json.JSONDecodeError: - logger.error("The response was not valid JSON.") + logger.error("The response was not valid JSON") return False except ConnectTimeout: - logger.error("Can't connect to pisa API. Connection timeout.") + logger.error("Can't connect to pisa API. Connection timeout") return False except ConnectionError: - logger.error("Can't connect to pisa API. Server cannot be reached.") + logger.error("Can't connect to pisa API. Server cannot be reached") return False if r.status_code != HTTP_OK: if "error" not in response_json: - logger.error("The server returned status code {}, but no error description.".format(r.status_code)) + logger.error("The server returned an error status code but no error description", status_code=r.status_code) else: error = response_json["error"] logger.error( - "The server returned status code {}, and the following error: {}.".format(r.status_code, error) + "The server returned an error status code with an error description", + status_code=r.status_code, + description=error, ) return False if "signature" not in response_json: - logger.error("The response does not contain the signature of the appointment.") + logger.error("The response does not contain the signature of the appointment") return False signature = response_json["signature"] @@ -208,30 +214,30 @@ def add_appointment(args): pisa_pk = Cryptographer.load_public_key_der(pisa_pk_der) if pisa_pk is None: - logger.error("Failed to deserialize the public key. It might be in an unsupported format.") + logger.error("Failed to deserialize the public key. It might be in an unsupported format") return False is_sig_valid = Cryptographer.verify(Cryptographer.signature_format(appointment), signature, pisa_pk) except FileNotFoundError: - logger.error("Pisa's public key file not found. Please check your settings.") + logger.error("Pisa's public key file not found. Please check your settings") return False except IOError as e: - logger.error("I/O error({}): {}".format(e.errno, e.strerror)) + logger.error("I/O error", errno=e.errno, error=e.strerror) return False if not is_sig_valid: - logger.error("The returned appointment's signature is invalid.") + logger.error("The returned appointment's signature is invalid") return False - logger.info("Appointment accepted and signed by Pisa.") + logger.info("Appointment accepted and signed by Pisa") # all good, store appointment and signature try: save_signed_appointment(appointment, signature) except OSError as e: - logger.error("There was an error while saving the appointment: {}".format(e)) + logger.error("There was an error while saving the appointment", error=e) return False return True @@ -239,7 +245,7 @@ def add_appointment(args): def get_appointment(args): if not args: - logger.error("No arguments were given.") + logger.error("No arguments were given") return False arg_opt = args.pop(0) @@ -251,7 +257,7 @@ def get_appointment(args): valid_locator = check_sha256_hex_format(locator) if not valid_locator: - logger.error("The provided locator is not valid: {}".format(locator)) + logger.error("The provided locator is not valid", locator=locator) return False get_appointment_endpoint = "http://{}:{}/get_appointment".format(pisa_api_server, pisa_api_port) @@ -262,11 +268,11 @@ def get_appointment(args): print(json.dumps(r.json(), indent=4, sort_keys=True)) except ConnectTimeout: - logger.error("Can't connect to pisa API. Connection timeout.") + logger.error("Can't connect to pisa API. Connection timeout") return False except ConnectionError: - logger.error("Can't connect to pisa API. Server cannot be reached.") + logger.error("Can't connect to pisa API. Server cannot be reached") return False return True @@ -363,10 +369,10 @@ if __name__ == "__main__": logger.error("Unknown command. Use help to check the list of available commands") else: - logger.error("No command provided. Use help to check the list of available commands.") + logger.error("No command provided. Use help to check the list of available commands") except GetoptError as e: logger.error("{}".format(e)) except json.JSONDecodeError as e: - logger.error("Non-JSON encoded appointment passed as parameter.") + logger.error("Non-JSON encoded appointment passed as parameter") diff --git a/common/cryptographer.py b/common/cryptographer.py index 1b2d992..305da11 100644 --- a/common/cryptographer.py +++ b/common/cryptographer.py @@ -39,12 +39,12 @@ class Cryptographer: """ if len(data) % 2: - error = "Incorrect (Odd-length) value." + error = "Incorrect (Odd-length) value" logger.error(error, data=data) raise ValueError(error) if not check_sha256_hex_format(secret): - error = "Secret must be a 32-byte hex value (64 hex chars)." + error = "Secret must be a 32-byte hex value (64 hex chars)" logger.error(error, secret=secret) raise ValueError(error) @@ -82,7 +82,7 @@ class Cryptographer: sk = sha256(unhexlify(secret)).digest() nonce = bytearray(12) - logger.info("Encrypting blob.", sk=hexlify(sk).decode(), nonce=hexlify(nonce).decode(), blob=blob.data) + logger.info("Encrypting blob", sk=hexlify(sk).decode(), nonce=hexlify(nonce).decode(), blob=blob.data) # Encrypt the data cipher = ChaCha20Poly1305(sk) @@ -124,7 +124,7 @@ class Cryptographer: nonce = bytearray(12) logger.info( - "Decrypting Blob.", + "Decrypting Blob", sk=hexlify(sk).decode(), nonce=hexlify(nonce).decode(), encrypted_blob=encrypted_blob.data, @@ -185,13 +185,13 @@ class Cryptographer: return pk except UnsupportedAlgorithm: - logger.error("Could not deserialize the public key (unsupported algorithm).") + logger.error("Could not deserialize the public key (unsupported algorithm)") except ValueError: - logger.error("The provided data cannot be deserialized (wrong size or format).") + logger.error("The provided data cannot be deserialized (wrong size or format)") except TypeError: - logger.error("The provided data cannot be deserialized (wrong type).") + logger.error("The provided data cannot be deserialized (wrong type)") return None @@ -220,10 +220,10 @@ class Cryptographer: raise ValueError("Could not deserialize the private key (unsupported algorithm).") except ValueError: - logger.error("The provided data cannot be deserialized (wrong size or format).") + logger.error("The provided data cannot be deserialized (wrong size or format)") except TypeError: - logger.error("The provided data cannot be deserialized (wrong type).") + logger.error("The provided data cannot be deserialized (wrong type)") @staticmethod def sign(data, sk, rtype="str"): @@ -246,7 +246,7 @@ class Cryptographer: raise ValueError("Wrong return type. Return type must be 'str' or 'bytes'") if not isinstance(sk, ec.EllipticCurvePrivateKey): - logger.error("The value passed as sk is not a private key (EllipticCurvePrivateKey).") + logger.error("The value passed as sk is not a private key (EllipticCurvePrivateKey)") return None else: @@ -274,7 +274,7 @@ class Cryptographer: """ if not isinstance(pk, ec.EllipticCurvePublicKey): - logger.error("The value passed as pk is not a public key (EllipticCurvePublicKey).") + logger.error("The value passed as pk is not a public key (EllipticCurvePublicKey)") return False if isinstance(signature, str): diff --git a/pisa/block_processor.py b/pisa/block_processor.py index ff59d58..9eb0ee2 100644 --- a/pisa/block_processor.py +++ b/pisa/block_processor.py @@ -30,7 +30,7 @@ class BlockProcessor: except JSONRPCException as e: block = None - logger.error("Couldn't get block from bitcoind.", error=e.error) + logger.error("Couldn't get block from bitcoind", error=e.error) return block @@ -50,7 +50,7 @@ class BlockProcessor: except JSONRPCException as e: block_hash = None - logger.error("Couldn't get block hash.", error=e.error) + logger.error("Couldn't get block hash", error=e.error) return block_hash @@ -94,7 +94,7 @@ class BlockProcessor: except JSONRPCException as e: tx = None - logger.error("Can't build transaction from decoded data.", error=e.error) + logger.error("Can't build transaction from decoded data", error=e.error) return tx diff --git a/pisa/carrier.py b/pisa/carrier.py index 73326df..d4029d4 100644 --- a/pisa/carrier.py +++ b/pisa/carrier.py @@ -97,7 +97,7 @@ class Carrier: else: # If something else happens (unlikely but possible) log it so we can treat it in future releases - logger.error("JSONRPCException.", method="Carrier.send_transaction", error=e.error) + logger.error("JSONRPCException", method="Carrier.send_transaction", error=e.error) receipt = Receipt(delivered=False, reason=UNKNOWN_JSON_RPC_EXCEPTION) return receipt @@ -129,6 +129,6 @@ class Carrier: else: # If something else happens (unlikely but possible) log it so we can treat it in future releases - logger.error("JSONRPCException.", method="Carrier.get_transaction", error=e.error) + logger.error("JSONRPCException", method="Carrier.get_transaction", error=e.error) return tx_info diff --git a/pisa/cleaner.py b/pisa/cleaner.py index f3506e2..a00cc22 100644 --- a/pisa/cleaner.py +++ b/pisa/cleaner.py @@ -37,7 +37,7 @@ class Cleaner: else: locator_uuid_map[locator].remove(uuid) - logger.info("End time reached with no breach. Deleting appointment.", locator=locator, uuid=uuid) + logger.info("End time reached with no breach. Deleting appointment", locator=locator, uuid=uuid) # Delete appointment from the db db_manager.delete_watcher_appointment(uuid) @@ -92,7 +92,7 @@ class Cleaner: for uuid, confirmations in completed_trackers: logger.info( - "Appointment completed. Appointment ended after reaching enough confirmations.", + "Appointment completed. Appointment ended after reaching enough confirmations", uuid=uuid, height=height, confirmations=confirmations, @@ -105,7 +105,7 @@ class Cleaner: if len(tx_tracker_map[penalty_txid]) == 1: tx_tracker_map.pop(penalty_txid) - logger.info("No more trackers for penalty transaction.", penalty_txid=penalty_txid) + logger.info("No more trackers for penalty transaction", penalty_txid=penalty_txid) else: tx_tracker_map[penalty_txid].remove(uuid) @@ -126,7 +126,7 @@ class Cleaner: db_manager.store_update_locator_map(locator, locator_map) else: - logger.error("UUID not found in the db.", uuid=uuid) + logger.error("UUID not found in the db", uuid=uuid) else: - logger.error("Locator not found in the db.", uuid=uuid) + logger.error("Locator not found in the db", uuid=uuid) diff --git a/pisa/responder.py b/pisa/responder.py index e1f3f1c..0fce1cb 100644 --- a/pisa/responder.py +++ b/pisa/responder.py @@ -211,7 +211,7 @@ class Responder: # TODO: Add the missing reasons (e.g. RPC_VERIFY_REJECTED) # TODO: Use self.on_sync(block_hash) to check whether or not we failed because we are out of sync logger.warning( - "Tracker cannot be created.", reason=receipt.reason, uuid=uuid, on_sync=self.on_sync(block_hash) + "Tracker cannot be created", reason=receipt.reason, uuid=uuid, on_sync=self.on_sync(block_hash) ) pass @@ -255,7 +255,7 @@ class Responder: self.db_manager.store_responder_tracker(uuid, tracker.to_json()) logger.info( - "New tracker added.", dispute_txid=dispute_txid, penalty_txid=penalty_txid, appointment_end=appointment_end + "New tracker added", dispute_txid=dispute_txid, penalty_txid=penalty_txid, appointment_end=appointment_end ) if self.asleep: @@ -436,7 +436,7 @@ class Responder: for uuid in self.tx_tracker_map[txid]: tracker = self.trackers[uuid] logger.warning( - "Transaction has missed many confirmations. Rebroadcasting.", penalty_txid=tracker.penalty_txid + "Transaction has missed many confirmations. Rebroadcasting", penalty_txid=tracker.penalty_txid ) receipt = carrier.send_transaction(tracker.penalty_rawtx, tracker.penalty_txid) @@ -444,7 +444,7 @@ class Responder: if not receipt.delivered: # FIXME: Can this actually happen? - logger.warning("Transaction failed.", penalty_txid=tracker.penalty_txid) + logger.warning("Transaction failed", penalty_txid=tracker.penalty_txid) return receipts @@ -475,7 +475,7 @@ class Responder: self.unconfirmed_txs.append(tracker.penalty_txid) logger.info( - "Penalty transaction back in mempool. Updating unconfirmed transactions.", + "Penalty transaction back in mempool. Updating unconfirmed transactions", penalty_txid=tracker.penalty_txid, ) @@ -502,5 +502,5 @@ class Responder: # ToDo: #24-properly-handle-reorgs # FIXME: if the dispute is not on chain (either in mempool or not there at all), we need to call the # reorg manager - logger.warning("Dispute and penalty transaction missing. Calling the reorg manager.") - logger.error("Reorg manager not yet implemented.") + logger.warning("Dispute and penalty transaction missing. Calling the reorg manager") + logger.error("Reorg manager not yet implemented") diff --git a/pisa/watcher.py b/pisa/watcher.py index 19d160d..5079050 100644 --- a/pisa/watcher.py +++ b/pisa/watcher.py @@ -139,7 +139,7 @@ class Watcher: appointment_added = True - logger.info("New appointment accepted.", locator=appointment.locator) + logger.info("New appointment accepted", locator=appointment.locator) signature = Cryptographer.sign(Cryptographer.signature_format(appointment.to_dict()), self.signing_key) @@ -147,7 +147,7 @@ class Watcher: appointment_added = False signature = None - logger.info("Maximum appointments reached, appointment rejected.", locator=appointment.locator) + logger.info("Maximum appointments reached, appointment rejected", locator=appointment.locator) return appointment_added, signature @@ -177,7 +177,7 @@ class Watcher: if block is not None: txids = block.get("tx") - logger.info("List of transactions.", txids=txids) + logger.info("List of transactions", txids=txids) expired_appointments = [ uuid @@ -195,7 +195,7 @@ class Watcher: # Errors decrypting the Blob will result in a None penalty_txid if filtered_breach["valid_breach"] is True: logger.info( - "Notifying responder and deleting appointment.", + "Notifying responder and deleting appointment", penalty_txid=filtered_breach["penalty_txid"], locator=filtered_breach["locator"], uuid=uuid, @@ -287,7 +287,7 @@ class Watcher: penalty_txid = penalty_tx.get("txid") valid_breach = True - logger.info("Breach found for locator.", locator=locator, uuid=uuid, penalty_txid=penalty_txid) + logger.info("Breach found for locator", locator=locator, uuid=uuid, penalty_txid=penalty_txid) else: penalty_txid = None