Search code examples
pythonloggingstack-traceformatter

Python - How to print stack trace at all log levels and even outside exceptions?


My codebase is extremely large, and we’d like to print the stack for all logs.

This includes logs at all levels (even INFO and DEBUG).

This also includes logs outside of an exception happening.

Things I have learned:

  • stack traces do not show up unless you’re inside an except: when calling logger.exception, set_exec=True, trace back.print_exc()
  • only way I’ve found to show stack is traceback.print_stack()
  • I would now like all my logs to print this, but I don’t know how to override logger.debug/info/warning/error to add traceback.print_stack()
  • Is this possible using a formatter? If not, is it possible to override the logger.info() method before it sends to the formatter?
  • Any other suggestions?

Solution

  • You are on the right track. I recommend that you read the logging HOWTO, it explains a lot of things.

    You can use levels and filters to decide if your handler should handle or not the log. And you can use a Formatter to add the stacktrace to the log record message.

    Here is a Proof-of-Concept :

    import logging
    import traceback
    import sys
    
    
    logger = logging.getLogger("app.main")
    
    
    class StacktraceLogFormatter(logging.Formatter):
        def format(self, record: logging.LogRecord) -> str:
            stack_lines = traceback.format_stack()
            # we have the lines down to ^^^^^^ this call, but we don't want to show it, nor the internal logging ones
            stack_lines_without_logging_intermediary_calls = filter(
                lambda line: ("lib/logging/__init__.py" not in line)
                             and ("lib\\logging\\__init__.py") not in line,
                stack_lines[:-1]
            )
            return record.msg + "\nOrigin :\n" + "".join(stack_lines_without_logging_intermediary_calls)
            # beware of : https://stackoverflow.com/q/8162419/11384184
    
    
    class InfoOrLessFilter(logging.Filter):
        def filter(self, record: logging.LogRecord) -> bool:
            return record.levelno <= logging.INFO
    
    
    def do_some_logging():
        logger.debug("debug message")
        logger.info("info message")
        logger.warning("warning message")
        logger.error("error message")
        try:
            1/0
        except ZeroDivisionError:
            logger.exception("exception message")
        logger.critical("critical message")
    
    
    def setup_custom_logging():
        logger.handlers = []  # remove the existing handlers from the logger
    
        regular_handler_for_info_messages = logging.StreamHandler(sys.stdout)
        regular_handler_for_info_messages.setLevel(logging.DEBUG)  # at least DEBUG
        regular_handler_for_info_messages.addFilter(InfoOrLessFilter())  # but not more than INFO
        logger.addHandler(regular_handler_for_info_messages)
    
        stacktrace_handler_for_important_messages = logging.StreamHandler(sys.stderr)
        stacktrace_handler_for_important_messages.setLevel(logging.INFO + 1)  # more than INFO
        stacktrace_handler_for_important_messages.setFormatter(StacktraceLogFormatter())
        logger.addHandler(stacktrace_handler_for_important_messages)
    
        logger.propagate = False
    
    
    def main():
        logging.basicConfig(level=logging.DEBUG)
        do_some_logging()
        setup_custom_logging()
        do_some_logging()
    
    
    if __name__ == "__main__":
        main()
    

    It produces before :

    debug message
    info message
    DEBUG:app.main:debug message
    INFO:app.main:info message
    WARNING:app.main:warning message
    ERROR:app.main:error message
    ERROR:app.main:exception message
    Traceback (most recent call last):
      File "C:/PycharmProjects/stack_overflow/67846424.py", line 43, in do_some_logging
        1/0
    ZeroDivisionError: division by zero
    CRITICAL:app.main:critical message
    

    and after :

    warning message
    Origin :
      File "C:/PycharmProjects/stack_overflow/67846424.py", line 73, in <module>
        main()
      File "C:/PycharmProjects/stack_overflow/67846424.py", line 69, in main
        do_some_logging()
      File "C:/PycharmProjects/stack_overflow/67846424.py", line 40, in do_some_logging
        logger.warning("warning message")
    
    error message
    Origin :
      File "C:/PycharmProjects/stack_overflow/67846424.py", line 73, in <module>
        main()
      File "C:/PycharmProjects/stack_overflow/67846424.py", line 69, in main
        do_some_logging()
      File "C:/PycharmProjects/stack_overflow/67846424.py", line 41, in do_some_logging
        logger.error("error message")
    
    exception message
    Origin :
      File "C:/PycharmProjects/stack_overflow/67846424.py", line 73, in <module>
        main()
      File "C:/PycharmProjects/stack_overflow/67846424.py", line 69, in main
        do_some_logging()
      File "C:/PycharmProjects/stack_overflow/67846424.py", line 45, in do_some_logging
        logger.exception("exception message")
    
    critical message
    Origin :
      File "C:/PycharmProjects/stack_overflow/67846424.py", line 73, in <module>
        main()
      File "C:/PycharmProjects/stack_overflow/67846424.py", line 69, in main
        do_some_logging()
      File "C:/PycharmProjects/stack_overflow/67846424.py", line 46, in do_some_logging
        logger.critical("critical message")