testing,internal/fuzz: Fuzzer reports 0 execs/sec and keeps running

[capnspacehook]

#!watchflakes
post <- pkg == "cmd/go" && `fuzz: elapsed: \d+m\d+s, execs: \d+ \(0/sec\),` && (date < "2023-10-01" || builder ~ `^go1.20`)

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

$ go version
go version go1.18rc1 linux/amd64

Does this issue reproduce with the latest release?

Yes

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

go env Output

$ go env
GO111MODULE="" 
GOARCH="amd64"                                                      
GOBIN="" 
GOCACHE="/home/capnspacehook/.cache/go-build"
GOENV="/home/capnspacehook/.config/go/env"
GOEXE=""             
GOEXPERIMENT=""    
GOFLAGS=""          
GOHOSTARCH="amd64"     
GOHOSTOS="linux"                                                                                                                        
GOINSECURE=""
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/capnspacehook/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/capnspacehook/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/capnspacehook/sdk/go1.18rc1"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/capnspacehook/sdk/go1.18rc1/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.18rc1"
GCCGO="gccgo"
GOAMD64="v1"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="0"
GOMOD="/home/capnspacehook/Documents/git/egress-eddie/go.mod"
GOWORK=""
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 -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build1895014098=/tmp/go-build -gno-record-gcc-switches"

What did you do?

• Clone https://github.com/capnspacehook/toml
• Switch to the invalid_utf8 branch
• Clone https://github.com/capnspacehook/egress-eddie
• Switch to the go_fuzzer_bug branch
• Replace your local fuzz cache with the contents of fuzzcache
• Add a replace directive to the go.mod file replacing github.com/BurntSushi/toml with where you cloned github.com/capnspacehook/toml
• Start fuzzing: go test -run Parse -fuzz Fuzz

What did you expect to see?

The fuzzer trying many inputs per second

What did you see instead?

fuzz: elapsed: 0s, gathering baseline coverage: 0/253 completed                                                                                               
fuzz: elapsed: 1s, gathering baseline coverage: 253/253 completed, now fuzzing with 12 workers                                                                
fuzz: elapsed: 3s, execs: 42532 (14175/sec), new interesting: 14 (total: 267)                                                                                 
fuzz: elapsed: 6s, execs: 78830 (12092/sec), new interesting: 20 (total: 273)                                                                                 
fuzz: elapsed: 9s, execs: 78830 (0/sec), new interesting: 20 (total: 273)                                                                                     
fuzz: elapsed: 12s, execs: 78830 (0/sec), new interesting: 20 (total: 273)                                                                                    
fuzz: elapsed: 15s, execs: 78830 (0/sec), new interesting: 20 (total: 273)                                                                                    
fuzz: elapsed: 18s, execs: 78830 (0/sec), new interesting: 20 (total: 273)                                                                                    
fuzz: elapsed: 21s, execs: 78830 (0/sec), new interesting: 20 (total: 273)                                                                                    
fuzz: elapsed: 24s, execs: 78830 (0/sec), new interesting: 20 (total: 273)                                                                                    
fuzz: elapsed: 27s, execs: 78830 (0/sec), new interesting: 20 (total: 273)                                                                                    
fuzz: elapsed: 30s, execs: 78830 (0/sec), new interesting: 20 (total: 273)

May be related to #48591.

[bcmills]

(CC @rolandshoemaker)

[joewreschnig]

I've also noticed this in one test; after running with 0/sec for a while (but clearly not actually 0, given my computer's CPU usage) it came back with an unusually, almost implausibly, high number of execs/sec for a few runs before returning to normal:

fuzz: elapsed: 0s, gathering baseline coverage: 0/9 completed
fuzz: elapsed: 0s, gathering baseline coverage: 9/9 completed, now fuzzing with 8 workers
fuzz: elapsed: 3s, execs: 79681 (26558/sec), new interesting: 35 (total: 44)
fuzz: elapsed: 6s, execs: 93444 (4588/sec), new interesting: 36 (total: 45)
fuzz: elapsed: 9s, execs: 153249 (19933/sec), new interesting: 39 (total: 48)
fuzz: elapsed: 12s, execs: 166674 (4475/sec), new interesting: 40 (total: 49)
fuzz: elapsed: 15s, execs: 438829 (90711/sec), new interesting: 41 (total: 50)
fuzz: elapsed: 18s, execs: 438829 (0/sec), new interesting: 41 (total: 50)
fuzz: elapsed: 21s, execs: 438829 (0/sec), new interesting: 41 (total: 50)
fuzz: elapsed: 24s, execs: 438829 (0/sec), new interesting: 41 (total: 50)
fuzz: elapsed: 27s, execs: 438829 (0/sec), new interesting: 41 (total: 50)
fuzz: elapsed: 30s, execs: 438829 (0/sec), new interesting: 41 (total: 50)
fuzz: elapsed: 33s, execs: 438829 (0/sec), new interesting: 41 (total: 50)
fuzz: elapsed: 36s, execs: 438829 (0/sec), new interesting: 41 (total: 50)
fuzz: elapsed: 39s, execs: 438829 (0/sec), new interesting: 41 (total: 50)
fuzz: elapsed: 42s, execs: 438829 (0/sec), new interesting: 41 (total: 50)
fuzz: elapsed: 45s, execs: 438829 (0/sec), new interesting: 41 (total: 50)
fuzz: elapsed: 48s, execs: 438829 (0/sec), new interesting: 41 (total: 50)
fuzz: elapsed: 51s, execs: 438829 (0/sec), new interesting: 41 (total: 50)
fuzz: elapsed: 54s, execs: 438829 (0/sec), new interesting: 41 (total: 50)
fuzz: elapsed: 57s, execs: 2051825 (537812/sec), new interesting: 45 (total: 54)
fuzz: elapsed: 1m0s, execs: 3173094 (373707/sec), new interesting: 49 (total: 58)
fuzz: elapsed: 1m3s, execs: 3257748 (28217/sec), new interesting: 50 (total: 59)
fuzz: elapsed: 1m6s, execs: 3450825 (64365/sec), new interesting: 52 (total: 61)
fuzz: elapsed: 1m9s, execs: 4098105 (215768/sec), new interesting: 52 (total: 61)
fuzz: elapsed: 1m12s, execs: 5313498 (405066/sec), new interesting: 54 (total: 63)
fuzz: elapsed: 1m15s, execs: 5483457 (56668/sec), new interesting: 55 (total: 64)
fuzz: elapsed: 1m18s, execs: 5647501 (54672/sec), new interesting: 57 (total: 66)
fuzz: elapsed: 1m21s, execs: 5834412 (62312/sec), new interesting: 57 (total: 66)
fuzz: elapsed: 1m24s, execs: 6009865 (58477/sec), new interesting: 57 (total: 66)
fuzz: elapsed: 1m27s, execs: 6185876 (58669/sec), new interesting: 57 (total: 66)
fuzz: elapsed: 1m30s, execs: 6362102 (58654/sec), new interesting: 57 (total: 66)

