Improvements to logger and how to correctly use it

Question

I am working on a project, neurodecode, which uses a logger based on the logging library. As I am not very familiar with logging, I don't know how to further improve this aspect of the project.

The project is constructed as:

neurodecode
|_ __init__.py
|_ logger.py
|_ folder1
    |_ script1.py
    |_ script2.py
...

The logger.py contains: (I removed the docstring to compact the code).

import sys
import logging

LOG_LEVELS = {
    'DEBUG': logging.DEBUG,
    'INFO': logging.INFO,
    'WARNING': logging.WARNING,
    'ERROR': logging.ERROR
}


def init_logger(logger, verbosity='INFO'):
    if not logger.hasHandlers():
        logger.setLevel(verbosity)
        add_logger_handler(logger, sys.stdout, verbosity=verbosity)


def add_logger_handler(logger, stream, verbosity='INFO'):
    c_handler = logging.StreamHandler(stream)
    c_handler.setFormatter(neurodecodeFormatter())
    logger.addHandler(c_handler)

    set_log_level(logger, verbosity, -1)

    return logger


def set_log_level(logger, verbosity, handler_id=0):
    logger.handlers[handler_id].level = LOG_LEVELS[verbosity]


class neurodecodeFormatter(logging.Formatter):
    # Format string syntax for the different Log levels
    fmt_debug = "[%(module)s:%(funcName)s:%(lineno)d] DEBUG: %(message)s (%(asctime)s)"
    fmt_info = "[%(module)s.%(funcName)s] %(message)s"
    fmt_warning = "[%(module)s.%(funcName)s] WARNING: %(message)s"
    fmt_error = "[%(module)s:%(funcName)s:%(lineno)d] ERROR: %(message)s"

    def __init__(self, fmt='%(levelno)s: %(message)s'):
        super().__init__(fmt)

    def format(self, record):
        if record.levelno == LOG_LEVELS['DEBUG']:
            self._fmt = self.fmt_debug
        elif record.levelno == LOG_LEVELS['INFO']:
            self._fmt = self.fmt_info
        elif record.levelno == LOG_LEVELS['WARNING']:
            self._fmt = self.fmt_warning
        elif record.levelno >= LOG_LEVELS['ERROR']:
            self._fmt = self.fmt_error

        self._style = logging.PercentStyle(self._fmt)

        return logging.Formatter.format(self, record)

And the __init__.py contains:

import logging

from .logger import init_logger

# set loggers
logging.getLogger('matplotlib').setLevel(logging.ERROR)
logger = logging.getLogger('neurodecode')
logger.propagate = False
init_logger(logger, verbosity='INFO')

First, do you see any improvements which could be made to those 2 parts? Maybe I could add from .logger import set_log_level to the __init__.py to be able to set the log level as neurodecode.set_log_level().

Second, in the different subfolders and scripts, I am using the logger as:

from pathlib import Path
from .. import logger # relative import vary depending on the script

class Foo:
    def __init__(self, param1, param2):
        self.param1 = str(param1)
        logger.info(f'Param1 set as {self.param1}')
        param2 = Foo._check_param2(param2)

    def method_to_do_stuff(self, n):
        try:
            # do stuff
            x = 2/n
        except Exception as error:
            logger.error('Something didn't work..')
            raise error

    @staticmethod
    def _check_param2(param2):
        # let's imagine it's a path -> pathlib
        param2 = Path(param2)
        if not param2.exists():
            logger.error('The path to param2 was not found')
            raise IOError

In this dummy example above, which sums up well most of my use case of the logger, I feel like I am not using it correctly. Shouldn't the logger catch the exception and the message attached directly, e.g. with raise IOError('The path to param2 was not found')?

\$\begingroup\$ See also stackoverflow.com/a/68154386/313768 \$\endgroup\$

Reinderien
– Reinderien

2021-06-27 18:56:58 +00:00
Commented Jun 27, 2021 at 18:56 — Reinderien
– Reinderien, Commented Jun 27, 2021 at 18:56

Reinderien · Accepted Answer · 2021-06-27 18:05:14Z

Part of your interface accepts strings as levels, and you have a string-level mapping. Why? There are standard symbols available from the logging library for anyone to use. There is no advantage to passing around stringly-typed levels, and in fact the standard levels being integral is a feature. It's entirely possible for a user to want to pass in a level integer that does not have an entry in your map and it should still behave well. So I would suggest dropping your LOG_LEVELS entirely, accepting verbosity: int (for which you should have a type hint), and replacing this:

    if record.levelno == LOG_LEVELS['DEBUG']:
        self._fmt = self.fmt_debug
    elif record.levelno == LOG_LEVELS['INFO']:
        self._fmt = self.fmt_info
    elif record.levelno == LOG_LEVELS['WARNING']:
        self._fmt = self.fmt_warning
    elif record.levelno >= LOG_LEVELS['ERROR']:
        self._fmt = self.fmt_error

with something that respects ranges instead, i.e.

if record.levelno <= logging.DEBUG:
    self._fmt = self.fmt_debug
elif record.levelno <= logging.INFO:
    self._fmt = self.fmt_info
elif record.levelno <= logging.WARNING:
    self._fmt = self.fmt_warning
else:
    self._fmt = self.fmt_error

That said, there are other problems with the above:

neurodecodeFormatter should be NeurodecodeFormatter by PEP8
Rather than baking in DEBUG: etc. in your format string, just use %(levelname)
logging.Formatter.format(self, record) should use super()
I question setting self._fmt and relying on it not to change while the super's implementation of format() uses it. I realize that's how the accepted answer on SO does it, but don't trust everything you read on SO. This introduces a concurrency vulnerability where two threaded calls to the same formatter will have unpredictable results - which _fmt assignment will win? You could either add a lock and keep doing what you're doing, which is not awesome; or you could keep surrogate formatter instances - one for every level - and call into them while avoiding mutating your own instance or theirs. I would recommend the latter.

I recommend changing

    try:
        # do stuff
        x = 2/n
    except Exception as error:
        logger.error('Something didn't work..')
        raise error

to

    try:
        # do stuff
        x = 2/n
    except Exception:
        logger.error("Something didn't work..", exc_info=True)
        raise

There's no need to keep a reference to the exception at all; and you should be including the stack trace. Also your quote syntax was wrong.

Shouldn't the logger catch the exception

Absolutely not. Loggers are not for exception catching; they're for exception logging.

Stack Exchange Network

Improvements to logger and how to correctly use it

1 Answer 1

You must log in to answer this question.

Hot Network Questions

Improvements to logger and how to correctly use it

1 Answer 1

You must log in to answer this question.

Related

Hot Network Questions