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.

Sign up for GitHub

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

Debugging "restarts: 1/1" on windows/amd64 #328

Closed
nanokatze opened this issue Nov 27, 2021 · 5 comments · May be fixed by #330
Closed

Debugging "restarts: 1/1" on windows/amd64 #328

nanokatze opened this issue Nov 27, 2021 · 5 comments · May be fixed by #330

Comments

@nanokatze
Copy link

Hi,

it appears latest go-fuzz has an issue on go 1.17.3 windows/amd64. A simple

func Fuzz(data []byte) (score int) {
	return
}

test, when run, yields the following output

$ go-fuzz
2021/11/28 01:08:15 workers: 24, corpus: 386 (3s ago), crashers: 0, restarts: 1/0, execs: 0 (0/sec), cover: 0, uptime: 3s
2021/11/28 01:08:18 workers: 24, corpus: 386 (6s ago), crashers: 0, restarts: 1/0, execs: 0 (0/sec), cover: 0, uptime: 6s
2021/11/28 01:08:21 workers: 24, corpus: 386 (9s ago), crashers: 0, restarts: 1/1, execs: 3627 (401/sec), cover: 0, uptime: 9s
2021/11/28 01:08:24 workers: 24, corpus: 386 (12s ago), crashers: 0, restarts: 1/1, execs: 7249 (601/sec), cover: 0, uptime: 12s
2021/11/28 01:08:27 workers: 24, corpus: 386 (15s ago), crashers: 0, restarts: 1/1, execs: 10851 (721/sec), cover: 0, uptime: 15s
2021/11/28 01:08:30 workers: 24, corpus: 386 (18s ago), crashers: 0, restarts: 1/1, execs: 14499 (803/sec), cover: 0, uptime: 18s

With verbosity level of 999, a lot of odd "write to testee failed: write |1: The pipe is being closed." can be seen.

