log: TestDiscard failures due to too many allocs

[gopherbot]

#!watchflakes
post <- log ~ `--- FAIL: TestDiscard` && log ~ `got \d+ allocs, want at most 1`

Issue created automatically to collect these failures.

Example (log):

vcs-test.golang.org rerouted to http://127.0.0.1:39277
https://vcs-test.golang.org rerouted to https://127.0.0.1:34125
go test proxy running at GOPROXY=http://127.0.0.1:46305/mod
--- FAIL: TestFilepathUnderCwdFormat (1.42s)
    go_test.go:2821: running testgo [test -x -cover log]
    go_test.go:2821: standard output:
    go_test.go:2821: --- FAIL: TestDiscard (0.03s)
            log_test.go:207: got 2 allocs, want at most 1
        FAIL
        	log	coverage: 71.1% of statements
...
        packagefile crypto/subtle=/workdir/gocache/93/936c2e22f4fcbd0b7273f97e835d5d6372de93d45fdb25c586e01b67ed05aa1d-d
        modinfo "0w\xaf\f\x92t\b\x02A\xe1\xc1\a\xe6\xd6\x18\xe6\xf92C1\x86\x18 r\x00\x82B\x10A\x16\xd8\xf2"
        EOF
        cd .
        /workdir/go/pkg/tool/linux_amd64/link -o $WORK/b001/log.test -importcfg $WORK/b001/importcfg.link -s -w -X=runtime.godebugDefault=panicnil=1 -buildmode=exe -buildid=Uffi6O2soViLSt0_OPlD/ELOjj7ShqfLNCy4nSPrW/23DB8BLVe9RvRZykr_Rq/Uffi6O2soViLSt0_OPlD -extld=gcc $WORK/b001/_pkg_.a
        mkdir -p $WORK/b001/gocoverdir
        $WORK/b001/log.test -test.testlogfile=$WORK/b001/testlog.txt -test.paniconexit0 -test.gocoverdir=$WORK/b001/gocoverdir -test.timeout=10m0s
        rm -r $WORK/b001/

    go_test.go:2821: go [test -x -cover log] failed unexpectedly in /workdir/go/src/cmd/go: exit status 1

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "cmd/go" && test == "TestFilepathUnderCwdFormat"

2023-02-28 21:59 linux-amd64-goamd64v3 go@ec26277a cmd/go.TestFilepathUnderCwdFormat (log)

vcs-test.golang.org rerouted to http://127.0.0.1:39277
https://vcs-test.golang.org rerouted to https://127.0.0.1:34125
go test proxy running at GOPROXY=http://127.0.0.1:46305/mod
--- FAIL: TestFilepathUnderCwdFormat (1.42s)
    go_test.go:2821: running testgo [test -x -cover log]
    go_test.go:2821: standard output:
    go_test.go:2821: --- FAIL: TestDiscard (0.03s)
            log_test.go:207: got 2 allocs, want at most 1
        FAIL
        	log	coverage: 71.1% of statements
...
        packagefile crypto/subtle=/workdir/gocache/93/936c2e22f4fcbd0b7273f97e835d5d6372de93d45fdb25c586e01b67ed05aa1d-d
        modinfo "0w\xaf\f\x92t\b\x02A\xe1\xc1\a\xe6\xd6\x18\xe6\xf92C1\x86\x18 r\x00\x82B\x10A\x16\xd8\xf2"
        EOF
        cd .
        /workdir/go/pkg/tool/linux_amd64/link -o $WORK/b001/log.test -importcfg $WORK/b001/importcfg.link -s -w -X=runtime.godebugDefault=panicnil=1 -buildmode=exe -buildid=Uffi6O2soViLSt0_OPlD/ELOjj7ShqfLNCy4nSPrW/23DB8BLVe9RvRZykr_Rq/Uffi6O2soViLSt0_OPlD -extld=gcc $WORK/b001/_pkg_.a
        mkdir -p $WORK/b001/gocoverdir
        $WORK/b001/log.test -test.testlogfile=$WORK/b001/testlog.txt -test.paniconexit0 -test.gocoverdir=$WORK/b001/gocoverdir -test.timeout=10m0s
        rm -r $WORK/b001/

    go_test.go:2821: go [test -x -cover log] failed unexpectedly in /workdir/go/src/cmd/go: exit status 1