[ianlancetaylor]

CC @golang/fuzzing

What is the current status here? This issue is currently in the 1.19 milestone. Should it move to 1.20? To Backlog? Thanks.

[capnspacehook]

I can still easily reproduce this in github actions, it doesn't seem to be as specific as I thought: https://github.com/capnspacehook/egress-eddie/actions/runs/3374243584/jobs/5599662068

[bcmills]

There is at least one instance of this in the Go build dashboard as well: https://build.golang.org/log/99d38c470b4df7a559bb833dc8f1fd15bf8d1aa3

[mdempsky]

I'm seeing this happen too (i.e., 10-30 second stretches of 0 execs/sec reported). I've instrumented my fuzz target to call T.Fatal if it takes longer than 1 second to finish, and it doesn't seem to trigger at all. So I'm guessing it's just a UI issue, and that the fuzzer is actually steadily working the whole time still.

[bcmills]

@mdempsky, I don't think it's just a UI issue, or the cmd/go test that runs a fixed number of times would have terminated. It may be an accounting issue, or a deadlock (or livelock) in which none of the workers are able to start new work.

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "cmd/go" && `fuzz: elapsed: \d+m\d+s, execs: \d+ \(0/sec\),`

2022-11-19 16:50 windows-amd64-longtest go@58a2db18 cmd/go.TestScript (log)

vcs-test.golang.org rerouted to http://127.0.0.1:54031 https://vcs-test.golang.org rerouted to https://127.0.0.1:54032 go test proxy running at GOPROXY=http://127.0.0.1:54033/mod --- FAIL: TestScript (0.15s) --- FAIL: TestScript/test_fuzz_mutator (2472.10s) script_test.go:134: 2022-11-19T18:29:47Z script_test.go:136: $WORK=C:\Users\gopher\AppData\Local\Temp\1\cmd-go-test-545967725\tmpdir2602773748\test_fuzz_mutator3453940057 script_test.go:154: > [!fuzz] skip [condition not met] ... fuzz: elapsed: 40m45s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 40m48s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 40m51s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 40m54s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 40m57s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m0s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m3s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m6s, execs: 110 (0/sec), new interesting: 0 (total: 1) script_test.go:154: FAIL: test_fuzz_mutator.txt:12: go test -fuzz=FuzzA -fuzztime=100x -parallel=1 -log=fuzz: exit status 1 2022/11/19 19:11:19 unexpected files left in tmpdir: [tmpdir2602773748]

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "cmd/go" && `fuzz: elapsed: \d+m\d+s, execs: \d+ \(0/sec\),`

2022-11-17 13:46 windows-amd64-longtest go@bed970b3 cmd/go.TestScript (log)

vcs-test.golang.org rerouted to http://127.0.0.1:54013 https://vcs-test.golang.org rerouted to https://127.0.0.1:54014 go test proxy running at GOPROXY=http://127.0.0.1:54015/mod --- FAIL: TestScript (0.16s) --- FAIL: TestScript/test_fuzz_mutator (2496.66s) script_test.go:134: 2022-11-17T14:21:00Z script_test.go:136: $WORK=C:\Users\gopher\AppData\Local\Temp\1\cmd-go-test-4137783702\tmpdir1013264568\test_fuzz_mutator2546986549 script_test.go:154: > [!fuzz] skip [condition not met] ... fuzz: elapsed: 41m9s, execs: 111 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m12s, execs: 111 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m15s, execs: 111 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m18s, execs: 111 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m21s, execs: 111 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m24s, execs: 111 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m27s, execs: 111 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m30s, execs: 111 (0/sec), new interesting: 0 (total: 1) script_test.go:154: FAIL: test_fuzz_mutator.txt:12: go test -fuzz=FuzzA -fuzztime=100x -parallel=1 -log=fuzz: exit status 1 2022/11/17 15:02:57 unexpected files left in tmpdir: [tmpdir1013264568]

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "cmd/go" && `fuzz: elapsed: \d+m\d+s, execs: \d+ \(0/sec\),`

2023-01-20 17:47 linux-arm64-longtest go@09d852ce cmd/go.TestScript (log)

vcs-test.golang.org rerouted to http://127.0.0.1:41503 https://vcs-test.golang.org rerouted to https://127.0.0.1:40595 go test proxy running at GOPROXY=http://127.0.0.1:37979/mod 2023/01/20 18:09:34 http: TLS handshake error from 127.0.0.1:51270: read tcp 127.0.0.1:40595->127.0.0.1:51270: read: connection reset by peer 2023/01/20 18:09:34 http: TLS handshake error from 127.0.0.1:51342: read tcp 127.0.0.1:40595->127.0.0.1:51342: read: connection reset by peer 2023/01/20 18:09:34 http: TLS handshake error from 127.0.0.1:51336: EOF 2023/01/20 18:09:35 http: TLS handshake error from 127.0.0.1:51384: EOF --- FAIL: TestScript (0.06s) --- FAIL: TestScript/test_fuzz_mutator (2542.19s) script_test.go:134: 2023-01-20T18:09:47Z ... fuzz: elapsed: 41m57s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m0s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m3s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m6s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m9s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m12s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m15s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m18s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m21s, execs: 110 (0/sec), new interesting: 0 (total: 1) script_test.go:154: FAIL: test_fuzz_mutator.txt:12: go test -fuzz=FuzzA -fuzztime=100x -parallel=1 -log=fuzz: signal: killed

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "cmd/go" && `fuzz: elapsed: \d+m\d+s, execs: \d+ \(0/sec\),`

