Practical Debugging - Tips, Tricks & Ways to think

Radoslav Georgiev

EuroPython 2017

Radoslav "Rado" Georgiev

Sofia, Bulgaria

HackSoft Academy

~ 9 Python / Django courses, preparing people for their first job.

Goal of this talk

  • I want to share my experience with debugging and looking at a lot of code
     
  • I want to be helpful and pragmatic
     
  • By no means extensive (DebugCon)

Debugging play in
3+ parts

  • There's an exception.
  • Nothing's happening
  • We got a wrong answer.
  • Common things.

There's an exception

Level of frustration:

1

2

3

You run your code, things blow up.

There's an exception.

Example: Text file with datetime intervals & python program that checks if there are any overlapping.

$ head -5 intervals.txt
(2017-06-25 19:27:51, 2017-06-25 19:42:51)
(2017-06-25 19:43:51, 2017-06-25 19:58:51)
(2017-06-25 19:59:51, 2017-06-25 20:14:51)
(2017-06-25 20:15:51, 2017-06-25 20:30:51)
(2017-06-25 21:51:51, 2017-06-25 22:06:51)

$ cat intervals.txt | wc -l
100
$ python overlapping.py intervals.txt
All good.
$ python overlapping.py intervals.txt
There are overlapping intervals.

We have stack trace.

$ python exceptions.py intervals.txt
Traceback (most recent call last):
  File "exceptions.py", line 55, in <module>
    main()
  File "exceptions.py", line 45, in main
    result = run(contents)
  File "exceptions.py", line 32, in run
    data = [parse_datetime(value) for value in contents]
  File "exceptions.py", line 32, in <listcomp>
    data = [parse_datetime(value) for value in contents]
  File "exceptions.py", line 10, in parse_datetime
    return datetime.strptime(value, fmt)
  File "/usr/lib/python3.5/_strptime.py", line 510, in _strptime_datetime
    tt, fraction = _strptime(data_string, format)
  File "/usr/lib/python3.5/_strptime.py", line 343, in _strptime
    (data_string, format))
ValueError: time data '(' does not match format '%Y-%m-%d %H:%M:%S'

Stack trace is a friend!

$ python exceptions.py intervals.txt
Traceback (most recent call last):
  File "exceptions.py", line 55, in <module>
    main()
  File "exceptions.py", line 45, in main
    result = run(contents)
  File "exceptions.py", line 32, in run
    data = [parse_datetime(value) for value in contents]
  File "exceptions.py", line 32, in <listcomp>
    data = [parse_datetime(value) for value in contents]
  File "exceptions.py", line 10, in parse_datetime
    return datetime.strptime(value, fmt)
  File "/usr/lib/python3.5/_strptime.py", line 510, in _strptime_datetime
    tt, fraction = _strptime(data_string, format)
  File "/usr/lib/python3.5/_strptime.py", line 343, in _strptime
    (data_string, format))
ValueError: time data '(' does not match format '%Y-%m-%d %H:%M:%S'

A stack trace contains:

  • The exception (if there was an exception)
     
  • The function / method call path to that exception
     
  • We can use the call path to trace what happened & debug

Lets find the line that separates our code from python / external lib.

Very important thing when reading stack traces.

$ python exceptions.py intervals.txt
Traceback (most recent call last):
  File "exceptions.py", line 55, in <module>
    main()
  File "exceptions.py", line 45, in main
    result = run(contents)
  File "exceptions.py", line 32, in run
    data = [parse_datetime(value) for value in contents]
  File "exceptions.py", line 32, in <listcomp>
    data = [parse_datetime(value) for value in contents]
  File "exceptions.py", line 10, in parse_datetime
    return datetime.strptime(value, fmt)
  File "/usr/lib/python3.5/_strptime.py", line 510, in _strptime_datetime
    tt, fraction = _strptime(data_string, format)
  File "/usr/lib/python3.5/_strptime.py", line 343, in _strptime
    (data_string, format))
ValueError: time data '(' does not match format '%Y-%m-%d %H:%M:%S'

We find the problematic line

def parse_datetime(value: str) -> datetime:
    fmt = '%Y-%m-%d %H:%M:%S'

    return datetime.strptime(value, fmt)


def run(contents: str) -> bool:
    data = [parse_datetime(value) for value in contents]

    result = overlapping_intervals(data)

    return result

There's a golden rule.
If you find a bug - add a test for it.

Constant regressions can make you crazy.

Also known as - reproduce the bug.

import unittest

from overlapping_intervals import run


class OverlappingIntervalsTests(unittest.TestCase):
    def test_overlapping_intervals(self):
        input = ["(2017-06-25 19:27:51, 2017-06-25 19:42:51)",
                 "(2017-06-25 19:43:51, 2017-06-25 19:58:51)"]

        input = '\n'.join(input)

        result = run(input)

        self.assertFalse(result)


if __name__ == '__main__':
    unittest.main()
E
======================================================================
ERROR: test_overlapping_intervals (__main__.OverlappingIntervalsTests)
----------------------------------------------------------------------