— watchflakes

[bcmills]

This is the regression test for #47164 added in CL 348741.

(attn @ianlancetaylor, @robpike)

[ianlancetaylor]

The test case that is failing is running go test -x -cover log. @thanm Is it possible for coverage to insert allocations somehow?

I'll note that I was not able to recreate the problem myself, even running the test 10,000 times.

[thanm]

Is it possible for coverage to insert allocations somehow

The runtime support routines for -cover do certainly perform memory allocation, but those functions are kicked off by testing.M.after -> testing.M.writeProfiles -> testing.coverReport, and in theory testing.M.after is happening after all testing is done.

If we can somehow reproduce this I am happy to take a look...

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- log ~ `--- FAIL: TestDiscard` && log ~ `got \d+ allocs, want at most 1`

2023-02-28 05:12 linux-mips64-rtrk go@41e86796 log.TestDiscard (log)

--- FAIL: TestDiscard (0.01s)
    log_test.go:207: got 2 allocs, want at most 1

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- log ~ `--- FAIL: TestDiscard` && log ~ `got \d+ allocs, want at most 1`

2023-03-20 23:33 darwin-amd64-13 go@9279a9af cmd/go.TestFilepathUnderCwdFormat (log)

vcs-test.golang.org rerouted to http://127.0.0.1:54776
https://vcs-test.golang.org rerouted to https://127.0.0.1:54777
go test proxy running at GOPROXY=http://127.0.0.1:54778/mod
--- FAIL: TestFilepathUnderCwdFormat (4.10s)
    go_test.go:2798: running testgo [test -x -cover log]
    go_test.go:2798: standard output:
    go_test.go:2798: --- FAIL: TestDiscard (0.01s)
            log_test.go:207: got 2 allocs, want at most 1
        FAIL
        	log	coverage: 71.1% of statements
...
        packagefile crypto/subtle=/tmp/buildlet/gocache/c2/c25f0cd6522fc628fca0fe22e637bc8d274db11b7d85ddf4f43111e11ba661f3-d
        modinfo "0w\xaf\f\x92t\b\x02A\xe1\xc1\a\xe6\xd6\x18\xe6\xf92C1\x86\x18 r\x00\x82B\x10A\x16\xd8\xf2"
        EOF
        cd .
        /tmp/buildlet/go/pkg/tool/darwin_amd64/link -o $WORK/b001/log.test -importcfg $WORK/b001/importcfg.link -s -w -X=runtime.godebugDefault=panicnil=1 -buildmode=exe -buildid=SpLWNRFkCxf4tBgzLIOV/LjXtifL9GK-wY1AI7ixQ/LzREVNCffgKx9KQveT9m/SpLWNRFkCxf4tBgzLIOV -X testing.testBinary=1 -extld=clang $WORK/b001/_pkg_.a
        mkdir -p $WORK/b001/gocoverdir
        $WORK/b001/log.test -test.testlogfile=$WORK/b001/testlog.txt -test.paniconexit0 -test.gocoverdir=$WORK/b001/gocoverdir -test.timeout=10m0s
        rm -r $WORK/b001/

    go_test.go:2798: go [test -x -cover log] failed unexpectedly in /tmp/buildlet/go/src/cmd/go: exit status 1

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- log ~ `--- FAIL: TestDiscard` && log ~ `got \d+ allocs, want at most 1`

2023-03-22 18:20 linux-ppc64le-power9osu go@7f4a54c0 cmd/go.TestFilepathUnderCwdFormat (log)

vcs-test.golang.org rerouted to http://127.0.0.1:40403
https://vcs-test.golang.org rerouted to https://127.0.0.1:36413
go test proxy running at GOPROXY=http://127.0.0.1:41593/mod
--- FAIL: TestFilepathUnderCwdFormat (1.23s)
    go_test.go:2798: running testgo [test -x -cover log]
    go_test.go:2798: standard output:
    go_test.go:2798: --- FAIL: TestDiscard (0.00s)
            log_test.go:207: got 3 allocs, want at most 1
        FAIL
        	log	coverage: 71.1% of statements