2023-01-25 19:53 windows-amd64-longtest go@b68d699a cmd/go.TestScript (log)

vcs-test.golang.org rerouted to http://127.0.0.1:54148 https://vcs-test.golang.org rerouted to https://127.0.0.1:54149 go test proxy running at GOPROXY=http://127.0.0.1:54150/mod --- FAIL: TestScript (0.16s) --- FAIL: TestScript/test_fuzz_mutator (2500.74s) script_test.go:134: 2023-01-25T21:35:34Z script_test.go:136: $WORK=C:\Users\gopher\AppData\Local\Temp\1\cmd-go-test-542847270\tmpdir2371678741\test_fuzz_mutator2724278266 script_test.go:154: > [!fuzz] skip [condition not met] ... fuzz: elapsed: 41m15s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m18s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m21s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m24s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m27s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m30s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m33s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m36s, execs: 110 (0/sec), new interesting: 0 (total: 1) script_test.go:154: FAIL: test_fuzz_mutator.txt:12: go test -fuzz=FuzzA -fuzztime=100x -parallel=1 -log=fuzz: exit status 1 2023/01/25 22:17:33 unexpected files left in tmpdir: [tmpdir2371678741]

2023-01-26 00:52 linux-amd64-longtest go@45110692 cmd/go.TestScript (log)

vcs-test.golang.org rerouted to http://127.0.0.1:44675 https://vcs-test.golang.org rerouted to https://127.0.0.1:40027 go test proxy running at GOPROXY=http://127.0.0.1:34513/mod 2023/01/26 01:27:26 http: TLS handshake error from 127.0.0.1:55452: EOF 2023/01/26 01:27:28 http: TLS handshake error from 127.0.0.1:55514: EOF 2023/01/26 01:27:28 http: TLS handshake error from 127.0.0.1:55576: read tcp 127.0.0.1:40027->127.0.0.1:55576: read: connection reset by peer --- FAIL: TestScript (0.07s) --- FAIL: TestScript/test_fuzz_mutator (2559.92s) script_test.go:134: 2023-01-26T01:25:28Z script_test.go:136: $WORK=/workdir/tmp/cmd-go-test-843707451/tmpdir2125951140/test_fuzz_mutator1884690564 ... fuzz: elapsed: 42m6s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m9s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m12s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m15s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m18s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m21s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m24s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m27s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m30s, execs: 110 (0/sec), new interesting: 0 (total: 1) script_test.go:154: FAIL: test_fuzz_mutator.txt:12: go test -fuzz=FuzzA -fuzztime=100x -parallel=1 -log=fuzz: signal: killed

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "cmd/go" && `fuzz: elapsed: \d+m\d+s, execs: \d+ \(0/sec\),`

2023-02-09 18:01 linux-amd64-longtest-race go@9987cb6c cmd/go.TestScript (log)

vcs-test.golang.org rerouted to http://127.0.0.1:38563 https://vcs-test.golang.org rerouted to https://127.0.0.1:37157 go test proxy running at GOPROXY=http://127.0.0.1:33779/mod 2023/02/09 18:53:37 http: TLS handshake error from 127.0.0.1:46432: EOF 2023/02/09 18:55:10 http: TLS handshake error from 127.0.0.1:58398: EOF 2023/02/09 18:55:10 http: TLS handshake error from 127.0.0.1:58416: EOF --- FAIL: TestScript (0.14s) --- FAIL: TestScript/test_fuzz_mutator (2414.61s) script_test.go:134: 2023-02-09T18:55:03Z script_test.go:136: $WORK=/workdir/tmp/cmd-go-test-3405197563/tmpdir2644547310/test_fuzz_mutator3164770644 ... fuzz: elapsed: 39m48s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 39m51s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 39m54s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 39m57s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 40m0s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 40m3s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 40m6s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 40m9s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 40m12s, execs: 110 (0/sec), new interesting: 0 (total: 1) script_test.go:154: FAIL: test_fuzz_mutator.txt:12: go test -fuzz=FuzzA -fuzztime=100x -parallel=1 -log=fuzz: signal: killed

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "cmd/go" && `fuzz: elapsed: \d+m\d+s, execs: \d+ \(0/sec\),`

2023-02-10 14:49 windows-amd64-longtest go@c3d3be10 cmd/go.TestScript (log)

vcs-test.golang.org rerouted to http://127.0.0.1:54159 https://vcs-test.golang.org rerouted to https://127.0.0.1:54160 go test proxy running at GOPROXY=http://127.0.0.1:54161/mod --- FAIL: TestScript (0.17s) --- FAIL: TestScript/test_fuzz_mutator (2517.22s) script_test.go:134: 2023-02-10T15:23:34Z script_test.go:136: $WORK=C:\Users\gopher\AppData\Local\Temp\1\cmd-go-test-2764378961\tmpdir2413758927\test_fuzz_mutator415649562 script_test.go:154: > [!fuzz] skip [condition not met] ... fuzz: elapsed: 41m21s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m24s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m27s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m30s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m33s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m36s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m39s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m42s, execs: 110 (0/sec), new interesting: 0 (total: 1) script_test.go:154: FAIL: test_fuzz_mutator.txt:12: go test -fuzz=FuzzA -fuzztime=100x -parallel=1 -log=fuzz: exit status 1 2023/02/10 16:05:52 unexpected files left in tmpdir: [tmpdir2413758927]

2023-02-17 21:23 linux-amd64-longtest go@209df389 cmd/go.TestScript (log)

