Refactor logs using structlog

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 = {

cli/requirements.txt

@@ -1,2 +1,3 @@
 cryptography
 requests
+structlog

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"))

common/logger.py

@@ -1,96 +1,124 @@
-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 _repr(self, val):
+        """Returns the representation of *val* if it's not a ``str``."""
+        return val if isinstance(val, str) else repr(val)
 
-    def _add_prefix(self, msg):
-        return msg if self.actor is None else "[{}]: {}".format(self.actor, msg)
+    def __call__(self, _, __, event_dict):
+        """Returns ``event_dict`` rendered as a string."""
+        sio = StringIO()
 
-    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"])
+        ts = event_dict.pop("timestamp", None)
+        if ts:
+            sio.write(str(ts) + " ")
 
-        # 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"])
+        component = event_dict.pop("component", None)
+        if component:
+            sio.write("[" + component + "] ")
 
-            # Remove the extra 2 characters (space and comma) and add all data to the final message.
-            message += " ({})".format(params[:-2])
+        event = self._repr(event_dict.pop("event"))
 
-        return message
+        sio.write(event)
 
-    @staticmethod
-    def _create_file_message(msg, **kwargs):
-        return json.dumps(_StructuredMessage(msg, **kwargs).to_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)
 
-    def info(self, msg, **kwargs):
-        """
-        Logs an ``INFO`` level message to stdout and file.
+        return sio.getvalue()
 
-        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 setup_logging(log_file_path, silent=False):
+    """
+    Configures the logging options. It must be called only once, before using get_logger.
 
-    def error(self, msg, **kwargs):
-        """
-        Logs an ``ERROR`` level message to stdout and file.
+    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.
 
-        Args:
-             msg (:obj:`str`): the message to be logged.
-             kwargs (:obj:`dict`): a ``key:value`` collection parameters to be added to the output.
-        """
+    Raises:
+        :obj:`RuntimeError` setup_logger had already been called.
+    """
 
-        self.f_logger.error(self._create_file_message(msg, **kwargs))
-        self.c_logger.error(self._create_console_message(msg, **kwargs))
+    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,
+                },
+            },
+            "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.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.
 
-    def warning(self, msg, **kwargs):
-        """
-        Logs a ``WARNING`` level message to stdout and file.
+    Returns:
+        a proxy obtained from structlog.get_logger with the `component` as bound variable.
 
-        Args:
-             msg (:obj:`str`): the message to be logged.
-             kwargs (:obj:`dict`): a ``key:value`` collection parameters to be added to the output.
-        """
+    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(component=component)
 
-        self.f_logger.warning(self._create_file_message(msg, **kwargs))
-        self.c_logger.warning(self._create_console_message(msg, **kwargs))

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)

requirements.txt

@@ -6,4 +6,5 @@ coincurve
 pyzbase32
 requests
 plyvel
-readerwriterlock
+readerwriterlock
+structlog

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 = {

teos/api.py

@@ -2,21 +2,20 @@
 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
 
 
 # ToDo: #5-add-async-to-api
 app = Flask(__name__)
-logger = Logger(actor="API", log_name_prefix=LOG_PREFIX)
+logger = get_logger(component="API")
 
 
 # NOTCOVERED: not sure how to monkey path this one. May be related to #77