PySnooper vs traditional debugging & logging

Python Debugging Logging

PySnooper vs traditional debugging & logging

This article is a look at PySnooper and a revision of debugging and logging in Python. I use a simple algorithm to determine if a number is an Armstrong number type or not.

I was intrigued to hear about PySnooper on episode 185 of the Python Bytes podcast Python Bytes podcast. It promised a play-by-play log of a function, including which lines ran and when, and exactly when local variables were changed simply by adding just one decorator line to the function.

I know it's frowned upon to use print statements for debugging, and I do try to use Python's interactive source code debugger, pdb, but it comes with commands I have to remember. Actually, this is a poor excuse, and especially if you use an IDE such as PyCharm which makes debugging so easy! If you're using print statements because you don't know how to use a debugger, that's bad. There's even a case for logging instead of using a debugger sometimes too. E.g. If you do print, consider using a logging function designed for that, rather than just an ordinary print statement.

The best way to install PySnooper is with Pip:

$ pip install pysnooper

There's also a Conda install with conda-forge too.

Armstrong Number's

My example will use a function to solve the Armstrong number question: given an integer, determine if it is an armstrong number.

An armstrong number is a number that is the sum of its own digits each raised to the power of the number of digits.

a) 153 is an armstrong number. It's a 3 digit number:

(1^3) + (5^3) + (3^3)= 153.

b) 371 is also an armstrong number.

c) any single digit numbers (1-9) are armstrong numbers as well.

A revision and comparison of debugging and logging techniques.

My original Armstrong number algorithm

Here is the code that I'll first demonstrate works with no means of any debugging:

def is_armstrong(n: int) -> bool:
    '''
    input: 153
    output: True
    '''
    n_length = len(str(n))
    sum = 0
    temp = n

    while temp > 0:
        digit = temp % 10
        sum += digit ** n_length
        temp //= 10

    return (n == sum)


print(is_armstrong(153))

The output is simply:

True
Process finished with exit code 0

If this wasn't working, we'd have to inspect the error messages.

1. Using print statements

This is the same code, but interspersed with a number of simple print statements:

def is_armstrong(n: int) -> bool:
    '''
    input: 153
    output: True
    '''
    n_length = len(str(n))
    print(f"n_length: {n_length}") # delete later
    sum = 0
    temp = n
    print(f"The starting number is {temp}") # delete later

    while temp > 0:
        digit = temp % 10
        print(f"digit: {digit}") # delete later
        sum += digit ** n_length
        print(f"sum: {sum}") # delete later
        temp //= 10
        print(f"temp: {temp}") # delete later

    return (n == sum)

print(is_armstrong(153))

The output of this is quite helpful:

n_length: 3
The starting number is 153
digit: 3
sum: 27
temp: 15
digit: 5
sum: 152
temp: 1
digit: 1
sum: 153
temp: 0
True

Process finished with exit code 0

2. Using the PySnooper decorator

This is the same code as the original, but using the PySnooper decorator:

import pysnooper

@pysnooper.snoop()
def is_armstrong(n: int) -> bool:
    '''
    input: 153
    output: True
    '''
    n_length = len(str(n))
    sum = 0
    temp = n

    while temp > 0:
        digit = temp % 10
        sum += digit ** n_length
        temp //= 10

    return (n == sum)


print(is_armstrong(153))

The output of this is more involved using only one extra line of code (not including the import)!

Source path:... /Users/anthlis/pycharmprojects/pysnooper/arm_3_snoops.py
Starting var:.. n = 153
14:55:00.081637 call         5 def is_armstrong(n: int) -> bool:
14:55:00.082160 line        10     n_length = len(str(n))
New var:....... n_length = 3
14:55:00.082252 line        11     sum = 0
New var:....... sum = 0
14:55:00.082350 line        12     temp = n
New var:....... temp = 153
14:55:00.082455 line        14     while temp > 0:
14:55:00.082562 line        15         digit = temp % 10
New var:....... digit = 3
14:55:00.082650 line        16         sum += digit ** n_length
Modified var:.. sum = 27
14:55:00.082765 line        17         temp //= 10
Modified var:.. temp = 15
14:55:00.082875 line        14     while temp > 0:
14:55:00.083132 line        15         digit = temp % 10
Modified var:.. digit = 5
14:55:00.083300 line        16         sum += digit ** n_length
Modified var:.. sum = 152
14:55:00.083507 line        17         temp //= 10
Modified var:.. temp = 1
14:55:00.083765 line        14     while temp > 0:
14:55:00.083983 line        15         digit = temp % 10
Modified var:.. digit = 1
14:55:00.084080 line        16         sum += digit ** n_length
Modified var:.. sum = 153
14:55:00.084177 line        17         temp //= 10
Modified var:.. temp = 0
14:55:00.084507 line        14     while temp > 0:
14:55:00.084770 line        19     return (n == sum)
14:55:00.085044 return      19     return (n == sum)
Return value:.. True
Elapsed time: 00:00:00.003629
True

