log: TestDiscard failures due to too many allocs #58797

gopherbot · 2023-02-28T22:40:09Z

#!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

The text was updated successfully, but these errors were encountered:

gopherbot · 2023-02-28T22:40:12Z

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 · 2023-03-01T14:19:22Z

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

(attn @ianlancetaylor, @robpike)

ianlancetaylor · 2023-03-01T17:57:52Z

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 · 2023-03-01T18:10:17Z

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 · 2023-03-08T18:18:44Z

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 · 2023-03-21T02:49:55Z

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 · 2023-03-22T19:30:10Z

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 · 2023-03-27T18:23:47Z

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 · 2023-03-28T06:13:21Z

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 · 2023-03-30T21:26:42Z

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 · 2023-04-19T18:57:07Z

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

gopherbot · 2023-04-21T15:46:18Z

Change https://go.dev/cl/487356 mentions this issue: log: avoid leaking goroutines in TestOutputRace

gopherbot · 2023-04-21T17:07:10Z

Found new dashboard test flakes for:

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

2023-04-20 21:46 linux-ppc64le-power10osu go@608f204a log.TestDiscard (log)

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

— watchflakes

Leaked goroutines are the only explanation I can think of for excess allocs in TestDiscard, and TestOutputRace is the only place I can see where the log package leaks goroutines. Let's fix that leak and see if it eliminates the TestDiscard flakes. Fixes golang#58797 (maybe). Change-Id: I2d54dcba3eb52bd10a62cd1c380131add6a2f651 Reviewed-on: https://go-review.googlesource.com/c/go/+/487356 TryBot-Result: Gopher Robot <gobot@golang.org> Auto-Submit: Bryan Mills <bcmills@google.com> Run-TryBot: Bryan Mills <bcmills@google.com> Reviewed-by: Ian Lance Taylor <iant@google.com>

gopherbot added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Feb 28, 2023

bcmills changed the title ~~cmd/go: TestFilepathUnderCwdFormat failures~~ log: TestDiscard failures due to too many allocs Mar 1, 2023

bcmills added this to the Backlog milestone Mar 1, 2023

bcmills self-assigned this Apr 21, 2023

bcmills added Testing An issue that has been verified to require only test changes, not just a test failure. NeedsFix The path to resolution is known, but the work has not been done. labels Apr 21, 2023

bcmills modified the milestones: Backlog, Go1.21 Apr 21, 2023

gopherbot removed the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Apr 21, 2023

gopherbot closed this as completed in 6328e44 Apr 21, 2023

golang locked and limited conversation to collaborators Apr 20, 2024

gopherbot added the FrozenDueToAge label Apr 20, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

log: TestDiscard failures due to too many allocs #58797

log: TestDiscard failures due to too many allocs #58797

gopherbot commented Feb 28, 2023 •

edited by bcmills

gopherbot commented Feb 28, 2023

bcmills commented Mar 1, 2023

ianlancetaylor commented Mar 1, 2023

thanm commented Mar 1, 2023

gopherbot commented Mar 8, 2023

gopherbot commented Mar 21, 2023

gopherbot commented Mar 22, 2023

gopherbot commented Mar 27, 2023

gopherbot commented Mar 28, 2023

gopherbot commented Mar 30, 2023

gopherbot commented Apr 19, 2023

gopherbot commented Apr 21, 2023

gopherbot commented Apr 21, 2023

log: TestDiscard failures due to too many allocs #58797

log: TestDiscard failures due to too many allocs #58797

Comments

gopherbot commented Feb 28, 2023 • edited by bcmills

gopherbot commented Feb 28, 2023

bcmills commented Mar 1, 2023

ianlancetaylor commented Mar 1, 2023

thanm commented Mar 1, 2023

gopherbot commented Mar 8, 2023

gopherbot commented Mar 21, 2023

gopherbot commented Mar 22, 2023

gopherbot commented Mar 27, 2023

gopherbot commented Mar 28, 2023

gopherbot commented Mar 30, 2023

gopherbot commented Apr 19, 2023

gopherbot commented Apr 21, 2023

gopherbot commented Apr 21, 2023

gopherbot commented Feb 28, 2023 •

edited by bcmills