1

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?
  • 1
    You want the entire stack trace to be included in every single log message, wouldn't that make your logs incredibly noisy? Would the message you pass to log call appear before or after, on a new line? – Iain Shelvington Jun 05 '21 at 05:03
  • If there's something wrong with the code and you really expect that this level of detail in logging information will be either required or helpful in figuring out the problem... have you considered using a debugger instead? Actually, first off, is the problem *reproducible*? – Karl Knechtel Jun 05 '21 at 05:13
  • correct, it will be incredibly noisy, we may have some controls to filter which logs should have entire stack traces. regardless, we certainly want at least our error level logs to always have a stack trace, and these logs don't necessarily come from when an exception is caught – AncientArtOfDesign Jun 05 '21 at 05:37
  • it will be very noisy ,and first you can consider debugging if that doesnt sollve the issue then dwell into stacktrace. – Ishika Mishra Jun 05 '21 at 05:57

1 Answers1

2

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")
Lenormju
  • 4,078
  • 2
  • 8
  • 22