Process finished with exit code 0

3. Using the Python's pdb debugger

Since Python 3.7, it has been possible to simply enter the debugger by using the built-in function:

breakpoint()

instead of writing

import pdb; set_trace()

When the line above is executed, Python stops and waits for you to tell it what to do next. You’ll see a (Pdb) prompt. This means that you’re now paused in the interactive debugger and can enter a command. I tend to only use 'n' to execute the current statement (step over), 'c' to continue execution until a breakpoint is encountered or 'p expr' to print the value of expr. (There are cheatsheets on the interwebs and you can always type 'h' or 'help' for a list of commands to get further help on).

This uses the same code as the original, but using Python's pdb debugger:

def is_armstrong(n: int) -> bool:
    '''
    input: 153
    output: True
    '''
    n_length = len(str(n))
    sum = 0
    temp = n

    while temp > 0:
        breakpoint()
        digit = temp % 10
        sum += digit ** n_length
        temp //= 10

    return (n == sum)

print(is_armstrong(153))

The output requires you to instruct the debugger what to do next in terms of stepping through the code:

> /Users/anthlis/pycharmprojects/pysnooper/arm_4_pdb.py(12)is_armstrong()
-> digit = temp % 10
(Pdb) 

At the command prompt is where you enter the instruction of course. I've chosen to enter 'p' several times...

-> temp //= 10
(Pdb) p digit
3
(Pdb) p sum
27
(Pdb) p temp
153
(Pdb) n
> /Users/anthlis/pycharmprojects/pysnooper/arm_4_pdb.py(10)is_armstrong()
-> while temp > 0:
(Pdb) p digit
3
(Pdb) p sum
27
(Pdb) p temp
15
(Pdb) 

and so on...

4. A revision of Logging

I mentioned logging at the start. Logging has its place, but I hardly ever use it, and I think it's because it seemingly takes a lot of effort to set-up initially. Afterall, I just want to fix the code and move on, right? For the most part, I'm writing simple code functions that I can inspect and debug quickly using other means. I suppose logging is useful for code where you don't readily have access to a terminal to inspect values of expressions such as web applications with multiple users, time stamped events or databases maybe?

I first encountered logging during the Talk Python & PyBites 100 days of code course. Michael Kennedy discussed logging as per the standard library, and then introduced Logbook for simpler logging. This is what I have used here, which needs a pip install.

from logbook import Logger, StreamHandler
import sys

StreamHandler(sys.stdout).push_application()
log = Logger('Logbook')

def is_armstrong(n: int) -> bool:
    '''
    input: 153
    output: True
    '''
    n_length = len(str(n))
    sum = 0
    temp = n

    while temp > 0:
        digit = temp % 10
        sum += digit ** n_length
        temp //= 10
        log.info(f'digit: {digit}, sum: {sum}, temp: {temp}')

    return (n == sum)

print(is_armstrong(153))

The ouput produces a simple and tidy log output as shown:

[2020-08-16 03:48:39.927662] INFO: Logbook: digit: 3, sum: 27, temp: 15
[2020-08-16 03:48:39.928117] INFO: Logbook: digit: 5, sum: 152, temp: 1
[2020-08-16 03:48:39.928214] INFO: Logbook: digit: 1, sum: 153, temp: 0
True

Process finished with exit code 0

Conclusion

The most obvious case where a debugger is the most useful is if my program crashes. With a debugger I can stop exactly where the problem occurs and inspect some variables to see what's going on.

On the flip side, sometimes with very complex programs with multiple threads or processes, using a debugger can be a real pain! In that sort of program it's often easiest to print or log things.

With PySnooper, there is no need to setup a debugger to debug code. And there is no need to delete all the strategically placed print statements either that PySnooper does away with.

I like PySnooper and will continue to use it in my arsenal to obliterate bugs and crashes in my future code, no matter how hard I try not to let them occur in the first place!

This was also a useful exercise for me to revisit the use of Logbook and I will try to use this more often too.

[1]: PySnooper on GitHub
[2]: Real Python's Python Debugging With Pdb
[3]: "Goodbye Print Statements, Hello Debugger!" - Nina Zakharenko (PyCon AU 2019)
[4]: Talk Python / PyBites 100 days of code
[5]: Logbook for better Python logging

Thanks for reading!