Fixes logs and removes redundant tailing dots

This commit is contained in:
Sergi Delgado Segura
2019-12-16 19:45:30 +01:00
parent a9df67d787
commit 1184b4648a
7 changed files with 68 additions and 62 deletions

View File

@@ -3,6 +3,7 @@ import sys
import json import json
import requests import requests
import time import time
import binascii
from sys import argv from sys import argv
from getopt import getopt, GetoptError from getopt import getopt, GetoptError
from requests import ConnectTimeout, ConnectionError from requests import ConnectTimeout, ConnectionError
@@ -84,7 +85,7 @@ def save_signed_appointment(appointment, signature):
def add_appointment(args): def add_appointment(args):
appointment_data = None 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: if not args:
logger.error("No appointment data provided. " + use_help) logger.error("No appointment data provided. " + use_help)
@@ -99,7 +100,7 @@ def add_appointment(args):
if arg_opt in ["-f", "--file"]: if arg_opt in ["-f", "--file"]:
fin = args.pop(0) fin = args.pop(0)
if not os.path.isfile(fin): if not os.path.isfile(fin):
logger.error("Can't find file " + fin) logger.error("Can't find file", filename=fin)
return False return False
try: try:
@@ -107,7 +108,7 @@ def add_appointment(args):
appointment_data = json.load(f) appointment_data = json.load(f)
except IOError as e: 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 return False
else: else:
appointment_data = json.loads(arg_opt) appointment_data = json.loads(arg_opt)
@@ -117,13 +118,13 @@ def add_appointment(args):
return False return False
if not appointment_data: if not appointment_data:
logger.error("The provided JSON is empty.") logger.error("The provided JSON is empty")
return False return False
valid_locator = check_sha256_hex_format(appointment_data.get("tx_id")) valid_locator = check_sha256_hex_format(appointment_data.get("tx_id"))
if not valid_locator: if not valid_locator:
logger.error("The provided locator is not valid.") logger.error("The provided locator is not valid")
return False return False
add_appointment_endpoint = "http://{}:{}".format(pisa_api_server, pisa_api_port) 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) cli_sk = Cryptographer.load_private_key_der(sk_der)
except ValueError: 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 return False
except FileNotFoundError: 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 return False
except IOError as e: 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 return False
signature = Cryptographer.sign(Cryptographer.signature_format(appointment), cli_sk) signature = Cryptographer.sign(Cryptographer.signature_format(appointment), cli_sk)
try: try:
cli_pk_der = load_key_file_data(CLI_PUBLIC_KEY) cli_pk_der = load_key_file_data(CLI_PUBLIC_KEY)
hex_pk_der = binascii.hexlify(cli_pk_der)
except FileNotFoundError: 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 return False
except IOError as e: 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 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=(",", ":")) appointment_json = json.dumps(data, sort_keys=True, separators=(",", ":"))
@@ -176,29 +180,31 @@ def add_appointment(args):
response_json = r.json() response_json = r.json()
except json.JSONDecodeError: except json.JSONDecodeError:
logger.error("The response was not valid JSON.") logger.error("The response was not valid JSON")
return False return False
except ConnectTimeout: except ConnectTimeout:
logger.error("Can't connect to pisa API. Connection timeout.") logger.error("Can't connect to pisa API. Connection timeout")
return False return False
except ConnectionError: 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 False
if r.status_code != HTTP_OK: if r.status_code != HTTP_OK:
if "error" not in response_json: 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: else:
error = response_json["error"] error = response_json["error"]
logger.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 return False
if "signature" not in response_json: 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 return False
signature = response_json["signature"] signature = response_json["signature"]
@@ -208,30 +214,30 @@ def add_appointment(args):
pisa_pk = Cryptographer.load_public_key_der(pisa_pk_der) pisa_pk = Cryptographer.load_public_key_der(pisa_pk_der)
if pisa_pk is None: 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 return False
is_sig_valid = Cryptographer.verify(Cryptographer.signature_format(appointment), signature, pisa_pk) is_sig_valid = Cryptographer.verify(Cryptographer.signature_format(appointment), signature, pisa_pk)
except FileNotFoundError: 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 return False
except IOError as e: 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 return False
if not is_sig_valid: 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 return False
logger.info("Appointment accepted and signed by Pisa.") logger.info("Appointment accepted and signed by Pisa")
# all good, store appointment and signature # all good, store appointment and signature
try: try:
save_signed_appointment(appointment, signature) save_signed_appointment(appointment, signature)
except OSError as e: 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 False
return True return True
@@ -239,7 +245,7 @@ def add_appointment(args):
def get_appointment(args): def get_appointment(args):
if not args: if not args:
logger.error("No arguments were given.") logger.error("No arguments were given")
return False return False
arg_opt = args.pop(0) arg_opt = args.pop(0)
@@ -251,7 +257,7 @@ def get_appointment(args):
valid_locator = check_sha256_hex_format(locator) valid_locator = check_sha256_hex_format(locator)
if not valid_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 return False
get_appointment_endpoint = "http://{}:{}/get_appointment".format(pisa_api_server, pisa_api_port) 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)) print(json.dumps(r.json(), indent=4, sort_keys=True))
except ConnectTimeout: except ConnectTimeout:
logger.error("Can't connect to pisa API. Connection timeout.") logger.error("Can't connect to pisa API. Connection timeout")
return False return False
except ConnectionError: 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 False
return True return True
@@ -363,10 +369,10 @@ if __name__ == "__main__":
logger.error("Unknown command. Use help to check the list of available commands") logger.error("Unknown command. Use help to check the list of available commands")
else: 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: except GetoptError as e:
logger.error("{}".format(e)) logger.error("{}".format(e))
except json.JSONDecodeError as e: except json.JSONDecodeError as e:
logger.error("Non-JSON encoded appointment passed as parameter.") logger.error("Non-JSON encoded appointment passed as parameter")

