Fix logging in tests - Githubissues

Tests will fail to execute multiple times with go test -count X with the following error:

panic: Log in goroutine after TESTNAME has completed

The reason for this is that the callback that is set when post is initialised holds a reference to testing.T and running it multiple times will always use the reference from the first test run (which eventually becomes invalid).

This change only allows to execute the same test multiple times (when it directly or indirectly calls setLogCallback) but it doesn't solve the issue that tests might still log on the wrong log reference:

$ go test -count 2 ./initialization/
ok      github.com/spacemeshos/post/initialization      3.312s
$ go test -race -count 2 ./initialization/
--- FAIL: TestBenchmark (1.14s)
panic: Log in goroutine after TestSearchForNonceNotFound has completed: 2023-09-26T15:02:50.941Z        DEBUG   Found new smallest nonce: Some(VrfNonce { index: 1, label: [130, 3, 35, 146, 197, 96, 91, 251, 254, 208, 147, 67, 250, 6, 240, 134, 255, 136, 27, 171, 78, 119, 243, 176, 198, 255, 64, 140, 54, 155, 244, 211] })     {"module": "post::initialize", "file": "src/initialize.rs", "line": 132} [recovered]
        panic: Log in goroutine after TestSearchForNonceNotFound has completed: 2023-09-26T15:02:50.941Z        DEBUG   Found new smallest nonce: Some(VrfNonce { index: 1, label: [130, 3, 35, 146, 197, 96, 91, 251, 254, 208, 147, 67, 250, 6, 240, 134, 255, 136, 27, 171, 78, 119, 243, 176, 198, 255, 64, 140, 54, 155, 244, 211] })     {"module": "post::initialize", "file": "src/initialize.rs", "line": 132}

goroutine 98 [running]:
testing.tRunner.func1.2({0x7086c0, 0xc00048e0a0})
        /usr/local/go/src/testing/testing.go:1545 +0x274
testing.tRunner.func1()
        /usr/local/go/src/testing/testing.go:1548 +0x448
panic({0x7086c0?, 0xc00048e0a0?})
        /usr/local/go/src/runtime/panic.go:920 +0x26c
testing.(*common).logDepth(0xc000197d40, {0xc0004c8140, 0x13a}, 0x3)
        /usr/local/go/src/testing/testing.go:1022 +0x4c8
testing.(*common).log(...)
        /usr/local/go/src/testing/testing.go:1004
testing.(*common).Logf(0xc000197d40, {0x758799, 0x2}, {0xc00048e080, 0x1, 0x1})
        /usr/local/go/src/testing/testing.go:1055 +0x84
go.uber.org/zap/zaptest.testingWriter.Write({{0x7de0e0?, 0xc000197d40?}, 0x70?}, {0xc00036a800, 0x13b, 0x400})
        /go/pkg/mod/go.uber.org/zap@v1.26.0/zaptest/logger.go:130 +0xf4
go.uber.org/zap/zapcore.(*ioCore).Write(0xc0003f52c0, {0xff, {0xc13cda86b8221ed5, 0xa0630756, 0x9aad40}, {0x0, 0x0}, {0xc0004ba000, 0xd2}, {0x0, ...}, ...}, ...)
        /go/pkg/mod/go.uber.org/zap@v1.26.0/zapcore/core.go:99 +0x120
go.uber.org/zap/zapcore.(*CheckedEntry).Write(0xc0004940d0, {0xc0004be000, 0x3, 0x3})
        /go/pkg/mod/go.uber.org/zap@v1.26.0/zapcore/entry.go:253 +0x1f0
go.uber.org/zap.(*Logger).Log(0x717680?, 0x90?, {0xc0004ba000, 0xd2}, {0xc0004be000, 0x3, 0x3})
        /go/pkg/mod/go.uber.org/zap@v1.26.0/logger.go:230 +0x64
github.com/spacemeshos/post/internal/postrs.logCallback(0xffff2714e240)
        /workspaces/spacemesh/post/internal/postrs/log.go:60 +0x330
github.com/spacemeshos/post/internal/postrs._Cfunc_initialize(0xfffee0000e00, 0x1, 0x1000, 0xfffee0000e60, 0xc00048a038)
        _cgo_gotypes.go:370 +0x48
github.com/spacemeshos/post/internal/postrs.cScryptPositions.func2(0xfffee0000e00, 0xfffee0000e60?, 0xc0ffffffff?, 0x2000?, 0xfffee0000b70?)
        /workspaces/spacemesh/post/internal/postrs/initializer.go:117 +0x88
github.com/spacemeshos/post/internal/postrs.cScryptPositions(0xc0000760f0?, 0x46ee10?, 0x1, 0x1000)
        /workspaces/spacemesh/post/internal/postrs/initializer.go:117 +0xd0
github.com/spacemeshos/post/internal/postrs.(*Scrypt).Positions(0xc00048e050, 0x1, 0x1000)
        /workspaces/spacemesh/post/internal/postrs/api.go:180 +0xd4
github.com/spacemeshos/post/initialization.Benchmark({0x7dd278?, {0xc0004a4000?, 0x0?}, 0x0?})
        /workspaces/spacemesh/post/initialization/benchmark.go:27 +0x14c
github.com/spacemeshos/post/initialization.TestBenchmark(0x0?)
        /workspaces/spacemesh/post/initialization/benchmark_test.go:14 +0xa8
testing.tRunner(0xc000148000, 0x785cc8)
        /usr/local/go/src/testing/testing.go:1595 +0x198
created by testing.(*T).Run in goroutine 1
        /usr/local/go/src/testing/testing.go:1648 +0x5dc
FAIL    github.com/spacemeshos/post/initialization      2.709s
FAIL

Parallel test execution might only be possible by not using a global logger on postrs side. Until then I removed t.Parallel() from all tests in this repo and will remove them form tests in go-spacemesh that involve initialization, proof generation or verification.

spacemeshos / post

Fix logging in tests #242

Codecov Report