Quick Start¶

Basic usage¶

First, let’s import the log_calls decorator from the package of the same name:

>>> from log_calls import log_calls

In code, log_calls now refers to the decorator, a class (an object of type type), and not to the module:

>>> type(log_calls)
type

The decorator has many options, and thus can take many parameters, but let’s first see the simplest examples possible, using no parameters at all.

>>> @log_calls()
... def f(a, b, c):
...     print("--- Hi from f")
>>> f(1, 2, 3)
f <== called by <module>
    arguments: a=1, b=2, c=3
--- Hi from f
f ==> returning to <module>

>>> @log_calls()
... def g(n):
...     print("*** Hi from g")
...     f(n, 2*n, 3*n)
...     print("*** Bye from g")
>>> g(3)
g <== called by <module>
    arguments: n=3
*** Hi from g
    f <== called by g
        arguments: a=3, b=6, c=9
--- Hi from f
    f ==> returning to g
*** Bye from g
g ==> returning to <module>

>>> def g1(n): f(n, 2*n, 3*n)
>>> def g2(n): g1(n)
>>> @log_calls()
... def h(x, y): g2(x+y)

>>> h(2, 3)
h <== called by <module>
    arguments: x=2, y=3
    f <== called by g1 <== g2 <== h
        arguments: a=5, b=10, c=15
--- Hi from f
    f ==> returning to g1 ==> g2 ==> h
h ==> returning to <module>

>>> class A():
...     def __init__(self, n):
...         self.n = n
...
...     @log_calls()
...     def ntimes(self, m):
...         return self.n * m

>>> a = A(3)            # __init__ called
>>> a.ntimes(4)                 
A.ntimes <== called by <module>
    arguments: self=<__main__.A object at 0x...>, m=4
A.ntimes ==> returning to <module>
12

Decorating classes¶

To decorate all methods of a class, simply decorate the class itself:

>>> @log_calls()
... class C():
...     def __init__(self, n):
...         self.n = n if n >= 0 else -n
...
...     @staticmethod
...     def revint(x): return int(str(x)[::-1])
...
...     @property
...     def revn(self): return self.revint(self.n)

All methods of C are now decorated. Creating an instance logs the call to __init__:

>>> c = C(123)                    
C.__init__ <== called by <module>
    arguments: self=<__main__.C object at 0x...>, n=123
C.__init__ ==> returning to <module>

Accessing its revn property calls the staticmethod revint, and both calls are logged:

>>> c.revn                        
C.revn <== called by <module>
    arguments: self=<__main__.C object at 0x...>
    C.revint <== called by C.revn
        arguments: x=123
    C.revint ==> returning to C.revn
C.revn ==> returning to <module>
321

If you want to decorate only some of the methods of a class, you don’t have to individually decorate all and only all the ones you want: the only and omit keyword parameters to the class decorator let you concisely specify which methods will and won’t be decorated. The section on the omit and only keyword parameters contains the details.

>>> @log_calls(omit='revint')
... class D():
...     def __init__(self, n):
...         self.n = n if n >= 0 else -n
...
...     @staticmethod
...     def revint(x): return int(str(x)[::-1])
...
...     def double(self): return self.n + self.n
...
...     @property
>>>     @log_calls(log_retval=True)
...     def revn(self): return self.revint(self.n)

>>> d = D(71)                                           
D.__init__ <== called by <module>
    arguments: self=<__main__.D object at 0x...>, n=71
D.__init__ ==> returning to <module>

>>> d.double()                                          
D.double <== called by <module>
    arguments: self=<__main__.D object at 0x...>
D.double ==> returning to <module>

>>> print('~~~\\nMy favorite number plus 3 is', d.revn + 3)   
D.revn <== called by <module>
    arguments: self=<__main__.D object at 0x...>
    D.revn return value: 17
D.revn ==> returning to <module>
~~~
My favorite number plus 3 is 20

Writing log_calls-aware debugging messages¶

Printing statements to an output device or file is one of the oldest forms of debugging. These statements track a program’s progress, display the values of variables, announce milestones, report on the consistency of internal state, and so on. Let’s call such statements debugging messages.

The @log_calls decorator automates the boilerplate aspects of this reportage: who calls whom, when, how, and with what result. log_calls also provides the methods

• log_calls.print() and
• log_calls.print_exprs()

as attractive alternatives to the print function for writing other debugging messages.

One common kind of debugging message reports the values of variables as a program runs, taking snapshots at strategic places at the top level of the code, or within a loop as an algorithm executes. Writing such statements becomes tedious quickly — they’re all alike though in details all different too. The log_calls.print_exprs method lets you easily display the values of variables and expressions within a decorated function.

