Debugging a flaky test — how I methodologically tamed an annoying bug

This blog post is an update of my journey in Djangonaut Space , an 8-week mentoring program for future open source developers in the Django ecosystem.

A flaky is a automated test in software development that seemingly non-deterministically fails. I hate them with passion because they erode your trust to your test suite, can cause people to start ignoring test failures and are annoying as heck to deal with.

Yesterday, I spent an afternoon dealing with one as part of my Djangonaut Space work for the Django Girls+ project. Here’s an exploration report for how I narrowed it down, found the root cause and fixed it. I followed my debugging process that relies to almost no prior knowledge about a project (other than knowing how to use your test runner) and that leaves all assumptions at the door.

Crime scene

We had a test called test_it_sorts_applications_by_score_excluding_hidden that sometimes failed. Like a good Schrödinger’s cat, every time you ran it in isolation trying to replicate it so you could figure out what was happening, it succeeded. It also succeeded sometimes when running the full suite.

In a situation like this, my first intuition is that I need to find a way to make it fail and hopefully succeed consistently to learn what the root cause is.

Discovery and investigation

We use pytest as our test runner.

The first thing I did was start running it with the -x flag that reads:

Exit instantly on first error or failed test.

This way, our almost 300 tests don’t have to run every time. I decided to run it multiple times in a row without making any changes to see if I could spot a pattern.

1. Fails at with user case with the result having all was_scored_by_user as False
2. Succeeds
3. Fails at with user case with the result having all was_scored_by_user as False
4. Succeeds

In our pytest.ini, we’ve defined options as

[pytest]
DJANGO_SETTINGS_MODULE=djangogirls.settings
addopts = --ff --nomigrations

The --ff flag, also known as --failed-first means that when you re-run your tests, any tests that failed the previous run are ran first. This explains the 50/50 behaviour I noticed above: it fails when it’s ran in the middle of the suite, then it’s picked up as the first test and it passes.

This is an indication that something in it is dependent on other tests being ran before it.

Next, I tried running pytest -x --clear-cache to run without any caching — which also clears the “failed on last run” memory. My initial idea was to test it with that flag to see if something weird was happening with caching but I ended up learning that since it reset the order, it started failing consistently every time.

Now, I started digging deeper and moving outwards.

I ran pytest --cache-clear tests/applications/test_services.py and confirmed it succeeds when ran alone — this confirmed my conclusion from the earlier.

Then I stepped up one folder. pytest --cache-clear tests/applications/ which gave me a consistently failing test:

tests/applications/models/test_applications.py ..........[ 19%]
tests/applications/models/test_email.py ... [ 25%]
tests/applications/models/test_forms.py ..... [ 34%]
tests/applications/models/test_questions.py . [ 36%]
tests/applications/test_forms.py ... [ 42%]
tests/applications/test_services.py F [ 44%]

I now knew that the issue was in one of the five test files being run before it. I started from the bottom and moved up.

With pytest --cache-clear tests/applications/ -k "not models" , I excluded the first four tests and only ran the two at the bottom. Green.

Continuing that way step by step, I discovered that I could include all but test_applications.py to keep it passing but when I brought that test into the mix, we got a fail. Wonderful, I managed to narrow the issue down to a combination of two files.

In that file, we have 10 tests. To start, I added @pytest.mark.skip(reason=None) above each test to tell pytest to skip them. I then took it out from one test and reran the test suite and recorded how it went into my notes. Repeat with all 10 and I got a list of three tests that caused the original one to fail:

• test_average_score
• test_is_scored_by_user
• test_score_str

At this point, I created an issue to our issue tracker because I didn’t know how long it would take me to figure out how to fix it. I let my team know I’m on it and shared in the ticket my discoveries. I documented it this way for a couple of reasons:

1. To let people know I’ve been investigating it.
2. To document what I had discovered in case I had to drop this and do something else, helping someone else (including future me) get started with it.

