CODEWITHSUNDEEP
python-3.xpython-logging
Sushil
Sushil

Reputation: 11

Why custom log level not showing the correct filename (%(filename)s) in the log file in python

Added new log level verbose to the logger module. It is working, but the filename which gets logged along with it is not the correct one. It is always showing the logger module name instead of the module from where the log is getting triggered.

Below is the logger module code,

class _CustomRotatingFileHandler(logging.handlers.RotatingFileHandler):
    def __init__(self, *args, **kwargs):
        prev_umask = os.umask(0o000)
        super().__init__(*args, **kwargs)
        os.umask(prev_umask)

    def doRollover(self):
        prev_umask = os.umask(0o000)
        super().doRollover()
        os.umask(prev_umask)

def setup_logging():
    reference = 'my_project'
    date_fmt = '%(asctime)s %(levelname)s %(filename)s:%(lineno)d' \
               ' : %(message)s'

    # Defining a custom log level for verbose log level
    # selected a value between logging.INFO and logging.DEBUG
    log_level_verbose = 15

    logging.addLevelName(log_level_verbose, 'VERBOSE')
    logger = logging.getLogger(reference)
    logger.setLevel(logging.DEBUG)

    # For custom log level verbose
    log_func = lambda msg, *args, **kwargs: logger.log(log_level_verbose, msg, *args, **kwargs)  # noqa: E731
    setattr(logger, 'verbose', log_func)

    file_handler = _CustomRotatingFileHandler(
        log_file, maxBytes=10485760, backupCount=3
    )

    file_log_format = logging.Formatter(date_fmt, "%b %e %H:%M:%S")
    file_handler.setFormatter(file_log_format)
    file_handler.setLevel(log_level_verbose)

    console_handler = logging.StreamHandler(sys.stdout)
    console_log_format = logging.Formatter("%(message)s")
    console_handler.setFormatter(console_log_format)
    console_handler.setLevel(logging.INFO)

    logger.handlers = [file_handler, console_handler]
    return logger

The verbose level created here is to log message only to the log file and not to console. The flow is, main.py creates the logger object by calling setup_logging and this logger object passed to test_module.py function for execution and logging.

The log file content is something like below where VERBOSE message is getting logged only in the file (as expected) but the filename logged along with it is wrong, it should be test_module.py

Feb  4 16:54:31 INFO main.py:151 : ----------------------
Feb  4 16:54:31 INFO main.py:152 : Executing command for 'task1'
Feb  4 16:54:31 INFO main.py:153 : ----------------------
Feb  4 16:54:31 INFO test_module.py:34 : Executing command 'ls -ltr'
Feb  4 16:54:31 VERBOSE log.py:88 : Some verbose log message
Feb  4 16:54:32 INFO test_module.py:37 : Result: total 24
-rwxr-xr-x. 1 root root 20606 Jan 13 13:31 main.py
Feb  4 16:54:32 INFO main.py:160 : Completed

Currently for the VERBOSE log, I'm getting the log message as below,

Feb 4 16:54:31 VERBOSE log.py:88 : Some verbose log message

The expected log message with correct filename should be as below,

Feb 4 16:54:31 VERBOSE test_module.py:35 : Some verbose log message

Upvotes: 1

Views: 169

Answers (1)

Sushil
Sushil

Reputation: 11

Finally I got the answer. Here is the line of the code that got modified,

# For custom log level verbose
log_func = lambda msg, *args, **kwargs: logger._log(log_level_verbose, msg, args, **kwargs)  # noqa: E731

Changed from logger.log to logger._log and argument *args changed to args.

I found the precise reason behind this in one of the comments for an answer in How to add a custom loglevel to Python's logging facility by @rivy. Below is the explanation,

Using _log() instead of log() is needed to avoid introducing an extra level in the call stack. If log() is used, the introduction of the extra stack frame causes several LogRecord attributes (funcName, lineno, filename, pathname, ...) to point at the debug function instead of the actual caller.

And this is exactly the reason why filename was not working correctly with logger.log

Upvotes: 0

Related Questions