Skip to content

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

Closed
Closed
testing,internal/fuzz: Fuzzer reports 0 execs/sec and keeps running#51484
Labels
FrozenDueToAgeNeedsInvestigationSomeone must examine and confirm this is a valid issue and not a duplicate of an existing one.fuzzIssues related to native fuzzing support
Milestone
Backlog

Description

@capnspacehook
capnspacehook
opened on Mar 4, 2022
#!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.

Activity

  1. bcmills commented on Mar 4, 2022

    @bcmills
    bcmills
    on Mar 4, 2022
    Contributor

    (CC @rolandshoemaker)

  2. bcmills
    added
    fuzzIssues related to native fuzzing support
    NeedsInvestigationSomeone must examine and confirm this is a valid issue and not a duplicate of an existing one.
    on Mar 4, 2022
  3. bcmills
    added this to the Go1.19 milestone on Mar 4, 2022

  4. joewreschnig commented on Mar 23, 2022

    @joewreschnig
    joewreschnig
    on Mar 23, 2022

    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)
  5. joedian
    added this to Release Blockerson Jun 15, 2022

  6. ianlancetaylor commented on Jun 24, 2022

    @ianlancetaylor
    ianlancetaylor
    on Jun 24, 2022
    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.

  7. gopherbot
    modified the milestones: Go1.19, Go1.20 on Aug 2, 2022
  8. julieqiu
    added this to Go Securityon Sep 8, 2022
  9. julieqiu
    modified the milestones: Go1.20, Backlog on Sep 8, 2022

  10. capnspacehook commented on Nov 2, 2022

    @capnspacehook
    capnspacehook
    on Nov 2, 2022
    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

  11. bcmills commented on Nov 21, 2022

    @bcmills
    bcmills
    on Nov 21, 2022
    Contributor

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

  12. mdempsky commented on Nov 22, 2022

    @mdempsky
    mdempsky
    on Nov 22, 2022
    Contributor

    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.

  13. 28 remaining items

  14. gopherbot
    added a commit that references this issue on Mar 16, 2023

    internal/fuzz: release lock when reading file fails

    e91876f

  15. rolandshoemaker commented on Apr 19, 2023

    @rolandshoemaker
    rolandshoemaker
    on Apr 19, 2023
    Member

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

  16. bcmills
    closed this as completedon Apr 19, 2023
  17. github-project-automation
    moved this to Done in Test Flakeson Apr 19, 2023
  18. github-project-automation
    moved this to Done in Release Blockerson Apr 19, 2023
  19. github-project-automation
    moved this to Done in Go Securityon Apr 19, 2023
  20. gopherbot
    reopened this on Sep 8, 2023

  21. gopherbot commented on Sep 8, 2023

    @gopherbot
    gopherbot
    on Sep 8, 2023
    Contributor

    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

  22. bcmills commented on Sep 8, 2023

    @bcmills
    bcmills
    on Sep 8, 2023
    Contributor

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

  23. bcmills
    closed this as completedon Sep 8, 2023
  24. gopherbot
    reopened this on Feb 5, 2024

  25. gopherbot commented on Feb 5, 2024

    @gopherbot
    gopherbot
    on Feb 5, 2024
    Contributor

    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

  26. bcmills
    closed this as completedon Feb 5, 2024
  27. golang
    locked and limited conversation to collaborators on Feb 4, 2025
  28. gopherbot
    added
    FrozenDueToAge
    on Feb 4, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    FrozenDueToAgeNeedsInvestigationSomeone must examine and confirm this is a valid issue and not a duplicate of an existing one.fuzzIssues related to native fuzzing support

    Type

    No type

    Projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions