tinygo icon indicating copy to clipboard operation
tinygo copied to clipboard

Published 20 hours ago • verified publisher icon tinygo-org

core: compile failures due to SSA race condition

Open scottfeldman opened this issue 1 year ago • 29 comments

Several folks on the Slack TinyGo channel reported in-frequent compile failures with 0.31.2.

Here's some I've captured in my build logs. I would estimate it happens 1/40 compiles. A re-compile is the work-around.

#13 144.9 /usr/local/bin/tinygo build -target wioterminal -o ../../relays-wioterminal.uf2 -stack-size 8kb -size short /tmp/build-3411892484.go
#13 148.5 2024/03/14 07:35:32 Error generating UF2s: exit status 1: Basic Block in function '(*github.com/***/dean.mutex).islocked' does not have terminator!
#13 148.5 label %entry
#13 148.5 error: verification error after compiling package command-line-arguments

#14 141.8 /usr/local/bin/tinygo build -target wioterminal -o ../../relays-wioterminal.uf2 -stack-size 8kb -size short /tmp/build-1005049736.go
#14 145.2 2024/03/17 04:38:03 Error generating UF2s: exit status 1: Basic Block in function '(*struct{github.com/***/dean.Thing; github.com/***/device/target.Targets "json:\"-\""; ModelStruct string "json:\"-\""; github.com/***/device.WifiAuth "json:\"-\""; DialURLs string "json:\"-\""; DeployParams string; deployValues net/url.Values; github.com/***/device.ViewMode "json:\"-\""; WsScheme string "json:\"-\""; fs embed.FS; github.com/***/device.deviceOS}).TestFlag' does not have terminator!
#14 145.2 label %entry
#14 145.2 error: verification error after compiling package command-line-arguments

