`go test` prints FAIL with no obvious indication of which test failed or why

user_2088767 0
Viewed 708

I've seen this happen a number of different ways, but usually the end of test output looks something like

...
        --- PASS: TestVariousQueries/7-node/34-G (8.50s)
FAIL
FAIL    github.com/pilosa/pilosa/v2 483.327s
FAIL

In our particular case, we have a lot of nested subtests using t.Run, and tests which run in parallel, but in general we've found that it's possible for the test suite to FAIL without an individual test failing.

in my above example, if you search backward for "FAIL" you seem something like:

--- FAIL: TestVariousQueries/7-node (482.60s)
        --- PASS: TestVariousQueries/7-node/0-G
...

where it's indicated that the top level test failed, but all the subtests seem to pass and there's no other output or message indicating why the test failed.

Sometimes it will look like this, which gives a bit more of a clue

...
=== RUN   TestVariousQueries/7-node/8-Count(All())
FAIL    github.com/pilosa/pilosa/v2 394.988s
FAIL

In this case it seems like that last test started, but somehow failed with no output (we would expect to get a --- FAIL line for that particular test rather than just the package level FAIL.

What scenarios can cause this to happen? How can it be debugged?

go
2 Answers

What scenarios can cause this to happen?

Are you using t.Fail() (or t.FailNow())? Calling t.Fail() outside the subtests it will reproduce what you are observing: all the subtests pass but the overall test fails with no output. Example https://go.dev/play/p/oOeQ_migV1l:

func TestVariousQueries(t *testing.T) {
    t.Run("7-node", func(t *testing.T) {
        t.Run("0-G", func(t *testing.T) { return })
        t.Run("1-G", func(t *testing.T) { return })
        t.Run("2-G", func(t *testing.T) { return })
        t.Run("3-G", func(t *testing.T) { return })
        if true {
            t.Fail()
        }
    })
}

--- FAIL: TestVariousQueries (0.00s)
    --- FAIL: TestVariousQueries/7-node (0.00s)
        --- PASS: TestVariousQueries/7-node/0-G (0.00s)
        --- PASS: TestVariousQueries/7-node/1-G (0.00s)
        --- PASS: TestVariousQueries/7-node/2-G (0.00s)
        --- PASS: TestVariousQueries/7-node/3-G (0.00s)
FAIL
user_30308280

I'm not sure I have a full accounting of what can cause this, but I have definitely seen it happen when the system runs out of memory and the OOM killer kills the test process. On Linux at least you can run dmesg or something like tail -f /var/log/syslog while the tests are running to see the kernel logs. If you see something like:

[58234.350712] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=/,mems_allowed=0,global_oom,task_memcg=/user.slice/user-1000.slice/session-12.scope,task=pilosa.test,pid=62637,uid=1000
[58234.351191] Out of memory: Killed process 62637 (pilosa.test) total-vm:178386044kB, anon-rss:15656564kB, file-rss:0kB, shmem-rss:0kB, UID:1000 pgtables:63880kB oom_score_adj:0
[58235.243972] oom_reaper: reaped process 62637 (pilosa.test), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB

You can be pretty sure the test was killed due to being out of memory.

Another way this can happen is if some code in the test (or being tested) calls os.Exit. In this case, depending on the Go version and OS, you might see a status code, or you might just see FAIL messages as in the examples in the original question.

In general, if you see output like this from tests, it seems like it's a good bet that something is causing the test process to exit which causes the test runner (go test) to print the FAIL line without telling you which test failed.

user_20887670
Related