.... traceback here ...

----------------------------------------------------------------------
Ran 1 test in 0.011s

Lets properly handle that

def parse_line(value: str) -> Tuple[datetime, datetime]:
    parts = value.split(',')

    first = parts[0]
    second = parts[1]

    # Remove ()

    first = first[1:]
    second = second[0:len(second) - 1]

    return parse_datetime(first), parse_datetime(second)

Now, lets run.

$ python exceptions.py intervals.txt
Traceback (most recent call last):
  File "exceptions.py", line 69, in <module>
    main()
  File "exceptions.py", line 59, in main
    result = run(fname)
  File "exceptions.py", line 49, in run
    data = [parse_line(value) for value in contents.split('\n')]
  File "exceptions.py", line 49, in <listcomp>
    data = [parse_line(value) for value in contents.split('\n')]
  File "exceptions.py", line 24, in parse_line
    return parse_datetime(first), parse_datetime(second)
  File "exceptions.py", line 10, in parse_datetime
    return datetime.strptime(value, fmt)
  File "/usr/lib/python3.5/_strptime.py", line 510, in _strptime_datetime
    tt, fraction = _strptime(data_string, format)
  File "/usr/lib/python3.5/_strptime.py", line 343, in _strptime
    (data_string, format))
ValueError: time data ' 2017-06-25 19:42:51' does not match format '%Y-%m-%d %H:%M:%S'

Debugger time!

def parse_line(value: str) -> Tuple[datetime, datetime]:
    parts = value.split(',')

    first = parts[0]
    second = parts[1]

    # Remove ()

    first = first[1:]
    second = second[0:len(second) - 1]

    import ipdb; ipdb.set_trace()

    return parse_datetime(first), parse_datetime(second)

pip install ipdb

ipdb / pdb

  • Interactive python debugger
     
  • Console interface
     
  • Stops the world and lets you take a look around.
     
  • The better print function

Inside the debugger

$ python exceptions.py intervals.txt
> /home/radorado/code/Talks/EuroPython2017/exceptions.py(26)parse_line()
     25 
---> 26     return parse_datetime(first), parse_datetime(second)
     27 

ipdb> first
'2017-06-25 19:27:51'
ipdb> second
' 2017-06-25 19:42:51'
ipdb> exit
Exiting Debugger.

Bug => Test

    def test_parse_line(self):
        input = '(2017-06-25 19:27:51, 2017-06-25 19:42:51)'
        expected = (datetime(year=2017, month=6, day=25,
                             hour=19, minute=27, second=51),
                    datetime(year=2017, month=6, day=25,
                             hour=19, minute=42, second=51))

        result = parse_line(input)

        self.assertEqual(expected, result)

Fixing the funciton

def parse_line(value: str) -> Tuple[datetime, datetime]:
    parts = value.split(', ')

    first = parts[0]
    second = parts[1]

    # Remove ()

    first = first[1:]
    second = second[0:len(second) - 1]

    return parse_datetime(first), parse_datetime(second)

Test are passing.
Lets try real world!

..
----------------------------------------------------------------------
Ran 2 tests in 0.004s

OK

Aaaand

$ python exceptions.py intervals.txt
Traceback (most recent call last):
  File "exceptions.py", line 69, in <module>
    main()
  File "exceptions.py", line 59, in main
    result = run(fname)
  File "exceptions.py", line 49, in run
    data = [parse_line(value) for value in contents.split('\n')]
  File "exceptions.py", line 49, in <listcomp>
    data = [parse_line(value) for value in contents.split('\n')]
  File "exceptions.py", line 17, in parse_line
    second = parts[1]
IndexError: list index out of range

ipdb to the rescue

def parse_line(value: str) -> Tuple[datetime, datetime]:
    parts = value.split(',')

    import ipdb; ipdb.set_trace()

    first = parts[0]
    second = parts[1]

    # Remove ()

    first = first[1:]
    second = second[0:len(second) - 1]

    return parse_datetime(first), parse_datetime(second)

But we have >= 100 lines

$ python exceptions.py intervals.txt
> /home/radorado/code/Talks/EuroPython2017/exceptions.py(18)parse_line()
     16     import ipdb; ipdb.set_trace()
     17 
---> 18     first = parts[0]
     19     second = parts[1]
     20 

ipdb> parts
['(2017-06-25 19:27:51', '2017-06-25 19:42:51)']
ipdb> cont
> /home/radorado/code/Talks/EuroPython2017/exceptions.py(18)parse_line()
     16     import ipdb; ipdb.set_trace()
     17 
---> 18     first = parts[0]
     19     second = parts[1]
     20 

ipdb> parts
['(2017-06-25 19:43:51', '2017-06-25 19:58:51)']
ipdb> cont
> /home/radorado/code/Talks/EuroPython2017/exceptions.py(18)parse_line()
     16     import ipdb; ipdb.set_trace()
     17 
---> 18     first = parts[0]
     19     second = parts[1]
     20 

