Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
capnspacehook opened this issue Mar 4, 2022 · 33 comments
Closed

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

capnspacehook opened this issue Mar 4, 2022 · 33 comments
Labels
fuzz Issues related to native fuzzing support NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Backlog

Comments

@capnspacehook
Copy link

capnspacehook commented Mar 4, 2022 •
edited by bcmills 

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

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
Copy link
Contributor

bcmills commented Mar 4, 2022

(CC @rolandshoemaker)

@bcmills bcmills added fuzz Issues related to native fuzzing support NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Mar 4, 2022
@bcmills bcmills added this to the Go1.19 milestone Mar 4, 2022
@joewreschnig
Copy link

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
Copy link
Contributor

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.

@gopherbot gopherbot modified the milestones: Go1.19, Go1.20 Aug 2, 2022
@julieqiu julieqiu modified the milestones: Go1.20, Backlog Sep 8, 2022
@capnspacehook
Copy link
Author

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
Copy link
Contributor

bcmills commented Nov 21, 2022

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

@mdempsky
Copy link
Member

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
Copy link
Contributor

bcmills commented Nov 23, 2022 •
edited

@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.

@bcmills bcmills mentioned this issue Dec 7, 2022
Closed
@gopherbot
Copy link

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
Copy link

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
Copy link

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
Copy link

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
Copy link

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
Copy link

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
Copy link

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
Copy link

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
Copy link

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

gopherbot pushed a commit that referenced this issue Mar 10, 2023
@rolandshoemaker @gopherbot
internal/fuzz: avoid deadlock on duplicate entries with exec limit
49588d0 
If there was a execution limit enabled, and a result put us beyond that
limit, but the result expanded coverage *and* was a duplicate of an
entry already in the cache, the check if we were passed the limit would
be skipped. Since this check was inside the result check body, and we
would no longer send any new inputs, we'd never get to that check again,
causing the coordinator to just sit in an infinite loop.

This moves the check up to the top of the coordinator loop, so that it
is checked after every result is processed. Also add a cmd/go TestScript
regression test which triggered this case much more frequently.

Updates #51484

Change-Id: I7a2181051177acb853c1009beedd334a40796177
Reviewed-on: https://go-review.googlesource.com/c/go/+/475196
Auto-Submit: Roland Shoemaker <roland@golang.org>
Reviewed-by: Bryan Mills <bcmills@google.com>
Run-TryBot: Roland Shoemaker <roland@golang.org>
TryBot-Result: Gopher Robot <gobot@golang.org>
@gopherbot
Copy link

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
Copy link

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
Copy link

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
Copy link
Contributor

bcmills commented Mar 13, 2023

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

@rolandshoemaker
Copy link
Member

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
Copy link

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
Copy link

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
Copy link

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
Copy link

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

gopherbot pushed a commit that referenced this issue Mar 15, 2023
@rolandshoemaker @gopherbot
internal/fuzz: improve debugging messages
70308d1 
Also enable debugging information in TestScript/test_fuzz_cov, which
hits a deadlock on builders, but I am unable to trigger locally. This
should make it somewhat easier to track down where the issue actually
is.

Updates #51484

Change-Id: I98124f862242798f2d9eba15cacefbd02924cfe2
Reviewed-on: https://go-review.googlesource.com/c/go/+/476595
Auto-Submit: Roland Shoemaker <roland@golang.org>
TryBot-Result: Gopher Robot <gobot@golang.org>
Run-TryBot: Roland Shoemaker <roland@golang.org>
Reviewed-by: Bryan Mills <bcmills@google.com>
@gopherbot
Copy link

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
Copy link

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
Copy link

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

@gopherbot
Copy link

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

gopherbot pushed a commit that referenced this issue Mar 16, 2023
@rolandshoemaker @gopherbot
internal/fuzz: release lock when reading file fails
e91876f 
When corpusEntryData failed in workerClient.fuzz and
workerClient.minimize, the shared memory mutex wasn't properly given up,
which would cause a deadlock when worker.cleanup was called.

This was tickled by #59062, wherein the fuzz cache directory would be
removed during operation of the fuzzer, causing corpusEntryData to fail
because the entry files no longer existed.

Updates #51484

Change-Id: Iea284041c20d1581c662bddbbc7e12191771a364
Reviewed-on: https://go-review.googlesource.com/c/go/+/476815
Run-TryBot: Roland Shoemaker <roland@golang.org>
TryBot-Result: Gopher Robot <gobot@golang.org>
Auto-Submit: Roland Shoemaker <roland@golang.org>
Reviewed-by: Bryan Mills <bcmills@google.com>
@rolandshoemaker
Copy link
Member

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

@bcmills bcmills closed this as completed Apr 19, 2023
@gopherbot gopherbot reopened this Sep 8, 2023
@gopherbot
Copy link

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
Copy link
Contributor

bcmills commented Sep 8, 2023

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

@bcmills bcmills closed this as completed Sep 8, 2023
@bcmills bcmills mentioned this issue Feb 5, 2024
Closed
@gopherbot gopherbot reopened this Feb 5, 2024
@gopherbot
Copy link

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

@bcmills bcmills closed this as completed Feb 5, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
fuzz Issues related to native fuzzing support NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
Go Security
Status: Done
Release Status & Release Blockers
Status: Done
Test Flakes
Status: Done
Milestone
Backlog
Development

No branches or pull requests
8 participants
@mdempsky @joewreschnig @ianlancetaylor @rolandshoemaker @bcmills @julieqiu @gopherbot @capnspacehook