#13 197.4 /usr/local/bin/tinygo build -target wioterminal -o ../../relays-wioterminal.uf2 -stack-size 8kb -size short /tmp/build-3732778842.go
#13 200.7 2024/03/14 07:05:36 Error generating UF2s: exit status 2: SIGSEGV: segmentation violation
#13 200.7 PC=0x813d1c m=3 sigcode=18446744073709551610 addr=0x4a5
#13 200.7
#13 200.7 goroutine 110 gp=0xc017982e00 m=3 mp=0xc000051008 [running]:
#13 200.7 github.com/tinygo-org/tinygo/compiler.getPos({0x0, 0x0})
#13 200.7       /__w/tinygo/tinygo/compiler/compiler.go:1402 +0x1c fp=0xc0191b3198 sp=0xc0191b3168 pc=0x813d1c
#13 200.7 github.com/tinygo-org/tinygo/compiler.(*builder).createInstruction(0xc01811e900, {0x0, 0x0})
#13 200.7       /__w/tinygo/tinygo/compiler/compiler.go:1442 +0xd85 fp=0xc0191b32e0 sp=0xc0191b3198 pc=0x814f05
#13 200.7 github.com/tinygo-org/tinygo/compiler.(*builder).createFunction(0xc01811e900)
#13 200.7       /__w/tinygo/tinygo/compiler/compiler.go:1336 +0x915 fp=0xc0191b34d0 sp=0xc0191b32e0 pc=0x8134f5
#13 200.7 github.com/tinygo-org/tinygo/compiler.(*compilerContext).getFunction(0xc017c5a140, 0xc018086d00)
#13 200.7       /__w/tinygo/tinygo/compiler/symbol.go:222 +0xdaf fp=0xc0191b36b0 sp=0xc0191b34d0 pc=0x85472f
#13 200.7 github.com/tinygo-org/tinygo/compiler.(*compilerContext).getTypeMethodSet(0xc017c5a140, {0x605cf28, 0xc01367eb10})
#13 200.7       /__w/tinygo/tinygo/compiler/interface.go:619 +0x24d fp=0xc0191b3810 sp=0xc0191b36b0 pc=0x84166d
#13 200.7 github.com/tinygo-org/tinygo/compiler.(*compilerContext).getTypeCode(0xc017c5a140, {0x605cf28, 0xc01367eb10})
#13 200.7       /__w/tinygo/tinygo/compiler/interface.go:417 +0x3448 fp=0xc0191b3e00 sp=0xc0191b3810 pc=0x83dac8
#13 200.7 github.com/tinygo-org/tinygo/compiler.(*compilerContext).getTypeCode(0xc017c5a140, {0x605cf00, 0xc00426d0b0})
#13 200.7       /__w/tinygo/tinygo/compiler/interface.go:352 +0x2b33 fp=0xc0191b43f0 sp=0xc0191b3e00 pc=0x83d1b3
#13 200.7 github.com/tinygo-org/tinygo/compiler.(*compilerContext).getTypeCode(0xc017c5a140, {0x605ce10, 0xc010d37880})
#13 200.7       /__w/tinygo/tinygo/compiler/interface.go:292 +0x292d fp=0xc0191b49e0 sp=0xc0191b43f0 pc=0x83cfad
#13 200.7 github.com/tinygo-org/tinygo/compiler.(*compilerContext).getTypeCode(0xc017c5a140, {0x605cf28, 0xc00401b560})
#13 200.7       /__w/tinygo/tinygo/compiler/interface.go:322 +0x317e fp=0xc0191b4fd0 sp=0xc0191b49e0 pc=0x83d7fe
#13 200.7 github.com/tinygo-org/tinygo/compiler.(*builder).createMakeInterface(0xc017c7a180, {0x60607f8?}, {0x605cf28, 0xc00401b560}, 0x2?)
#13 200.7       /__w/tinygo/tinygo/compiler/interface.go:80 +0x6e fp=0xc0191b5020 sp=0xc0191b4fd0 pc=0x839bce
#13 200.7 github.com/tinygo-org/tinygo/compiler.(*builder).createExpr(0xc017c7a180, {0x60608d0, 0xc01780ea00})
#13 200.7       /__w/tinygo/tinygo/compiler/compiler.go:2209 +0x1d45 fp=0xc0191b54d0 sp=0xc0191b5020 pc=0x81ddc5
#13 200.7 github.com/tinygo-org/tinygo/compiler.(*builder).createInstruction(0xc017c7a180, {0x60619b0, 0xc01780ea00})
#13 200.7       /__w/tinygo/tinygo/compiler/compiler.go:1447 +0xa5e fp=0xc0191b5618 sp=0xc0191b54d0 pc=0x814bde
#13 200.7 github.com/tinygo-org/tinygo/compiler.(*builder).createFunction(0xc017c7a180)
#13 200.7       /__w/tinygo/tinygo/compiler/compiler.go:1336 +0x915 fp=0xc0191b5808 sp=0xc0191b5618 pc=0x8134f5
#13 200.7 github.com/tinygo-org/tinygo/compiler.(*compilerContext).createPackage(0xc017c5a140, {0xc0075ed040?}, 0xc003fe7280)
#13 200.7       /__w/tinygo/tinygo/compiler/compiler.go:888 +0x965 fp=0xc0191b5a68 sp=0xc0191b5808 pc=0x80d2a5
#13 200.7 github.com/tinygo-org/tinygo/compiler.CompilePackage({0xc00033fc40?, 0x53?}, 0xc0004274a0, 0xc003fe7280, {0xa1bad0e8a1cbdddb?}, 0x5fbafac?, 0x79?)
#13 200.7       /__w/tinygo/tinygo/compiler/compiler.go:311 +0x42a fp=0xc0191b5c28 sp=0xc0191b5a68 pc=0x805e4a
#13 200.7 github.com/tinygo-org/tinygo/builder.Build.func3(0xc017878720)
#13 200.7       /__w/tinygo/tinygo/builder/build.go:370 +0x205 fp=0xc0191b5f80 sp=0xc0191b5c28 pc=0x8b4845
#13 200.7 github.com/tinygo-org/tinygo/builder.runJob(0xc017878720, 0xc01782ac60)
#13 200.7       /__w/tinygo/tinygo/builder/jobs.go:222 +0x4d fp=0xc0191b5fc0 sp=0xc0191b5f80 pc=0x8c126d
#13 200.7 github.com/tinygo-org/tinygo/builder.runJobs.gowrap1()
#13 200.7       /__w/tinygo/tinygo/builder/jobs.go:123 +0x25 fp=0xc0191b5fe0 sp=0xc0191b5fc0 pc=0x8c0be5
#13 200.7 runtime.goexit({})
#13 200.7       /usr/local/go/src/runtime/asm_amd64.s:1695 +0x1 fp=0xc0191b5fe8 sp=0xc0191b5fe0 pc=0x578d01
#13 200.7 created by github.com/tinygo-org/tinygo/builder.runJobs in goroutine 1
#13 200.7       /__w/tinygo/tinygo/builder/jobs.go:123 +0x5bd
#13 200.7
<....cut...>

