runtime/coverage: TestCoverageApis failures

[gopherbot]

#!watchflakes
post <- pkg == "runtime/coverage" && test == "TestCoverageApis"

Issue created automatically to collect these failures.

Example (log):

--- FAIL: TestCoverageApis (225.26s)
    emitdata_test.go:44: harness path is /home/gopher/build/tmp/TestCoverageApis3430482397/001/build/harness.exe
    --- FAIL: TestCoverageApis/emitWithCounterClear (161.51s)
        emitdata_test.go:146: running: /home/gopher/build/tmp/TestCoverageApis3430482397/001/build/harness.exe -tp emitWithCounterClear -o /home/gopher/build/tmp/TestCoverageApis3430482397/001/emitWithCounterClear1-edir-y with rdir=/home/gopher/build/tmp/TestCoverageApis3430482397/001/emitWithCounterClear1-rdir-y and GOCOVERDIR=false
        emitdata_test.go:146: running: /home/gopher/build/tmp/TestCoverageApis3430482397/001/build2/harness.exe -tp emitWithCounterClear -o /home/gopher/build/tmp/TestCoverageApis3430482397/001/emitWithCounterClear2-edir-y with rdir=/home/gopher/build/tmp/TestCoverageApis3430482397/001/emitWithCounterClear2-rdir-y and GOCOVERDIR=false
        emitdata_test.go:158: running: go [tool covdata debugdump -live -pkg=main -i=/home/gopher/build/tmp/TestCoverageApis3430482397/001/emitWithCounterClear2-edir-y]
        emitdata_test.go:376: warning: GOCOVERDIR not set, no coverage data emitted
            I run last.
        emitdata_test.go:377: coverage data from "emitWithCounterClear" output match failed: error: output should contain "Func: emitWithCounterClear" but does not
        emitdata_test.go:146: running: /home/gopher/build/tmp/TestCoverageApis3430482397/001/build/harness.exe -tp emitWithCounterClear -o /home/gopher/build/tmp/TestCoverageApis3430482397/001/emitWithCounterClear1-edir-x with rdir=/home/gopher/build/tmp/TestCoverageApis3430482397/001/emitWithCounterClear1-rdir-x and GOCOVERDIR=true
        emitdata_test.go:146: running: /home/gopher/build/tmp/TestCoverageApis3430482397/001/build2/harness.exe -tp emitWithCounterClear -o /home/gopher/build/tmp/TestCoverageApis3430482397/001/emitWithCounterClear2-edir-x with rdir=/home/gopher/build/tmp/TestCoverageApis3430482397/001/emitWithCounterClear2-rdir-x and GOCOVERDIR=true
        emitdata_test.go:158: running: go [tool covdata debugdump -live -pkg=main -i=/home/gopher/build/tmp/TestCoverageApis3430482397/001/emitWithCounterClear2-edir-x]

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "runtime/coverage" && test == "TestCoverageApis"

2022-10-06 05:21 openbsd-arm64-jsing go@af668c68 runtime/coverage.TestCoverageApis (log)

