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')?

• Reinderien: See also stackoverflow.com/a/68154386/313768

Answer 1

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.