Get more out of your logs with lightweight stacktraces

2025-05-23

I mostly work in Python, within a largish code base. When debugging a non-obvious problem, such as when the stacktrace is insufficient, I turn to the logs. Logging is an invaluable debugging tool, but it is not always a primary concern of the application. You're likely to discover that your logs are lacking when you need them the most, debugging an annoying and hard to reproduce bug.

To get the most out of logs without too much effort, I find it best to focus on logging at the edge of the application: external API calls, HTTP requests, IO, DB access, ... With logging in only a few key places, you can trace the interactions with the outside world. The drawback is that those logs lack context, sure you can see the API call, but why was it made? One way to solve that is by adding that missing context manually, for example with logging at higher levels. That requires work touching a lot of code, so I went for a lazier approach: rely on the stack for context by including a stacktrace on each log message.

The Python standard logging module supports including a stacktrace by passing stack_info=True to log calls. It's rather verbose as it includes the filename, line number, function name and line of code for each frame. All we really need are the filename and line number: the rest can be derived from the code base with the right commit hash.

The below examples demonstrates reconstructing the necessary context from limited logs. The raw logs only include the filename and line number of each frame for the stacktrace. By combining that with the code base, we can find the function name and let the user trace the execution through the code. The program does a single HTTP request using httpx, it relies on the logging already done by that library. It does a GET request to https://www.example.com, we can figure out why by looking at the stack: the request is done by the get_title() function.

Since the logging is deep in the stack, you can see the internal httpx library calls with links to the code. This has proven useful in real cases for debugging issues coming from third party code!

DEBUG: Starting program
stack: example.py:13
       example.py:16
INFO: HTTP Request: GET https://www.example.com "HTTP/1.1 200 OK"
stack: httpx/_client.py:1025
       httpx/_client.py:979
       httpx/_client.py:942
       httpx/_client.py:914
       httpx/_client.py:825
       httpx/_api.py:109
       httpx/_api.py:195
       web.py:9
       web.py:14
       example.py:9
       example.py:14
       example.py:16
INFO: Title is: Example Domain
stack: example.py:10
       example.py:14
       example.py:16

import logstack
import logging
import web
import sys

LOGGER = logging.getLogger(__name__)

def process_website(url: str) -> None:
    title = web.get_title(url)
    LOGGER.info("Title is: %s", title)

def main():
    LOGGER.debug("Starting program")
    process_website(sys.argv[1])

main()

import logging
import httpx

LOGGER = logging.getLogger(__name__)

def get_check_status(
    url: str,
) -> httpx.Response:
    response = httpx.get(url)
    assert response.status_code == 200
    return response

def get_title(url: str) -> str:
    response = get_check_status(url)
    title = response.text.split(
        '<title>',
        1
    )[1].split('</title>', 1)[0]
    return title

example.py:13 at main()
example.py:16 at __main__

httpx/_client.py:1025 at Client._send_single_request()
httpx/_client.py:979 at Client._send_handling_redirects()
httpx/_client.py:942 at Client._send_handling_auth()
httpx/_client.py:914 at Client.send()
httpx/_client.py:825 at Client.request()
httpx/_api.py:109 at request()
httpx/_api.py:195 at get()
web.py:9 at get_check_status()
web.py:14 at get_title()
example.py:9 at process_website()
example.py:14 at main()
example.py:16 at __main__

example.py:10 at process_website()
example.py:14 at main()
example.py:16 at __main__

(You can find the code for the demo on Gitlab.)

Smaller stacktrace

In the above approach, each stack frame is represented by filename:lineno, which is not particularly space efficient. With a compiled language, you can instead store the return address of each stack frame, as possible with the backtrace function. You then only need one pointer per stack frame. The addresses can be resolved back to source code and function names using debug information just like debuggers.

This is demonstrated in the below example. The raw logs only contain the stack return addresses, which are resolved using addr2line when processing the logs. The code is compiled with optimizations disabled and debugging symbols included: gcc -O0 -g stack.c, to prevent functions from being inlined and allow addr2line to resolve to source code. It works for this simple case, I expect in real applications you would for example need to deal with address randomization.

INFO: Example log
@ 0x401211
@ 0x401244
INFO: Example log
@ 0x401211
@ 0x401226
@ 0x40124e

#include "log.c"

void example_function() {
    log_backtrace("Example log");
}

void indirect_call() {
    example_function();
}

int main(int argc, char *argv[]) {
    example_function();
    indirect_call();
    return 0;
}

stack.c:4 at example_function()
stack.c:12 at main()

stack.c:4 at example_function()
stack.c:8 at indirect_call()
stack.c:13 at main()

Closing thoughts

I spend quite some time debugging problems by going through logs, and having access to a stacktrace is like a small superpower: I can trace how code I don't know is calling into my code instead of having to guess from other context. By focusing on storing the bare minimum and computing the rest after the fact, it is lightweight enough to be added and stored with each log message.

While this is nothing particularly novel, I'm always enthusiastic about simple ways to extract value out of a code base. I implemented it in Python but I am curious how performant it could be made by implementing it at a lower level and pushing as much as possible into pre and post-processing.