Based on a discussion on IRC and Mastodon: “How can I get access to the return values of my (Python-) programs functions?” And more generally, how can I trace function execution in Python, showing function parameters and return values?

PyCharm builtin method

Of course, you can always simply turn on this in the PyCharm debugger:

PyCharm, Debug Window, Gear Icon, “Show Return Values”

Do it yourself: sys.settrace()

(via Peterkelly ): Python has a built-in API for tracing: sys.settrace() .

Here’s an example of how to use it:

def mytrace(frame, event, arg):
    if event == "call":
        print("call", frame.f_code.co_name, frame.f_locals)
    elif event == "return":
        print("return", frame.f_code.co_name, arg)
    return mytrace

import sys
sys.settrace(mytrace)

def fac(n: int) -> int:
if n == 1:
    return 1
else:
    return n * fac(n - 1)

if __name__ == '__main__':
    result = fac(3)
    print(f"{result=}")

This will output:

call fac {'n': 3}
call fac {'n': 2}
call fac {'n': 1}
return fac 1
return fac 2
return fac 6
result=6

Do it yourself: @logging

You can also implement such a thing from first principles, in Python:

import functools


def args_to_str(*args):
    return ", ".join(map(str, args))


def kwargs_to_str(**kwargs):
    ret = ""
    for k, v in kwargs.items():
        ret += f"{k}={v},"

    return ret[:-1]


def logging(func):
    func.__indent__ = 0

    @functools.wraps(func)
    def wrapper_logging(*args, **kwargs):
        func_indent = " " * func.__indent__
        func.__indent__ += 2

        func_name = func.__qualname__
        func_args = args_to_str(*args)
        func_kwargs = kwargs_to_str(**kwargs)

        print(f"{func_indent} -> Enter: {func_name}({func_args}", end="")
        if func_kwargs != "":
            print(f", {func_kwargs}", end="")
        print(")")

        result = func(*args, **kwargs)

        print(f"{func_indent} <- Leave: {func_name}({result})")
        return result

    return wrapper_logging


@logging
def fac(n: int) -> int:
    if n == 1:
        return 1
    else:
        return n * fac(n - 1)


if __name__ == '__main__':
    result = fac(3)
    print(f"{result=}")

This makes use of @functools.wraps() to define a decorator , @logging. It also leverages the fact, that anything, including a callable, can have properties, which we are using to maintain an indent count in func.__indent__. This is initialized to 0, and then incremented by 2 for each call in the call stack. Unwinding the call stack resets the counter, so we don’t have to do that manually.

We have two helper functions to turn the functions *args and **kwargs into proper strings, and we access func.__qualname__ to get the functions name . We are using __qualname__ to handle inner functions properly here, even if that is sometimes creating less readable output.

Running the code results in

Output from the Python program above shows function calls and results.

Using autologging

The autologging package makes this simpler, even if it lacks the nice indentation.

Our code becomes much shorter:

import logging
import sys
from autologging import logged, traced, TRACE

logging.basicConfig(
    level=TRACE,
    stream=sys.stdout,
    format="%(levelname)s:%(name)s:%(funcName)s:%(message)s"
)


@logged
@traced
class Fac:
    def __init__(self):
        pass

    def fac(self, n: int) -> int:
        self.__log.debug("OHAI")

        if n == 1:
            return 1
        else:
            return n * self.fac(n - 1)


if __name__ == '__main__':
    f = Fac()
    print(f.fac(10))

We get to use a new loglevel TRACE, and import @logged and @traced decorators from the package. After setting up a log channel with proper formatting, we can mark functions with the decorator, get their execution traced and can simply log.

The output:

Output of our program using the autologging package.

Using icecream

At this point Andreas Thienemann mentioned icecream, which is remarkable comfortable. Versions of icecream exist for many programming languages, so this is not Python specific.

from icecream import ic

ic.configureOutput(includeContext=True)


class Fac:
    def __init__(self):
        pass

    def fac(self, n: int) -> int:
        ic(n)
        if n == 1:
            return ic(1)
        else:
            return ic(n * self.fac(n - 1))


if __name__ == '__main__':
    f = Fac()
    print(f.fac(10))

Icecream defined a function ic(), which you can call with parameters (ic(n), ic(1), and ic(n * self.fac(n - 1))), or without (ic()). The function will print its parameters, just like a debug print, or when called without parameters, just log its execution including source file and line. Options to prettify the output exist.

The package also provides a function install(), which will simply make ic() available as a builtin:

from icecream import ic
install()
# this basically does builtin.ic = ic