All other debugging messages require a method as general as print: the log_calls.print method is that counterpart.

Both methods write to the same output destination as the decorator, whether that’s the console, a file or a logger, and their output is properly synced and aligned with the decorator’s output:

>>> @log_calls()
... def gcd(a, b):
...     log_calls.print("At bottom of loop:")
...     while b:
...         a, b = b, (a % b)
...         log_calls.print_exprs('a', 'b', prefix="\\t", suffix= '\\t<--')
...     return a
>>> gcd(48, 246)            
gcd <== called by <module>
    arguments: a=48, b=246
    At bottom of loop:
            a = 246, b = 48 <--
            a = 48, b = 6   <--
            a = 6, b = 0    <--
gcd ==> returning to <module>
6

If you delete, comment out or otherwise disable the decorator, the print* methods will do nothing (except waste a little time). To illustrate this, we could just repeat the above function with the decorator omitted or commented out; but we can also disable the decorator dynamically, and the print* methods will be silent too:

>>> gcd.log_calls_settings.enabled = False
>>> gcd(48, 246)
6

You can pass expressions to print_exprs:

>>> @log_calls()
... def f():
...     x = 42
...     log_calls.print_exprs('x', 'x//6', 'x/6')
>>> f()
f <== called by <module>
    x = 42, x//6 = 7, x/6 = 7.0
f ==> returning to <module>

print and print_exprs properly indent even multiline messages:

>>> @log_calls()
... def f(a):
...     log_calls.print("Even multiline messages\\n"
...                     "are properly indented.")
...     return g(a, 2*a)
>>> @log_calls()
... def g(x, y):
...     retval = x + y + 1
...     log_calls.print_exprs('retval',
...                           prefix="So are multiline\\n"
...                                  "prefixes --\\n",
...                           suffix="\\n-- and suffixes.")
...     return retval
>>> f(2)
f <== called by <module>
    arguments: a=2
    Even multiline messages
    are properly indented.
    g <== called by f
        arguments: x=2, y=4
        So are multiline
        prefixes --
        retval = 7
        -- and suffixes.
    g ==> returning to f
f ==> returning to <module>
7

You can specify multiple lines for print either with one string that has explicit newlines, as above, or by using the sep keyword parameter together with multiple positional string arguments:

>>> @log_calls()
... def h():
...     log_calls.print("Line 1 of 3", "line 2 of 3", "line 3 of 3",
...                     sep='\\n')
>>> h()
h <== called by <module>
    Line 1 of 3
    line 2 of 3
    line 3 of 3
h ==> returning to <module>

The behavior of the print* methods is configurable in a few ways:

• their output can be “allowed through” while muting the output of the decorators;
• their output doesn’t have to be indented, it can be flush left (extra_indent_level=-1000);
• optionally the methods can raise an exception if called from within a function or method that isn’t decorated, so that development-only code doesn’t sneak into production.

See the chapter Writing log_calls-Aware Debugging Messages for details about the print() and print_exprs() methods. The chapter Dynamic Control of Settings documents the log_calls_settings attribute of a decorated callable.

Decorating “external” code¶

Sometimes it’s enlightening and instructive to decorate objects in a package or module that you import. It might be in a new codebase you’re getting to know, your own nontrivial code from a while ago which you now wish you had documented more, or even a function, class or module in Python’s standard library.

We’ll illustrate techniques with a simple example: decorating the fractions class fractions.Fraction in the standard library, to examine how it works. Along the way we’ll illustrate using log_calls settings to filter the output, forming hunches about how Fraction works based on the information the decorator presents, and consulting the source code to confirm or refute those hunches.

First, let’s import the class, decorate it and create an instance:

>>> from fractions import Fraction as Frac
>>> log_calls.decorate_class(Frac)
>>> print(Frac(3,4))
Fraction.__new__ <== called by <module>
    arguments: cls=<class 'fractions.Fraction'>, numerator=3, denominator=4
    defaults:  _normalize=True
Fraction.__new__ ==> returning to <module>
Fraction.__str__ <== called by <module>
    arguments: self=Fraction(3, 4)
Fraction.__str__ ==> returning to <module>
3/4

(Note: In this section, the expected output shown is from Python 3.6 and 3.5. The output of Python ≤ 3.4 differs slightly: in places it’s less efficient, and __new__, indirectly called below, had no _normalize parameter.)

Now create a couple of fractions, using the log_calls global mute to do it in silence:

>>> log_calls.mute = True
>>> fr56 = Frac(5,6)
>>> fr78 = Frac(7,8)
>>> log_calls.mute = False

