From a5950556537812b5b4963013a0c559423d385209 Mon Sep 17 00:00:00 2001 From: Salvatore Ingala <6681844+bigspider@users.noreply.github.com> Date: Mon, 6 Jul 2020 12:09:13 +0200 Subject: [PATCH 01/22] Added structlog and config; removed setup_logging from common.tools (now in common.logger); removed LOG_PREFIX; removed Logger class, replaced with a get_logger method with the 'actor' parameter --- cli/__init__.py | 1 - cli/teos_cli.py | 10 +-- common/logger.py | 154 +++++++++++++++------------------ common/tools.py | 41 --------- requirements.txt | 3 +- teos/__init__.py | 1 - teos/api.py | 5 +- teos/appointments_dbm.py | 6 +- teos/block_processor.py | 5 +- teos/carrier.py | 5 +- teos/chain_monitor.py | 5 +- teos/cleaner.py | 6 +- teos/inspector.py | 6 +- teos/responder.py | 5 +- teos/teosd.py | 10 +-- teos/users_dbm.py | 6 +- teos/watcher.py | 5 +- test/common/unit/test_tools.py | 19 ---- 18 files changed, 103 insertions(+), 190 deletions(-) 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/teos_cli.py b/cli/teos_cli.py index 33437690..df9b0e1d 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(actor="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..6c1c0966 100644 --- a/common/logger.py +++ b/common/logger.py @@ -1,96 +1,84 @@ import json import logging +import logging.config +import structlog from datetime import datetime +configured = False # set to True once setuo_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 = [ + # Add the log level and a timestamp to the event_dict if the log entry + # is not from structlog. + structlog.stdlib.add_log_level, + timestamper, +] - def to_dict(self): - return {**self.kwargs, "message": self.message, "time": self.time} - -class Logger: +def setup_logging(log_file_path, silent=False): """ - The :class:`Logger` is in charge of logging events into the log file. + Configures the logging options. It must be called only once, before using get_logger. 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``, ...). + 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. """ - 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]) - - return message - - @staticmethod - def _create_file_message(msg, **kwargs): - return json.dumps(_StructuredMessage(msg, **kwargs).to_dict()) - - def info(self, msg, **kwargs): - """ - Logs an ``INFO`` level message to stdout and file. - - Args: - msg (:obj:`str`): the message to be logged. - kwargs (:obj:`dict`): a ``key:value`` collection parameters to be added to the output. - """ - - self.f_logger.info(self._create_file_message(msg, **kwargs)) - self.c_logger.info(self._create_console_message(msg, **kwargs)) - - def debug(self, msg, **kwargs): - """ - Logs a ``DEBUG`` level message to stdout and file. - - Args: - msg (:obj:`str`): the message to be logged. - kwargs (:obj:`dict`): a ``key:value`` collection parameters to be added to the output. - """ - - 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. - - Args: - msg (:obj:`str`): the message to be logged. - kwargs (:obj:`dict`): a ``key:value`` collection parameters to be added to the output. - """ - - self.f_logger.error(self._create_file_message(msg, **kwargs)) - self.c_logger.error(self._create_console_message(msg, **kwargs)) - - def warning(self, msg, **kwargs): - """ - Logs a ``WARNING`` level message to stdout and file. - - Args: - msg (:obj:`str`): the message to be logged. - kwargs (:obj:`dict`): a ``key:value`` collection parameters to be added to the output. - """ + 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": structlog.dev.ConsoleRenderer(colors=False), + "foreign_pre_chain": pre_chain, + }, + }, + "handlers": { + "console": { + "level": "INFO" if not silent else "CRITICAL", + "class": "logging.StreamHandler", + "formatter": "plain", + }, + "file": { + "level": "DEBUG", + "class": "logging.handlers.WatchedFileHandler", + "filename": log_file_path, + "formatter": "plain", + }, + }, + "loggers": { + "": { + "handlers": ["console", "file"], + "level": "DEBUG", + "propagate": True, + }, + } + }) + + structlog.configure( + processors=[ + structlog.stdlib.add_log_level, + structlog.stdlib.PositionalArgumentsFormatter(), + timestamper, + structlog.processors.StackInfoRenderer(), + structlog.processors.format_exc_info, + 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(actor=None): + return structlog.get_logger(actor=actor) - self.f_logger.warning(self._create_file_message(msg, **kwargs)) - self.c_logger.warning(self._create_console_message(msg, **kwargs)) diff --git a/common/tools.py b/common/tools.py index 874e6398..ce812dd9 100644 --- a/common/tools.py +++ b/common/tools.py @@ -79,44 +79,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..ff6442d6 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,7 @@ # ToDo: #5-add-async-to-api app = Flask(__name__) -logger = Logger(actor="API", log_name_prefix=LOG_PREFIX) +logger = get_logger(actor="API") # NOTCOVERED: not sure how to monkey path this one. May be related to #77 diff --git a/teos/appointments_dbm.py b/teos/appointments_dbm.py index 2ad51f32..557b3b97 100644 --- a/teos/appointments_dbm.py +++ b/teos/appointments_dbm.py @@ -1,12 +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 -logger = Logger(actor="AppointmentsDBM", log_name_prefix=LOG_PREFIX) +logger = get_logger(actor="AppointmentsDBM") WATCHER_PREFIX = "w" WATCHER_LAST_BLOCK_KEY = "bw" diff --git a/teos/block_processor.py b/teos/block_processor.py index 73b83708..2f1bacc7 100644 --- a/teos/block_processor.py +++ b/teos/block_processor.py @@ -1,11 +1,10 @@ -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) +logger = get_logger(actor="BlockProcessor") class InvalidTransactionFormat(BasicException): diff --git a/teos/carrier.py b/teos/carrier.py index 11b578f7..e77f7747 100644 --- a/teos/carrier.py +++ b/teos/carrier.py @@ -1,11 +1,10 @@ -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) +logger = get_logger(actor="Carrier") # FIXME: This class is not fully covered by unit tests diff --git a/teos/chain_monitor.py b/teos/chain_monitor.py index e61dd31f..a62af9b0 100644 --- a/teos/chain_monitor.py +++ b/teos/chain_monitor.py @@ -2,10 +2,9 @@ import binascii from threading import Thread, Event, Condition -from teos import LOG_PREFIX -from common.logger import Logger +from common.logger import get_logger -logger = Logger(actor="ChainMonitor", log_name_prefix=LOG_PREFIX) +logger = get_logger(actor="ChainMonitor") class ChainMonitor: diff --git a/teos/cleaner.py b/teos/cleaner.py index 938fcfde..98b88788 100644 --- a/teos/cleaner.py +++ b/teos/cleaner.py @@ -1,8 +1,6 @@ -from teos import LOG_PREFIX +from common.logger import get_logger -from common.logger import Logger - -logger = Logger(actor="Cleaner", log_name_prefix=LOG_PREFIX) +logger = get_logger(actor="Cleaner") class Cleaner: diff --git a/teos/inspector.py b/teos/inspector.py index d61d6c73..f652398d 100644 --- a/teos/inspector.py +++ b/teos/inspector.py @@ -1,15 +1,13 @@ import re from common import errors -from common.logger import Logger +from common.logger import get_logger from common.tools import is_locator from common.appointment import Appointment from common.constants import LOCATOR_LEN_HEX -from teos import LOG_PREFIX - -logger = Logger(actor="Inspector", log_name_prefix=LOG_PREFIX) +logger = get_logger(actor="Inspector") # 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..0beea003 100644 --- a/teos/responder.py +++ b/teos/responder.py @@ -1,16 +1,15 @@ 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) +logger = get_logger(actor="Responder") class TransactionTracker: diff --git a/teos/teosd.py b/teos/teosd.py index 4070ae7a..5ef00abe 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(actor="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..b2c8396f 100644 --- a/teos/users_dbm.py +++ b/teos/users_dbm.py @@ -1,13 +1,11 @@ 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) +logger = get_logger(actor="UsersDBM") class UsersDBM(DBManager): diff --git a/teos/watcher.py b/teos/watcher.py index 0fd37842..3649fbf1 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,12 +11,11 @@ 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) +logger = get_logger(actor="Watcher") class AppointmentLimitReached(BasicException): diff --git a/test/common/unit/test_tools.py b/test/common/unit/test_tools.py index 697f614d..4ceaedc3 100644 --- a/test/common/unit/test_tools.py +++ b/test/common/unit/test_tools.py @@ -111,22 +111,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) From 46418ea552c3c8378eb35d73501ecaf4aec5d61b Mon Sep 17 00:00:00 2001 From: Salvatore Ingala <6681844+bigspider@users.noreply.github.com> Date: Mon, 6 Jul 2020 14:32:27 +0200 Subject: [PATCH 02/22] Better docs --- common/logger.py | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/common/logger.py b/common/logger.py index 6c1c0966..f024bd9c 100644 --- a/common/logger.py +++ b/common/logger.py @@ -22,6 +22,10 @@ def setup_logging(log_file_path, silent=False): 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. + + Raises: + (:obj:`RuntimeError`) setup_logger had already been called. + """ global configured @@ -80,5 +84,12 @@ def setup_logging(log_file_path, silent=False): def get_logger(actor=None): + """ + Returns a logger, that has the given `actor` in all future log entries. + + Args: + actor(:obj:`str`): the name of the "actor" field that will be attached to all the logs issued by this logger. + + """ return structlog.get_logger(actor=actor) From 6b8af2ebbf9e0390142a98c2168048e79727bbce Mon Sep 17 00:00:00 2001 From: Salvatore Ingala <6681844+bigspider@users.noreply.github.com> Date: Mon, 6 Jul 2020 15:11:26 +0200 Subject: [PATCH 03/22] Added custom Renderer for logs; removed unused log processors --- common/logger.py | 53 ++++++++++++++++++++++++++++++++++++++++++------ 1 file changed, 47 insertions(+), 6 deletions(-) diff --git a/common/logger.py b/common/logger.py index f024bd9c..c1e447a3 100644 --- a/common/logger.py +++ b/common/logger.py @@ -1,20 +1,62 @@ import json import logging import logging.config -import structlog +from io import StringIO from datetime import datetime +import structlog configured = False # set to True once setuo_logging is called timestamper = structlog.processors.TimeStamper(fmt="%d/%m/%Y %H:%M:%S") pre_chain = [ - # Add the log level and a timestamp to the event_dict if the log entry - # is not from structlog. - structlog.stdlib.add_log_level, timestamper, ] +# Stripped down version of structlog.dev.ConsoleRenderer, adding the "actor" instead of the level. +class CustomLogRenderer: + """ + Render ``event_dict``. It renders the timestamp, followed by the actor within "[]" (unless it's None), + followed by the event, then any remaining argument in the key=value format + """ + + def _repr(self, val): + """ + Determine representation of *val* depending on its type. + """ + if isinstance(val, str): + return val + else: + return repr(val) + + def __call__(self, _, __, event_dict): + # Initialize lazily to prevent import side-effects. + sio = StringIO() + + ts = event_dict.pop("timestamp", None) + if ts is not None: + sio.write(str(ts) + " ") + + actor = event_dict.pop("actor", None) + if actor is not None: + sio.write("[" + actor + "] ") + + # force event to str for compatibility with standard library + event = event_dict.pop("event") + if not isinstance(event, str): + event = str(event) + + sio.write(event) + + # Represent all the key=value elements still in event_dict + sio.write( + " ".join(key + "=" + self._repr(event_dict[key]) for key in sorted(event_dict.keys())) + ) + + return sio.getvalue() + + + def setup_logging(log_file_path, silent=False): """ Configures the logging options. It must be called only once, before using get_logger. @@ -39,7 +81,7 @@ def setup_logging(log_file_path, silent=False): "formatters": { "plain": { "()": structlog.stdlib.ProcessorFormatter, - "processor": structlog.dev.ConsoleRenderer(colors=False), + "processor": CustomLogRenderer(), "foreign_pre_chain": pre_chain, }, }, @@ -67,7 +109,6 @@ def setup_logging(log_file_path, silent=False): structlog.configure( processors=[ - structlog.stdlib.add_log_level, structlog.stdlib.PositionalArgumentsFormatter(), timestamper, structlog.processors.StackInfoRenderer(), From ce109d1271da8fe9627370581d697b67194e26a5 Mon Sep 17 00:00:00 2001 From: Salvatore Ingala <6681844+bigspider@users.noreply.github.com> Date: Mon, 6 Jul 2020 15:35:41 +0200 Subject: [PATCH 04/22] Removed wrong import --- test/common/unit/test_tools.py | 1 - 1 file changed, 1 deletion(-) diff --git a/test/common/unit/test_tools.py b/test/common/unit/test_tools.py index 4ceaedc3..55aa64e7 100644 --- a/test/common/unit/test_tools.py +++ b/test/common/unit/test_tools.py @@ -8,7 +8,6 @@ is_locator, compute_locator, setup_data_folder, - setup_logging, is_u4int, ) from test.common.unit.conftest import get_random_value_hex From 94e1959c147454608bd1215bdd3e1ded72ec0aa0 Mon Sep 17 00:00:00 2001 From: Salvatore Ingala <6681844+bigspider@users.noreply.github.com> Date: Mon, 6 Jul 2020 16:49:32 +0200 Subject: [PATCH 05/22] Removed wrong unused processors; added separator for the key-value part of a log entry --- common/logger.py | 9 +++------ 1 file changed, 3 insertions(+), 6 deletions(-) diff --git a/common/logger.py b/common/logger.py index c1e447a3..7897bddd 100644 --- a/common/logger.py +++ b/common/logger.py @@ -30,7 +30,6 @@ def _repr(self, val): return repr(val) def __call__(self, _, __, event_dict): - # Initialize lazily to prevent import side-effects. sio = StringIO() ts = event_dict.pop("timestamp", None) @@ -49,9 +48,9 @@ def __call__(self, _, __, event_dict): sio.write(event) # Represent all the key=value elements still in event_dict - sio.write( - " ".join(key + "=" + self._repr(event_dict[key]) for key in sorted(event_dict.keys())) - ) + 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("\t" + key_value_part) return sio.getvalue() @@ -111,8 +110,6 @@ def setup_logging(log_file_path, silent=False): processors=[ structlog.stdlib.PositionalArgumentsFormatter(), timestamper, - structlog.processors.StackInfoRenderer(), - structlog.processors.format_exc_info, structlog.stdlib.ProcessorFormatter.wrap_for_formatter, ], context_class=dict, From 4eb7f76f3b839150c902955792a9177b4e934879 Mon Sep 17 00:00:00 2001 From: Salvatore Ingala <6681844+bigspider@users.noreply.github.com> Date: Tue, 7 Jul 2020 11:07:44 +0200 Subject: [PATCH 06/22] Fix typos --- common/logger.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/common/logger.py b/common/logger.py index 7897bddd..7e0e7af8 100644 --- a/common/logger.py +++ b/common/logger.py @@ -5,7 +5,7 @@ from datetime import datetime import structlog -configured = False # set to True once setuo_logging is called +configured = False # set to True once setup_logging is called timestamper = structlog.processors.TimeStamper(fmt="%d/%m/%Y %H:%M:%S") pre_chain = [ @@ -17,7 +17,7 @@ class CustomLogRenderer: """ Render ``event_dict``. It renders the timestamp, followed by the actor within "[]" (unless it's None), - followed by the event, then any remaining argument in the key=value format + followed by the event, then any remaining item in event_dict in the key=value format """ def _repr(self, val): From ebb157a86decc5dc16c2aa02415d17c81d34e4bf Mon Sep 17 00:00:00 2001 From: Salvatore Ingala <6681844+bigspider@users.noreply.github.com> Date: Tue, 7 Jul 2020 12:51:30 +0200 Subject: [PATCH 07/22] Added structlog as requirements for teos_cli --- cli/requirements.txt | 1 + 1 file changed, 1 insertion(+) 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 From 59ec971e682a295726ea4d27cb6dc8056521c55b Mon Sep 17 00:00:00 2001 From: Salvatore Ingala <6681844+bigspider@users.noreply.github.com> Date: Fri, 10 Jul 2020 11:30:07 +0200 Subject: [PATCH 08/22] Addressing some comments from the PR; changed "actor" to "component" --- cli/teos_cli.py | 2 +- common/logger.py | 51 +++++++++++++++++----------------------- teos/api.py | 2 +- teos/appointments_dbm.py | 2 +- teos/block_processor.py | 2 +- teos/carrier.py | 2 +- teos/chain_monitor.py | 2 +- teos/cleaner.py | 2 +- teos/inspector.py | 2 +- teos/responder.py | 2 +- teos/teosd.py | 2 +- teos/users_dbm.py | 2 +- teos/watcher.py | 2 +- 13 files changed, 33 insertions(+), 42 deletions(-) diff --git a/cli/teos_cli.py b/cli/teos_cli.py index df9b0e1d..a7f796be 100644 --- a/cli/teos_cli.py +++ b/cli/teos_cli.py @@ -24,7 +24,7 @@ from common.exceptions import InvalidKey, InvalidParameter, SignatureError from common.tools import is_256b_hex_str, is_locator, compute_locator, is_compressed_pk -logger = get_logger(actor="Client") +logger = get_logger(component="Client") def register(user_id, teos_id, teos_url): diff --git a/common/logger.py b/common/logger.py index 7e0e7af8..8cc6b051 100644 --- a/common/logger.py +++ b/common/logger.py @@ -1,8 +1,5 @@ -import json -import logging import logging.config from io import StringIO -from datetime import datetime import structlog configured = False # set to True once setup_logging is called @@ -13,37 +10,30 @@ ] -# Stripped down version of structlog.dev.ConsoleRenderer, adding the "actor" instead of the level. +# Stripped down version of structlog.dev.ConsoleRenderer, adding the "component" instead of the level. class CustomLogRenderer: """ - Render ``event_dict``. It renders the timestamp, followed by the actor within "[]" (unless it's None), - followed by the event, then any remaining item in event_dict in the key=value format + 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 _repr(self, val): - """ - Determine representation of *val* depending on its type. - """ - if isinstance(val, str): - return val - else: - return repr(val) + """Returns the representation of *val* if it's not a ``str``.""" + return val if isinstance(val, str) else repr(val) def __call__(self, _, __, event_dict): + """Returns ``event_dict`` rendered as a string.""" sio = StringIO() ts = event_dict.pop("timestamp", None) - if ts is not None: + if ts: sio.write(str(ts) + " ") - actor = event_dict.pop("actor", None) - if actor is not None: - sio.write("[" + actor + "] ") + component = event_dict.pop("component", None) + if component: + sio.write("[" + component + "] ") - # force event to str for compatibility with standard library - event = event_dict.pop("event") - if not isinstance(event, str): - event = str(event) + event = self._repr(event_dict.pop("event")) sio.write(event) @@ -61,12 +51,11 @@ def setup_logging(log_file_path, silent=False): Configures the logging options. It must be called only once, before using get_logger. 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. + 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. Raises: - (:obj:`RuntimeError`) setup_logger had already been called. - + :obj:`RuntimeError` setup_logger had already been called. """ global configured @@ -121,13 +110,15 @@ def setup_logging(log_file_path, silent=False): configured = True -def get_logger(actor=None): +def get_logger(component=None): """ - Returns a logger, that has the given `actor` in all future log entries. + Returns a logger, that has the given `component` in all future log entries. - Args: - actor(:obj:`str`): the name of the "actor" field that will be attached to all the logs issued by this logger. + Returns: + a proxy obtained from structlog.get_logger with the `component` as bound variable. + Args: + component(:obj:`str`): the name of the "component" field that will be attached to all the logs issued by this logger. """ - return structlog.get_logger(actor=actor) + return structlog.get_logger(component=component) diff --git a/teos/api.py b/teos/api.py index ff6442d6..3ef24425 100644 --- a/teos/api.py +++ b/teos/api.py @@ -15,7 +15,7 @@ # ToDo: #5-add-async-to-api app = Flask(__name__) -logger = get_logger(actor="API") +logger = get_logger(component="API") # NOTCOVERED: not sure how to monkey path this one. May be related to #77 diff --git a/teos/appointments_dbm.py b/teos/appointments_dbm.py index 557b3b97..ea6334e1 100644 --- a/teos/appointments_dbm.py +++ b/teos/appointments_dbm.py @@ -4,7 +4,7 @@ from common.logger import get_logger from common.db_manager import DBManager -logger = get_logger(actor="AppointmentsDBM") +logger = get_logger(component="AppointmentsDBM") WATCHER_PREFIX = "w" WATCHER_LAST_BLOCK_KEY = "bw" diff --git a/teos/block_processor.py b/teos/block_processor.py index 2f1bacc7..08ac5510 100644 --- a/teos/block_processor.py +++ b/teos/block_processor.py @@ -4,7 +4,7 @@ from teos.tools import bitcoin_cli from teos.utils.auth_proxy import JSONRPCException -logger = get_logger(actor="BlockProcessor") +logger = get_logger(component="BlockProcessor") class InvalidTransactionFormat(BasicException): diff --git a/teos/carrier.py b/teos/carrier.py index e77f7747..ba37cc7a 100644 --- a/teos/carrier.py +++ b/teos/carrier.py @@ -4,7 +4,7 @@ from teos.utils.auth_proxy import JSONRPCException from common.errors import UNKNOWN_JSON_RPC_EXCEPTION, RPC_TX_REORGED_AFTER_BROADCAST -logger = get_logger(actor="Carrier") +logger = get_logger(component="Carrier") # FIXME: This class is not fully covered by unit tests diff --git a/teos/chain_monitor.py b/teos/chain_monitor.py index a62af9b0..787e7fe5 100644 --- a/teos/chain_monitor.py +++ b/teos/chain_monitor.py @@ -4,7 +4,7 @@ from common.logger import get_logger -logger = get_logger(actor="ChainMonitor") +logger = get_logger(component="ChainMonitor") class ChainMonitor: diff --git a/teos/cleaner.py b/teos/cleaner.py index 98b88788..a4ddc1d4 100644 --- a/teos/cleaner.py +++ b/teos/cleaner.py @@ -1,6 +1,6 @@ from common.logger import get_logger -logger = get_logger(actor="Cleaner") +logger = get_logger(component="Cleaner") class Cleaner: diff --git a/teos/inspector.py b/teos/inspector.py index f652398d..cadce56e 100644 --- a/teos/inspector.py +++ b/teos/inspector.py @@ -7,7 +7,7 @@ from common.constants import LOCATOR_LEN_HEX -logger = get_logger(actor="Inspector") +logger = get_logger(component="Inspector") # 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 0beea003..dd9d254c 100644 --- a/teos/responder.py +++ b/teos/responder.py @@ -9,7 +9,7 @@ CONFIRMATIONS_BEFORE_RETRY = 6 MIN_CONFIRMATIONS = 6 -logger = get_logger(actor="Responder") +logger = get_logger(component="Responder") class TransactionTracker: diff --git a/teos/teosd.py b/teos/teosd.py index 5ef00abe..dd69dc0f 100644 --- a/teos/teosd.py +++ b/teos/teosd.py @@ -23,7 +23,7 @@ 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 = get_logger(actor="Daemon") +logger = get_logger(component="Daemon") def handle_signals(signal_received, frame): diff --git a/teos/users_dbm.py b/teos/users_dbm.py index b2c8396f..d2b430e6 100644 --- a/teos/users_dbm.py +++ b/teos/users_dbm.py @@ -5,7 +5,7 @@ from common.db_manager import DBManager from common.tools import is_compressed_pk -logger = get_logger(actor="UsersDBM") +logger = get_logger(component="UsersDBM") class UsersDBM(DBManager): diff --git a/teos/watcher.py b/teos/watcher.py index 3649fbf1..d0b05ff3 100644 --- a/teos/watcher.py +++ b/teos/watcher.py @@ -15,7 +15,7 @@ from teos.extended_appointment import ExtendedAppointment from teos.block_processor import InvalidTransactionFormat -logger = get_logger(actor="Watcher") +logger = get_logger(component="Watcher") class AppointmentLimitReached(BasicException): From e30b92f112ebb529ff3d7778ff3cdb6562cdffb9 Mon Sep 17 00:00:00 2001 From: Salvatore Ingala <6681844+bigspider@users.noreply.github.com> Date: Fri, 10 Jul 2020 12:00:07 +0200 Subject: [PATCH 09/22] Moved logger to class member wherever possible --- teos/appointments_dbm.py | 54 ++++++++++++++++++++-------------------- teos/block_processor.py | 11 ++++---- teos/carrier.py | 21 ++++++++-------- teos/chain_monitor.py | 7 +++--- teos/inspector.py | 4 --- teos/responder.py | 29 +++++++++++---------- teos/users_dbm.py | 18 +++++++------- teos/watcher.py | 34 +++++++++++++------------ 8 files changed, 86 insertions(+), 92 deletions(-) diff --git a/teos/appointments_dbm.py b/teos/appointments_dbm.py index ea6334e1..79218c24 100644 --- a/teos/appointments_dbm.py +++ b/teos/appointments_dbm.py @@ -4,8 +4,6 @@ from common.logger import get_logger from common.db_manager import DBManager -logger = get_logger(component="AppointmentsDBM") - WATCHER_PREFIX = "w" WATCHER_LAST_BLOCK_KEY = "bw" RESPONDER_PREFIX = "r" @@ -41,12 +39,14 @@ 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 @@ -183,15 +183,15 @@ 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): @@ -208,15 +208,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): @@ -239,7 +239,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 @@ -259,14 +259,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")) @@ -288,7 +288,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): """ @@ -303,11 +303,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): @@ -323,11 +323,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): @@ -341,7 +341,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): """ @@ -356,11 +356,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): @@ -374,7 +374,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): """ @@ -443,7 +443,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): """ @@ -456,7 +456,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): """ @@ -484,11 +484,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): @@ -502,4 +502,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 08ac5510..a14b2c2d 100644 --- a/teos/block_processor.py +++ b/teos/block_processor.py @@ -4,8 +4,6 @@ from teos.tools import bitcoin_cli from teos.utils.auth_proxy import JSONRPCException -logger = get_logger(component="BlockProcessor") - class InvalidTransactionFormat(BasicException): """Raised when a transaction is not properly formatted""" @@ -22,6 +20,7 @@ class BlockProcessor: """ 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): @@ -42,7 +41,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 @@ -61,7 +60,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 @@ -80,7 +79,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 @@ -104,7 +103,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 ba37cc7a..938b0b52 100644 --- a/teos/carrier.py +++ b/teos/carrier.py @@ -4,8 +4,6 @@ from teos.utils.auth_proxy import JSONRPCException from common.errors import UNKNOWN_JSON_RPC_EXCEPTION, RPC_TX_REORGED_AFTER_BROADCAST -logger = get_logger(component="Carrier") - # FIXME: This class is not fully covered by unit tests @@ -49,6 +47,7 @@ class Carrier: """ def __init__(self, btc_connect_params): + self.logger = get_logger(component=Carrier.__name__) self.btc_connect_params = btc_connect_params self.issued_receipts = {} @@ -66,13 +65,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) @@ -83,15 +82,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 @@ -113,12 +112,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 @@ -146,10 +145,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 787e7fe5..c2c0db8c 100644 --- a/teos/chain_monitor.py +++ b/teos/chain_monitor.py @@ -4,8 +4,6 @@ from common.logger import get_logger -logger = get_logger(component="ChainMonitor") - class ChainMonitor: """ @@ -39,6 +37,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 @@ -119,7 +118,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): @@ -143,7 +142,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/inspector.py b/teos/inspector.py index cadce56e..8e9f4cc9 100644 --- a/teos/inspector.py +++ b/teos/inspector.py @@ -1,14 +1,10 @@ import re -from common import errors -from common.logger import get_logger from common.tools import is_locator from common.appointment import Appointment from common.constants import LOCATOR_LEN_HEX -logger = get_logger(component="Inspector") - # 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 # since teos would store any kind of message (no matter the length). Solution: truncate the length of the fields diff --git a/teos/responder.py b/teos/responder.py index dd9d254c..db3dc8b8 100644 --- a/teos/responder.py +++ b/teos/responder.py @@ -9,8 +9,6 @@ CONFIRMATIONS_BEFORE_RETRY = 6 MIN_CONFIRMATIONS = 6 -logger = get_logger(component="Responder") - class TransactionTracker: """ @@ -134,6 +132,7 @@ class Responder: """ def __init__(self, db_manager, gatekeeper, carrier, block_processor): + self.logger = get_logger(component="Responder") self.trackers = dict() self.tx_tracker_map = dict() self.unconfirmed_txs = [] @@ -208,7 +207,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) ) @@ -249,7 +248,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): """ @@ -267,7 +266,7 @@ 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") @@ -297,7 +296,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"), @@ -310,7 +309,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) @@ -333,7 +332,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 @@ -343,7 +342,7 @@ 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): """ @@ -444,7 +443,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 ) @@ -453,7 +452,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 @@ -485,7 +484,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, ) @@ -502,7 +501,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 ) @@ -510,5 +509,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/users_dbm.py b/teos/users_dbm.py index d2b430e6..9f144e35 100644 --- a/teos/users_dbm.py +++ b/teos/users_dbm.py @@ -5,8 +5,6 @@ from common.db_manager import DBManager from common.tools import is_compressed_pk -logger = get_logger(component="UsersDBM") - class UsersDBM(DBManager): """ @@ -23,6 +21,8 @@ class UsersDBM(DBManager): """ def __init__(self, db_path): + self.logger = get_logger(component="UsersDBM") + if not isinstance(db_path, str): raise ValueError("db_path must be a valid path/name") @@ -31,7 +31,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 @@ -50,18 +50,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): @@ -99,11 +99,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 d0b05ff3..a9d335b4 100644 --- a/teos/watcher.py +++ b/teos/watcher.py @@ -15,8 +15,6 @@ from teos.extended_appointment import ExtendedAppointment from teos.block_processor import InvalidTransactionFormat -logger = get_logger(component="Watcher") - class AppointmentLimitReached(BasicException): """Raised when the tower maximum appointment count has been reached""" @@ -49,6 +47,8 @@ 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 @@ -111,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() @@ -129,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): """ @@ -211,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() @@ -314,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) @@ -335,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 @@ -391,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, @@ -423,7 +425,7 @@ 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"): @@ -454,7 +456,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"], @@ -496,7 +498,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) @@ -521,10 +523,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 @@ -551,14 +553,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") ) From ae108a125768e71b1f1962c1f27e2653765d026d Mon Sep 17 00:00:00 2001 From: Salvatore Ingala <6681844+bigspider@users.noreply.github.com> Date: Fri, 10 Jul 2020 12:19:00 +0200 Subject: [PATCH 10/22] Fixed missing import after rebase --- teos/inspector.py | 1 + 1 file changed, 1 insertion(+) diff --git a/teos/inspector.py b/teos/inspector.py index 8e9f4cc9..8353423e 100644 --- a/teos/inspector.py +++ b/teos/inspector.py @@ -3,6 +3,7 @@ from common.tools import is_locator from common.appointment import Appointment from common.constants import LOCATOR_LEN_HEX +import common.errors as errors # FIXME: The inspector logs the wrong messages sent form the users. A possible attack surface would be to send a really From 57ff453fe387ff2e174a70d68200aaebfab73a6f Mon Sep 17 00:00:00 2001 From: Salvatore Ingala <6681844+bigspider@users.noreply.github.com> Date: Fri, 10 Jul 2020 13:03:45 +0200 Subject: [PATCH 11/22] Added tests for CustomLogRenderer --- test/common/unit/test_logger.py | 44 +++++++++++++++++++++++++++++++++ 1 file changed, 44 insertions(+) create mode 100644 test/common/unit/test_logger.py diff --git a/test/common/unit/test_logger.py b/test/common/unit/test_logger.py new file mode 100644 index 00000000..89c19b6b --- /dev/null +++ b/test/common/unit/test_logger.py @@ -0,0 +1,44 @@ +import os +import logging + +from common.constants import LOCATOR_LEN_BYTES +from common.logger import get_logger, setup_logging, CustomLogRenderer + + +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\taKeyBefore=42 key=6" From 56adb9b00824a51b85d6f1f370260da8d07943f0 Mon Sep 17 00:00:00 2001 From: Salvatore Ingala <6681844+bigspider@users.noreply.github.com> Date: Fri, 10 Jul 2020 13:53:45 +0200 Subject: [PATCH 12/22] Update error message as per PR review --- common/logger.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/common/logger.py b/common/logger.py index 8cc6b051..a71f3dc0 100644 --- a/common/logger.py +++ b/common/logger.py @@ -61,7 +61,7 @@ def setup_logging(log_file_path, silent=False): global configured if configured: - raise RuntimeError("logging was already configured.") + raise RuntimeError("Logging was already configured") logging.config.dictConfig({ "version": 1, From d2d2d3275e64d12b52bde5d304946ea748099434 Mon Sep 17 00:00:00 2001 From: Salvatore Ingala <6681844+bigspider@users.noreply.github.com> Date: Mon, 13 Jul 2020 09:09:46 +0200 Subject: [PATCH 13/22] Improvements from PR review --- teos/api.py | 19 +++++++++++-------- teos/appointments_dbm.py | 7 ++++++- teos/block_processor.py | 3 +++ teos/carrier.py | 1 + teos/chain_monitor.py | 1 + teos/cleaner.py | 18 +++++++++--------- teos/responder.py | 11 ++++++++--- teos/users_dbm.py | 5 ++++- teos/watcher.py | 6 ++++-- test/common/unit/test_logger.py | 6 +----- 10 files changed, 48 insertions(+), 29 deletions(-) diff --git a/teos/api.py b/teos/api.py index 3ef24425..5f071493 100644 --- a/teos/api.py +++ b/teos/api.py @@ -15,7 +15,6 @@ # ToDo: #5-add-async-to-api app = Flask(__name__) -logger = get_logger(component="API") # NOTCOVERED: not sure how to monkey path this one. May be related to #77 @@ -71,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 @@ -109,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") @@ -143,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 @@ -163,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: @@ -199,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): @@ -229,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": diff --git a/teos/appointments_dbm.py b/teos/appointments_dbm.py index 79218c24..8c418016 100644 --- a/teos/appointments_dbm.py +++ b/teos/appointments_dbm.py @@ -33,6 +33,9 @@ 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): @@ -187,7 +190,9 @@ def store_watcher_appointment(self, uuid, appointment): return True except json.JSONDecodeError: - self.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: diff --git a/teos/block_processor.py b/teos/block_processor.py index a14b2c2d..78ce5c11 100644 --- a/teos/block_processor.py +++ b/teos/block_processor.py @@ -17,6 +17,9 @@ 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): diff --git a/teos/carrier.py b/teos/carrier.py index 938b0b52..d9966d37 100644 --- a/teos/carrier.py +++ b/teos/carrier.py @@ -41,6 +41,7 @@ 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. diff --git a/teos/chain_monitor.py b/teos/chain_monitor.py index c2c0db8c..739015a9 100644 --- a/teos/chain_monitor.py +++ b/teos/chain_monitor.py @@ -21,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). diff --git a/teos/cleaner.py b/teos/cleaner.py index a4ddc1d4..a68a3b48 100644 --- a/teos/cleaner.py +++ b/teos/cleaner.py @@ -1,7 +1,5 @@ from common.logger import get_logger -logger = get_logger(component="Cleaner") - class Cleaner: """ @@ -10,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): """ @@ -77,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): @@ -102,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) @@ -141,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 ) @@ -201,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 ) @@ -218,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/responder.py b/teos/responder.py index db3dc8b8..cf03f267 100644 --- a/teos/responder.py +++ b/teos/responder.py @@ -111,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``. @@ -132,7 +133,7 @@ class Responder: """ def __init__(self, db_manager, gatekeeper, carrier, block_processor): - self.logger = get_logger(component="Responder") + self.logger = get_logger(component=Responder.__name__) self.trackers = dict() self.tx_tracker_map = dict() self.unconfirmed_txs = [] @@ -266,7 +267,9 @@ def do_watch(self): while True: block_hash = self.block_queue.get() block = self.block_processor.get_block(block_hash) - self.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") @@ -342,7 +345,9 @@ def check_confirmations(self, txs): else: self.missed_confirmations[tx] = 1 - self.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): """ diff --git a/teos/users_dbm.py b/teos/users_dbm.py index 9f144e35..6ad2d9d9 100644 --- a/teos/users_dbm.py +++ b/teos/users_dbm.py @@ -18,10 +18,13 @@ 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") + self.logger = get_logger(component=UsersDBM.__name__) if not isinstance(db_path, str): raise ValueError("db_path must be a valid path/name") diff --git a/teos/watcher.py b/teos/watcher.py index a9d335b4..bc81bd87 100644 --- a/teos/watcher.py +++ b/teos/watcher.py @@ -38,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). @@ -48,7 +49,6 @@ 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 @@ -425,7 +425,9 @@ def do_watch(self): while True: block_hash = self.block_queue.get() block = self.block_processor.get_block(block_hash) - self.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"): diff --git a/test/common/unit/test_logger.py b/test/common/unit/test_logger.py index 89c19b6b..4d107c37 100644 --- a/test/common/unit/test_logger.py +++ b/test/common/unit/test_logger.py @@ -1,8 +1,4 @@ -import os -import logging - -from common.constants import LOCATOR_LEN_BYTES -from common.logger import get_logger, setup_logging, CustomLogRenderer +from common.logger import CustomLogRenderer def test_CustomLogRenderer_with_event(): From 4bc8a315940de42d9db91794830eac0ca56b7139 Mon Sep 17 00:00:00 2001 From: Salvatore Ingala <6681844+bigspider@users.noreply.github.com> Date: Mon, 13 Jul 2020 09:10:37 +0200 Subject: [PATCH 14/22] Fix typo in Gatekeeper's docstring --- teos/gatekeeper.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) 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. From e2601494837b42927ed1b1a4afa933c6a5336f0d Mon Sep 17 00:00:00 2001 From: Salvatore Ingala <6681844+bigspider@users.noreply.github.com> Date: Mon, 13 Jul 2020 09:15:37 +0200 Subject: [PATCH 15/22] Add commas and parentheses to extra arguments in console logs --- common/logger.py | 13 +++++++------ test/common/unit/test_logger.py | 2 +- 2 files changed, 8 insertions(+), 7 deletions(-) diff --git a/common/logger.py b/common/logger.py index a71f3dc0..da4df337 100644 --- a/common/logger.py +++ b/common/logger.py @@ -2,7 +2,7 @@ from io import StringIO import structlog -configured = False # set to True once setup_logging is called +configured = False # set to True once setup_logging is called timestamper = structlog.processors.TimeStamper(fmt="%d/%m/%Y %H:%M:%S") pre_chain = [ @@ -38,14 +38,13 @@ def __call__(self, _, __, event_dict): sio.write(event) # 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())) + 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("\t" + key_value_part) + sio.write("\t(" + key_value_part + ")") return sio.getvalue() - def setup_logging(log_file_path, silent=False): """ Configures the logging options. It must be called only once, before using get_logger. @@ -63,7 +62,8 @@ def setup_logging(log_file_path, silent=False): if configured: raise RuntimeError("Logging was already configured") - logging.config.dictConfig({ + logging.config.dictConfig( + { "version": 1, "disable_existing_loggers": False, "formatters": { @@ -93,7 +93,8 @@ def setup_logging(log_file_path, silent=False): "propagate": True, }, } - }) + } + ) structlog.configure( processors=[ diff --git a/test/common/unit/test_logger.py b/test/common/unit/test_logger.py index 4d107c37..f1371c22 100644 --- a/test/common/unit/test_logger.py +++ b/test/common/unit/test_logger.py @@ -37,4 +37,4 @@ def test_CustomLogRenderer_with_event_and_timestamp_and_component_and_extra_keys "aKeyBefore": 42, # should be rendered before "key", because it comes lexicographically before } renderer = CustomLogRenderer() - assert renderer(None, None, event_dict) == "today [MyAwesomeComponent] Test\taKeyBefore=42 key=6" + assert renderer(None, None, event_dict) == "today [MyAwesomeComponent] Test\t(aKeyBefore=42, key=6)" From 72f4d4b8c883ac34c5bec4912841b168857557f1 Mon Sep 17 00:00:00 2001 From: Salvatore Ingala <6681844+bigspider@users.noreply.github.com> Date: Mon, 13 Jul 2020 10:13:20 +0200 Subject: [PATCH 16/22] Fix typo in docs --- common/logger.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/common/logger.py b/common/logger.py index da4df337..d8d4b7f8 100644 --- a/common/logger.py +++ b/common/logger.py @@ -119,7 +119,7 @@ def get_logger(component=None): a proxy obtained from structlog.get_logger with the `component` as bound variable. Args: - component(:obj:`str`): the name of the "component" field that will be attached to all the logs issued by this logger. + 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(component=component) From 28033cdecb5ca7727a91f52107c5db0edf6e708d Mon Sep 17 00:00:00 2001 From: Salvatore Ingala <6681844+bigspider@users.noreply.github.com> Date: Mon, 13 Jul 2020 10:27:24 +0200 Subject: [PATCH 17/22] Added test for get_logger --- test/common/unit/test_logger.py | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/test/common/unit/test_logger.py b/test/common/unit/test_logger.py index f1371c22..ef965b46 100644 --- a/test/common/unit/test_logger.py +++ b/test/common/unit/test_logger.py @@ -1,4 +1,4 @@ -from common.logger import CustomLogRenderer +from common.logger import CustomLogRenderer, get_logger def test_CustomLogRenderer_with_event(): @@ -38,3 +38,11 @@ def test_CustomLogRenderer_with_event_and_timestamp_and_component_and_extra_keys } renderer = CustomLogRenderer() assert renderer(None, None, event_dict) == "today [MyAwesomeComponent] Test\t(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) From 6d93a577db19c8573048a5d5074fcd053b57fe1e Mon Sep 17 00:00:00 2001 From: Sergi Delgado Segura Date: Mon, 13 Jul 2020 11:20:08 +0200 Subject: [PATCH 18/22] common - fix formatting issues --- common/logger.py | 18 +++++------------- common/tools.py | 1 - 2 files changed, 5 insertions(+), 14 deletions(-) diff --git a/common/logger.py b/common/logger.py index d8d4b7f8..d48a1976 100644 --- a/common/logger.py +++ b/common/logger.py @@ -5,9 +5,7 @@ configured = False # set to True once setup_logging is called timestamper = structlog.processors.TimeStamper(fmt="%d/%m/%Y %H:%M:%S") -pre_chain = [ - timestamper, -] +pre_chain = [timestamper] # Stripped down version of structlog.dev.ConsoleRenderer, adding the "component" instead of the level. @@ -71,7 +69,7 @@ def setup_logging(log_file_path, silent=False): "()": structlog.stdlib.ProcessorFormatter, "processor": CustomLogRenderer(), "foreign_pre_chain": pre_chain, - }, + } }, "handlers": { "console": { @@ -86,13 +84,7 @@ def setup_logging(log_file_path, silent=False): "formatter": "plain", }, }, - "loggers": { - "": { - "handlers": ["console", "file"], - "level": "DEBUG", - "propagate": True, - }, - } + "loggers": {"": {"handlers": ["console", "file"], "level": "DEBUG", "propagate": True}}, } ) @@ -119,7 +111,7 @@ def get_logger(component=None): a proxy obtained from structlog.get_logger with the `component` as bound variable. Args: - component(:obj:`str`): the value of the "component" field that will be attached to all the logs issued by this logger. + 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(component=component) - diff --git a/common/tools.py b/common/tools.py index ce812dd9..fa597d67 100644 --- a/common/tools.py +++ b/common/tools.py @@ -78,4 +78,3 @@ def setup_data_folder(data_folder): """ Path(data_folder).mkdir(parents=True, exist_ok=True) - From 728ae3d624b00b3e155f469d7a9b445de26bdc3a Mon Sep 17 00:00:00 2001 From: Sergi Delgado Segura Date: Mon, 13 Jul 2020 11:20:19 +0200 Subject: [PATCH 19/22] test - fix formatting issues --- test/common/unit/test_logger.py | 4 +--- test/common/unit/test_tools.py | 10 +--------- 2 files changed, 2 insertions(+), 12 deletions(-) diff --git a/test/common/unit/test_logger.py b/test/common/unit/test_logger.py index ef965b46..f224adff 100644 --- a/test/common/unit/test_logger.py +++ b/test/common/unit/test_logger.py @@ -2,9 +2,7 @@ def test_CustomLogRenderer_with_event(): - event_dict = { - "event": "Test", - } + event_dict = {"event": "Test"} renderer = CustomLogRenderer() assert renderer(None, None, event_dict) == "Test" diff --git a/test/common/unit/test_tools.py b/test/common/unit/test_tools.py index 55aa64e7..05fbde28 100644 --- a/test/common/unit/test_tools.py +++ b/test/common/unit/test_tools.py @@ -1,15 +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, - 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 From d54397e297faad46e4b08f1bee9c81f7dead9ed5 Mon Sep 17 00:00:00 2001 From: Salvatore Ingala <6681844+bigspider@users.noreply.github.com> Date: Mon, 13 Jul 2020 12:24:06 +0200 Subject: [PATCH 20/22] Filter out logs that are not from teos --- common/logger.py | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/common/logger.py b/common/logger.py index d48a1976..c8e031f3 100644 --- a/common/logger.py +++ b/common/logger.py @@ -1,3 +1,4 @@ +import logging import logging.config from io import StringIO import structlog @@ -71,17 +72,22 @@ def setup_logging(log_file_path, silent=False): "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}}, @@ -114,4 +120,4 @@ def get_logger(component=None): 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(component=component) + return structlog.get_logger("teos", component=component) From e2bbf0ecb9ea2c8a4b314cd0ed38b4bc02004ca0 Mon Sep 17 00:00:00 2001 From: Sergi Delgado Segura Date: Mon, 13 Jul 2020 12:30:36 +0200 Subject: [PATCH 21/22] teos - removes unnecesary log setup in API after d54397e297faad46e4b08f1bee9c81f7dead9ed5 --- teos/api.py | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/teos/api.py b/teos/api.py index 5f071493..a29f0204 100644 --- a/teos/api.py +++ b/teos/api.py @@ -285,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) From 0cf7ce1d57a81d70e7c3cc96c8b97af360b5b069 Mon Sep 17 00:00:00 2001 From: Sergi Delgado Segura Date: Mon, 13 Jul 2020 12:51:10 +0200 Subject: [PATCH 22/22] common + test - changes tab for two spaces for logger key_value_part --- common/logger.py | 2 +- test/common/unit/test_logger.py | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/common/logger.py b/common/logger.py index c8e031f3..089a40d4 100644 --- a/common/logger.py +++ b/common/logger.py @@ -39,7 +39,7 @@ def __call__(self, _, __, event_dict): # 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("\t(" + key_value_part + ")") + sio.write(" (" + key_value_part + ")") return sio.getvalue() diff --git a/test/common/unit/test_logger.py b/test/common/unit/test_logger.py index f224adff..9d4d39b5 100644 --- a/test/common/unit/test_logger.py +++ b/test/common/unit/test_logger.py @@ -35,7 +35,7 @@ def test_CustomLogRenderer_with_event_and_timestamp_and_component_and_extra_keys "aKeyBefore": 42, # should be rendered before "key", because it comes lexicographically before } renderer = CustomLogRenderer() - assert renderer(None, None, event_dict) == "today [MyAwesomeComponent] Test\t(aKeyBefore=42, key=6)" + assert renderer(None, None, event_dict) == "today [MyAwesomeComponent] Test (aKeyBefore=42, key=6)" def test_get_logger():