--- FAIL: TestCoverageApis (225.26s)
    emitdata_test.go:44: harness path is /home/gopher/build/tmp/TestCoverageApis3430482397/001/build/harness.exe
    --- FAIL: TestCoverageApis/emitWithCounterClear (161.51s)
        emitdata_test.go:146: running: /home/gopher/build/tmp/TestCoverageApis3430482397/001/build/harness.exe -tp emitWithCounterClear -o /home/gopher/build/tmp/TestCoverageApis3430482397/001/emitWithCounterClear1-edir-y with rdir=/home/gopher/build/tmp/TestCoverageApis3430482397/001/emitWithCounterClear1-rdir-y and GOCOVERDIR=false
        emitdata_test.go:146: running: /home/gopher/build/tmp/TestCoverageApis3430482397/001/build2/harness.exe -tp emitWithCounterClear -o /home/gopher/build/tmp/TestCoverageApis3430482397/001/emitWithCounterClear2-edir-y with rdir=/home/gopher/build/tmp/TestCoverageApis3430482397/001/emitWithCounterClear2-rdir-y and GOCOVERDIR=false
        emitdata_test.go:158: running: go [tool covdata debugdump -live -pkg=main -i=/home/gopher/build/tmp/TestCoverageApis3430482397/001/emitWithCounterClear2-edir-y]
        emitdata_test.go:376: warning: GOCOVERDIR not set, no coverage data emitted
            I run last.
        emitdata_test.go:377: coverage data from "emitWithCounterClear" output match failed: error: output should contain "Func: emitWithCounterClear" but does not
        emitdata_test.go:146: running: /home/gopher/build/tmp/TestCoverageApis3430482397/001/build/harness.exe -tp emitWithCounterClear -o /home/gopher/build/tmp/TestCoverageApis3430482397/001/emitWithCounterClear1-edir-x with rdir=/home/gopher/build/tmp/TestCoverageApis3430482397/001/emitWithCounterClear1-rdir-x and GOCOVERDIR=true
        emitdata_test.go:146: running: /home/gopher/build/tmp/TestCoverageApis3430482397/001/build2/harness.exe -tp emitWithCounterClear -o /home/gopher/build/tmp/TestCoverageApis3430482397/001/emitWithCounterClear2-edir-x with rdir=/home/gopher/build/tmp/TestCoverageApis3430482397/001/emitWithCounterClear2-rdir-x and GOCOVERDIR=true
        emitdata_test.go:158: running: go [tool covdata debugdump -live -pkg=main -i=/home/gopher/build/tmp/TestCoverageApis3430482397/001/emitWithCounterClear2-edir-x]

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "runtime/coverage" && test == "TestCoverageApis"

2022-10-14 12:48 netbsd-amd64-9_0 go@a4b4717f runtime/coverage.TestCoverageApis (log)

panic: test timed out after 3m0s

syscall.Syscall6(0x1e1, 0x1, 0x3e96, 0xc00007bc14, 0x10020, 0x0, 0x0)
	/tmp/workdir/go/src/syscall/asm_unix_amd64.s:39 +0x5 fp=0xc00007bbc0 sp=0xc00007bbb8 pc=0x471f65
os.wait6(0x46e194?, 0xc00006a420?, 0xc00006a3c0?)
	/tmp/workdir/go/src/os/wait6_netbsd.go:16 +0x4d fp=0xc00007bc30 sp=0xc00007bbc0 pc=0x48d48d
os.(*Process).blockUntilWaitable(0xc00001c240)
	/tmp/workdir/go/src/os/wait_wait6.go:20 +0x36 fp=0xc00007bc60 sp=0xc00007bc30 pc=0x48d516
os.(*Process).wait(0xc00001c240)
	/tmp/workdir/go/src/os/exec_unix.go:22 +0x28 fp=0xc00007bcc0 sp=0xc00007bc60 pc=0x488588
os.(*Process).Wait(...)
	/tmp/workdir/go/src/os/exec.go:132
os/exec.(*Cmd).Wait(0xc00012c000)
	/tmp/workdir/go/src/os/exec/exec.go:721 +0x4b fp=0xc00007bd30 sp=0xc00007bcc0 pc=0x4d874b
os/exec.(*Cmd).Run(0xc00001a108?)
	/tmp/workdir/go/src/os/exec/exec.go:500 +0x39 fp=0xc00007bd50 sp=0xc00007bd30 pc=0x4d7659
os/exec.(*Cmd).CombinedOutput(0xc00012c000)
	/tmp/workdir/go/src/os/exec/exec.go:788 +0xa8 fp=0xc00007bd78 sp=0xc00007bd50 pc=0x4d8a68
runtime/coverage.buildHarness(0xc000007860, {0xc0000200c0?, 0x34?}, {0xc00007bf20, 0x2, 0x552?})
	/tmp/workdir/go/src/runtime/coverage/emitdata_test.go:109 +0x29e fp=0xc00007be90 sp=0xc00007bd78 pc=0x51d9be