Before using these, let’s redecorate to improve log_calls output. After trying other examples at the command line it becomes apparent that __str__ gets called a lot, and the calls become just noise, so let’s omit that. To eliminate more clutter, let’s suppress the exit lines (”... returning to...”). We’ll also display return values. Here’s how to accomplish all of that, with another call to decorate_class, which won’t wrap the log_calls wrappers already created but will instead just update their settings:

>>> log_calls.decorate_class(Frac,
...                          omit='__str__', log_exit=False, log_retval=True)

Finally, let’s do some arithmetic on fractions:

>>> print(fr78 - fr56)      
Fraction._operator_fallbacks.<locals>.forward (__sub__) <== called by <module>
    arguments: a=Fraction(7, 8), b=Fraction(5, 6)
    Fraction.denominator <== called by _sub <== Fraction._operator_fallbacks.<locals>.forward (__sub__)
        arguments: a=Fraction(7, 8)
        Fraction.denominator return value: 8
    Fraction.denominator <== called by _sub <== Fraction._operator_fallbacks.<locals>.forward (__sub__)
        arguments: a=Fraction(5, 6)
        Fraction.denominator return value: 6
    Fraction.numerator <== called by _sub <== Fraction._operator_fallbacks.<locals>.forward (__sub__)
        arguments: a=Fraction(7, 8)
        Fraction.numerator return value: 7
    Fraction.numerator <== called by _sub <== Fraction._operator_fallbacks.<locals>.forward (__sub__)
        arguments: a=Fraction(5, 6)
        Fraction.numerator return value: 5
    Fraction.__new__ <== called by _sub <== Fraction._operator_fallbacks.<locals>.forward (__sub__)
        arguments: cls=<class 'fractions.Fraction'>, numerator=2, denominator=48
        defaults:  _normalize=True
        Fraction.__new__ return value: 1/24
    Fraction._operator_fallbacks.<locals>.forward (__sub__) return value: 1/24
1/24

The topmost call is to an inner function forward of the method Fraction._operator_fallbacks, presumably a closure. The __name__ of the callable is actually __sub__ (its __qualname__ is Fraction._operator_fallbacks.<locals>.forward). We know that classes implement the infix subtraction operator - with “dunder” methods __sub__ and __rsub__, so it appears that in Fraction, the closure is the value of the attribute __sub__:

>>> Frac.__sub__      
<function Fraction._operator_fallbacks.<locals>.forward...>
>>> Frac.__sub__.__qualname__
'Fraction._operator_fallbacks.<locals>.forward'
>>> Frac.__sub__.__name__
'__sub__'

The closure calls an undecorated function or method _sub. Because _sub isn’t decorated we don’t know what its arguments are, and the call chains for the decorated numerator, denominator and __new__ chase back to __sub__. It appears to know about both operands, so we might guess that it takes two arguments. A look at the source code for fractions, fractions.py confirms that guess (_sub is on line 433).

>>> print(Frac._sub(fr78, fr56))
Fraction._sub <== called by <module>
    arguments: a=Fraction(7, 8), b=Fraction(5, 6)
    Fraction.denominator <== called by Fraction._sub
        arguments: a=Fraction(7, 8)
        Fraction.denominator return value: 8
    Fraction.denominator <== called by Fraction._sub
        arguments: a=Fraction(5, 6)
        Fraction.denominator return value: 6
    Fraction.numerator <== called by Fraction._sub
        arguments: a=Fraction(7, 8)
        Fraction.numerator return value: 7
    Fraction.numerator <== called by Fraction._sub
        arguments: a=Fraction(5, 6)
        Fraction.numerator return value: 5
    Fraction.__new__ <== called by Fraction._sub
        arguments: cls=<class 'fractions.Fraction'>, numerator=2, denominator=48
        defaults:  _normalize=True
        Fraction.__new__ return value: 1/24
    Fraction._sub return value: 1/24
1/24

Where to go from here¶

These examples have shown just a few of the features that make log_calls powerful, versatile, yet easy to use. They introduced a few of log_calls‘s keyword parameters, the source of much of its versatility, as well as one of the decorate_* methods.

The next chapter, What log_calls Can Decorate, gives general culture but also introduces terminology and concepts subsequently used throughout. An essential chapter follows: Keyword Parameters documents the parameters in detail. That chapter is a reference; it’s not necessary to assimilate its details before proceeding on to further topics. For an even more concise reference, in cheatsheet format, see Appendix I: Keyword Parameters Reference.

log_calls provides a lot of functionality, which these examples have only introduced. The remaining chapters document all of it.