testing: go1.14rc1 b.Cleanup behaves differently from t.Cleanup

[lestrrat]

What version of Go are you using (go version)?

$ go version
go version go1.14rc1 darwin/amd64

Does this issue reproduce with the latest release?

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
go1.14rc1 env
GO111MODULE="on"
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/lestrrat/Library/Caches/go-build"
GOENV="/Users/lestrrat/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/lestrrat/dev"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/Users/lestrrat/sdk/go1.14rc1"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/Users/lestrrat/sdk/go1.14rc1/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/lestrrat/dev/src/gitlab.com/endeworks/gihyo-wdpress/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/lj/kxy3y5j545772wn23sg34qk00000gn/T/go-build418226800=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

package foo_test

import (
  "testing"
)

func TestCleanup(t *testing.T) {
  t.Logf("In test")
  t.Cleanup(func() { t.Logf("Hello, test cleanup!") })
}

func BenchmarkCleanup(b *testing.B) {
  b.Logf("In benchmark")
  b.Cleanup(func() { b.Logf("Hello, benchmark cleanup!") })
}

What did you expect to see?

finch% go1.14rc1 test -bench . -benchmem ./src -v
=== RUN   TestCleanup
    TestCleanup: foo_test.go:8: In test
    TestCleanup: foo_test.go:9: Hello, test cleanup!
--- PASS: TestCleanup (0.00s)
goos: darwin
goarch: amd64
pkg: <snip>
    BenchmarkCleanup: foo_test.go:13: In benchmark
    BenchmarkCleanup: foo_test.go:13: In benchmark
    BenchmarkCleanup: foo_test.go:13: In benchmark
    BenchmarkCleanup: foo_test.go:13: In benchmark
    BenchmarkCleanup: foo_test.go:13: In benchmark
    BenchmarkCleanup: foo_test.go:13: In benchmark
    BenchmarkCleanup: foo_test.go:14: Hello, benchmark cleanup!  <<< This
BenchmarkCleanup-4   	1000000000	         0.000015 ns/op	       0 B/op	       0 allocs/op
PASS

What did you see instead?

finch% go1.14rc1 test -bench . -benchmem ./src -v
=== RUN   TestCleanup
    TestCleanup: foo_test.go:8: In test
    TestCleanup: foo_test.go:9: Hello, test cleanup!
--- PASS: TestCleanup (0.00s)
goos: darwin
goarch: amd64
pkg: <snip>
    BenchmarkCleanup: foo_test.go:13: In benchmark
    BenchmarkCleanup: foo_test.go:13: In benchmark
    BenchmarkCleanup: foo_test.go:13: In benchmark
    BenchmarkCleanup: foo_test.go:13: In benchmark
    BenchmarkCleanup: foo_test.go:13: In benchmark
    BenchmarkCleanup: foo_test.go:13: In benchmark
BenchmarkCleanup-4   	1000000000	         0.000015 ns/op	       0 B/op	       0 allocs/op
PASS

---

I'm not sure if the Cleanup isn't being fired at all, or the b.Logf is just not outputting anything. FWIW, I tried replacing b.Logf with a panic, and I didn't see anything different so I'm inclined to say that b.Cleanup just isn't firing?

(Edit: expected and actual output were flipped)

[ianlancetaylor]

CC @rogpeppe

[ianlancetaylor]

I'm not even sure how to use the Cleanup method for a Benchmark. Unlike a Test, a Benchmark function is invoked multiple times. Should the Cleanup be run once? Or should it be run each time the Benchmark function is called?

[lestrrat]

My assumption was that it will be run once at the end of the entire benchmark function. I was merely testing it out to possibly include it in a article on "what's new in go1.14", so my stance is just that "the documentation says X, but it's doing Y" :)

[ianlancetaylor]

Unfortunately I have no idea how to implement that suggestion. The problem is that the benchmark function will be invoked multiple times, and it might call the Cleanup method each time, and it might call the Cleanup method multiple times, and it might call the Cleanup method conditionally. We have no way of knowing whether this is a Cleanup function that was already registered and therefore should not be added to the list, or whether it is a new Cleanup that we haven't seen before and need to add to the list.

[lestrrat]

I understand. In that case I should probably study the behavior further and propose a doc patch, as I found it vague (at least when I glanced through it very briefly prior to testing it out) as to exactly how b.Cleanup should work. Feel free to close this issue or otherwise I will add my findings here

[lestrrat]

Upon reading the source code that came with go1.14rc1, I think it's safe to say that *testing.B does not run cleanup at all. Would it be better if I propose a doc change or should I wait and/or propose a change like moving the cleanup code to *testing.T instead of *testing.common ?

If a doc change should suffice, and there are plans to make this work somehow on *testing.B, I propose to change it from

// Cleanup registers a function to be called when the test and all its
// subtests complete. Cleanup functions will be called in last added,
// first called order.

to something like

// Cleanup registers a function to be called when the test and all its
// subtests complete. Cleanup functions will be called in last added,
// first called order. While this method exists for both *testing.T and
// *testing.B, currently it only works for *testing.T

Otherwise moving its implementation from *testing.common to *testing.T may be clearer?

[myitcv]

I have to say it was a surprise to me (as someone who was involved in discussing the implementation/docs) to read that you could even call (*testing.B).Cleanup. Because my understanding was that we had only looked to define this for *testing.T. I'd certainly missed this.

Hence, the method only be defined on *testing.T sounds most appropriate, but again, @rogpeppe will be better placed to comment.

[lestrrat]

Just for the record, the only reason I started testing this was because it was explicitly stated in the release docs... :)

[myitcv]

@lestrrat indeed. Ashamedly, I didn't even read the release notes following the change. Again, something at least I missed, apologies.

[rogpeppe]

Thanks for bringing this up. It's definitely an omission (and my fault!). By my understanding, a benchmark cleanup function should be run every time the benchmark function is called, after all sub-benchmarks have returned. The idea is that you should potentially be able to use the same resource-lifetime-control mechanism for benchmarks as you would for tests. I don't see any particular reason that someone might want a resource to stay around after a benchmark function returns - there would be no way to access it.

[gopherbot]

Change https://golang.org/cl/218117 mentions this issue: testing: make Cleanup work for benchmarks too.