TLDR
How can I get a custom logging level to accurately find out the pathname?
Problem description
When I try and add my own custom logging levels (e.g. for very verbose program tracing) I want to print the pathname. For most of the standard loggers, it is able to get this correctly, but for my own custom loggers, these all ultimately call logging.log(levelNum, message, *args, **kwargs) with levelNum as my custom level number. This means that only this line is ever printed, not the desired line.
A similar issue was raised here: Python, logging: wrong pathname when extending Logger and in this comment by "Aya" they say:
actually, you can get the correct pathname, but it's much more complicated [...]
I am currently using the formatter approach outlined here, and the adding of the log levels outlined here.
Is there a way to get the desired behaviour?
Some example code
The output from the below is:
/Users/oliver/ClionProjects/testing/venv/bin/python3 /Users/oliver/ClionProjects/testing/misc/misc.py
writing some logs...
DEBUG: (/Users/oliver/ClionProjects/testing/misc/misc.py:90) something debug message
TRACE: (/Users/oliver/ClionProjects/testing/venv/lib/python3.11/site-packages/haggis/logs.py:211) something trace message
[2023-08-18 19:10:17,539]: WARNING: (/Users/oliver/ClionProjects/testing/misc/misc.py:92) something warning message
Process finished with exit code 0
Notably, the trace line is showing the wrong file path...
The code:
#!/usr/bin/env python3
"""
Some wrapping around the default logging module.
"""
import logging
import sys
from haggis.logs import add_logging_level
from termcolor import colored
class MyFormatter(logging.Formatter):
"""A nice formatter for logging messages."""
line_formatting = f" {colored('(%(pathname)s:%(lineno)d)', 'light_grey')}"
timestamp_formatting = f"{colored('[%(asctime)s]: ', 'green')}"
trace_format = f"{colored('TRACE', 'cyan')}:{line_formatting} %(msg)s"
debug_format = f"{colored('DEBUG', 'magenta')}:{line_formatting} %(msg)s"
info_format = f"{colored('INFO', 'blue')}:{line_formatting} %(msg)s"
print_format = f"%(msg)s"
warning_format = f"{timestamp_formatting}{colored('WARNING', 'yellow')}:{line_formatting} %(msg)s"
error_format = f"{timestamp_formatting}{colored('ERROR', 'red')}:{line_formatting} %(msg)s"
critical_format = f"{timestamp_formatting}{colored('CRITICAL', 'red', attrs=['reverse', 'blink', 'bold'])}: {line_formatting} %(msg)s"
def __init__(self):
super().__init__(fmt=f"UNKNOWN: %(msg)s", datefmt=None, style='%')
def format(self, record):
# Save the original format configured by the user
# when the logger formatter was instantiated
format_orig = self._style._fmt
# Replace the original format with one customized by logging level
if record.levelno == logging.TRACE:
self._style._fmt = MyFormatter.trace_format
elif record.levelno == logging.DEBUG:
self._style._fmt = MyFormatter.debug_format
elif record.levelno == logging.INFO:
self._style._fmt = MyFormatter.info_format
elif record.levelno == logging.PRINT:
self._style._fmt = MyFormatter.print_format
elif record.levelno == logging.WARNING:
self._style._fmt = MyFormatter.warning_format
elif record.levelno == logging.ERROR:
self._style._fmt = MyFormatter.error_format
elif record.levelno == logging.CRITICAL:
self._style._fmt = MyFormatter.critical_format
else:
raise NotImplementedError(f"We don't know how to format logging levels: {record.levelno}")
# Call the original formatter class to do the grunt work
result = logging.Formatter.format(self, record)
# Restore the original format configured by the user
self._style._fmt = format_orig
return result
class StdOutFilter(logging.Filter):
def filter(self, rec):
return rec.levelno <= logging.PRINT
class StdErrFilter(logging.Filter):
def filter(self, rec):
stdout_filter = StdOutFilter()
return not stdout_filter.filter(rec)
def setup_console_output():
fmt = MyFormatter()
stdout_handler = logging.StreamHandler(sys.stdout)
stdout_handler.setFormatter(fmt)
stdout_handler.addFilter(StdOutFilter())
logging.root.addHandler(stdout_handler)
stderr_handler = logging.StreamHandler(sys.stderr)
stderr_handler.setFormatter(fmt)
stderr_handler.addFilter(StdErrFilter())
logging.root.addHandler(stderr_handler)
add_logging_level('TRACE', logging.DEBUG - 5)
add_logging_level('PRINT', logging.WARNING - 5)
if __name__ == "__main__":
logging.root.setLevel(logging.TRACE)
setup_console_output()
print("writing some logs...")
logging.debug("something debug message")
logging.trace("something trace message")
logging.warning("something warning message")