scottfeldman avatar Mar 25 '24 18:03 scottfeldman

for additional context, here is the link to the msg in slack where we started this conversation: https://gophers.slack.com/archives/CDJD3SUP6/p1711334267168799

rajatjindal avatar Mar 25 '24 19:03 rajatjindal

I tried reproducing by calling TinyGo build in a loop, but no luck so far. It's gone over 600 iterations. I'll keep trying. The suggestion was to restrict TinyGo build to one CPU using taskset -c 0 tinygo build ..., but right now I'm just trying to get it to fail in a loop without taskset...

However, just in my normal GitHub workflow build, I did get another one:

#14 171.4 /usr/local/bin/tinygo build -target wioterminal -o ../../skeleton-wioterminal.uf2 -stack-size 8kb -size short /tmp/build-770892309.go
#14 174.9 2024/03/26 05:37:41 Error generating UF2s: exit status 1: Basic Block in function '(*github.com/***/dean.mutex).setlock' does not have terminator!
#14 174.9 label %gep.next
#14 174.9 error: verification error after compiling package command-line-arguments

I've noticed that all of the failures I've posted to this Issue are with -target=wioterminal, but I'm pretty sure I've seen if fail with other targets.

scottfeldman avatar Mar 26 '24 16:03 scottfeldman

It just hit me. Oddly, this was just after I did "brew upgrade".

Here's the error:

 tinygo: "Basic Block in function '(*math/big.nat).sticky' does not have terminator!\nlabel %entry\nBasic Block in function '(*math/big.nat).sticky' does not have terminator!\nlabel %entry\nerror: verification error after compiling package crypto/ecdsa\n": exit status 1

And here's the program I was compiling:

package main

import (
        "context"
        "fmt"

        "github.com/fastly/compute-sdk-go/fsthttp"
)

func main() {
        fsthttp.ServeFunc(func(ctx context.Context, w fsthttp.ResponseWriter, r *fsthttp.Request) {
                fmt.Fprintf(w, "Hello, %s!\n", r.RemoteAddr)
        })
}

Options included -opt=2 -target=wasi -gc=leaking and probably a few others.

dkegel-fastly avatar Mar 29 '24 21:03 dkegel-fastly

I hit it again today, this time on -target nano-rp2040 and with a different failure signature:

#14 77.46 /usr/local/bin/tinygo build -target nano-rp2040 -o ../../garage-nano-rp2040.uf2 -stack-size 8kb -size short /tmp/build-2321174789.go
#14 81.12 2024/04/04 19:15:09 Error generating UF2s: exit status 2: panic: runtime error: index out of range [0] with length 0
#14 81.12 
#14 81.12 goroutine 296 [running]:
#14 81.12 github.com/tinygo-org/tinygo/compiler.(*builder).createFunctionStart(0xc012ecbb00, 0x0)
#14 81.12 	/__w/tinygo/tinygo/compiler/compiler.go:1206 +0x11cf
#14 81.12 github.com/tinygo-org/tinygo/compiler.(*builder).createFunction(0xc012ecbb00)
#14 81.12 	/__w/tinygo/tinygo/compiler/compiler.go:1295 +0x2c
#14 81.12 github.com/tinygo-org/tinygo/compiler.(*compilerContext).getFunction(0xc0155a2780, 0xc0130c84e0)
#14 81.12 	/__w/tinygo/tinygo/compiler/symbol.go:222 +0xdaf
#14 81.12 github.com/tinygo-org/tinygo/compiler.(*compilerContext).getTypeMethodSet(0xc0155a2780, {0x605b928, 0xc00c80a580})
#14 81.12 	/__w/tinygo/tinygo/compiler/interface.go:619 +0x24d
#14 81.12 github.com/tinygo-org/tinygo/compiler.(*compilerContext).getTypeCode(0xc0155a2780, {0x605b928, 0xc00c80a580})
#14 81.12 	/__w/tinygo/tinygo/compiler/interface.go:417 +0x3448
#14 81.12 github.com/tinygo-org/tinygo/compiler.(*compilerContext).getTypeCode(0xc0155a2780, {0x605b900, 0xc00bbd4c00})
#14 81.12 	/__w/tinygo/tinygo/compiler/interface.go:352 +0x2b33
#14 81.12 github.com/tinygo-org/tinygo/compiler.(*compilerContext).getTypeCode(0xc0155a2780, {0x605b810, 0xc0112d7730})
#14 81.12 	/__w/tinygo/tinygo/compiler/interface.go:292 +0x292d
#14 81.12 github.com/tinygo-org/tinygo/compiler.(*compilerContext).getTypeCode(0xc0155a2780, {0x605b928, 0xc0118d74c0})
#14 81.12 	/__w/tinygo/tinygo/compiler/interface.go:322 +0x317e
#14 81.12 github.com/tinygo-org/tinygo/compiler.(*compilerContext).getTypeCode(0xc0155a2780, {0x605b900, 0xc00be1ac30})
#14 81.12 	/__w/tinygo/tinygo/compiler/interface.go:394 +0x3d68
#14 81.12 github.com/tinygo-org/tinygo/compiler.(*compilerContext).getTypeCode(0xc0155a2780, {0x605b810, 0xc0112d7b90})
#14 81.12 	/__w/tinygo/tinygo/compiler/interface.go:292 +0x292d
#14 81.12 github.com/tinygo-org/tinygo/compiler.(*compilerContext).getTypeCode(0xc0155a2780, {0x605b928, 0xc0118d7630})
#14 81.12 	/__w/tinygo/tinygo/compiler/interface.go:322 +0x317e
#14 81.12 github.com/tinygo-org/tinygo/compiler.(*builder).createMakeInterface(0xc0165c7380, {0x605f208?}, {0x605b928, 0xc0118d7630}, 0x2?)
#14 81.12 	/__w/tinygo/tinygo/compiler/interface.go:80 +0x6e
#14 81.12 github.com/tinygo-org/tinygo/compiler.(*builder).createExpr(0xc0165c7380, {0x605f2e0, 0xc017803810})
#14 81.12 	/__w/tinygo/tinygo/compiler/compiler.go:2209 +0x1d45
#14 81.12 github.com/tinygo-org/tinygo/compiler.(*builder).createInstruction(0xc0165c7380, {0x60603c0, 0xc017803810})
#14 81.12 	/__w/tinygo/tinygo/compiler/compiler.go:1447 +0xa5e
#14 81.12 github.com/tinygo-org/tinygo/compiler.(*builder).createFunction(0xc0165c7380)
#14 81.12 	/__w/tinygo/tinygo/compiler/compiler.go:1336 +0x915
#14 81.12 github.com/tinygo-org/tinygo/compiler.(*compilerContext).createPackage(0xc0155a2780, {0xc003fb11e0?}, 0xc003871080)
#14 81.12 	/__w/tinygo/tinygo/compiler/compiler.go:888 +0x965
#14 81.12 github.com/tinygo-org/tinygo/compiler.CompilePackage({0xc0002d1cc0?, 0x53?}, 0xc000361860, 0xc003871080, {0xc01288e4d0?}, 0x5fb9fac?, 0x68?)
#14 81.12 	/__w/tinygo/tinygo/compiler/compiler.go:311 +0x42a
#14 81.12 github.com/tinygo-org/tinygo/builder.Build.func3(0xc015c61260)
#14 81.12 	/__w/tinygo/tinygo/builder/build.go:370 +0x205
#14 81.12 github.com/tinygo-org/tinygo/builder.runJob(0xc015c61260, 0xc0125ab620)
#14 81.12 	/__w/tinygo/tinygo/builder/jobs.go:222 +0x4d
#14 81.12 created by github.com/tinygo-org/tinygo/builder.runJobs in goroutine 1
#14 81.12 	/__w/tinygo/tinygo/builder/jobs.go:123 +0x5bd
#14 81.12 
#14 81.12 exit status 1
#14 81.12 cmd/gen-uf2/main.go:10: running "go": exit status 1
#14 ERROR: process "/bin/sh -c go generate ./cmd/gen-uf2/" did not complete successfully: exit code: 1