ipdb> parts
['(2017-06-25 19:59:51', '2017-06-25 20:14:51)']
ipdb> cont
> /home/radorado/code/Talks/EuroPython2017/exceptions.py(18)parse_line()
     16     import ipdb; ipdb.set_trace()
     17 
---> 18     first = parts[0]
     19     second = parts[1]
     20 

ipdb>

launch_ipdb_on_exception

def main() -> None:
    fname = sys.argv[1]

    from ipdb import launch_ipdb_on_exception
    with launch_ipdb_on_exception():
        result = run(fname)

    if result:
        print('There are overlapping intervals')
        sys.exit(1)

    print('All good.')

And we found our bug!

$ python exceptions.py intervals.txt
IndexError('list index out of range',)
> /home/radorado/code/Talks/EuroPython2017/exceptions.py(17)parse_line()
     15 
     16     first = parts[0]
---> 17     second = parts[1]
     18 
     19     # Remove ()

ipdb> parts
['']

Fix, tests passing, all good

def run(fname: str) -> bool:
    with open(fname, 'r') as f:
        contents = f.read()

    data = [parse_line(value)
            for value in contents.split('\n')
            if value.strip() != '']

    result = overlapping_intervals(data)

    return result

Exception types

Sometimes, the library or framework is going to tell you that you messed up.

ImproperlyConfigured, ValidationError, PermissionDenied, etc.

Fixes here should be easy. Just read the exception.

Summary

  • Stack traces are your friend. Read them.
     
  • Stack traces can be huge with a lot of code inside a lib or framework. Look for executions in your code.
     
  • Use ipdb. Learn how to navigate and you'll be ahead in the bug-hunting game.
     
  • If you hit a bug, write test for it. Stay away from constant regression.

Nothing's happening!

You run your code. There's no exception. There's no answer.

Level of frustration:

1

2

3

Do the detective work.

  • You are in the dark and you need to find a source of light to guide you.
     
  • What should happen? What is the expected behavior?
     
  • Doubt everything!
     
  • If there's no exception, are there any error logs to check?

Break it on purpose & try to get an exception

Fixing an error is much better than not knowing what to fix.

Code isolation is your friend

  • Create a new file and test just the thing that's not working as expected.
     
  • Sprinkle with debuggers and trace the steps of execution. Are you hitting the code?

Common gothcas

  • Module hiding -> datetime.py
  • Exception hiding -> except + pass
  • Typos -> calling the wrong thing -> :(
  • Not calling a function / method -> :(
  • Editing the wrong file / running the wrong file -> :(
  • Debugging something that's working -> :(

An example

Binary search debugging

  1. Commented everything in users/tasks.py -> ✓

  2. Uncommented tasks & celery imports -> ✓
  3. Uncommented app imports -> x
  4. Commented a specific import -> ✓
  5. Uncommented that import -> x
  6. Found the bug!

Binary search debugging

  1. Comment parts of code until everything's working

  2. Uncomment smaller portion of the code.
    1. If it's working, go to step 2.
    2. If it's not working, go to step 1 for that code.
  3. Find the breaking line/s of code and fix them.

Summary

  • Try go get an exception. Break it on purpose.
     
  • Isolate code. Running smaller things is always easier to debug.
     
  • Make sure you know what needs to happen for the code to be "working"
     
  • Try "binary search debugging" when navigating a large codebase or you have no idea what's happening.

There's a wrong answer.

Level of frustration:

1

2

3

Everything's working but the answer is the wrong one.

I usually follow the "5-step drilldown" when things are wrong.

1) Are your tests OK?

I always look first for errors in the tests. A lot of times, this is the case.

some_object.refresh_from_db()

2) Do you need validation?

Is the input correct? Maybe you need to validate things.

This is often the case with implicit type castings.

3) Is your algo OK?

Are you using external library? Have you implemented it yourself?

ipdb on every line & trace the value of everything. Understand where in the algo things start to get wrong.

4) Is your system design OK?

Perhaps there are more dimensions to the problem.

For example - you are dealing with some kind of timelines but have implemented only the future & you need to support the past.

Starting fresh & going to the whiteboard always helps here.

5) Do you understand the problem space well enough?

You may be solving the wrong thing.

Understanding & learning more is the way to go here.

And finally, some practical tips

Explain your problem to someone

Parallel debugging

  1. Ask a question in SO
  2. Open GH issue
  3. Ask a co-worker for help
  4. All of that while you are debugging

Help others avoid traps

  • Answer questions on SO
     
  • Write on GH issues
     
  • Open PRs with bugfixes, more examples or documentation improvements
     
  • Do a talk on a conference

That's it. Thanks!
Questions?

github.com/RadoRado/EuroPython2017

github.com/HackSoftware/

hacksoft.io

Practical Debugging - Tips & Tricks & Ways to think

By Hack Bulgaria

Made with Slides.com

Practical Debugging - Tips & Tricks & Ways to think

  • 1,021

More from Hack Bulgaria