Improving Failure Messages with Async Tests in Go

Testing highly asynchronous code can be highly time-consuming and tricky. If possible, I always try to include some sort of synchronization mechanism even if only exposed to unit tests.

However, sometimes, there's no alternative, and an async test is better than no test!

Writing an Async Test

I'm a big fan of stretchr/testify when writing any kind of test in Go: I find it makes tests very readable and has fantastic failure messages.

It also includes a lot of assertion methods, including some for async code!

In particular, require.Eventually:

func Eventually(
	t TestingT,
	condition func() bool,
	waitFor time.Duration,
	tick time.Duration,
	msgAndArgs ...interface{}, 
)

We pass a condition function that should return true once the condition has been met. It'll be invoked every tick until the waitFor time limit has been reached.

For example:

package example

import (
	"github.com/stretchr/testify/require"
	"testing"
	"time"
)

func TestEventuallyExample(t *testing.T) {
	require.Eventually(t, func() bool {
		return getStatus() == "done"
	}, time.Second, time.Millisecond, "Status was not done")
}

This will check getStatus() every millisecond succeeding if the status is done or failing after one second if never fulfilled.

If we ran this and it fails, we'd see something like:

=== RUN   TestEventuallyExample
    example_test.go:10: 
        	Error Trace:	example_test.go:10
        	Error:      	Condition never satisfied
        	Test:       	TestEventuallyExample
        	Messages:   	"Status was not done"
--- FAIL: TestEventuallyExample (1.00s)

The Problem With String Formatting In Async Tests

This is great, but I'd like to know what the status was when the test timed out to help me debug.

Let's adjust our function slightly:

func TestEventuallyExample(t *testing.T) {
	var status string
	require.Eventually(t, func() bool {
		status = getStatus()
		return status == "done"
    }, time.Second, time.Millisecond, "Status was not done: %v", &status)
}

Now, we have a status variable local to our test (but outside the condition function) that we use as a string format argument (%v).

Critically, we're actually passing a pointer &status; otherwise, if we passed status by value, it would always be "" (the empty string) at the point that require.Eventually is invoked.

Let's see what this looks like:

=== RUN   TestEventuallyExample
    example_test.go:11: 
        	Error Trace:	example_test.go:11
        	Error:      	Condition never satisfied
        	Test:       	TestEventuallyExample
        	Messages:   	Status was not done: 0xc000080ec0
--- FAIL: TestEventuallyExample (1.00s)

Well, that's unfortunate! The fmt package saw the *string type and gave us the pointer address.

Remember that we used %v above, which is the default format for a value. You might be tempted to try %s instead, but alas, since *string is itself not a string nor does it implement fmt.Stringer, so this will result in something like %!s(*string=0xc000080ec0). (Go gently chastises us for passing the wrong format type but still tries to show us something useful.)

Fixing Formatting Woes With strings.Builder

To resolve the formatting issues, we need a type who implements fmt.Stringer.

Luckily, strings.Builder can come to our rescue, as *Builder fulfills the fmt.Stringer interface!

Let's make some changes and try running the test again:

func TestEventuallyExample(t *testing.T) {
	var status strings.Builder
	require.Eventually(t, func() bool {
		// prevent appending to the prior invocation(s)
		status.Reset()

		currentStatus := getStatus()
		status.WriteString(currentStatus)

		return currentStatus == "done"
	}, time.Second, time.Millisecond, "Status was not done: %s", &status)
}

=== RUN   TestEventuallyExample
    example_test.go:12: 
        	Error Trace:	example_test.go:12
        	Error:      	Condition never satisfied
        	Test:       	TestEventuallyExample
        	Messages:   	Status was not done: error
--- FAIL: TestEventuallyExample (1.00s)

That looks great! I mean, our fake test is still failing, but we have some insight now because we can see that it was error at the last invocation of our condition function.

While this might seem excessive for a single string value, imagine the common scenario of polling an HTTP API: we could populate our strings.Builder with useful data from the response such as status code, JSON body, and more.

Visibility into test failures is only one of the many challenges with testing asynchronous code, but I've found the pattern of using a strings.Builder inside my require.Eventually calls to be a straightforward & flexible way to dramatically improve the usefulness of my test failure output. 🙌🏻