View File

@@ -39,12 +39,12 @@ class Cryptographer:
""" """
if len(data) % 2: if len(data) % 2:
error = "Incorrect (Odd-length) value." error = "Incorrect (Odd-length) value"
logger.error(error, data=data) logger.error(error, data=data)
raise ValueError(error) raise ValueError(error)
if not check_sha256_hex_format(secret): 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) logger.error(error, secret=secret)
raise ValueError(error) raise ValueError(error)
@@ -82,7 +82,7 @@ class Cryptographer:
sk = sha256(unhexlify(secret)).digest() sk = sha256(unhexlify(secret)).digest()
nonce = bytearray(12) 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 # Encrypt the data
cipher = ChaCha20Poly1305(sk) cipher = ChaCha20Poly1305(sk)
@@ -124,7 +124,7 @@ class Cryptographer:
nonce = bytearray(12) nonce = bytearray(12)
logger.info( logger.info(
"Decrypting Blob.", "Decrypting Blob",
sk=hexlify(sk).decode(), sk=hexlify(sk).decode(),
nonce=hexlify(nonce).decode(), nonce=hexlify(nonce).decode(),
encrypted_blob=encrypted_blob.data, encrypted_blob=encrypted_blob.data,
@@ -185,13 +185,13 @@ class Cryptographer:
return pk return pk
except UnsupportedAlgorithm: except UnsupportedAlgorithm:
logger.error("Could not deserialize the public key (unsupported algorithm).") logger.error("Could not deserialize the public key (unsupported algorithm)")
except ValueError: 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: except TypeError:
logger.error("The provided data cannot be deserialized (wrong type).") logger.error("The provided data cannot be deserialized (wrong type)")
return None return None
@@ -220,10 +220,10 @@ class Cryptographer:
raise ValueError("Could not deserialize the private key (unsupported algorithm).") raise ValueError("Could not deserialize the private key (unsupported algorithm).")
except ValueError: 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: except TypeError:
logger.error("The provided data cannot be deserialized (wrong type).") logger.error("The provided data cannot be deserialized (wrong type)")
@staticmethod @staticmethod
def sign(data, sk, rtype="str"): def sign(data, sk, rtype="str"):
@@ -246,7 +246,7 @@ class Cryptographer:
raise ValueError("Wrong return type. Return type must be 'str' or 'bytes'") raise ValueError("Wrong return type. Return type must be 'str' or 'bytes'")
if not isinstance(sk, ec.EllipticCurvePrivateKey): 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 return None
else: else:
@@ -274,7 +274,7 @@ class Cryptographer:
""" """
if not isinstance(pk, ec.EllipticCurvePublicKey): 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 return False
if isinstance(signature, str): if isinstance(signature, str):

View File

@@ -30,7 +30,7 @@ class BlockProcessor:
except JSONRPCException as e: except JSONRPCException as e:
block = None 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 return block
@@ -50,7 +50,7 @@ class BlockProcessor:
except JSONRPCException as e: except JSONRPCException as e:
block_hash = None 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 return block_hash
@@ -94,7 +94,7 @@ class BlockProcessor:
except JSONRPCException as e: except JSONRPCException as e:
tx = None 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 return tx

View File

@@ -97,7 +97,7 @@ class Carrier:
else: else:
# If something else happens (unlikely but possible) log it so we can treat it in future releases # 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) receipt = Receipt(delivered=False, reason=UNKNOWN_JSON_RPC_EXCEPTION)
return receipt return receipt
@@ -129,6 +129,6 @@ class Carrier:
else: else:
# If something else happens (unlikely but possible) log it so we can treat it in future releases # 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 return tx_info

View File

@@ -37,7 +37,7 @@ class Cleaner:
else: else:
locator_uuid_map[locator].remove(uuid) 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 # Delete appointment from the db
db_manager.delete_watcher_appointment(uuid) db_manager.delete_watcher_appointment(uuid)
@@ -92,7 +92,7 @@ class Cleaner:
for uuid, confirmations in completed_trackers: for uuid, confirmations in completed_trackers:
logger.info( logger.info(
"Appointment completed. Appointment ended after reaching enough confirmations.", "Appointment completed. Appointment ended after reaching enough confirmations",
uuid=uuid, uuid=uuid,
height=height, height=height,
confirmations=confirmations, confirmations=confirmations,
@@ -105,7 +105,7 @@ class Cleaner:
if len(tx_tracker_map[penalty_txid]) == 1: if len(tx_tracker_map[penalty_txid]) == 1:
tx_tracker_map.pop(penalty_txid) 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: else:
tx_tracker_map[penalty_txid].remove(uuid) tx_tracker_map[penalty_txid].remove(uuid)
@@ -126,7 +126,7 @@ class Cleaner:
db_manager.store_update_locator_map(locator, locator_map) db_manager.store_update_locator_map(locator, locator_map)
else: else:
logger.error("UUID not found in the db.", uuid=uuid) logger.error("UUID not found in the db", uuid=uuid)
else: else:
logger.error("Locator not found in the db.", uuid=uuid) logger.error("Locator not found in the db", uuid=uuid)

View File

@@ -211,7 +211,7 @@ class Responder:
# TODO: Add the missing reasons (e.g. RPC_VERIFY_REJECTED) # 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 # TODO: Use self.on_sync(block_hash) to check whether or not we failed because we are out of sync
logger.warning( 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 pass
@@ -255,7 +255,7 @@ class Responder:
self.db_manager.store_responder_tracker(uuid, tracker.to_json()) self.db_manager.store_responder_tracker(uuid, tracker.to_json())
logger.info( 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: if self.asleep:
@@ -436,7 +436,7 @@ class Responder:
for uuid in self.tx_tracker_map[txid]: for uuid in self.tx_tracker_map[txid]:
tracker = self.trackers[uuid] tracker = self.trackers[uuid]
logger.warning( 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) receipt = carrier.send_transaction(tracker.penalty_rawtx, tracker.penalty_txid)
@@ -444,7 +444,7 @@ class Responder:
if not receipt.delivered: if not receipt.delivered:
# FIXME: Can this actually happen? # 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 return receipts
@@ -475,7 +475,7 @@ class Responder:
self.unconfirmed_txs.append(tracker.penalty_txid) self.unconfirmed_txs.append(tracker.penalty_txid)
logger.info( logger.info(
"Penalty transaction back in mempool. Updating unconfirmed transactions.", "Penalty transaction back in mempool. Updating unconfirmed transactions",
penalty_txid=tracker.penalty_txid, penalty_txid=tracker.penalty_txid,
) )
@@ -502,5 +502,5 @@ class Responder:
# ToDo: #24-properly-handle-reorgs # 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 # FIXME: if the dispute is not on chain (either in mempool or not there at all), we need to call the
# reorg manager # reorg manager
logger.warning("Dispute and penalty transaction missing. Calling the reorg manager.") logger.warning("Dispute and penalty transaction missing. Calling the reorg manager")
logger.error("Reorg manager not yet implemented.") logger.error("Reorg manager not yet implemented")

View File

@@ -139,7 +139,7 @@ class Watcher:
appointment_added = True 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) signature = Cryptographer.sign(Cryptographer.signature_format(appointment.to_dict()), self.signing_key)
@@ -147,7 +147,7 @@ class Watcher:
appointment_added = False appointment_added = False
signature = None 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 return appointment_added, signature
@@ -177,7 +177,7 @@ class Watcher:
if block is not None: if block is not None:
txids = block.get("tx") txids = block.get("tx")
logger.info("List of transactions.", txids=txids) logger.info("List of transactions", txids=txids)
expired_appointments = [ expired_appointments = [
uuid uuid
@@ -195,7 +195,7 @@ class Watcher:
# Errors decrypting the Blob will result in a None penalty_txid # Errors decrypting the Blob will result in a None penalty_txid
if filtered_breach["valid_breach"] is True: if filtered_breach["valid_breach"] is True:
logger.info( logger.info(
"Notifying responder and deleting appointment.", "Notifying responder and deleting appointment",
penalty_txid=filtered_breach["penalty_txid"], penalty_txid=filtered_breach["penalty_txid"],
locator=filtered_breach["locator"], locator=filtered_breach["locator"],
uuid=uuid, uuid=uuid,
@@ -287,7 +287,7 @@ class Watcher:
penalty_txid = penalty_tx.get("txid") penalty_txid = penalty_tx.get("txid")
valid_breach = True 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: else:
penalty_txid = None penalty_txid = None