At this point, I had a couple of pages of notes, following my Running Notes concept. I do this with anything non-trivial I ever work on. In past, they have become so useful because down the line, I (or someone else in the team) might have to figure out a similar thing and having notes on what I did helps a lot. Another good reason is that if I need to argue and defend my decisions down the line, I have more to go on than just the end result or intermediate commits. I have my reasoning and what I’ve tried.

I highly highly highly recommend every developer to start keeping notes for themselves.

Repairs

I now knew how it happened and had figured out the first step: how to consistently run it so that it fails and succeeds. Before you get to such state, it’s going to be difficult to reliably fix things because especially with flaky tests, you never really know otherwise if you succeeded or if you’re just running on a lucky streak.

Next up, I switched tools and started debugger sessions.

I added breakpoint() as the first line into the test.

def test_it_sorts_applications_by_score_excluding_hidden(
    future_event, scored_applications, admin_user, scores_by_other_users
):
    """Tests if, when the user sorts the applications by average score, we don't include the ones they
    haven't scored yet.

    For example, consider [these applications](https://cln.sh/JAoo8H) sorted by average score with the
    previous implementation. We know #1 is higher than 4.375 and #3 is lower than 4.375 and higher than
    4.25 just because of the sorting."""
    breakpoint()

I ran it in both scenarios: failing and passing and inside the Python debugger, I ran the following:

for score in Score.objects.all():
	print(score.pk, score.score, score.user)

I recorded the output and started comparing.

For the passing case, I got

1 1.0 admin@example.com
2 2.0 admin@example.com
3 3.0 admin@example.com
4 4.0 admin@example.com
5 5.0 admin@example.com
6 1.0 user-1@test.com
7 2.0 user-2@test.com
8 4.0 user-1@test.com
9 5.0 user-2@test.com
10 1.0 user-1@test.com
11 2.0 user-2@test.com
12 4.0 user-1@test.com
13 5.0 user-2@test.com
14 1.0 user-1@test.com
15 2.0 user-2@test.com

and for the failing case, I got (I can’t exactly remember which of the culprit test cases I had enabled at this point):

3 1.0 admin@example.com
4 2.0 admin@example.com
5 3.0 admin@example.com
6 4.0 admin@example.com
7 5.0 admin@example.com
8 1.0 user-1@test.com
9 2.0 user-2@test.com
10 4.0 user-1@test.com
11 5.0 user-2@test.com
12 1.0 user-1@test.com
13 2.0 user-2@test.com
14 4.0 user-1@test.com
15 5.0 user-2@test.com
16 1.0 user-1@test.com
17 2.0 user-2@test.com

BOOM!

We have discrepancy! Everything else is the same but the primary keys have been shifted.

I had been working on this for a few hours at this point and this was basically the first time I started to look at what the failing test actually does. Everything until now was just asking questions and following breadcrumbs: “what is happening”, “when does this happen”, “what is causing it”.

In the test, we did:

# Delete some of the scores given by the admin user so we can test the sorting
Score.objects.filter(
	user=admin_user,
	application__in=scored_applications,
	pk__gt=scored_applications.count() / 2,
).delete()

We were using the primary keys as absolute values to delete the second half of the Scores to create our test data.

This meant that if there were 5 scores by admins, on a fresh run, we’d find the last three and remove them. But if the primary keys had been shifted by 2, we’d delete them all and thus, ruining our test data.

The fix was the easy part: I ended up hardcoding the amount in the test instead of using the pk__gt filter option.

scored_by_admin = Score.objects.filter(user=admin_user, application__in=scored_applications)
to_delete = scored_by_admin[2:].values_list("id", flat=True)
Score.objects.filter(pk__in=list(to_delete)).delete()

It’s not quite as elegant and I think it hits the database an extra time (although I didn’t confirm that) but given it’s a small test and only run when a developer or CI runs the tests (and not in production), it’s a good enough trade-off for me.

Once I got that done and tested, I created a pull request and now we have one less failing test in the project.

It’s always a good day when a flaky test is retired and you can start trusting your test suite again.

There’s probably more that could be done to improve this test. I’ll leave that to another day though because often it’s good to keep changes small and it’s always better to get a thing done and fixed than go down the perfection rabbit hole (no matter how tempting it is) and never reach a fix.