...
        packagefile crypto/subtle=/workdir/gocache/c4/c4713334dcb95d74e04f7e7ca5264e5282bfe73b5069cd78139089938322f13e-d
        modinfo "0w\xaf\f\x92t\b\x02A\xe1\xc1\a\xe6\xd6\x18\xe6\xf92C1\x86\x18 r\x00\x82B\x10A\x16\xd8\xf2"
        EOF
        cd .
        /workdir/go/pkg/tool/linux_ppc64le/link -o $WORK/b001/log.test -importcfg $WORK/b001/importcfg.link -s -w -X=runtime.godebugDefault=panicnil=1 -buildmode=exe -buildid=T4sl4LNflqowPGgSLEAQ/HqOPC-NpUnjcxJvBrMi9/cNySWi_qt4tOsggKdcKc/T4sl4LNflqowPGgSLEAQ -X testing.testBinary=1 -extld=gcc $WORK/b001/_pkg_.a
        mkdir -p $WORK/b001/gocoverdir
        $WORK/b001/log.test -test.testlogfile=$WORK/b001/testlog.txt -test.paniconexit0 -test.gocoverdir=$WORK/b001/gocoverdir -test.timeout=10m0s
        rm -r $WORK/b001/

    go_test.go:2798: go [test -x -cover log] failed unexpectedly in /workdir/go/src/cmd/go: exit status 1

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- log ~ `--- FAIL: TestDiscard` && log ~ `got \d+ allocs, want at most 1`

2023-03-27 17:27 linux-ppc64le-power9osu go@93682105 cmd/go.TestFilepathUnderCwdFormat (log)

vcs-test.golang.org rerouted to http://127.0.0.1:46555
https://vcs-test.golang.org rerouted to https://127.0.0.1:41789
go test proxy running at GOPROXY=http://127.0.0.1:45461/mod
--- FAIL: TestFilepathUnderCwdFormat (1.43s)
    go_test.go:2798: running testgo [test -x -cover log]
    go_test.go:2798: standard output:
    go_test.go:2798: --- FAIL: TestDiscard (0.00s)
            log_test.go:207: got 4 allocs, want at most 1
        FAIL
        	log	coverage: 71.1% of statements
...
        packagefile crypto/subtle=/workdir/gocache/65/65f1116a00160d80ba638e7642dc0f6de291903cc5282efafc2cb709f7cfb244-d
        modinfo "0w\xaf\f\x92t\b\x02A\xe1\xc1\a\xe6\xd6\x18\xe6\xf92C1\x86\x18 r\x00\x82B\x10A\x16\xd8\xf2"
        EOF
        cd .
        /workdir/go/pkg/tool/linux_ppc64le/link -o $WORK/b001/log.test -importcfg $WORK/b001/importcfg.link -s -w -X=runtime.godebugDefault=panicnil=1 -buildmode=exe -buildid=PsSsS7Ym3g9qbgm2cntZ/gRTL3KSzsljtliDDhKcA/wp7LM_U94b3jC9-cUs26/PsSsS7Ym3g9qbgm2cntZ -X testing.testBinary=1 -extld=gcc $WORK/b001/_pkg_.a
        mkdir -p $WORK/b001/gocoverdir
        $WORK/b001/log.test -test.testlogfile=$WORK/b001/testlog.txt -test.paniconexit0 -test.gocoverdir=$WORK/b001/gocoverdir -test.timeout=10m0s
        rm -r $WORK/b001/

    go_test.go:2798: go [test -x -cover log] failed unexpectedly in /workdir/go/src/cmd/go: exit status 1

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- log ~ `--- FAIL: TestDiscard` && log ~ `got \d+ allocs, want at most 1`

2023-03-27 22:17 linux-ppc64le-power9osu go@8c2900bb cmd/go.TestFilepathUnderCwdFormat (log)

vcs-test.golang.org rerouted to http://127.0.0.1:35735
https://vcs-test.golang.org rerouted to https://127.0.0.1:45683
go test proxy running at GOPROXY=http://127.0.0.1:40391/mod
--- FAIL: TestFilepathUnderCwdFormat (1.19s)
    go_test.go:2798: running testgo [test -x -cover log]
    go_test.go:2798: standard output:
    go_test.go:2798: --- FAIL: TestDiscard (0.01s)
            log_test.go:207: got 2 allocs, want at most 1
        FAIL
        	log	coverage: 71.1% of statements