$ go-fuzz -v=999
2021/11/28 01:09:44 worker 0 triages coordinator input [80][245 191 131 123 69 180 11 5 233 10 197 184 57 245 54 226 123 253 140 70] minimized=true smashed=true
2021/11/28 01:09:44 worker 0: triageq=0 execs=0 mininp=0 mincrash=0 triage=1 fuzz=0 versifier=0 smash=0 sonar=0 hint=0
2021/11/28 01:09:44 worker 1 triages coordinator input [123][202 58 129 179 133 12 10 92 111 245 36 88 112 181 126 90 69 55 85 36] minimized=true smashed=true
2021/11/28 01:09:44 worker 1: triageq=0 execs=0 mininp=0 mincrash=0 triage=1 fuzz=0 versifier=0 smash=0 sonar=0 hint=0
2021/11/28 01:09:44 worker 2 triages coordinator input [562][176 221 18 101 72 117 116 139 78 171 216 219 233 168 56 198 143 140 196 194] minimized=true smashed=true
2021/11/28 01:09:44 worker 2: triageq=0 execs=0 mininp=0 mincrash=0 triage=1 fuzz=0 versifier=0 smash=0 sonar=0 hint=0
2021/11/28 01:09:44 worker 3 triages coordinator input [129][82 192 208 254 233 25 244 124 128 237 99 19 99 60 129 134 173 229 170 65] minimized=true smashed=true
2021/11/28 01:09:44 worker 3: triageq=0 execs=0 mininp=0 mincrash=0 triage=1 fuzz=0 versifier=0 smash=0 sonar=0 hint=0
2021/11/28 01:09:44 worker 4 triages coordinator input [44][31 48 168 23 101 62 221 71 94 142 222 255 129 31 209 165 126 231 179 50] minimized=true smashed=true
2021/11/28 01:09:44 worker 4: triageq=0 execs=0 mininp=0 mincrash=0 triage=1 fuzz=0 versifier=0 smash=0 sonar=0 hint=0
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 worker 5 triages coordinator input [97][27 253 189 229 110 181 83 47 213 29 88 226 125 108 210 7 49 237 131 137] minimized=true smashed=true
2021/11/28 01:09:44 worker 5: triageq=0 execs=0 mininp=0 mincrash=0 triage=1 fuzz=0 versifier=0 smash=0 sonar=0 hint=0
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 worker 6 triages coordinator input [188][12 160 190 95 142 207 192 30 159 146 247 223 139 39 169 158 217 35 165 51] minimized=true smashed=true
2021/11/28 01:09:44 worker 6: triageq=0 execs=0 mininp=0 mincrash=0 triage=1 fuzz=0 versifier=0 smash=0 sonar=0 hint=0
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 worker 7 triages coordinator input [101][244 194 236 10 31 240 46 80 66 224 243 200 83 231 244 133 221 65 147 128] minimized=true smashed=true
2021/11/28 01:09:44 worker 7: triageq=0 execs=0 mininp=0 mincrash=0 triage=1 fuzz=0 versifier=0 smash=0 sonar=0 hint=0
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 worker 8 triages coordinator input [48][225 202 174 250 224 221 17 82 155 115 237 26 251 152 182 87 27 131 27 91] minimized=true smashed=true
2021/11/28 01:09:44 worker 8: triageq=0 execs=0 mininp=0 mincrash=0 triage=1 fuzz=0 versifier=0 smash=0 sonar=0 hint=0
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 worker 9 triages coordinator input [26][167 252 236 109 243 212 88 34 214 145 87 86 57 77 230 197 169 173 88 248] minimized=true smashed=true
2021/11/28 01:09:44 worker 9: triageq=0 execs=0 mininp=0 mincrash=0 triage=1 fuzz=0 versifier=0 smash=0 sonar=0 hint=0
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 worker 10 triages coordinator input [95][148 102 128 146 91 64 166 209 19 22 225 228 126 161 215 187 253 69 124 49] minimized=true smashed=true
2021/11/28 01:09:44 worker 10: triageq=0 execs=0 mininp=0 mincrash=0 triage=1 fuzz=0 versifier=0 smash=0 sonar=0 hint=0
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 worker 11 triages coordinator input [50][114 111 98 52 215 71 1 190 132 81 182 90 132 117 114 35 49 233 12 155] minimized=true smashed=true
2021/11/28 01:09:44 worker 11: triageq=0 execs=0 mininp=0 mincrash=0 triage=1 fuzz=0 versifier=0 smash=0 sonar=0 hint=0
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 worker 12 triages coordinator input [114][88 189 35 70 121 59 139 30 54 190 152 49 108 176 4 16 136 1 123 245] minimized=true smashed=true
2021/11/28 01:09:44 worker 12: triageq=0 execs=0 mininp=0 mincrash=0 triage=1 fuzz=0 versifier=0 smash=0 sonar=0 hint=0
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 worker 13 triages coordinator input [60][47 82 98 63 156 46 86 225 195 137 81 35 176 43 107 77 183 3 96 100] minimized=true smashed=true
2021/11/28 01:09:44 worker 13: triageq=0 execs=0 mininp=0 mincrash=0 triage=1 fuzz=0 versifier=0 smash=0 sonar=0 hint=0
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 worker 14 triages coordinator input [36][26 150 200 176 85 221 249 228 63 123 2 16 7 237 244 244 119 68 209 46] minimized=true smashed=true
2021/11/28 01:09:44 worker 14: triageq=0 execs=0 mininp=0 mincrash=0 triage=1 fuzz=0 versifier=0 smash=0 sonar=0 hint=0
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 worker 15 triages coordinator input [309][215 161 80 16 38 37 22 205 159 78 246 170 4 102 20 220 24 223 110 48] minimized=true smashed=true
2021/11/28 01:09:44 worker 15: triageq=0 execs=0 mininp=0 mincrash=0 triage=1 fuzz=0 versifier=0 smash=0 sonar=0 hint=0
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 worker 16 triages coordinator input [19][189 11 225 202 136 5 42 115 37 82 12 27 9 78 46 122 84 91 2 247] minimized=true smashed=true
2021/11/28 01:09:44 worker 16: triageq=0 execs=0 mininp=0 mincrash=0 triage=1 fuzz=0 versifier=0 smash=0 sonar=0 hint=0
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 worker 17 triages coordinator input [27][242 112 21 19 56 165 73 71 250 27 70 81 140 88 193 15 108 111 208 230] minimized=true smashed=true
2021/11/28 01:09:44 worker 17: triageq=0 execs=0 mininp=0 mincrash=0 triage=1 fuzz=0 versifier=0 smash=0 sonar=0 hint=0
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 worker 18 triages coordinator input [123][165 163 39 20 102 209 88 112 238 92 104 226 90 230 180 48 34 74 44 181] minimized=true smashed=true
2021/11/28 01:09:44 worker 18: triageq=0 execs=0 mininp=0 mincrash=0 triage=1 fuzz=0 versifier=0 smash=0 sonar=0 hint=0
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 worker 19 triages coordinator input [164][161 226 44 135 151 54 170 235 0 36 183 206 189 60 85 46 138 117 19 65] minimized=true smashed=true
2021/11/28 01:09:44 worker 19: triageq=0 execs=0 mininp=0 mincrash=0 triage=1 fuzz=0 versifier=0 smash=0 sonar=0 hint=0
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 worker 20 triages coordinator input [20][100 137 18 130 200 177 212 34 93 106 81 93 106 70 67 31 114 52 130 145] minimized=true smashed=true
2021/11/28 01:09:44 worker 20: triageq=0 execs=0 mininp=0 mincrash=0 triage=1 fuzz=0 versifier=0 smash=0 sonar=0 hint=0
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 worker 21 triages coordinator input [84][74 177 162 160 149 38 69 244 17 241 122 154 188 8 56 86 251 175 92 243] minimized=true smashed=true
2021/11/28 01:09:44 worker 21: triageq=0 execs=0 mininp=0 mincrash=0 triage=1 fuzz=0 versifier=0 smash=0 sonar=0 hint=0
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 worker 22 triages coordinator input [258][21 206 195 233 145 50 127 109 164 209 54 3 140 224 32 169 145 146 56 163] minimized=true smashed=true
2021/11/28 01:09:44 worker 22: triageq=0 execs=0 mininp=0 mincrash=0 triage=1 fuzz=0 versifier=0 smash=0 sonar=0 hint=0
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 worker 23 triages coordinator input [18][19 103 114 164 198 140 170 103 150 199 112 213 188 58 215 210 88 193 139 249] minimized=true smashed=true
2021/11/28 01:09:44 worker 23: triageq=0 execs=0 mininp=0 mincrash=0 triage=1 fuzz=0 versifier=0 smash=0 sonar=0 hint=0
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 testee:
2021/11/28 01:09:44 write to testee failed: write |1: The pipe is being closed.