vcs-test.golang.org rerouted to http://127.0.0.1:46703 https://vcs-test.golang.org rerouted to https://127.0.0.1:46241 go test proxy running at GOPROXY=http://127.0.0.1:44307/mod 2023/02/17 21:50:03 http: TLS handshake error from 127.0.0.1:42244: EOF 2023/02/17 21:50:03 http: TLS handshake error from 127.0.0.1:42248: read tcp 127.0.0.1:46241->127.0.0.1:42248: read: connection reset by peer 2023/02/17 21:50:03 http: TLS handshake error from 127.0.0.1:42270: EOF --- FAIL: TestScript (0.07s) --- FAIL: TestScript/test_fuzz_mutator (2536.02s) script_test.go:134: 2023-02-17T21:49:47Z script_test.go:136: $WORK=/workdir/tmp/cmd-go-test-3503693006/tmpdir3556894025/test_fuzz_mutator1038626370 ... fuzz: elapsed: 41m48s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m51s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m54s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m57s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m0s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m3s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m6s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m9s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m12s, execs: 110 (0/sec), new interesting: 0 (total: 1) script_test.go:154: FAIL: test_fuzz_mutator.txt:12: go test -fuzz=FuzzA -fuzztime=100x -parallel=1 -log=fuzz: signal: killed

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "cmd/go" && `fuzz: elapsed: \d+m\d+s, execs: \d+ \(0/sec\),`

2023-03-01 21:23 windows-amd64-longtest go@c10ba768 cmd/go.TestScript (log)

vcs-test.golang.org rerouted to http://127.0.0.1:54157 https://vcs-test.golang.org rerouted to https://127.0.0.1:54158 go test proxy running at GOPROXY=http://127.0.0.1:54159/mod --- FAIL: TestScript (0.16s) --- FAIL: TestScript/test_fuzz_mutator (2532.73s) script_test.go:134: 2023-03-01T22:04:34Z script_test.go:136: $WORK=C:\Users\gopher\AppData\Local\Temp\1\cmd-go-test-2333707969\tmpdir2719946696\test_fuzz_mutator187299215 script_test.go:154: > [!fuzz] skip [condition not met] ... fuzz: elapsed: 41m48s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m51s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m54s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m57s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m0s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m3s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m6s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m9s, execs: 110 (0/sec), new interesting: 0 (total: 1) script_test.go:154: FAIL: test_fuzz_mutator.txt:12: go test -fuzz=FuzzA -fuzztime=100x -parallel=1 -log=fuzz: exit status 1 2023/03/01 22:47:09 unexpected files left in tmpdir: [tmpdir2719946696]

2023-03-02 15:57 linux-amd64-longtest go@b958d4a5 cmd/go.TestScript (log)

vcs-test.golang.org rerouted to http://127.0.0.1:46071 https://vcs-test.golang.org rerouted to https://127.0.0.1:45027 go test proxy running at GOPROXY=http://127.0.0.1:41955/mod 2023/03/02 16:24:56 http: TLS handshake error from 127.0.0.1:44990: EOF 2023/03/02 16:24:56 http: TLS handshake error from 127.0.0.1:45018: EOF 2023/03/02 16:24:57 http: TLS handshake error from 127.0.0.1:45058: read tcp 127.0.0.1:45027->127.0.0.1:45058: read: connection reset by peer --- FAIL: TestScript (0.04s) --- FAIL: TestScript/test_fuzz_mutator (2540.76s) script_test.go:134: 2023-03-02T16:25:00Z script_test.go:136: $WORK=/workdir/tmp/cmd-go-test-4130748747/tmpdir3756329173/test_fuzz_mutator2354259621 ... fuzz: elapsed: 41m54s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m57s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m0s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m3s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m6s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m9s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m12s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m15s, execs: 110 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m18s, execs: 110 (0/sec), new interesting: 0 (total: 1) script_test.go:154: FAIL: test_fuzz_mutator.txt:12: go test -fuzz=FuzzA -fuzztime=100x -parallel=1 -log=fuzz: signal: killed

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "cmd/go" && `fuzz: elapsed: \d+m\d+s, execs: \d+ \(0/sec\),`

2023-03-09 19:19 linux-amd64-longtest go@642542cb cmd/go.TestScript (log)

vcs-test.golang.org rerouted to http://127.0.0.1:34581 https://vcs-test.golang.org rerouted to https://127.0.0.1:46291 go test proxy running at GOPROXY=http://127.0.0.1:33507/mod 2023/03/09 19:51:43 http: TLS handshake error from 127.0.0.1:49450: EOF 2023/03/09 19:51:43 http: TLS handshake error from 127.0.0.1:49456: read tcp 127.0.0.1:46291->127.0.0.1:49456: read: connection reset by peer 2023/03/09 19:51:44 http: TLS handshake error from 127.0.0.1:49528: read tcp 127.0.0.1:46291->127.0.0.1:49528: read: connection reset by peer --- FAIL: TestScript (0.06s) --- FAIL: TestScript/test_fuzz_mutator (2536.95s) script_test.go:134: 2023-03-09T19:49:55Z script_test.go:136: $WORK=/workdir/tmp/cmd-go-test-2081396492/tmpdir79341683/test_fuzz_mutator2006497029 ... fuzz: elapsed: 41m48s, execs: 114 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m51s, execs: 114 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m54s, execs: 114 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m57s, execs: 114 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m0s, execs: 114 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m3s, execs: 114 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m6s, execs: 114 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m9s, execs: 114 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 42m12s, execs: 114 (0/sec), new interesting: 0 (total: 1) script_test.go:154: FAIL: test_fuzz_mutator.txt:12: go test -fuzz=FuzzA -fuzztime=100x -parallel=1 -log=fuzz: signal: killed

— watchflakes

[gopherbot]

Change https://go.dev/cl/475196 mentions this issue: internal/fuzz: avoid deadlock on duplicate entris with exec limit

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "cmd/go" && `fuzz: elapsed: \d+m\d+s, execs: \d+ \(0/sec\),`

2023-03-10 17:18 linux-amd64-longtest-race go@f52bede3 cmd/go.TestScript (log)

vcs-test.golang.org rerouted to http://127.0.0.1:38429 https://vcs-test.golang.org rerouted to https://127.0.0.1:41039 go test proxy running at GOPROXY=http://127.0.0.1:41941/mod 2023/03/10 18:06:22 http: TLS handshake error from 127.0.0.1:34610: read tcp 127.0.0.1:41039->127.0.0.1:34610: read: connection reset by peer 2023/03/10 18:06:22 http: TLS handshake error from 127.0.0.1:34624: read tcp 127.0.0.1:41039->127.0.0.1:34624: read: connection reset by peer 2023/03/10 18:06:22 http: TLS handshake error from 127.0.0.1:34630: EOF 2023/03/10 18:06:22 http: TLS handshake error from 127.0.0.1:34648: EOF 2023/03/10 18:06:22 http: TLS handshake error from 127.0.0.1:34634: EOF 2023/03/10 18:07:14 http: TLS handshake error from 127.0.0.1:51190: read tcp 127.0.0.1:41039->127.0.0.1:51190: read: connection reset by peer 2023/03/10 18:07:14 http: TLS handshake error from 127.0.0.1:51206: EOF ... --- FAIL: TestScript (0.12s) --- FAIL: TestScript/test_fuzz_cov (2558.01s) script_test.go:134: 2023-03-10T18:04:47Z script_test.go:136: $WORK=/workdir/tmp/cmd-go-test-1586127799/tmpdir2124851826/test_fuzz_cov2246382605 script_test.go:154: # Test that coverage instrumentation is working. Without the instrumentation # it is _extremely_ unlikely that the fuzzer would produce this particular # input in any reasonable amount of time. (2558.001s) > [short] skip [condition not met] ... fuzz: elapsed: 42m12s, execs: 302930 (0/sec), new interesting: 5 (total: 5) fuzz: elapsed: 42m15s, execs: 302930 (0/sec), new interesting: 5 (total: 5) fuzz: elapsed: 42m18s, execs: 302930 (0/sec), new interesting: 5 (total: 5) fuzz: elapsed: 42m21s, execs: 302930 (0/sec), new interesting: 5 (total: 5) fuzz: elapsed: 42m24s, execs: 302930 (0/sec), new interesting: 5 (total: 5) fuzz: elapsed: 42m27s, execs: 302930 (0/sec), new interesting: 5 (total: 5) fuzz: elapsed: 42m30s, execs: 302930 (0/sec), new interesting: 5 (total: 5) fuzz: elapsed: 42m33s, execs: 302930 (0/sec), new interesting: 5 (total: 5) [signal: killed] script_test.go:154: FAIL: test_fuzz_cov.txt:8: context deadline exceeded

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "cmd/go" && `fuzz: elapsed: \d+m\d+s, execs: \d+ \(0/sec\),`

2023-03-10 17:59 linux-arm64-longtest go@3790ceca cmd/go.TestScript (log)

vcs-test.golang.org rerouted to http://127.0.0.1:46819 https://vcs-test.golang.org rerouted to https://127.0.0.1:44059 go test proxy running at GOPROXY=http://127.0.0.1:40183/mod 2023/03/10 18:21:27 http: TLS handshake error from 127.0.0.1:43984: read tcp 127.0.0.1:44059->127.0.0.1:43984: read: connection reset by peer 2023/03/10 18:21:27 http: TLS handshake error from 127.0.0.1:43998: EOF 2023/03/10 18:21:27 http: TLS handshake error from 127.0.0.1:44034: EOF 2023/03/10 18:21:27 http: TLS handshake error from 127.0.0.1:44058: read tcp 127.0.0.1:44059->127.0.0.1:44058: read: connection reset by peer 2023/03/10 18:21:27 http: TLS handshake error from 127.0.0.1:44072: EOF 2023/03/10 18:21:27 http: TLS handshake error from 127.0.0.1:44044: EOF --- FAIL: TestScript (0.06s) --- FAIL: TestScript/test_fuzz_cov (2485.07s) script_test.go:134: 2023-03-10T18:22:02Z script_test.go:136: $WORK=/tmp/workdir/tmp/cmd-go-test-979541931/tmpdir1444416238/test_fuzz_cov2443857143 script_test.go:154: # Test that coverage instrumentation is working. Without the instrumentation # it is _extremely_ unlikely that the fuzzer would produce this particular # input in any reasonable amount of time. (2485.070s) > [short] skip [condition not met] > [!fuzz-instrumented] skip ... fuzz: elapsed: 41m0s, execs: 70173 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 41m3s, execs: 70173 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 41m6s, execs: 70173 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 41m9s, execs: 70173 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 41m12s, execs: 70173 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 41m15s, execs: 70173 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 41m18s, execs: 70173 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 41m21s, execs: 70173 (0/sec), new interesting: 6 (total: 6) [signal: killed] script_test.go:154: FAIL: test_fuzz_cov.txt:8: context deadline exceeded

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "cmd/go" && `fuzz: elapsed: \d+m\d+s, execs: \d+ \(0/sec\),`

2023-03-13 17:03 linux-amd64-longtest go@e671fe0c cmd/go.TestScript (log)

vcs-test.golang.org rerouted to http://127.0.0.1:33105 https://vcs-test.golang.org rerouted to https://127.0.0.1:40181 go test proxy running at GOPROXY=http://127.0.0.1:33767/mod 2023/03/13 17:31:28 http: TLS handshake error from 127.0.0.1:36572: EOF 2023/03/13 17:31:28 http: TLS handshake error from 127.0.0.1:36588: EOF 2023/03/13 17:31:28 http: TLS handshake error from 127.0.0.1:36642: read tcp 127.0.0.1:40181->127.0.0.1:36642: read: connection reset by peer 2023/03/13 17:31:28 http: TLS handshake error from 127.0.0.1:36622: EOF 2023/03/13 17:31:29 http: TLS handshake error from 127.0.0.1:36674: EOF --- FAIL: TestScript (0.06s) --- FAIL: TestScript/test_fuzz_cov (2533.53s) ... fuzz: elapsed: 41m51s, execs: 421270 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 41m54s, execs: 421270 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 41m57s, execs: 421270 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 42m0s, execs: 421270 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 42m3s, execs: 421270 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 42m6s, execs: 421270 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 42m9s, execs: 421270 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 42m12s, execs: 421270 (0/sec), new interesting: 6 (total: 6) [signal: killed] script_test.go:154: FAIL: test_fuzz_cov.txt:8: context deadline exceeded

— watchflakes

[bcmills]

Looks like CL 475196 didn't quite fix it: commit e671fe0c is after it on the main branch.

[rolandshoemaker]

Looks like we switched from test_fuzz_mutator triggering it to test_fuzz_cov triggering it. Either another deadlock, or I just managed to shuffle it around...

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "cmd/go" && `fuzz: elapsed: \d+m\d+s, execs: \d+ \(0/sec\),`