# ic() is now available in all your modules 
# without having to include it in every submodule.

The output looks like this:

Running our code with icecream produces this output, nicely colorized and pretty printed. We enabled includeContext=True, so we also get file names and line numbers.

snoop and birdseye

Of course, this is not the end of it. The package snoop provides tracing of one or all functions, comes with its own version of icecream called pp (PrettyPrint). Using pp.deep(), it will show expression evaluation step by step.

from snoop import pp
pp.deep(lambda: x + 1 + max(y + 2, y + 3))

logs

12:34:56.78 LOG:
12:34:56.78 ............ x = 1
12:34:56.78 ........ x + 1 = 2
12:34:56.78 ................ y = 2
12:34:56.78 ............ y + 2 = 4
12:34:56.78 ................ y = 2
12:34:56.78 ............ y + 3 = 5
12:34:56.78 ........ max(y + 2, y + 3) = 5
12:34:56.78 .... x + 1 + max(y + 2, y + 3) = 7

Snoop understands Python: It shows not just file numbers, but actual code call context, parameters. It handles debugging Decorators, can log Exceptions properly, and can log call stacks of a configurable depth.

Check out the examples in the link above.

birdseye is a continuation of snoop to the extreme, and integrated with it. It captures the same data as snoop, but logs it to a SQLite file in your $HOME. It will then allow you to start a flask-based Webserver on port 7777 to evaluate the trace file and replay it step by step.

@spy allows you to run snoop and birdseye in tandem.

from birdseye import eye
from snoop import snoop, spy

@spy
def fac(n: int) -> int:
    if n <= 1:
        return 1
    else:
        return n * fac(n-1)

if __name__ == '__main__':
    result = fac(3)
    print(f"{result=}")

This will instrument the code to run with snoop, and also log into the database file.

The trace is pretty:

Output of snoop running on our test function. We instrumented with @spy, which will also create a trace file.

Running the Birdseye decoder is easy: python -m birdeye will start it on the default port, 7777.

Starting the birdseye web server to serve trace files. It is bound to localhost, and listens by default on Port 7777.

The rendered trace looks like this:

birdseye webserver showing a trace. You can click through the program execution.

pysnoop

(via lathiat ) A similar but different thing is pysnoop . You pip install pysnoop and

#! /usr/bin/env python3

import pysnooper

@pysnooper.snoop()
def fac(n: int) -> int:
    if n <= 1:
        return 1
    else:
        return n * fac(n-1)

if __name__ == '__main__':
    result = fac(3)
    print(f"{result=}")

to get

Source path:... /Users/kris/keks.py
Starting var:.. n = 3
09:38:58.287242 call         6 def fac(n: int) -> int:
09:38:58.287317 line         7     if n <= 1:
09:38:58.287330 line        10         return n * fac(n-1)
    Starting var:.. n = 2
    09:38:58.287352 call         6 def fac(n: int) -> int:
    09:38:58.287369 line         7     if n <= 1:
    09:38:58.287380 line        10         return n * fac(n-1)
        Starting var:.. n = 1
        09:38:58.287392 call         6 def fac(n: int) -> int:
        09:38:58.287405 line         7     if n <= 1:
        09:38:58.287420 line         8         return 1
        09:38:58.287428 return       8         return 1
        Return value:.. 1
        Elapsed time: 00:00:00.000054
    09:38:58.287456 return      10         return n * fac(n-1)
    Return value:.. 2
    Elapsed time: 00:00:00.000122

peepshow, a commandline debugger

The package peepshow then offers a full scale commandline debugger, which allows you to trace program execution, set breakpoints and so on.

Unfortunately, it has been abandoned (the last commit was in November 2020), and does not support modern Python.

Honeycomb and Opentracing

What if you cannot access the host your code runs on, for example, because that host is variable and many, because you are running in Kubernetes? In this case, Honeycomb and other OpenTelemetry packages have you covered. They do the same logging as above, but package data in OpenTelemetry Spans, and send these over the network.

The old, original Honeycomb Beeline for Python is documented here: Python Beeline . The current OTel compatible implementation is here: OTel replacement .

A medium article discussion the same decorator usage as we do here, but in the context of OpenTelemetry, is available: Using Decorators to Instrument Python Code With OpenTelemetry Traces .

And in C?

A similar solution exists for the C programming language since 1987, in the form of the Fred Fish Debug Macros.

See the usage in MySQL , and grab the source .

This is older than time itself, and C is a bit limited compared to Python, but it basically does the same thing, in 36 years old code.

The code for these samples has been made avialable on GitHub .