Just to note, go-fuzz appears to work fine on go 1.16.8 linux/amd64 (Fedora 34) on same machine.

I've ensured latest go-fuzz is installed by running

go get -d github.com/dvyukov/go-fuzz/go-fuzz@latest github.com/dvyukov/go-fuzz/go-fuzz-build@latest
go install github.com/dvyukov/go-fuzz/go-fuzz@latest github.com/dvyukov/go-fuzz/go-fuzz-build@latest

In case of windows, I have tried running go-fuzz-build and go-fuzz commands with CGO_ENABLED=0, but the output was exactly the same.

How would debugging this issue be approached?
@nanokatze nanokatze changed the title Debugging restarts: 1/1 Debugging restarts: 1/1 on windows/amd64 Nov 27, 2021
@nanokatze nanokatze changed the title Debugging restarts: 1/1 on windows/amd64 Debugging "restarts: 1/1" on windows/amd64 Nov 27, 2021
@josharian
Copy link
Collaborator

Thanks for taking the time to file an issue. Unfortunately, go-fuzz is pretty much unmaintained at this point; the expectation is the fuzzing in the standard library will replace go-fuzz.

@nanokatze
Copy link
Author

Ah right, I see, thanks

thepudds pushed a commit to thepudds/go-fuzz that referenced this issue Dec 2, 2021
go-fuzz: set fd inheritance properly for Go 1.17+ on Windows
829e0cb 
During Go 1.17 development, fd inheritance on Windows was changed in:
    CL 288297 - "syscall: restrict inherited handles on Windows"
    https://golang.org/cl/288297