2023-03-13 20:25 linux-amd64-longtest-race go@82c713fe cmd/go.TestScript (log)

vcs-test.golang.org rerouted to http://127.0.0.1:42741 https://vcs-test.golang.org rerouted to https://127.0.0.1:38301 go test proxy running at GOPROXY=http://127.0.0.1:42127/mod 2023/03/13 21:21:11 http: TLS handshake error from 127.0.0.1:60916: EOF --- FAIL: TestScript (0.17s) --- FAIL: TestScript/get_test_only (10.66s) script_test.go:134: 2023-03-13T21:22:31Z script_test.go:136: $WORK=/workdir/tmp/cmd-go-test-3083707113/tmpdir160692266/get_test_only2236343467 script_test.go:154: > [!net] skip ... --- FAIL: TestScript/test_fuzz_cov (2562.01s) script_test.go:134: 2023-03-13T21:19:13Z script_test.go:136: $WORK=/workdir/tmp/cmd-go-test-3083707113/tmpdir160692266/test_fuzz_cov1599637190 script_test.go:154: # Test that coverage instrumentation is working. Without the instrumentation # it is _extremely_ unlikely that the fuzzer would produce this particular # input in any reasonable amount of time. (2561.994s) > [short] skip [condition not met] > [!fuzz-instrumented] skip ... fuzz: elapsed: 42m9s, execs: 630443 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 42m12s, execs: 630443 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 42m15s, execs: 630443 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 42m18s, execs: 630443 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 42m21s, execs: 630443 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 42m24s, execs: 630443 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 42m27s, execs: 630443 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 42m30s, execs: 630443 (0/sec), new interesting: 6 (total: 6) [signal: killed] script_test.go:154: FAIL: test_fuzz_cov.txt:8: context deadline exceeded

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "cmd/go" && `fuzz: elapsed: \d+m\d+s, execs: \d+ \(0/sec\),`

2023-03-14 09:07 linux-amd64-longtest-race go@a54fe8a2 cmd/go.TestScript (log)

vcs-test.golang.org rerouted to http://127.0.0.1:33397 https://vcs-test.golang.org rerouted to https://127.0.0.1:34493 go test proxy running at GOPROXY=http://127.0.0.1:32783/mod 2023/03/14 09:53:17 http: TLS handshake error from 127.0.0.1:55522: EOF 2023/03/14 09:54:13 http: TLS handshake error from 127.0.0.1:33232: EOF 2023/03/14 09:54:13 http: TLS handshake error from 127.0.0.1:33204: EOF 2023/03/14 09:54:13 http: TLS handshake error from 127.0.0.1:33248: EOF --- FAIL: TestScript (0.11s) --- FAIL: TestScript/test_fuzz_cov (2445.75s) script_test.go:134: 2023-03-14T09:53:45Z ... fuzz: elapsed: 40m24s, execs: 851238 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 40m27s, execs: 851238 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 40m30s, execs: 851238 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 40m33s, execs: 851238 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 40m36s, execs: 851238 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 40m39s, execs: 851238 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 40m42s, execs: 851238 (0/sec), new interesting: 6 (total: 6) fuzz: elapsed: 40m45s, execs: 851238 (0/sec), new interesting: 6 (total: 6) [signal: killed] script_test.go:154: FAIL: test_fuzz_cov.txt:8: context deadline exceeded

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "cmd/go" && `fuzz: elapsed: \d+m\d+s, execs: \d+ \(0/sec\),`

2023-03-15 07:15 linux-amd64-longtest-race go@574c6209 cmd/go.TestScript (log)

vcs-test.golang.org rerouted to http://127.0.0.1:40485 https://vcs-test.golang.org rerouted to https://127.0.0.1:41239 go test proxy running at GOPROXY=http://127.0.0.1:44525/mod 2023/03/15 08:10:48 http: TLS handshake error from 127.0.0.1:42386: EOF 2023/03/15 08:10:51 http: TLS handshake error from 127.0.0.1:41280: EOF 2023/03/15 08:10:51 http: TLS handshake error from 127.0.0.1:41264: EOF --- FAIL: TestScript (0.17s) --- FAIL: TestScript/test_fuzz_cov (2545.92s) script_test.go:134: 2023-03-15T08:08:50Z script_test.go:136: $WORK=/workdir/tmp/cmd-go-test-1594439502/tmpdir2749669090/test_fuzz_cov4094467851 ... fuzz: elapsed: 41m48s, execs: 167695 (0/sec), new interesting: 3 (total: 3) fuzz: elapsed: 41m51s, execs: 167695 (0/sec), new interesting: 3 (total: 3) fuzz: elapsed: 41m54s, execs: 167695 (0/sec), new interesting: 3 (total: 3) fuzz: elapsed: 41m57s, execs: 167695 (0/sec), new interesting: 3 (total: 3) fuzz: elapsed: 42m0s, execs: 167695 (0/sec), new interesting: 3 (total: 3) fuzz: elapsed: 42m3s, execs: 167695 (0/sec), new interesting: 3 (total: 3) fuzz: elapsed: 42m6s, execs: 167695 (0/sec), new interesting: 3 (total: 3) fuzz: elapsed: 42m9s, execs: 167695 (0/sec), new interesting: 3 (total: 3) [signal: killed] script_test.go:154: FAIL: test_fuzz_cov.txt:8: context deadline exceeded

— watchflakes

[gopherbot]

Change https://go.dev/cl/476595 mentions this issue: internal/fuzz: improve debugging messages

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "cmd/go" && `fuzz: elapsed: \d+m\d+s, execs: \d+ \(0/sec\),`

2023-03-15 21:08 linux-amd64-longtest go@3128edfe cmd/go.TestScript (log)

