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

Question

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?

Answer 1

We see FAIL in test output if go vet finds issues in our code. You can bypass (altho maybe not recommended) with go test ./... -vet=off.

From https://pkg.go.dev/cmd/go/internal/test

As part of building a test binary, go test runs go vet on the package and its test source files to identify significant problems. If go vet finds any problems, go test reports those and does not run the test binary. Only a high-confidence subset of the default go vet checks are used. That subset is: 'atomic', 'bool', 'buildtags', 'errorsas', 'ifaceassert', 'nilfunc', 'printf', and 'stringintconv'. You can see the documentation for these and other vet tests via "go doc cmd/vet". To disable the running of go vet, use the -vet=off flag. To run all checks, use the -vet=all flag.

Answer 2

In case anyone else stumbles on this question - make sure to pay attention to your process memory usage. I injected the following log into my test and never saw more than 100 MB's of growth - which confused me. Then I ran the linux/unix command "top" and sorted by memory (Shift M) - my process was climbing to 4 gigabytes!

func bToMb(b uint64) uint64 {
    return b / 1024 / 1024
}
func PrintMemUsage(text string) {
    var m runtime.MemStats
    runtime.ReadMemStats(&m)
    fmt.Printf("%v: ", text)
    fmt.Printf("HeapAlloc = %v MB", bToMb(m.HeapAlloc))
    fmt.Printf(" HeapInuse = %v MB", bToMb(m.HeapInuse))
    fmt.Printf(" HeapIdle = %v MB", bToMb(m.HeapIdle))
    fmt.Printf(" HeapReleased = %v MB", bToMb(m.HeapReleased))
    fmt.Printf(" HeapSys = %v MB", bToMb(m.HeapSys))
    fmt.Printf(" Alloc = %v MB", bToMb(m.Alloc))
    fmt.Printf(" TotalAlloc = %v MB", bToMb(m.TotalAlloc))
    fmt.Printf(" Sys = %v MB", bToMb(m.Sys))
    fmt.Printf(" NumGC = %v\n", m.NumGC)
}

The above log did not accurately display the memory my process was using (6 GB's vs 30 MB's).

I was wondering if it would be possible to trigger one or both of the following if my process exceeded some threshold - but since I can't seem to get any inkling of how much memory my process is using (at least using Go's internal MemStats) - not sure it will be useful to anyone:

runtime.GC()
debug.FreeOSMemory()

I am aware of the following page: https://golang.org/pkg/runtime/#MemStats

But, a discrepancy of 30 MB's to 6 GB's seems odd. After a fair bit more debugging it turned out the Go package I'm using is doing C/C++ unsafe alloc/free - not sure if there is a way to track those allocations using Go mem stats? At this point - I might have to call an OS command to get the OS to tell me how much memory my process is taking.

This post seems to have some good information/answers: How to analyze golang memory?

This package seems like a better solution than calling an OS command actually: https://github.com/pbnjay/memory

Answer 3

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

Answer 4

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.