diff --git a/cli/__init__.py b/cli/__init__.py index 5e3f3ac3..62764df9 100644 --- a/cli/__init__.py +++ b/cli/__init__.py @@ -2,7 +2,6 @@ DATA_DIR = os.path.expanduser("~/.teos_cli/") CONF_FILE_NAME = "teos_cli.conf" -LOG_PREFIX = "cli" # Load config fields DEFAULT_CONF = { diff --git a/cli/requirements.txt b/cli/requirements.txt index d75395b4..59eec448 100644 --- a/cli/requirements.txt +++ b/cli/requirements.txt @@ -1,2 +1,3 @@ cryptography requests +structlog diff --git a/cli/teos_cli.py b/cli/teos_cli.py index 33437690..a7f796be 100644 --- a/cli/teos_cli.py +++ b/cli/teos_cli.py @@ -11,20 +11,20 @@ from requests.exceptions import MissingSchema, InvalidSchema, InvalidURL from cli.exceptions import TowerResponseError -from cli import DEFAULT_CONF, DATA_DIR, CONF_FILE_NAME, LOG_PREFIX +from cli import DEFAULT_CONF, DATA_DIR, CONF_FILE_NAME from cli.help import show_usage, help_add_appointment, help_get_appointment, help_register, help_get_all_appointments from common import constants -from common.logger import Logger +from common.logger import get_logger, setup_logging import common.receipts as receipts from common.appointment import Appointment from common.config_loader import ConfigLoader from common.cryptographer import Cryptographer -from common.tools import setup_logging, setup_data_folder +from common.tools import setup_data_folder from common.exceptions import InvalidKey, InvalidParameter, SignatureError from common.tools import is_256b_hex_str, is_locator, compute_locator, is_compressed_pk -logger = Logger(actor="Client", log_name_prefix=LOG_PREFIX) +logger = get_logger(component="Client") def register(user_id, teos_id, teos_url): @@ -426,7 +426,7 @@ def main(command, args, command_line_conf): config = config_loader.build_config() setup_data_folder(DATA_DIR) - setup_logging(config.get("LOG_FILE"), LOG_PREFIX) + setup_logging(config.get("LOG_FILE")) # Set the teos url teos_url = "{}:{}".format(config.get("API_CONNECT"), config.get("API_PORT")) diff --git a/common/logger.py b/common/logger.py index 791a0ed0..089a40d4 100644 --- a/common/logger.py +++ b/common/logger.py @@ -1,96 +1,123 @@ -import json import logging -from datetime import datetime +import logging.config +from io import StringIO +import structlog +configured = False # set to True once setup_logging is called -class _StructuredMessage: - def __init__(self, message, **kwargs): - self.message = message - self.time = datetime.now().strftime("%d/%m/%Y %H:%M:%S") - self.kwargs = kwargs +timestamper = structlog.processors.TimeStamper(fmt="%d/%m/%Y %H:%M:%S") +pre_chain = [timestamper] - def to_dict(self): - return {**self.kwargs, "message": self.message, "time": self.time} - -class Logger: +# Stripped down version of structlog.dev.ConsoleRenderer, adding the "component" instead of the level. +class CustomLogRenderer: """ - The :class:`Logger` is in charge of logging events into the log file. - - Args: - log_name_prefix (:obj:`str`): the prefix of the logger where the data will be stored in (server, client, ...). - actor (:obj:`str`): the system actor that is logging the event (e.g. ``Watcher``, ``Cryptographer``, ...). + Render ``event_dict``. It renders the timestamp, followed by the component within "[]" (unless it's None), + followed by the event, then any remaining item in ``event_dict`` in the key=value format. """ - def __init__(self, log_name_prefix, actor=None): - self.actor = actor - self.f_logger = logging.getLogger("{}_file_log".format(log_name_prefix)) - self.c_logger = logging.getLogger("{}_console_log".format(log_name_prefix)) - - def _add_prefix(self, msg): - return msg if self.actor is None else "[{}]: {}".format(self.actor, msg) - - def _create_console_message(self, msg, **kwargs): - s_message = _StructuredMessage(self._add_prefix(msg), **kwargs).to_dict() - message = "{} {}".format(s_message["time"], s_message["message"]) - - # s_message will always have at least two items (message and time). - if len(s_message) > 2: - params = "".join("{}={}, ".format(k, v) for k, v in s_message.items() if k not in ["message", "time"]) - - # Remove the extra 2 characters (space and comma) and add all data to the final message. - message += " ({})".format(params[:-2]) + def _repr(self, val): + """Returns the representation of *val* if it's not a ``str``.""" + return val if isinstance(val, str) else repr(val) - return message + def __call__(self, _, __, event_dict): + """Returns ``event_dict`` rendered as a string.""" + sio = StringIO() - @staticmethod - def _create_file_message(msg, **kwargs): - return json.dumps(_StructuredMessage(msg, **kwargs).to_dict()) + ts = event_dict.pop("timestamp", None) + if ts: + sio.write(str(ts) + " ") - def info(self, msg, **kwargs): - """ - Logs an ``INFO`` level message to stdout and file. + component = event_dict.pop("component", None) + if component: + sio.write("[" + component + "] ") - Args: - msg (:obj:`str`): the message to be logged. - kwargs (:obj:`dict`): a ``key:value`` collection parameters to be added to the output. - """ + event = self._repr(event_dict.pop("event")) - self.f_logger.info(self._create_file_message(msg, **kwargs)) - self.c_logger.info(self._create_console_message(msg, **kwargs)) + sio.write(event) - def debug(self, msg, **kwargs): - """ - Logs a ``DEBUG`` level message to stdout and file. + # Represent all the key=value elements still in event_dict + key_value_part = ", ".join(key + "=" + self._repr(event_dict[key]) for key in sorted(event_dict.keys())) + if len(key_value_part) > 0: + sio.write(" (" + key_value_part + ")") - Args: - msg (:obj:`str`): the message to be logged. - kwargs (:obj:`dict`): a ``key:value`` collection parameters to be added to the output. - """ + return sio.getvalue() - self.f_logger.debug(self._create_file_message(msg, **kwargs)) - self.c_logger.debug(self._create_console_message(msg, **kwargs)) - def error(self, msg, **kwargs): - """ - Logs an ``ERROR`` level message to stdout and file. +def setup_logging(log_file_path, silent=False): + """ + Configures the logging options. It must be called only once, before using get_logger. - Args: - msg (:obj:`str`): the message to be logged. - kwargs (:obj:`dict`): a ``key:value`` collection parameters to be added to the output. - """ + Args: + log_file_path (:obj:`str`): the path and name of the log file. + silent (:obj:`str`): if True, only critical errors will be shown to console. - self.f_logger.error(self._create_file_message(msg, **kwargs)) - self.c_logger.error(self._create_console_message(msg, **kwargs)) + Raises: + :obj:`RuntimeError` setup_logger had already been called. + """ - def warning(self, msg, **kwargs): - """ - Logs a ``WARNING`` level message to stdout and file. + global configured + + if configured: + raise RuntimeError("Logging was already configured") + + logging.config.dictConfig( + { + "version": 1, + "disable_existing_loggers": False, + "formatters": { + "plain": { + "()": structlog.stdlib.ProcessorFormatter, + "processor": CustomLogRenderer(), + "foreign_pre_chain": pre_chain, + } + }, + "filters": { # filter out logs that do not come from teos + "onlyteos": {"()": logging.Filter, "name": "teos"} + }, + "handlers": { + "console": { + "level": "INFO" if not silent else "CRITICAL", + "class": "logging.StreamHandler", + "formatter": "plain", + "filters": ["onlyteos"], + }, + "file": { + "level": "DEBUG", + "class": "logging.handlers.WatchedFileHandler", + "filename": log_file_path, + "formatter": "plain", + "filters": ["onlyteos"], + }, + }, + "loggers": {"": {"handlers": ["console", "file"], "level": "DEBUG", "propagate": True}}, + } + ) + + structlog.configure( + processors=[ + structlog.stdlib.PositionalArgumentsFormatter(), + timestamper, + structlog.stdlib.ProcessorFormatter.wrap_for_formatter, + ], + context_class=dict, + logger_factory=structlog.stdlib.LoggerFactory(), + wrapper_class=structlog.stdlib.BoundLogger, + cache_logger_on_first_use=True, + ) + + configured = True + + +def get_logger(component=None): + """ + Returns a logger, that has the given `component` in all future log entries. - Args: - msg (:obj:`str`): the message to be logged. - kwargs (:obj:`dict`): a ``key:value`` collection parameters to be added to the output. - """ + Returns: + a proxy obtained from structlog.get_logger with the `component` as bound variable. - self.f_logger.warning(self._create_file_message(msg, **kwargs)) - self.c_logger.warning(self._create_console_message(msg, **kwargs)) + Args: + component(:obj:`str`): the value of the "component" field that will be attached to all the logs issued by this + logger. + """ + return structlog.get_logger("teos", component=component) diff --git a/common/tools.py b/common/tools.py index 874e6398..fa597d67 100644 --- a/common/tools.py +++ b/common/tools.py @@ -78,45 +78,3 @@ def setup_data_folder(data_folder): """ Path(data_folder).mkdir(parents=True, exist_ok=True) - - -def setup_logging(log_file_path, log_name_prefix): - """ - Setups a couple of loggers (console and file) given a prefix and a file path. - - The log names are: - - prefix | _file_log - prefix | _console_log - - Args: - log_file_path (:obj:`str`): the path of the file to output the file log. - log_name_prefix (:obj:`str`): the prefix to identify the log. - """ - - if not isinstance(log_file_path, str): - print(log_file_path) - raise ValueError("Wrong log file path") - - if not isinstance(log_name_prefix, str): - raise ValueError("Wrong log file name") - - # Create the file logger - f_logger = logging.getLogger("{}_file_log".format(log_name_prefix)) - f_logger.setLevel(logging.DEBUG) - - fh = logging.FileHandler(log_file_path) - fh.setLevel(logging.DEBUG) - fh_formatter = logging.Formatter("%(message)s") - fh.setFormatter(fh_formatter) - f_logger.addHandler(fh) - - # Create the console logger - c_logger = logging.getLogger("{}_console_log".format(log_name_prefix)) - c_logger.setLevel(logging.INFO) - - ch = logging.StreamHandler() - ch.setLevel(logging.INFO) - ch_formatter = logging.Formatter("%(message)s.", "%Y-%m-%d %H:%M:%S") - ch.setFormatter(ch_formatter) - c_logger.addHandler(ch) diff --git a/requirements.txt b/requirements.txt index 7661105d..9a0def7a 100644 --- a/requirements.txt +++ b/requirements.txt @@ -6,4 +6,5 @@ coincurve pyzbase32 requests plyvel -readerwriterlock \ No newline at end of file +readerwriterlock +structlog \ No newline at end of file diff --git a/teos/__init__.py b/teos/__init__.py index 6c2943c5..c801c1ad 100644 --- a/teos/__init__.py +++ b/teos/__init__.py @@ -3,7 +3,6 @@ DATA_DIR = os.path.expanduser("~/.teos/") CONF_FILE_NAME = "teos.conf" -LOG_PREFIX = "teos" # Default conf fields DEFAULT_CONF = { diff --git a/teos/api.py b/teos/api.py index efe2b5a8..a29f0204 100644 --- a/teos/api.py +++ b/teos/api.py @@ -2,13 +2,12 @@ import logging from flask import Flask, request, abort, jsonify -from teos import LOG_PREFIX import common.errors as errors from teos.inspector import InspectionFailed from teos.gatekeeper import NotEnoughSlots, AuthenticationFailure from teos.watcher import AppointmentLimitReached, AppointmentAlreadyTriggered, AppointmentNotFound -from common.logger import Logger +from common.logger import get_logger from common.appointment import Appointment from common.exceptions import InvalidParameter from common.constants import HTTP_OK, HTTP_BAD_REQUEST, HTTP_SERVICE_UNAVAILABLE, HTTP_NOT_FOUND @@ -16,7 +15,6 @@ # ToDo: #5-add-async-to-api app = Flask(__name__) -logger = Logger(actor="API", log_name_prefix=LOG_PREFIX) # NOTCOVERED: not sure how to monkey path this one. May be related to #77 @@ -72,9 +70,13 @@ class API: inspector (:obj:`Inspector `): an ``Inspector`` instance to check the correctness of the received appointment data. watcher (:obj:`Watcher `): a ``Watcher`` instance to pass the requests to. + + Attributes: + logger: the logger for this component. """ def __init__(self, host, port, inspector, watcher): + self.logger = get_logger(component=API.__name__) self.host = host self.port = port self.inspector = inspector @@ -110,14 +112,14 @@ def register(self): """ remote_addr = get_remote_addr() - logger.info("Received register request", from_addr="{}".format(remote_addr)) + self.logger.info("Received register request", from_addr="{}".format(remote_addr)) # Check that data type and content are correct. Abort otherwise. try: request_data = get_request_data_json(request) except InvalidParameter as e: - logger.info("Received invalid register request", from_addr="{}".format(remote_addr)) + self.logger.info("Received invalid register request", from_addr="{}".format(remote_addr)) return jsonify({"error": str(e), "error_code": errors.INVALID_REQUEST_FORMAT}), HTTP_BAD_REQUEST user_id = request_data.get("public_key") @@ -144,7 +146,7 @@ def register(self): "error_code": errors.REGISTRATION_WRONG_FIELD_FORMAT, } - logger.info("Sending response and disconnecting", from_addr="{}".format(remote_addr), response=response) + self.logger.info("Sending response and disconnecting", from_addr="{}".format(remote_addr), response=response) return jsonify(response), rcode @@ -164,7 +166,7 @@ def add_appointment(self): # Getting the real IP if the server is behind a reverse proxy remote_addr = get_remote_addr() - logger.info("Received add_appointment request", from_addr="{}".format(remote_addr)) + self.logger.info("Received add_appointment request", from_addr="{}".format(remote_addr)) # Check that data type and content are correct. Abort otherwise. try: @@ -200,7 +202,7 @@ def add_appointment(self): "error_code": errors.APPOINTMENT_ALREADY_TRIGGERED, } - logger.info("Sending response and disconnecting", from_addr="{}".format(remote_addr), response=response) + self.logger.info("Sending response and disconnecting", from_addr="{}".format(remote_addr), response=response) return jsonify(response), rcode def get_appointment(self): @@ -230,14 +232,14 @@ def get_appointment(self): request_data = get_request_data_json(request) except InvalidParameter as e: - logger.info("Received invalid get_appointment request", from_addr="{}".format(remote_addr)) + self.logger.info("Received invalid get_appointment request", from_addr="{}".format(remote_addr)) return jsonify({"error": str(e), "error_code": errors.INVALID_REQUEST_FORMAT}), HTTP_BAD_REQUEST locator = request_data.get("locator") try: self.inspector.check_locator(locator) - logger.info("Received get_appointment request", from_addr="{}".format(remote_addr), locator=locator) + self.logger.info("Received get_appointment request", from_addr="{}".format(remote_addr), locator=locator) appointment_data, status = self.watcher.get_appointment(locator, request_data.get("signature")) if status == "being_watched": @@ -283,9 +285,7 @@ def get_all_appointments(self): def start(self): """ This function starts the Flask server used to run the API """ - - # Setting Flask log to ERROR only so it does not mess with our logging. Also disabling flask initial messages - logging.getLogger("werkzeug").setLevel(logging.ERROR) + # Disable flask initial messages os.environ["WERKZEUG_RUN_MAIN"] = "true" app.run(host=self.host, port=self.port) diff --git a/teos/appointments_dbm.py b/teos/appointments_dbm.py index 2ad51f32..8c418016 100644 --- a/teos/appointments_dbm.py +++ b/teos/appointments_dbm.py @@ -1,13 +1,9 @@ import json import plyvel -from teos import LOG_PREFIX - -from common.logger import Logger +from common.logger import get_logger from common.db_manager import DBManager -logger = Logger(actor="AppointmentsDBM", log_name_prefix=LOG_PREFIX) - WATCHER_PREFIX = "w" WATCHER_LAST_BLOCK_KEY = "bw" RESPONDER_PREFIX = "r" @@ -37,18 +33,23 @@ class AppointmentsDBM(DBManager): Raises: :obj:`ValueError`: If the provided ``db_path`` is not a string. :obj:`plyvel.Error`: If the db is currently unavailable (being used by another process). + + Attributes: + logger: the logger for this component. """ def __init__(self, db_path): if not isinstance(db_path, str): raise ValueError("db_path must be a valid path/name") + self.logger = get_logger(component=AppointmentsDBM.__name__) + try: super().__init__(db_path) except plyvel.Error as e: if "LOCK: Resource temporarily unavailable" in str(e): - logger.info("The db is already being used by another process (LOCK)") + self.logger.info("The db is already being used by another process (LOCK)") raise e @@ -185,15 +186,17 @@ def store_watcher_appointment(self, uuid, appointment): try: self.create_entry(uuid, json.dumps(appointment), prefix=WATCHER_PREFIX) - logger.info("Adding appointment to Watchers's db", uuid=uuid) + self.logger.info("Adding appointment to Watchers's db", uuid=uuid) return True except json.JSONDecodeError: - logger.info("Could't add appointment to db. Wrong appointment format.", uuid=uuid, appoinent=appointment) + self.logger.info( + "Could't add appointment to db. Wrong appointment format.", uuid=uuid, appoinent=appointment + ) return False except TypeError: - logger.info("Could't add appointment to db.", uuid=uuid, appoinent=appointment) + self.logger.info("Could't add appointment to db.", uuid=uuid, appoinent=appointment) return False def store_responder_tracker(self, uuid, tracker): @@ -210,15 +213,15 @@ def store_responder_tracker(self, uuid, tracker): try: self.create_entry(uuid, json.dumps(tracker), prefix=RESPONDER_PREFIX) - logger.info("Adding tracker to Responder's db", uuid=uuid) + self.logger.info("Adding tracker to Responder's db", uuid=uuid) return True except json.JSONDecodeError: - logger.info("Could't add tracker to db. Wrong tracker format.", uuid=uuid, tracker=tracker) + self.logger.info("Could't add tracker to db. Wrong tracker format.", uuid=uuid, tracker=tracker) return False except TypeError: - logger.info("Could't add tracker to db.", uuid=uuid, tracker=tracker) + self.logger.info("Could't add tracker to db.", uuid=uuid, tracker=tracker) return False def load_locator_map(self, locator): @@ -241,7 +244,7 @@ def load_locator_map(self, locator): locator_map = json.loads(locator_map.decode("utf-8")) else: - logger.info("Locator not found in the db", locator=locator) + self.logger.info("Locator not found in the db", locator=locator) return locator_map @@ -261,14 +264,14 @@ def create_append_locator_map(self, locator, uuid): if locator_map is not None: if uuid not in locator_map: locator_map.append(uuid) - logger.info("Updating locator map", locator=locator, uuid=uuid) + self.logger.info("Updating locator map", locator=locator, uuid=uuid) else: - logger.info("UUID already in the map", locator=locator, uuid=uuid) + self.logger.info("UUID already in the map", locator=locator, uuid=uuid) else: locator_map = [uuid] - logger.info("Creating new locator map", locator=locator, uuid=uuid) + self.logger.info("Creating new locator map", locator=locator, uuid=uuid) key = (LOCATOR_MAP_PREFIX + locator).encode("utf-8") self.db.put(key, json.dumps(locator_map).encode("utf-8")) @@ -290,7 +293,7 @@ def update_locator_map(self, locator, locator_map): self.db.put(key, json.dumps(locator_map).encode("utf-8")) else: - logger.error("Trying to update a locator_map with completely different, or empty, data") + self.logger.error("Trying to update a locator_map with completely different, or empty, data") def delete_locator_map(self, locator): """ @@ -305,11 +308,11 @@ def delete_locator_map(self, locator): try: self.delete_entry(locator, prefix=LOCATOR_MAP_PREFIX) - logger.info("Deleting locator map from db", locator=locator) + self.logger.info("Deleting locator map from db", locator=locator) return True except TypeError: - logger.info("Couldn't delete locator map from db, locator has wrong type", locator=locator) + self.logger.info("Couldn't delete locator map from db, locator has wrong type", locator=locator) return False def delete_watcher_appointment(self, uuid): @@ -325,11 +328,11 @@ def delete_watcher_appointment(self, uuid): try: self.delete_entry(uuid, prefix=WATCHER_PREFIX) - logger.info("Deleting appointment from Watcher's db", uuid=uuid) + self.logger.info("Deleting appointment from Watcher's db", uuid=uuid) return True except TypeError: - logger.info("Couldn't delete appointment from db, uuid has wrong type", uuid=uuid) + self.logger.info("Couldn't delete appointment from db, uuid has wrong type", uuid=uuid) return False def batch_delete_watcher_appointments(self, uuids): @@ -343,7 +346,7 @@ def batch_delete_watcher_appointments(self, uuids): with self.db.write_batch() as b: for uuid in uuids: b.delete((WATCHER_PREFIX + uuid).encode("utf-8")) - logger.info("Deleting appointment from Watcher's db", uuid=uuid) + self.logger.info("Deleting appointment from Watcher's db", uuid=uuid) def delete_responder_tracker(self, uuid): """ @@ -358,11 +361,11 @@ def delete_responder_tracker(self, uuid): try: self.delete_entry(uuid, prefix=RESPONDER_PREFIX) - logger.info("Deleting tracker from Responder's db", uuid=uuid) + self.logger.info("Deleting tracker from Responder's db", uuid=uuid) return True except TypeError: - logger.info("Couldn't delete tracker from db, uuid has wrong type", uuid=uuid) + self.logger.info("Couldn't delete tracker from db, uuid has wrong type", uuid=uuid) return False def batch_delete_responder_trackers(self, uuids): @@ -376,7 +379,7 @@ def batch_delete_responder_trackers(self, uuids): with self.db.write_batch() as b: for uuid in uuids: b.delete((RESPONDER_PREFIX + uuid).encode("utf-8")) - logger.info("Deleting appointment from Responder's db", uuid=uuid) + self.logger.info("Deleting appointment from Responder's db", uuid=uuid) def load_last_block_hash_watcher(self): """ @@ -445,7 +448,7 @@ def create_triggered_appointment_flag(self, uuid): """ self.db.put((TRIGGERED_APPOINTMENTS_PREFIX + uuid).encode("utf-8"), "".encode("utf-8")) - logger.info("Flagging appointment as triggered", uuid=uuid) + self.logger.info("Flagging appointment as triggered", uuid=uuid) def batch_create_triggered_appointment_flag(self, uuids): """ @@ -458,7 +461,7 @@ def batch_create_triggered_appointment_flag(self, uuids): with self.db.write_batch() as b: for uuid in uuids: b.put((TRIGGERED_APPOINTMENTS_PREFIX + uuid).encode("utf-8"), b"") - logger.info("Flagging appointment as triggered", uuid=uuid) + self.logger.info("Flagging appointment as triggered", uuid=uuid) def load_all_triggered_flags(self): """ @@ -486,11 +489,11 @@ def delete_triggered_appointment_flag(self, uuid): try: self.delete_entry(uuid, prefix=TRIGGERED_APPOINTMENTS_PREFIX) - logger.info("Removing triggered flag from appointment appointment", uuid=uuid) + self.logger.info("Removing triggered flag from appointment appointment", uuid=uuid) return True except TypeError: - logger.info("Couldn't delete triggered flag from db, uuid has wrong type", uuid=uuid) + self.logger.info("Couldn't delete triggered flag from db, uuid has wrong type", uuid=uuid) return False def batch_delete_triggered_appointment_flag(self, uuids): @@ -504,4 +507,4 @@ def batch_delete_triggered_appointment_flag(self, uuids): with self.db.write_batch() as b: for uuid in uuids: b.delete((TRIGGERED_APPOINTMENTS_PREFIX + uuid).encode("utf-8")) - logger.info("Removing triggered flag from appointment appointment", uuid=uuid) + self.logger.info("Removing triggered flag from appointment appointment", uuid=uuid) diff --git a/teos/block_processor.py b/teos/block_processor.py index 73b83708..78ce5c11 100644 --- a/teos/block_processor.py +++ b/teos/block_processor.py @@ -1,12 +1,9 @@ -from common.logger import Logger +from common.logger import get_logger from common.exceptions import BasicException -from teos import LOG_PREFIX from teos.tools import bitcoin_cli from teos.utils.auth_proxy import JSONRPCException -logger = Logger(actor="BlockProcessor", log_name_prefix=LOG_PREFIX) - class InvalidTransactionFormat(BasicException): """Raised when a transaction is not properly formatted""" @@ -20,9 +17,13 @@ class BlockProcessor: Args: btc_connect_params (:obj:`dict`): a dictionary with the parameters to connect to bitcoind (rpc user, rpc password, host and port) + + Attributes: + logger: the logger for this component. """ def __init__(self, btc_connect_params): + self.logger = get_logger(component=BlockProcessor.__name__) self.btc_connect_params = btc_connect_params def get_block(self, block_hash): @@ -43,7 +44,7 @@ def get_block(self, block_hash): except JSONRPCException as e: block = None - logger.error("Couldn't get block from bitcoind", error=e.error) + self.logger.error("Couldn't get block from bitcoind", error=e.error) return block @@ -62,7 +63,7 @@ def get_best_block_hash(self): except JSONRPCException as e: block_hash = None - logger.error("Couldn't get block hash", error=e.error) + self.logger.error("Couldn't get block hash", error=e.error) return block_hash @@ -81,7 +82,7 @@ def get_block_count(self): except JSONRPCException as e: block_count = None - logger.error("Couldn't get block count", error=e.error) + self.logger.error("Couldn't get block count", error=e.error) return block_count @@ -105,7 +106,7 @@ def decode_raw_transaction(self, raw_tx): except JSONRPCException as e: msg = "Cannot build transaction from decoded data" - logger.error(msg, error=e.error) + self.logger.error(msg, error=e.error) raise InvalidTransactionFormat(msg) return tx diff --git a/teos/carrier.py b/teos/carrier.py index 11b578f7..d9966d37 100644 --- a/teos/carrier.py +++ b/teos/carrier.py @@ -1,12 +1,9 @@ -from teos import LOG_PREFIX -from common.logger import Logger +from common.logger import get_logger from teos.tools import bitcoin_cli import teos.rpc_errors as rpc_errors from teos.utils.auth_proxy import JSONRPCException from common.errors import UNKNOWN_JSON_RPC_EXCEPTION, RPC_TX_REORGED_AFTER_BROADCAST -logger = Logger(actor="Carrier", log_name_prefix=LOG_PREFIX) - # FIXME: This class is not fully covered by unit tests @@ -44,12 +41,14 @@ class Carrier: (rpc user, rpc password, host and port) Attributes: + logger: the logger for this component. issued_receipts (:obj:`dict`): a dictionary of issued receipts to prevent resending the same transaction over and over. It should periodically be reset to prevent it from growing unbounded. """ def __init__(self, btc_connect_params): + self.logger = get_logger(component=Carrier.__name__) self.btc_connect_params = btc_connect_params self.issued_receipts = {} @@ -67,13 +66,13 @@ def send_transaction(self, rawtx, txid): """ if txid in self.issued_receipts: - logger.info("Transaction already sent", txid=txid) + self.logger.info("Transaction already sent", txid=txid) receipt = self.issued_receipts[txid] return receipt try: - logger.info("Pushing transaction to the network", txid=txid, rawtx=rawtx) + self.logger.info("Pushing transaction to the network", txid=txid, rawtx=rawtx) bitcoin_cli(self.btc_connect_params).sendrawtransaction(rawtx) receipt = Receipt(delivered=True) @@ -84,15 +83,15 @@ def send_transaction(self, rawtx, txid): if errno == rpc_errors.RPC_VERIFY_REJECTED: # DISCUSS: 37-transaction-rejection receipt = Receipt(delivered=False, reason=rpc_errors.RPC_VERIFY_REJECTED) - logger.error("Transaction couldn't be broadcast", error=e.error) + self.logger.error("Transaction couldn't be broadcast", error=e.error) elif errno == rpc_errors.RPC_VERIFY_ERROR: # DISCUSS: 37-transaction-rejection receipt = Receipt(delivered=False, reason=rpc_errors.RPC_VERIFY_ERROR) - logger.error("Transaction couldn't be broadcast", error=e.error) + self.logger.error("Transaction couldn't be broadcast", error=e.error) elif errno == rpc_errors.RPC_VERIFY_ALREADY_IN_CHAIN: - logger.info("Transaction is already in the blockchain. Getting confirmation count", txid=txid) + self.logger.info("Transaction is already in the blockchain. Getting confirmation count", txid=txid) # If the transaction is already in the chain, we get the number of confirmations and watch the tracker # until the end of the appointment @@ -114,12 +113,12 @@ def send_transaction(self, rawtx, txid): # Adding this here just for completeness. We should never end up here. The Carrier only sends txs # handed by the Responder, who receives them from the Watcher, who checks that the tx can be properly # deserialized - logger.info("Transaction cannot be deserialized".format(txid)) + self.logger.info("Transaction cannot be deserialized".format(txid)) receipt = Receipt(delivered=False, reason=rpc_errors.RPC_DESERIALIZATION_ERROR) 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) + self.logger.error("JSONRPCException", method="Carrier.send_transaction", error=e.error) receipt = Receipt(delivered=False, reason=UNKNOWN_JSON_RPC_EXCEPTION) self.issued_receipts[txid] = receipt @@ -147,10 +146,10 @@ def get_transaction(self, txid): # reorged while we were querying bitcoind to get the confirmation count. In that case we just restart # the tracker if e.error.get("code") == rpc_errors.RPC_INVALID_ADDRESS_OR_KEY: - logger.info("Transaction not found in mempool nor blockchain", txid=txid) + self.logger.info("Transaction not found in mempool nor blockchain", txid=txid) 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) + self.logger.error("JSONRPCException", method="Carrier.get_transaction", error=e.error) return None diff --git a/teos/chain_monitor.py b/teos/chain_monitor.py index e61dd31f..739015a9 100644 --- a/teos/chain_monitor.py +++ b/teos/chain_monitor.py @@ -2,10 +2,7 @@ import binascii from threading import Thread, Event, Condition -from teos import LOG_PREFIX -from common.logger import Logger - -logger = Logger(actor="ChainMonitor", log_name_prefix=LOG_PREFIX) +from common.logger import get_logger class ChainMonitor: @@ -24,6 +21,7 @@ class ChainMonitor: bitcoind_feed_params (:obj:`dict`): a dict with the feed (ZMQ) connection parameters. Attributes: + logger: the logger for this component. best_tip (:obj:`str`): a block hash representing the current best tip. last_tips (:obj:`list`): a list of last chain tips. Used as a sliding window to avoid notifying about old tips. terminate (:obj:`bool`): a flag to signal the termination of the :class:`ChainMonitor` (shutdown the tower). @@ -40,6 +38,7 @@ class ChainMonitor: """ def __init__(self, watcher_queue, responder_queue, block_processor, bitcoind_feed_params): + self.logger = get_logger(component=ChainMonitor.__name__) self.best_tip = None self.last_tips = [] self.terminate = False @@ -120,7 +119,7 @@ def monitor_chain_polling(self): self.lock.acquire() if self.update_state(current_tip): self.notify_subscribers(current_tip) - logger.info("New block received via polling", block_hash=current_tip) + self.logger.info("New block received via polling", block_hash=current_tip) self.lock.release() def monitor_chain_zmq(self): @@ -144,7 +143,7 @@ def monitor_chain_zmq(self): self.lock.acquire() if self.update_state(block_hash): self.notify_subscribers(block_hash) - logger.info("New block received via zmq", block_hash=block_hash) + self.logger.info("New block received via zmq", block_hash=block_hash) self.lock.release() def monitor_chain(self): diff --git a/teos/cleaner.py b/teos/cleaner.py index 938fcfde..a68a3b48 100644 --- a/teos/cleaner.py +++ b/teos/cleaner.py @@ -1,8 +1,4 @@ -from teos import LOG_PREFIX - -from common.logger import Logger - -logger = Logger(actor="Cleaner", log_name_prefix=LOG_PREFIX) +from common.logger import get_logger class Cleaner: @@ -12,6 +8,8 @@ class Cleaner: Mutable objects (like dicts) are passed-by-reference in Python, so no return is needed for the Cleaner. """ + logger = get_logger(component="Cleaner") + @staticmethod def delete_appointment_from_memory(uuid, appointments, locator_uuid_map): """ @@ -79,10 +77,10 @@ def update_delete_db_locator_map(uuids, locator, db_manager): db_manager.update_locator_map(locator, locator_map) else: - logger.error("Some UUIDs not found in the db", locator=locator, all_uuids=uuids) + Cleaner.logger.error("Some UUIDs not found in the db", locator=locator, all_uuids=uuids) else: - logger.error("Locator map not found in the db", locator=locator) + Cleaner.logger.error("Locator map not found in the db", locator=locator) @staticmethod def delete_expired_appointments(expired_appointments, appointments, locator_uuid_map, db_manager): @@ -104,7 +102,7 @@ def delete_expired_appointments(expired_appointments, appointments, locator_uuid for uuid in expired_appointments: locator = appointments[uuid].get("locator") - logger.info("End time reached with no breach. Deleting appointment", locator=locator, uuid=uuid) + Cleaner.logger.info("End time reached with no breach. Deleting appointment", locator=locator, uuid=uuid) Cleaner.delete_appointment_from_memory(uuid, appointments, locator_uuid_map) @@ -143,7 +141,7 @@ def delete_completed_appointments(completed_appointments, appointments, locator_ for uuid in completed_appointments: locator = appointments[uuid].get("locator") - logger.warning( + Cleaner.logger.warning( "Appointment cannot be completed, it contains invalid data. Deleting", locator=locator, uuid=uuid ) @@ -203,13 +201,13 @@ def delete_trackers(completed_trackers, height, trackers, tx_tracker_map, db_man for uuid in completed_trackers: if expired: - logger.info( + Cleaner.logger.info( "Appointment couldn't be completed. Expiry reached but penalty didn't make it to the chain", uuid=uuid, height=height, ) else: - logger.info( + Cleaner.logger.info( "Appointment completed. Penalty transaction was irrevocably confirmed", uuid=uuid, height=height ) @@ -220,7 +218,7 @@ def delete_trackers(completed_trackers, height, trackers, tx_tracker_map, db_man 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) + Cleaner.logger.info("No more trackers for penalty transaction", penalty_txid=penalty_txid) else: tx_tracker_map[penalty_txid].remove(uuid) diff --git a/teos/gatekeeper.py b/teos/gatekeeper.py index 10111ae5..a99ce37c 100644 --- a/teos/gatekeeper.py +++ b/teos/gatekeeper.py @@ -60,7 +60,7 @@ class Gatekeeper: expiry_delta (:obj:`int`): the grace period given to the user to renew their subscription. block_processor (:obj:`BlockProcessor `): a ``BlockProcessor`` instance to get block from bitcoind. - user_db (:obj:`UserDBM `): a ``UserDBM`` instance to interact with the database. + user_db (:obj:`UsersDBM `): a ``UsersDBM`` instance to interact with the database. registered_users (:obj:`dict`): a map of user_pk:UserInfo. lock (:obj:`Lock`): a Threading.Lock object to lock access to the Gatekeeper on updates. diff --git a/teos/inspector.py b/teos/inspector.py index d61d6c73..8353423e 100644 --- a/teos/inspector.py +++ b/teos/inspector.py @@ -1,15 +1,10 @@ import re -from common import errors -from common.logger import Logger from common.tools import is_locator from common.appointment import Appointment from common.constants import LOCATOR_LEN_HEX +import common.errors as errors -from teos import LOG_PREFIX - - -logger = Logger(actor="Inspector", log_name_prefix=LOG_PREFIX) # FIXME: The inspector logs the wrong messages sent form the users. A possible attack surface would be to send a really # long field that, even if not accepted by TEOS, would be stored in the logs. This is a possible DoS surface diff --git a/teos/responder.py b/teos/responder.py index 39533525..cf03f267 100644 --- a/teos/responder.py +++ b/teos/responder.py @@ -1,17 +1,14 @@ from queue import Queue from threading import Thread -from teos import LOG_PREFIX from teos.cleaner import Cleaner -from common.logger import Logger +from common.logger import get_logger from common.constants import IRREVOCABLY_RESOLVED CONFIRMATIONS_BEFORE_RETRY = 6 MIN_CONFIRMATIONS = 6 -logger = Logger(actor="Responder", log_name_prefix=LOG_PREFIX) - class TransactionTracker: """ @@ -114,6 +111,7 @@ class Responder: get data from bitcoind. Attributes: + logger: the logger for this component. trackers (:obj:`dict`): A dictionary containing the minimum information about the :obj:`TransactionTracker` required by the :obj:`Responder` (``penalty_txid``, ``locator`` and ``user_id``). Each entry is identified by a ``uuid``. @@ -135,6 +133,7 @@ class Responder: """ def __init__(self, db_manager, gatekeeper, carrier, block_processor): + self.logger = get_logger(component=Responder.__name__) self.trackers = dict() self.tx_tracker_map = dict() self.unconfirmed_txs = [] @@ -209,7 +208,7 @@ def handle_breach(self, uuid, locator, dispute_txid, penalty_txid, penalty_rawtx else: # 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( + self.logger.warning( "Tracker cannot be created", reason=receipt.reason, uuid=uuid, on_sync=self.on_sync(block_hash) ) @@ -250,7 +249,7 @@ def add_tracker(self, uuid, locator, dispute_txid, penalty_txid, penalty_rawtx, self.db_manager.store_responder_tracker(uuid, tracker.to_dict()) - logger.info("New tracker added", dispute_txid=dispute_txid, penalty_txid=penalty_txid, user_id=user_id) + self.logger.info("New tracker added", dispute_txid=dispute_txid, penalty_txid=penalty_txid, user_id=user_id) def do_watch(self): """ @@ -268,7 +267,9 @@ def do_watch(self): while True: block_hash = self.block_queue.get() block = self.block_processor.get_block(block_hash) - logger.info("New block received", block_hash=block_hash, prev_block_hash=block.get("previousblockhash")) + self.logger.info( + "New block received", block_hash=block_hash, prev_block_hash=block.get("previousblockhash") + ) if len(self.trackers) > 0 and block is not None: txids = block.get("tx") @@ -298,7 +299,7 @@ def do_watch(self): # NOTCOVERED else: - logger.warning( + self.logger.warning( "Reorg found", local_prev_block_hash=self.last_known_block, remote_prev_block_hash=block.get("previousblockhash"), @@ -311,7 +312,7 @@ def do_watch(self): self.carrier.issued_receipts = {} if len(self.trackers) == 0: - logger.info("No more pending trackers") + self.logger.info("No more pending trackers") # Register the last processed block for the responder self.db_manager.store_last_block_hash_responder(block_hash) @@ -334,7 +335,7 @@ def check_confirmations(self, txs): if tx in self.tx_tracker_map and tx in self.unconfirmed_txs: self.unconfirmed_txs.remove(tx) - logger.info("Confirmation received for transaction", tx=tx) + self.logger.info("Confirmation received for transaction", tx=tx) # We also add a missing confirmation to all those txs waiting to be confirmed that have not been confirmed in # the current block @@ -344,7 +345,9 @@ def check_confirmations(self, txs): else: self.missed_confirmations[tx] = 1 - logger.info("Transaction missed a confirmation", tx=tx, missed_confirmations=self.missed_confirmations[tx]) + self.logger.info( + "Transaction missed a confirmation", tx=tx, missed_confirmations=self.missed_confirmations[tx] + ) def get_txs_to_rebroadcast(self): """ @@ -445,7 +448,7 @@ def rebroadcast(self, txs_to_rebroadcast): # should we do it only once? for uuid in self.tx_tracker_map[txid]: tracker = TransactionTracker.from_dict(self.db_manager.load_responder_tracker(uuid)) - logger.warning( + self.logger.warning( "Transaction has missed many confirmations. Rebroadcasting", penalty_txid=tracker.penalty_txid ) @@ -454,7 +457,7 @@ def rebroadcast(self, txs_to_rebroadcast): if not receipt.delivered: # FIXME: Can this actually happen? - logger.warning("Transaction failed", penalty_txid=tracker.penalty_txid) + self.logger.warning("Transaction failed", penalty_txid=tracker.penalty_txid) return receipts @@ -486,7 +489,7 @@ def handle_reorgs(self, block_hash): if penalty_tx.get("confirmations") is None: self.unconfirmed_txs.append(tracker.penalty_txid) - logger.info( + self.logger.info( "Penalty transaction back in mempool. Updating unconfirmed transactions", penalty_txid=tracker.penalty_txid, ) @@ -503,7 +506,7 @@ def handle_reorgs(self, block_hash): block_hash, ) - logger.warning( + self.logger.warning( "Penalty transaction banished. Resetting the tracker", penalty_tx=tracker.penalty_txid ) @@ -511,5 +514,5 @@ def handle_reorgs(self, block_hash): # 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") + self.logger.warning("Dispute and penalty transaction missing. Calling the reorg manager") + self.logger.error("Reorg manager not yet implemented") diff --git a/teos/teosd.py b/teos/teosd.py index 4070ae7a..dd69dc0f 100644 --- a/teos/teosd.py +++ b/teos/teosd.py @@ -3,10 +3,10 @@ from getopt import getopt, GetoptError from signal import signal, SIGINT, SIGQUIT, SIGTERM -from common.logger import Logger +from common.logger import setup_logging, get_logger from common.config_loader import ConfigLoader from common.cryptographer import Cryptographer -from common.tools import setup_logging, setup_data_folder +from common.tools import setup_data_folder from teos.api import API from teos.help import show_usage @@ -20,10 +20,10 @@ from teos.chain_monitor import ChainMonitor from teos.block_processor import BlockProcessor from teos.appointments_dbm import AppointmentsDBM -from teos import LOG_PREFIX, DATA_DIR, DEFAULT_CONF, CONF_FILE_NAME +from teos import DATA_DIR, DEFAULT_CONF, CONF_FILE_NAME from teos.tools import can_connect_to_bitcoind, in_correct_network, get_default_rpc_port -logger = Logger(actor="Daemon", log_name_prefix=LOG_PREFIX) +logger = get_logger(component="Daemon") def handle_signals(signal_received, frame): @@ -53,7 +53,7 @@ def main(command_line_conf): config["BTC_RPC_PORT"] = get_default_rpc_port(config.get("BTC_NETWORK")) setup_data_folder(data_dir) - setup_logging(config.get("LOG_FILE"), LOG_PREFIX) + setup_logging(config.get("LOG_FILE")) logger.info("Starting TEOS") diff --git a/teos/users_dbm.py b/teos/users_dbm.py index b3b85e3a..6ad2d9d9 100644 --- a/teos/users_dbm.py +++ b/teos/users_dbm.py @@ -1,14 +1,10 @@ import json import plyvel -from teos import LOG_PREFIX - -from common.logger import Logger +from common.logger import get_logger from common.db_manager import DBManager from common.tools import is_compressed_pk -logger = Logger(actor="UsersDBM", log_name_prefix=LOG_PREFIX) - class UsersDBM(DBManager): """ @@ -22,9 +18,14 @@ class UsersDBM(DBManager): Raises: :obj:`ValueError`: If the provided ``db_path`` is not a string. :obj:`plyvel.Error`: If the db is currently unavailable (being used by another process). + + Attributes: + logger: the logger for this component. """ def __init__(self, db_path): + self.logger = get_logger(component=UsersDBM.__name__) + if not isinstance(db_path, str): raise ValueError("db_path must be a valid path/name") @@ -33,7 +34,7 @@ def __init__(self, db_path): except plyvel.Error as e: if "LOCK: Resource temporarily unavailable" in str(e): - logger.info("The db is already being used by another process (LOCK)") + self.logger.info("The db is already being used by another process (LOCK)") raise e @@ -52,18 +53,18 @@ def store_user(self, user_id, user_data): if is_compressed_pk(user_id): try: self.create_entry(user_id, json.dumps(user_data)) - logger.info("Adding user to Gatekeeper's db", user_id=user_id) + self.logger.info("Adding user to Gatekeeper's db", user_id=user_id) return True except json.JSONDecodeError: - logger.info("Could't add user to db. Wrong user data format", user_id=user_id, user_data=user_data) + self.logger.info("Could't add user to db. Wrong user data format", user_id=user_id, user_data=user_data) return False except TypeError: - logger.info("Could't add user to db", user_id=user_id, user_data=user_data) + self.logger.info("Could't add user to db", user_id=user_id, user_data=user_data) return False else: - logger.info("Could't add user to db. Wrong pk format", user_id=user_id, user_data=user_data) + self.logger.info("Could't add user to db. Wrong pk format", user_id=user_id, user_data=user_data) return False def load_user(self, user_id): @@ -101,11 +102,11 @@ def delete_user(self, user_id): try: self.delete_entry(user_id) - logger.info("Deleting user from Gatekeeper's db", uuid=user_id) + self.logger.info("Deleting user from Gatekeeper's db", uuid=user_id) return True except TypeError: - logger.info("Cannot delete user from db, user key has wrong type", uuid=user_id) + self.logger.info("Cannot delete user from db, user key has wrong type", uuid=user_id) return False def load_all_users(self): diff --git a/teos/watcher.py b/teos/watcher.py index 0fd37842..bc81bd87 100644 --- a/teos/watcher.py +++ b/teos/watcher.py @@ -3,7 +3,7 @@ from collections import OrderedDict from readerwriterlock import rwlock -from common.logger import Logger +from common.logger import get_logger import common.receipts as receipts from common.tools import compute_locator from common.exceptions import BasicException @@ -11,13 +11,10 @@ from common.cryptographer import Cryptographer, hash_160 from common.exceptions import InvalidParameter, SignatureError -from teos import LOG_PREFIX from teos.cleaner import Cleaner from teos.extended_appointment import ExtendedAppointment from teos.block_processor import InvalidTransactionFormat -logger = Logger(actor="Watcher", log_name_prefix=LOG_PREFIX) - class AppointmentLimitReached(BasicException): """Raised when the tower maximum appointment count has been reached""" @@ -41,6 +38,7 @@ class LocatorCache: blocks_in_cache (:obj:`int`): the numbers of blocks to keep in the cache. Attributes: + logger: the logger for this component. cache (:obj:`dict`): a dictionary of ``locator:dispute_txid`` pairs that received appointments are checked against. blocks (:obj:`OrderedDict`): An ordered dictionary of the last ``blocks_in_cache`` blocks (block_hash:locators). @@ -50,6 +48,7 @@ class LocatorCache: """ def __init__(self, blocks_in_cache): + self.logger = get_logger(component=LocatorCache.__name__) self.cache = dict() self.blocks = OrderedDict() self.cache_size = blocks_in_cache @@ -112,7 +111,7 @@ def update(self, block_hash, locator_txid_map): with self.rw_lock.gen_wlock(): self.cache.update(locator_txid_map) self.blocks[block_hash] = list(locator_txid_map.keys()) - logger.debug("Block added to cache", block_hash=block_hash) + self.logger.debug("Block added to cache", block_hash=block_hash) if self.is_full(): self.remove_oldest_block() @@ -130,7 +129,7 @@ def remove_oldest_block(self): for locator in locators: del self.cache[locator] - logger.debug("Block removed from cache", block_hash=block_hash) + self.logger.debug("Block removed from cache", block_hash=block_hash) def fix(self, last_known_block, block_processor): """ @@ -212,6 +211,8 @@ class Watcher: """ def __init__(self, db_manager, gatekeeper, block_processor, responder, sk_der, max_appointments, blocks_in_cache): + self.logger = get_logger(component=Watcher.__name__) + self.appointments = dict() self.locator_uuid_map = dict() self.block_queue = Queue() @@ -315,7 +316,7 @@ def add_appointment(self, appointment, user_signature): if len(self.appointments) >= self.max_appointments: message = "Maximum appointments reached, appointment rejected" - logger.info(message, locator=appointment.locator) + self.logger.info(message, locator=appointment.locator) raise AppointmentLimitReached(message) user_id = self.gatekeeper.authenticate_user(appointment.serialize(), user_signature) @@ -336,7 +337,7 @@ def add_appointment(self, appointment, user_signature): # If this is a copy of an appointment we've already reacted to, the new appointment is rejected. if uuid in self.responder.trackers: message = "Appointment already in Responder" - logger.info(message) + self.logger.info(message) raise AppointmentAlreadyTriggered(message) # Add the appointment to the Gatekeeper @@ -392,10 +393,10 @@ def add_appointment(self, appointment, user_signature): except (InvalidParameter, SignatureError): # This should never happen since data is sanitized, just in case to avoid a crash - logger.error("Data couldn't be signed", appointment=extended_appointment.to_dict()) + self.logger.error("Data couldn't be signed", appointment=extended_appointment.to_dict()) signature = None - logger.info("New appointment accepted", locator=extended_appointment.locator) + self.logger.info("New appointment accepted", locator=extended_appointment.locator) return { "locator": extended_appointment.locator, @@ -424,7 +425,9 @@ def do_watch(self): while True: block_hash = self.block_queue.get() block = self.block_processor.get_block(block_hash) - logger.info("New block received", block_hash=block_hash, prev_block_hash=block.get("previousblockhash")) + self.logger.info( + "New block received", block_hash=block_hash, prev_block_hash=block.get("previousblockhash") + ) # If a reorg is detected, the cache is fixed to cover the last `cache_size` blocks of the new chain if self.last_known_block != block.get("previousblockhash"): @@ -455,7 +458,7 @@ def do_watch(self): appointments_to_delete = [] for uuid, breach in valid_breaches.items(): - logger.info( + self.logger.info( "Notifying responder and deleting appointment", penalty_txid=breach["penalty_txid"], locator=breach["locator"], @@ -497,7 +500,7 @@ def do_watch(self): Cleaner.delete_gatekeeper_appointments(self.gatekeeper, appointments_to_delete_gatekeeper) if len(self.appointments) != 0: - logger.info("No more pending appointments") + self.logger.info("No more pending appointments") # Register the last processed block for the Watcher self.db_manager.store_last_block_hash_watcher(block_hash) @@ -522,10 +525,10 @@ def get_breaches(self, locator_txid_map): breaches = {locator: locator_txid_map[locator] for locator in intersection} if len(breaches) > 0: - logger.info("List of breaches", breaches=breaches) + self.logger.info("List of breaches", breaches=breaches) else: - logger.info("No breaches found") + self.logger.info("No breaches found") return breaches @@ -552,14 +555,14 @@ def check_breach(self, uuid, appointment, dispute_txid): penalty_tx = self.block_processor.decode_raw_transaction(penalty_rawtx) except EncryptionError as e: - logger.info("Transaction cannot be decrypted", uuid=uuid) + self.logger.info("Transaction cannot be decrypted", uuid=uuid) raise e except InvalidTransactionFormat as e: - logger.info("The breach contained an invalid transaction", uuid=uuid) + self.logger.info("The breach contained an invalid transaction", uuid=uuid) raise e - logger.info( + self.logger.info( "Breach found for locator", locator=appointment.locator, uuid=uuid, penalty_txid=penalty_tx.get("txid") ) diff --git a/test/common/unit/test_logger.py b/test/common/unit/test_logger.py new file mode 100644 index 00000000..9d4d39b5 --- /dev/null +++ b/test/common/unit/test_logger.py @@ -0,0 +1,46 @@ +from common.logger import CustomLogRenderer, get_logger + + +def test_CustomLogRenderer_with_event(): + event_dict = {"event": "Test"} + renderer = CustomLogRenderer() + assert renderer(None, None, event_dict) == "Test" + + +def test_CustomLogRenderer_with_event_and_timestamp(): + event_dict = { + "event": "Test", + "timestamp": "today", # doesn't matter if it's not correct, should just copy it verbatim + } + renderer = CustomLogRenderer() + assert renderer(None, None, event_dict) == "today Test" + + +def test_CustomLogRenderer_with_event_and_timestamp_and_component(): + event_dict = { + "component": "MyAwesomeComponent", + "event": "Test", + "timestamp": "today", # doesn't matter if it's not correct, should just copy it verbatim + } + renderer = CustomLogRenderer() + assert renderer(None, None, event_dict) == "today [MyAwesomeComponent] Test" + + +def test_CustomLogRenderer_with_event_and_timestamp_and_component_and_extra_keys(): + event_dict = { + "component": "MyAwesomeComponent", + "event": "Test", + "timestamp": "today", # doesn't matter if it's not correct, should just copy it verbatim + "key": 6, + "aKeyBefore": 42, # should be rendered before "key", because it comes lexicographically before + } + renderer = CustomLogRenderer() + assert renderer(None, None, event_dict) == "today [MyAwesomeComponent] Test (aKeyBefore=42, key=6)" + + +def test_get_logger(): + # Test that get_logger actually adds a field called "component" with the expected value. + # As the public interface of the class does not expose the initial_values, we rely on the output + # of `repr` to check if the expected fields are indeed present. + logger = get_logger("MyAwesomeComponent") + assert "'component': 'MyAwesomeComponent'" in repr(logger) diff --git a/test/common/unit/test_tools.py b/test/common/unit/test_tools.py index 697f614d..05fbde28 100644 --- a/test/common/unit/test_tools.py +++ b/test/common/unit/test_tools.py @@ -1,16 +1,7 @@ import os -import logging from common.constants import LOCATOR_LEN_BYTES -from common.tools import ( - is_compressed_pk, - is_256b_hex_str, - is_locator, - compute_locator, - setup_data_folder, - setup_logging, - is_u4int, -) +from common.tools import is_compressed_pk, is_256b_hex_str, is_locator, compute_locator, setup_data_folder, is_u4int from test.common.unit.conftest import get_random_value_hex @@ -111,22 +102,3 @@ def test_setup_data_folder(): assert os.path.isdir(test_folder) os.rmdir(test_folder) - - -def test_setup_logging(): - # Check that setup_logging creates two new logs for every prefix - prefix = "foo" - log_file = "var.log" - - f_log_suffix = "_file_log" - c_log_suffix = "_console_log" - - assert len(logging.getLogger(prefix + f_log_suffix).handlers) == 0 - assert len(logging.getLogger(prefix + c_log_suffix).handlers) == 0 - - setup_logging(log_file, prefix) - - assert len(logging.getLogger(prefix + f_log_suffix).handlers) == 1 - assert len(logging.getLogger(prefix + c_log_suffix).handlers) == 1 - - os.remove(log_file)