Running go-fuzz with Go 1.17 on at least some Windows versions caused errors like:
    "write to testee failed: write |1: The pipe is being closed"

The fix is to properly set SysProcAttr.AdditionalInheritedHandles, which is modeled
after the suggestion from Jason Donenfeld in CL 320050:
    https://go-review.googlesource.com/c/go/+/320050/-1..3#message-ed1be75fda3d32c5ff2bd037b951a875cb07c3db

Fixes dvyukov#328
@thepudds thepudds mentioned this issue Dec 2, 2021
Open
@thepudds
Copy link
Collaborator

thepudds commented Dec 2, 2021

Hi @nanokatze, I hopefully have a fix for this in PR #330, and it does indeed seem to be a failure due to a change in Go 1.17.

One thing I'm mildly curious about is I could not reproduce the issue you reported if I used Windows 10 20H2, but I could reproduce it on a clean VM with Windows 10 1809... and I'm curious what exact version(s) of Windows you were running when you encountered this?

@nanokatze
Copy link
Author

Hi @thepudds, thanks for PR, I'll check out if it fixes the issue in some time. I'm not fully sure but I'm fairly certain the issue occurred with Windows 10 20H2 (About reports OS build value of 19042.1348, whatever that means).

@nanokatze
Copy link
Author

nanokatze commented Dec 23, 2021 •
edited

Hi @thepudds, sorry for delay. Your MR indeed fixes the issue, thank you!

craiggwilson pushed a commit to craiggwilson/go-fuzz that referenced this issue Jun 19, 2022
@craiggwilson
go-fuzz: set fd inheritance properly for Go 1.17+ on Windows
8b8c0a8 
During Go 1.17 development, fd inheritance on Windows was changed in:
    CL 288297 - "syscall: restrict inherited handles on Windows"
    https://golang.org/cl/288297

Running go-fuzz with Go 1.17 on at least some Windows versions caused errors like:
    "write to testee failed: write |1: The pipe is being closed"

The fix is to properly set SysProcAttr.AdditionalInheritedHandles, which is modeled
after the suggestion from Jason Donenfeld in CL 320050:
    https://go-review.googlesource.com/c/go/+/320050/-1..3#message-ed1be75fda3d32c5ff2bd037b951a875cb07c3db

Fixes dvyukov#328
craiggwilson pushed a commit to craiggwilson/go-fuzz that referenced this issue Jun 19, 2022
@craiggwilson
go-fuzz: set fd inheritance properly for Go 1.17+ on Windows
eaa2bfe 
During Go 1.17 development, fd inheritance on Windows was changed in:
    CL 288297 - "syscall: restrict inherited handles on Windows"
    https://golang.org/cl/288297

Running go-fuzz with Go 1.17 on at least some Windows versions caused errors like:
    "write to testee failed: write |1: The pipe is being closed"

The fix is to properly set SysProcAttr.AdditionalInheritedHandles, which is modeled
after the suggestion from Jason Donenfeld in CL 320050:
    https://go-review.googlesource.com/c/go/+/320050/-1..3#message-ed1be75fda3d32c5ff2bd037b951a875cb07c3db

Fixes dvyukov#328
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

go-fuzz: set fd inheritance properly for Go 1.17+ on Windows thepudds/go-fuzz
3 participants
@josharian @thepudds @nanokatze