vcs-test.golang.org rerouted to http://127.0.0.1:37297 https://vcs-test.golang.org rerouted to https://127.0.0.1:45383 go test proxy running at GOPROXY=http://127.0.0.1:42815/mod 2023/03/15 21:34:02 http: TLS handshake error from 127.0.0.1:60520: EOF 2023/03/15 21:34:03 http: TLS handshake error from 127.0.0.1:60532: read tcp 127.0.0.1:45383->127.0.0.1:60532: read: connection reset by peer 2023/03/15 21:34:03 http: TLS handshake error from 127.0.0.1:60552: read tcp 127.0.0.1:45383->127.0.0.1:60552: read: connection reset by peer 2023/03/15 21:34:03 http: TLS handshake error from 127.0.0.1:60548: read tcp 127.0.0.1:45383->127.0.0.1:60548: read: connection reset by peer --- FAIL: TestScript (0.06s) --- FAIL: TestScript/test_fuzz_cov (2465.04s) script_test.go:134: 2023-03-15T21:35:05Z ... fuzz: elapsed: 40m42s, execs: 309854 (0/sec), new interesting: 4 (total: 4) fuzz: elapsed: 40m45s, execs: 309854 (0/sec), new interesting: 4 (total: 4) fuzz: elapsed: 40m48s, execs: 309854 (0/sec), new interesting: 4 (total: 4) fuzz: elapsed: 40m51s, execs: 309854 (0/sec), new interesting: 4 (total: 4) fuzz: elapsed: 40m54s, execs: 309854 (0/sec), new interesting: 4 (total: 4) fuzz: elapsed: 40m57s, execs: 309854 (0/sec), new interesting: 4 (total: 4) fuzz: elapsed: 41m0s, execs: 309854 (0/sec), new interesting: 4 (total: 4) fuzz: elapsed: 41m3s, execs: 309854 (0/sec), new interesting: 4 (total: 4) [signal: killed] script_test.go:154: FAIL: test_fuzz_cov.txt:11: context deadline exceeded

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "cmd/go" && `fuzz: elapsed: \d+m\d+s, execs: \d+ \(0/sec\),`

2023-03-15 21:24 linux-arm64-longtest go@617cf132 cmd/go.TestScript (log)

vcs-test.golang.org rerouted to http://127.0.0.1:46151 https://vcs-test.golang.org rerouted to https://127.0.0.1:44877 go test proxy running at GOPROXY=http://127.0.0.1:41311/mod 2023/03/15 21:45:08 http: TLS handshake error from 127.0.0.1:46122: EOF 2023/03/15 21:45:08 http: TLS handshake error from 127.0.0.1:46118: EOF 2023/03/15 21:45:08 http: TLS handshake error from 127.0.0.1:46154: read tcp 127.0.0.1:44877->127.0.0.1:46154: read: connection reset by peer 2023/03/15 21:45:08 http: TLS handshake error from 127.0.0.1:46136: EOF 2023/03/15 21:45:09 http: TLS handshake error from 127.0.0.1:46192: read tcp 127.0.0.1:44877->127.0.0.1:46192: read: connection reset by peer 2023/03/15 21:45:09 http: TLS handshake error from 127.0.0.1:46188: read tcp 127.0.0.1:44877->127.0.0.1:46188: read: connection reset by peer --- FAIL: TestScript (0.07s) --- FAIL: TestScript/test_fuzz_cov (2475.83s) script_test.go:134: 2023-03-15T21:45:36Z script_test.go:136: $WORK=/tmp/workdir/tmp/cmd-go-test-1120256864/tmpdir3226819736/test_fuzz_cov315436921 script_test.go:154: # Test that coverage instrumentation is working. Without the instrumentation # it is _extremely_ unlikely that the fuzzer would produce this particular # input in any reasonable amount of time. (0.000s) # TODO(#51484): enabled debugging info to help diagnose a deadlock in the fuzzer (2475.830s) > env GODEBUG=fuzzdebug=1 > go clean --fuzzcache ... fuzz: elapsed: 40m51s, execs: 30393 (0/sec), new interesting: 3 (total: 3) fuzz: elapsed: 40m54s, execs: 30393 (0/sec), new interesting: 3 (total: 3) fuzz: elapsed: 40m57s, execs: 30393 (0/sec), new interesting: 3 (total: 3) fuzz: elapsed: 41m0s, execs: 30393 (0/sec), new interesting: 3 (total: 3) fuzz: elapsed: 41m3s, execs: 30393 (0/sec), new interesting: 3 (total: 3) fuzz: elapsed: 41m6s, execs: 30393 (0/sec), new interesting: 3 (total: 3) fuzz: elapsed: 41m9s, execs: 30393 (0/sec), new interesting: 3 (total: 3) fuzz: elapsed: 41m12s, execs: 30393 (0/sec), new interesting: 3 (total: 3) [signal: killed] script_test.go:154: FAIL: test_fuzz_cov.txt:11: context deadline exceeded

— watchflakes

[gopherbot]

Change https://go.dev/cl/476815 mentions this issue: internal/fuzz: release lock when reading file fails

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "cmd/go" && `fuzz: elapsed: \d+m\d+s, execs: \d+ \(0/sec\),`

2023-03-16 05:12 linux-amd64-longtest-race go@c69ff3a7 cmd/go.TestScript (log)

vcs-test.golang.org rerouted to http://127.0.0.1:39839 https://vcs-test.golang.org rerouted to https://127.0.0.1:43429 go test proxy running at GOPROXY=http://127.0.0.1:33839/mod 2023/03/16 06:08:49 http: TLS handshake error from 127.0.0.1:53612: read tcp 127.0.0.1:43429->127.0.0.1:53612: read: connection reset by peer 2023/03/16 06:08:49 http: TLS handshake error from 127.0.0.1:53642: EOF --- FAIL: TestScript (0.17s) --- FAIL: TestScript/test_fuzz_cov (2540.14s) script_test.go:134: 2023-03-16T06:07:16Z script_test.go:136: $WORK=/workdir/tmp/cmd-go-test-460480058/tmpdir2330553061/test_fuzz_cov1337934177 script_test.go:154: ... fuzz: elapsed: 41m57s, execs: 164898 (0/sec), new interesting: 5 (total: 5) fuzz: elapsed: 42m0s, execs: 164898 (0/sec), new interesting: 5 (total: 5) fuzz: elapsed: 42m3s, execs: 164898 (0/sec), new interesting: 5 (total: 5) fuzz: elapsed: 42m6s, execs: 164898 (0/sec), new interesting: 5 (total: 5) fuzz: elapsed: 42m9s, execs: 164898 (0/sec), new interesting: 5 (total: 5) fuzz: elapsed: 42m12s, execs: 164898 (0/sec), new interesting: 5 (total: 5) fuzz: elapsed: 42m15s, execs: 164898 (0/sec), new interesting: 5 (total: 5) fuzz: elapsed: 42m18s, execs: 164898 (0/sec), new interesting: 5 (total: 5) [signal: killed] script_test.go:154: FAIL: test_fuzz_cov.txt:11: context deadline exceeded