...
        packagefile crypto/subtle=/workdir/gocache/4d/4d2f296fb09d9c0b48fdec350a2eb51bcb005bd932e0dc544b6eb75287cb262c-d
        modinfo "0w\xaf\f\x92t\b\x02A\xe1\xc1\a\xe6\xd6\x18\xe6\xf92C1\x86\x18 r\x00\x82B\x10A\x16\xd8\xf2"
        EOF
        cd .
        /workdir/go/pkg/tool/linux_ppc64le/link -o $WORK/b001/log.test -importcfg $WORK/b001/importcfg.link -s -w -X=runtime.godebugDefault=panicnil=1 -buildmode=exe -buildid=ySyjEJghHYAWBZ8zpnyZ/vrcKuJwciCfKxoHO2X4u/0u8v_qCXUHbb1DOPjRNS/ySyjEJghHYAWBZ8zpnyZ -X testing.testBinary=1 -extld=gcc $WORK/b001/_pkg_.a
        mkdir -p $WORK/b001/gocoverdir
        $WORK/b001/log.test -test.testlogfile=$WORK/b001/testlog.txt -test.paniconexit0 -test.gocoverdir=$WORK/b001/gocoverdir -test.timeout=10m0s
        rm -r $WORK/b001/

    go_test.go:2798: go [test -x -cover log] failed unexpectedly in /workdir/go/src/cmd/go: exit status 1

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- log ~ `--- FAIL: TestDiscard` && log ~ `got \d+ allocs, want at most 1`

2023-03-30 15:55 linux-riscv64-unmatched go@92261b38 cmd/go.TestFilepathUnderCwdFormat (log)

vcs-test.golang.org rerouted to http://127.0.0.1:40571
https://vcs-test.golang.org rerouted to https://127.0.0.1:32793
go test proxy running at GOPROXY=http://127.0.0.1:38311/mod
--- FAIL: TestFilepathUnderCwdFormat (4.01s)
    go_test.go:2798: running testgo [test -x -cover log]
    go_test.go:2798: standard output:
    go_test.go:2798: --- FAIL: TestDiscard (0.01s)
            log_test.go:207: got 2 allocs, want at most 1
        FAIL
        	log	coverage: 71.1% of statements
...
        packagefile crypto/subtle=/tmp/workdir-host-linux-riscv64-unmatched/gocache/d4/d42023f86f44d22e7a86e6dc107d1f70b7947ea6519cdc2fa5bf618826927eb0-d
        modinfo "0w\xaf\f\x92t\b\x02A\xe1\xc1\a\xe6\xd6\x18\xe6\xf92C1\x86\x18 r\x00\x82B\x10A\x16\xd8\xf2"
        EOF
        cd .
        /tmp/workdir-host-linux-riscv64-unmatched/go/pkg/tool/linux_riscv64/link -o $WORK/b001/log.test -importcfg $WORK/b001/importcfg.link -s -w -X=runtime.godebugDefault=panicnil=1 -buildmode=exe -buildid=89RU6u5ind4gCxsxdplj/sKtFItfwEXhA-GTg9IJ9/vOxuc2DJAKwk06MS-k3n/89RU6u5ind4gCxsxdplj -X testing.testBinary=1 -extld=gcc $WORK/b001/_pkg_.a
        mkdir -p $WORK/b001/gocoverdir
        $WORK/b001/log.test -test.testlogfile=$WORK/b001/testlog.txt -test.paniconexit0 -test.gocoverdir=$WORK/b001/gocoverdir -test.timeout=10m0s
        rm -r $WORK/b001/

    go_test.go:2798: go [test -x -cover log] failed unexpectedly in /tmp/workdir-host-linux-riscv64-unmatched/go/src/cmd/go: exit status 1

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- log ~ `--- FAIL: TestDiscard` && log ~ `got \d+ allocs, want at most 1`

2023-04-19 14:27 linux-loong64-3a5000 go@1f9d80e3 log.TestDiscard (log)

--- FAIL: TestDiscard (0.01s)
    log_test.go:207: got 4 allocs, want at most 1

— watchflakes