This is part of the [tracer series](/tag/tracer), so have a look at its [introduction](/post/tracer-tricks) first. ![pause](/media/images/pause.png) There's a cool, not very well known module in Python called ``trace``, which lets you trace execution quite extensively: ```python def div(x, y): return do_div(x, y) def do_div(x, y): return x / y div(4, 2) try: div(1, 0) except ZeroDivisionError: pass ``` ```shell $ python -m trace --listfuncs demo.py functions called: filename: /home/user/.pyenv/versions/2.7.12/lib/python2.7/trace.py, modulename: trace, funcname: _unsettrace filename: demo.py, modulename: demo, funcname: <module> filename: demo.py, modulename: demo, funcname: div filename: demo.py, modulename: demo, funcname: do_div $ python -m trace --trackcalls demo.py calling relationships: *** demo.py *** demo.<module> -> demo.div demo.div -> demo.do_div ``` However, it's too verbose on one hand (I mean, it prints *a lot* of output); not verbose enough on the other hand (where are the function arguments and return values?); and quite annoying to tune to only work on specific functions. ![pause](/media/images/pause.png) Heisenberg's uncertainty principle states that it's impossible to measure a particle's energy, because the measurement itself affects its energy level. Similarly, a Heisenbug is a bug that changes (or even disappears) when you try to isolate or debug it: so you have no choice but to somehow trace it in production, usually by adding extensive logs around where you suspect the problem is, like some function that raises an exception or returns an unexpected value. Let's try to automate this with a nifty decorator: ```python def trace(function): @functools.wraps(function) def traced(*args, **kwds): name = function.__name__ callargs = inspect.getcallargs(function, *args, **kwds) signature = '%s(%s)' % (name, ', '.join('%s=%r' % item for item in callargs.items())) print('calling %s...' % signature) try: retval = function(*args, **kwds) print('%s returned %r' % (name, retval)) return retval except: print('%s raised an exceptin:%s%s' % (name, os.linesep, traceback.format_exc().strip())) raise return traced ``` Now all we have to do is decorate the problematic function with ``@trace``, and we get cool automatic traces whenever and however it's called: ```python @trace def div(x, y): ... ``` ```shell $ python demo.py calling div(y=2, x=4)... div returned 2 calling div(y=0, x=1)... div raised an exception: Traceback (most recent call last): ... ZeroDivisionError: integer division or modulo by zero ``` However, these traces have only helped us further narrow the problem to ``do_div``; so now we have to decorate *it*, then wait for the bug to happen again, and narrow the problem even further. And if, like in Linux kernel, ``do_div`` actually calls ``do_do_div``, which calls ``really_do_div``, which calls ``do_div_for_real``, which calls ``ok_seriously_you_guy_lets_do_div_already`` - it might take a few iterations to get to the bottom of it. ![pause](/media/images/pause.png) Luckily, Python's tracer can do just that. Yes, it's not ideal to run it in production, as it incurs some overhead; but having bugs in production is also not ideal, and what's more - once we limit it to a specific function, and only until we've found and fixed the bug, it should be tolerable. So let's get going: ```python def tracer(frame, event, arg): name = frame.f_code.co_name if event == 'call': argvalues = inspect.getargvalues(frame) signature = name + inspect.formatargvalues(*argvalues) print('calling %s' % signature) if event == 'return': print('%s returned %r' % (name, arg)) if event == 'exception': tb = ''.join(traceback.format_exception(*arg)).strip() print('%s raised an exception:%s%s' % (name, os.linesep, tb)) return tracer def trace(function): @functools.wraps(function) def traced(*args, **kwds): try: old = sys.gettrace() sys.settrace(tracer) return function(*args, **kwds) finally: sys.settrace(old) return traced ``` ```shell $ python demo.py calling div(x=4, y=2) calling do_div(x=4, y=2) do_div returned 2 div returned 2 calling div(x=1, y=0) calling do_div(x=1, y=0) do_div raised an exception: Traceback (most recent call last): ... ZeroDivisionError: integer division or modulo by zero do_div returned None div raised an exception: Traceback (most recent call last): ... ZeroDivisionError: integer division or modulo by zero div returned None ``` Except, now we have nesting, so it's a little hard to read. Let's add indentation: ```python INDENT = ' ' indent = 0 def tracer(frame, event, arg): global indent name = frame.f_code.co_name if event == 'call': argvalues = inspect.getargvalues(frame) signature = name + inspect.formatargvalues(*argvalues) print(INDENT*indent + 'calling %s' % signature) indent += 1 if event == 'return': indent -= 1 print(INDENT*indent + '%s returned %r' % (name, arg)) if event == 'exception': tb = ''.join(traceback.format_exception(*arg)).strip() tb = os.linesep.join(INDENT*indent + line for line in tb.splitlines()) print(INDENT*indent + '%s raised an exception:%s%s' % (name, os.linesep, tb)) return tracer ``` ```shell $ python demo.py calling div(x=4, y=2) calling do_div(x=4, y=2) do_div returned 2 div returned 2 calling div(x=1, y=0) calling do_div(x=1, y=0) do_div raised an exception: Traceback (most recent call last): ... ZeroDivisionError: integer division or modulo by zero do_div returned None div raised an exception: Traceback (most recent call last): ... ZeroDivisionError: integer division or modulo by zero div returned None ``` Much better, isn't it? One last touch and we're done: I don't like hardcoding the ``print`` function, so let's make it configurable. This decorator trick is a little mind-bending at first, but if you've read so far, you'll probably do fine: ```python def trace(function=None, log=None): # Decorator called as @trace(log=...), affix log and return the decorator. if function is None: return functools.partial(trace, log=log) # Define the tracer (this happens here so we get log by scope). if log is None: log = print def tracer(frame, event, arg): ... ``` If we use ``@trace``, the function is passed to the decorator, ``log`` defaults to ``print``, and everything works as expected. But if specify a log, like in ``@trace(log=logging.debug)``, then ``function`` is ``None``, and a partial ``trace`` is returned. This partial is then invoked to decorate the function, so this time it isn't ``None`` and the actual work happens, with ``log`` resolved to whatever we affixed to the partial. As per tradition, You can get the code on [GitHub](http://github.com/dan-gittik/tracer).