— watchflakes

[rolandshoemaker]

@bcmills I think we might've also squashed this 🎉.

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "cmd/go" && `fuzz: elapsed: \d+m\d+s, execs: \d+ \(0/sec\),`

2023-09-06 14:22 linux-amd64-longtest go@023b542e cmd/go.TestScript (log)

vcs-test.golang.org rerouted to http://127.0.0.1:41321 https://vcs-test.golang.org rerouted to https://127.0.0.1:39441 go test proxy running at GOPROXY=http://127.0.0.1:39787/mod 2023/09/06 14:56:10 http: TLS handshake error from 127.0.0.1:60152: read tcp 127.0.0.1:39441->127.0.0.1:60152: read: connection reset by peer 2023/09/06 14:56:10 http: TLS handshake error from 127.0.0.1:60192: EOF 2023/09/06 14:56:10 http: TLS handshake error from 127.0.0.1:60206: read tcp 127.0.0.1:39441->127.0.0.1:60206: read: connection reset by peer 2023/09/06 14:56:10 http: TLS handshake error from 127.0.0.1:60214: read tcp 127.0.0.1:39441->127.0.0.1:60214: read: connection reset by peer 2023/09/06 14:56:10 http: TLS handshake error from 127.0.0.1:60234: read tcp 127.0.0.1:39441->127.0.0.1:60234: read: connection reset by peer 2023/09/06 14:56:11 http: TLS handshake error from 127.0.0.1:60328: EOF --- FAIL: TestScript (0.07s) --- FAIL: TestScript/test_fuzz_mutator (2499.64s) script_test.go:134: 2023-09-06T14:56:39Z script_test.go:136: $WORK=/workdir/tmp/cmd-go-test-1266012417/tmpdir2064082176/test_fuzz_mutator3350690479 script_test.go:154: > [!fuzz] skip [condition not met] # Test basic fuzzing mutator behavior. # # fuzz_test.go has two fuzz targets (FuzzA, FuzzB) which both add a seed value. # Each fuzz function writes the input to a log file. The coordinator and worker ... fuzz: elapsed: 41m6s, execs: 112 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m9s, execs: 112 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m12s, execs: 112 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m15s, execs: 112 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m18s, execs: 112 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m21s, execs: 112 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m24s, execs: 112 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m27s, execs: 112 (0/sec), new interesting: 0 (total: 1) fuzz: elapsed: 41m30s, execs: 112 (0/sec), new interesting: 0 (total: 1) script_test.go:154: FAIL: test_fuzz_mutator.txt:12: go test -fuzz=FuzzA -fuzztime=100x -parallel=1 -log=fuzz: signal: killed

— watchflakes

[bcmills]

Commit 023b542e is on release-branch.go1.20 (#59483).

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "cmd/go" && `fuzz: elapsed: \d+m\d+s, execs: \d+ \(0/sec\),` && (date < "2023-10-01" || builder ~ `^go1.20`)

2024-01-31 17:29 go1.20-linux-amd64-longtest release-branch.go1.20@746a0727 cmd/go.TestScript/test_fuzz_mutator (log)

=== RUN TestScript/test_fuzz_mutator === PAUSE TestScript/test_fuzz_mutator === CONT TestScript/test_fuzz_mutator script_test.go:134: 2024-01-31T17:41:10Z script_test.go:136: $WORK=/home/swarming/.swarming/w/ir/x/t/cmd-go-test-496575198/tmpdir1725107858/test_fuzz_mutator2748934260 script_test.go:154: PATH=/home/swarming/.swarming/w/ir/x/t/cmd-go-test-496575198/tmpdir1725107858/testbin:/home/swarming/.swarming/w/ir/x/w/goroot/bin:/home/swarming/.swarming/w/ir/x/w/goroot/bin:/home/swarming/.swarming/w/ir/cache/tools/bin:/home/swarming/.swarming/w/ir/bbagent_utility_packages:/home/swarming/.swarming/w/ir/bbagent_utility_packages/bin:/home/swarming/.swarming/w/ir/cipd_bin_packages:/home/swarming/.swarming/w/ir/cipd_bin_packages/bin:/home/swarming/.swarming/w/ir/cipd_bin_packages/cpython3:/home/swarming/.swarming/w/ir/cipd_bin_packages/cpython3/bin:/home/swarming/.swarming/w/ir/cache/cipd_client:/home/swarming/.swarming/w/ir/cache/cipd_client/bin:/home/swarming/.swarming/cipd_cache/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin HOME=/no-home CCACHE_DISABLE=1 GOARCH=amd64 ... fuzz: elapsed: 46m6s, execs: 100 (0/sec), new interesting: 2 (total: 3) fuzz: elapsed: 46m9s, execs: 100 (0/sec), new interesting: 2 (total: 3) fuzz: elapsed: 46m12s, execs: 100 (0/sec), new interesting: 2 (total: 3) fuzz: elapsed: 46m15s, execs: 100 (0/sec), new interesting: 2 (total: 3) fuzz: elapsed: 46m18s, execs: 100 (0/sec), new interesting: 2 (total: 3) fuzz: elapsed: 46m21s, execs: 100 (0/sec), new interesting: 2 (total: 3) fuzz: elapsed: 46m24s, execs: 100 (0/sec), new interesting: 2 (total: 3) fuzz: elapsed: 46m27s, execs: 100 (0/sec), new interesting: 2 (total: 3) script_test.go:154: FAIL: test_fuzz_mutator.txt:12: go test -fuzz=FuzzA -fuzztime=100x -parallel=1 -log=fuzz: signal: killed --- FAIL: TestScript/test_fuzz_mutator (2803.34s)

— watchflakes