runtime/coverage.TestCoverageApis(0xc000007860)
	/tmp/workdir/go/src/runtime/coverage/emitdata_test.go:42 +0x1d8 fp=0xc00007bf70 sp=0xc00007be90 pc=0x51cc98
testing.tRunner(0xc000007860, 0x566298)

— watchflakes

[thanm]

For this last Oct 14 flake, it looks as though it timed out just building the harness, which is not especially far into the test (hmm). I'll send another CL to skip all the API tests in short mode.

[gopherbot]

Change https://go.dev/cl/443376 mentions this issue: runtime/coverage: skip more tests in short mode

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "runtime/coverage" && test == "TestCoverageApis"

2022-10-17 15:26 linux-ppc64-sid-buildlet go@c83d4fba runtime/coverage.TestCoverageApis (log)

--- FAIL: TestCoverageApis (26.08s)
    emitdata_test.go:44: harness path is /workdir/tmp/TestCoverageApis914856079/001/build/harness.exe
    --- FAIL: TestCoverageApis/emitToFailingWriter (0.05s)
        emitdata_test.go:146: running: /workdir/tmp/TestCoverageApis914856079/001/build/harness.exe -tp emitToFailingWriter -o /workdir/tmp/TestCoverageApis914856079/001/emitToFailingWriter-edir-y with rdir=/workdir/tmp/TestCoverageApis914856079/001/emitToFailingWriter-rdir-y and GOCOVERDIR=false
        emitdata_test.go:146: running: /workdir/tmp/TestCoverageApis914856079/001/build/harness.exe -tp emitToFailingWriter -o /workdir/tmp/TestCoverageApis914856079/001/emitToFailingWriter-edir-x with rdir=/workdir/tmp/TestCoverageApis914856079/001/emitToFailingWriter-rdir-x and GOCOVERDIR=true
        emitdata_test.go:320: panic: runtime error: slice bounds out of range [:4294968768] with capacity 24182

            goroutine 1 [running]:
            panic({0x127860, 0xc000014168})
            	/workdir/go/src/runtime/panic.go:987 +0x564 fp=0xc00008d988 sp=0xc00008d8b8 pc=0x5f644
...
            main.writeStressTest({0x13133c, 0xc}, 0x139f60)
            	/workdir/go/src/runtime/coverage/testdata/harness.go:170 +0xa0 fp=0xc00008deb8 sp=0xc00008de30 pc=0x107e50
            main.emitToFailingWriter()
            	/workdir/go/src/runtime/coverage/testdata/harness.go:206 +0x9c fp=0xc00008def0 sp=0xc00008deb8 pc=0x10802c
            main.main()
            	/workdir/go/src/runtime/coverage/testdata/harness.go:252 +0x230 fp=0xc00008df50 sp=0xc00008def0 pc=0x108470
            runtime.main()
            	/workdir/go/src/runtime/proc.go:250 +0x314 fp=0xc00008dfc0 sp=0xc00008df50 pc=0x63374
            runtime.goexit()
            	/workdir/go/src/runtime/asm_ppc64x.s:899 +0x4 fp=0xc00008dfc0 sp=0xc00008dfc0 pc=0xa5444

— watchflakes

[bcmills]

@thanm, is this fixed, or is there more to do here? That last failure on 2022-10-17 doesn't particularly look like a timeout to me...

[thanm]

I agree that last failure does not look like a timeout. I will see if I can reproduce it.

[thanm]

Well, so far no luck reproducing it:

gomote run thanm-linux-ppc64-sid-buildlet-0 go/bin/go test -test.count=1000 -test.run=TestCoverageApis/emitToFailingWriter runtime/coverage
...

Looking at the code that triggers the panic, it looks like a corrupt coverage counter section would do it, assuming that is what happened. I will wait and see if any other similar flakes turn up.