scottfeldman avatar Apr 04 '24 19:04 scottfeldman

@aykevl any clues on this?

deadprogram avatar Apr 05 '24 17:04 deadprogram

I think dgryski suggested building with race detection on to see if that catches anything, and ayke had a couple suggestions on top of that: https://gophers.slack.com/archives/CN4R2DQV7/p1711749220916969

dkegel-fastly avatar Apr 05 '24 17:04 dkegel-fastly

Is there anybody able to provide a reproducer?

If you try to reproduce, here are a few ways to increase success:

  • Remove cached files between runs: rm ~/.cache/tinygo/obj-* (or tinygo clean but that's slower)
  • Do it in a loop (something like while true; do tinygo xxx; rm ~/.cache/tinygo/obj-*; done )
  • Don't change the number of cores, use all of the available ones. It's unlikely to reproduce when you limit tinygo to a single core (there wouldn't be a race condition on a single core).

aykevl avatar Apr 08 '24 11:04 aykevl

Pretty sure I have seen this occur in CI builds as well.

deadprogram avatar Apr 08 '24 11:04 deadprogram

If you try to reproduce, here are a few ways to increase success:

  • Remove cached files between runs: rm ~/.cache/tinygo/obj-* (or tinygo clean but that's slower)
  • Do it in a loop (something like while true; do tinygo xxx; rm ~/.cache/tinygo/obj-*; done )
  • Don't change the number of cores, use all of the available ones. It's unlikely to reproduce when you limit tinygo to a single core (there wouldn't be a race condition on a single core).

I've added this step to my project's CI, after each TinyGo build cmd. So far I haven't seen anything, but I'll keep an eye on it.

scottfeldman avatar Apr 08 '24 18:04 scottfeldman

Hit another one tonight. And this is with rm .cache files after each TinyGo build per @aykevl's suggestion.

12.19 /usr/local/bin/tinygo build -target nano-rp2040 -o ../../garage-nano-rp2040.uf2 -stack-size 8kb -size short /tmp/build-2086407574.go
22.97 2024/04/10 08:06:34 Error generating UF2s: exit status 1: go: downloading tinygo.org/x/drivers v0.27.0
22.97 Basic Block in function '(struct{*bufio.Reader; *bufio.Writer}).writeBuf' does not have terminator!
22.97 label %entry

scottfeldman avatar Apr 10 '24 08:04 scottfeldman

I am also seeing this

rockwotj avatar Apr 16 '24 14:04 rockwotj

Duplicate of https://github.com/tinygo-org/tinygo/issues/3062?

rockwotj avatar Apr 16 '24 14:04 rockwotj

I will admit, this bug is remarkably similar to https://github.com/tinygo-org/tinygo/issues/4206

dkegel-fastly avatar Apr 16 '24 14:04 dkegel-fastly

Ugh clearly haven't had my coffee yet - I copied the wrong issue number: #3062

rockwotj avatar Apr 16 '24 14:04 rockwotj

Yes it is similar in the sense that it is a race of some sort, but for #3062 we found a specific cause that we fixed in https://github.com/tinygo-org/tinygo/pull/3920. The current issue seems to be a different problem.

aykevl avatar Apr 17 '24 15:04 aykevl

To all the people reporting crashes: please provide a reproducer. I can't debug this without a reproducer, I have to see the crash happening on my own system. Getting more crash logs is near-useless, what I need is:

  • the source code (enough that I can build the exact same binary you're building)
  • the full compiler command, with all flags
  • the environment (OS, architecture, TinyGo version, etc) - use tinygo version.

aykevl avatar Apr 17 '24 15:04 aykevl

For the record, apparently this command failed at some point in CI (CC @dkegel-fastly):

tinygo build -size short -o test.hex -target=nano-rp2040         examples/rtcinterrupt

EDIT: this doesn't seem to reproduce on my system even after many attempts. Or maybe I should leave it to run for a longer time...

aykevl avatar Apr 17 '24 17:04 aykevl

On the note of it being rare, I have seen it crop up on the order of ~1/10000 builds based on our CI stats.

rockwotj avatar Apr 19 '24 02:04 rockwotj

via CI https://github.com/tinygo-org/drivers/actions/runs/8812492890/job/24189343381#step:8:503

tinygo build -size short -o ./build/test.hex -target=challenger-rp2040 ./examples/net/ntpclient/
Basic Block in function '(*time.Time).Second' does not have terminator!
usage: go run ./smoketest.go smoketest.txt
label %entry
  -xtensa
error: verification error after compiling package context
    	Enable Xtensa tests (default true)
exit status 1
make: *** [Makefile:13: smoke-test] Error 1

deadprogram avatar Apr 24 '24 13:04 deadprogram

I think the race condition pretty consistently appears in this check https://github.com/tinygo-org/tinygo/blob/dev/builder/build.go#L384-L386

Is it perhaps because the IR for pkg.ImportPath is not yet fully written when some other package also needs it as a dependency, and then also tries to write it?

deadprogram avatar Apr 24 '24 17:04 deadprogram

I've found a reliable reproducer! Run this in the fish shell in ./tests/os/smoke:

while true; rm ~/.cache/tinygo/pkg-*; tinygo test -c -target=pybadge; end

I think the race condition pretty consistently appears in this check https://github.com/tinygo-org/tinygo/blob/dev/builder/build.go#L384-L386

VerifyModule probably isn't the problem (in fact it should only read the module), most likely the problem is introduced earlier and only detected when verifying the module.

aykevl avatar Apr 27 '24 07:04 aykevl

Found a race condition! ~I don't know whether it's the big one~ (edit: it's not) but it's a race so should be fixed: https://github.com/tinygo-org/tinygo/pull/4243

aykevl avatar Apr 27 '24 08:04 aykevl

So now I have a reliable reproducer, I found that the bug does not reproduce with -race :sob: only without that flag. My next suspect is golang.org/x/tools so I'm testing an older version now to see whether it still occurs there.

aykevl avatar Apr 27 '24 09:04 aykevl

golang.org/x/tools seems to be the culprit, I'm bisecting between v0.14.0 and v0.15.0.

aykevl avatar Apr 27 '24 10:04 aykevl

I think it's this commit: https://github.com/golang/tools/commit/75ff53bc6b14b0a09f5d4b838ea47ae679d748ba Almost done bisecting, I'll let this run a while to be sure (it may take a while for the bug to appear).

aykevl avatar Apr 27 '24 10:04 aykevl

Here is the upstream bug report: https://github.com/golang/go/issues/67079

aykevl avatar Apr 27 '24 11:04 aykevl

Here is our latest example of this bug doing its thing :bug: https://github.com/tinygo-org/tinygo/actions/runs/8880740326/job/24381494362?pr=4252#step:14:28

deadprogram avatar Apr 29 '24 15:04 deadprogram

the go tools change in question is https://go-review.googlesource.com/c/tools/+/538358/7

deadprogram avatar Apr 30 '24 13:04 deadprogram

Currently down to this set of packages that when compiled together leads to a race:

source_filename = "internal/testlog"
source_filename = "encoding"
source_filename = "sync"
source_filename = "context"
source_filename = "time"

Interestingly, this doesn't seem to include any reflection? (Though I haven't investigated the packages deeply).

(Still figuring stuff out, I plan on sharing my findings once I know exactly which packages are the culprit).

aykevl avatar May 13 '24 18:05 aykevl

Got a bit further, and managed to capture a race condition log. See the details over at https://github.com/golang/go/issues/67079#issuecomment-2149655971. Hopefully this is enough information for the Go developers to find the race.

aykevl avatar Jun 05 '24 12:06 aykevl