Log Breadcrumbs: only show Logs leading up to an Error

In this article, we’ll explore a way to efficiently log breadcrumbs, showing only the logs that lead up to an error. We’ll only use Python’s standard logging library to create an efficient logging setup that capture debug logs only when an exception occurs. This approach provides a detailed view of the steps leading up to a problem while reducing clutter and minimizing I/O. Let’s code!

Why Log Breadcrumbs?

When an error occurs you want to have as much information as possible to lead you to the problem in your code. Logging a lot of information is very useful in this respect. 

The downside is that all of these logs need to be processed. Then need to be written to a file or sent to an endpoint over HTTP, which might impact the performance of your app or server. Additionally it might clutter up your logs, making it harder to find relevant information when an error occurred. 

The breadcrumbs-approach “ignores” e.g. all debug logs unless an error occurs. This allows you to both log a lot of detail information about your error and keep performance and overview at level.

Setting up the breadcrumb trail

Below is a simple function, divide, with debug logs that help track its internal behavior. Ideally we don’t want to see the log every time, just when an error occurs so that we can see wich two numbers the function tried to divide. 

def divide(a, b):
    logger.debug(f"Dividing [{a}] by [{b}]")
    return a / b


for value in [1, 2, 3, 4, 5, 6, 7, 8, 9, 'not a number', 0]:
    try:
        logger.debug(f"start dividing..")
        res = divide(a=10, b=value)
    except Exception as e:
        logger.error(f"❌An exception occurred: {e}")

The first few values (1 till 9) divide successfully and don’t necessarily need the debug logs in these cases. 

For faulty inputs like not a number and 0, however, capturing the debug logs would provide valuable context. Our. How can we go back in time and retrieve the logs?

Turn Your Python Function into a Decorator with One Line of Code

A new way to write shorter, clearer, and more readable Python decorators that also act as a context manager

MikeHuls.comMike Huls

Solution overview

To create breadcrumbs we’ll configure our logger with two handlers:

• StreamHandler: Display only INFO-level messages and above
• MemoryHandler: Stores DEBUG messages temporarily and passes them to the StreamHandler only when an error occurs

This setup will not display DEBUG logs since the StreamHandler is set to INFO. We can store DEBUG messages in the MemoryHandler temporarily and, when we detect an error, flush the messages to the StreamHandler. This will then display the stored DEBUG messages.

Configuring the logger

Here’s how we configure the logger with a StreamHandler for regular output and a MemoryHandler for buffered DEBUG logs:

import logging
from logging.handlers import MemoryHandler

# Create logger and formatter for a structured log message
logger = logging.getLogger("my_logger")
formatter = logging.Formatter(
    fmt="%(levelname)-7s ⏱️%(asctime)s  📍%(funcName)12s:%(lineno)-2s  💌%(message)s", 
    datefmt="%H:%M:%S"
)

# Configure stream handler
stream_handler = logging.StreamHandler()
stream_handler.setLevel(logging.INFO)  # Only INFO and above will be displayed
stream_handler.setFormatter(formatter)
logger.addHandler(stream_handler)

# Configure memory handler
memory_handler = MemoryHandler(capacity=100, target=stream_handler, flushLevel=logging.ERROR)
memory_handler.setFormatter(formatter)
logger.addHandler(memory_handler)

In the setup above, the MemoryHandler buffers up to 100 log entries, flushing them only when an error occurs.

In the setup above, the MemoryHandler buffers up to 100 log entries. If an error occurs, we can flush the logs from the MemoryHandler to the StreamHandler, giving us a full breadcrumb trail.

How to Store and Query 100 Million Items Using Just 77MB with Python Bloom Filters

Perform lightning-fast, memory efficient membership checks in Python with this need-to-know data structure

MikeHuls.comMike Huls

Using the Breadcrumb Logger in Code

Here’s a demonstration of the newly configured logger. Notice the finally block, where we clear the buffer after each attempt, keeping debug logs specific to each operation.

def divide(a, b):
    logger.debug(f"Dividing [{a}] by [{b}]")
    return a / b

for value in [1, 2, 3, 4, 5, 6, 7, 8, 9, 'not a number', 0]:
    try:
        logger.debug("Start dividing..")
        res = divide(a=10, b=value)
    except Exception as e:
        logger.error(f"❌ An exception occurred: {e}")
    finally:
        memory_handler.buffer.clear()  # Clear memory after each pass

Up till not a number, we won’t see any logs since all preceding values execute without an error. When we process not a number, however, the divide function throws an exception since we cannot divide integers by strings. 

We end up in the except block and log an ERROR. We’ve configured the MemoryHandler to flush all buffered logs to the StreamHandler when it encounters an ERROR and that is exactly what will happen in this example. 

Lastly, we clear the buffer in the finally block so that the DEBUG logs from 9 are removed when we start processing not a number.

Sample output

When we run the final code, only logs for erroneous cases will show the debug messages as breadcrumbs. Here’s what the full output looks like:

# Logs corresponding to 'not a number'
ERROR   ⏱️17:07:03  📍main:44    💌❌ An exception occurred: unsupported operand type(s) for /: 'int' and 'str'
DEBUG   ⏱️17:07:03  📍main:41    💌Start dividing..
DEBUG   ⏱️17:07:03  📍divide:32  💌Dividing [10] by [not a number]

# Logs corresponding to 0
ERROR   ⏱️17:07:03  📍main:44    💌❌ An exception occurred: division by zero
DEBUG   ⏱️17:07:03  📍main:41    💌Start dividing..
DEBUG   ⏱️17:07:03  📍divide:32  💌Dividing [10] by [0]

In these examples, the MemoryHandler has captured and flushed the debug logs only on encoutering an error, providing a clear breadcrumb trail to that provides valuable information about the errors.

Applying Python multiprocessing in 2 lines of code

When and how to use multiple cores to execute many times faster

MikeHuls.comMike Huls

Conclusion

With this setup, we achieve a leaner logging process by buffering debug logs and only displaying them only upon encountering an error. This breadcrumb-style approach is ideal for applications where performance and log volume management are critical. The MemoryHandler gives us the best of both worlds: detailed tracing when we need it and minimized log volume when we don’t.

I hope this article was as clear as I hope it to be but if this is not the case please let me know what I can do to clarify further. In the meantime, check out my other articles on all kinds of programming-related topics.

Happy coding!

— Mike

P.s: like what I'm doing? Follow me!