runtime: frequent crashes in unlock2 on NetBSD and OpenBSD since 2021-10-07 #49453

bcmills · 2021-11-08T19:52:48Z

greplogs --dashboard -md -l -e '(?ms)fatal error.*unlock2'

Note the inflection point on the BSD builders around 2021-09-22. This may or may not share an underlying cause with #49209.

The text was updated successfully, but these errors were encountered:

bcmills · 2021-11-08T19:53:28Z

This appears to be a regression in Go 1.18.

Since NetBSD and OpenBSD are not first-class ports, this doesn't necessarily block the 1.18 release — however, if the regression remains at the time of the release it at least needs a clear writeup in the release notes. (That part, at least, is a release-blocker.)

bcmills · 2021-11-12T14:48:19Z

Curiously, at least the 2021-11-12T03:54:29-ea63613-3729a67/netbsd-amd64-9_0 record is on release-branch.go1.16. I'm not sure how to rectify that with the timing of the first BSD failures in September.

Maybe the regression was introduced by a backported change? I see a lot of failures involving updateTimerPMask, and a few spurious errors in my previous greplogs from tests that just dump all of the strings in the runtime.

Trying again with a more precise pattern:

greplogs --dashboard -md -l -e '(?m)fatal error:.*\n.*\n(?:\n(runtime stack|goroutine).*:\n(?:.+\n\t.+\n)*)+runtime\.unlock2\(.*\n\t.+\n(?:.+\n\t.+\n)*runtime\.updateTimerPMask\('

bcmills · 2021-11-12T15:08:38Z

@prattmic, there seems to be a strong connection between the NetBSD crashes and updateTimerPMask. (I would suspect CL 264477, but the timing for that being the cause is off by about a year! 😅)

Any theories?

jeremyfaller · 2021-11-12T20:22:20Z

CC @prattmic

prattmic · 2021-11-12T21:44:50Z

The crash is at https://cs.opensource.google/go/go/+/master:src/runtime/lock_sema.go;l=115;drc=f229e7031a6efb2f23241b5da000c3b3203081d6. The crash is always on addr 0x170 (386) or 0x280 (amd64). I believe this is the mp.nextwaitm access, with mp as nil.

I'm not sure yet how things get this way.

The updateTimerPMask code is related (though not directly) to some workarounds on NetBSD that were relaxed on 2021-08-16 in https://golang.org/cl/324472, so perhaps there is some relation there.

prattmic · 2021-11-16T23:00:59Z

I'm having trouble reproducing this just because there are so many other netbsd memory corruption crashes I'm hitting... (#49209)

But as an interesting data point, I've noticed thus far that every all.bash run I've done has either had all tests pass, or had numerous different crashes. I've yet to have just a single test crash. That could indicate something about the environment is making crashes more likely sometimes.

prattmic · 2021-11-17T17:40:43Z

Two OpenBSD crashes in unlock2 that do not involve updateTimerPMask:

https://build.golang.org/log/c6898314cb2fdaa7a39437c2186b5e8a804d47f3
https://build.golang.org/log/afdc1f994a11b5041fa0e3dff06cc4ce8c2070ef

prattmic · 2021-11-17T19:05:53Z

I believe some of the logs above show this as well, but it hasn't yet been pointed out that this crash sometimes occurs in the Go 1.4 bootstrap toolchain as well. Example below.

The line numbers here don't quite line up to the mp.nextwaitm line (src/runtime/lock_sema.go:107 in a comment in the copy of 1.4 I'm looking at), but it seems likely to be the same.

IMO, this indicates that we either have a bug that has been around since at least 1.4, or there is some more general system-provoked memory corruption going on.

fatal error: unexpected signal during runtime execution
[signal SIGSEGV: segmentation violation code=0x1 addr=0x1f8 pc=0x80553c7]

goroutine 20 [running]:
runtime.throw(0x8428440, 0x2a)
        /home/bradfitz/go-netbsd-386-bootstrap/src/runtime/panic.go:616 +0x6b fp=0x18971444 sp=0x18971438 pc=0x806e24b
runtime.sigpanic()
        /home/bradfitz/go-netbsd-386-bootstrap/src/runtime/signal_unix.go:366 +0x230 fp=0x18971468 sp=0x18971444 pc=0x8081480
runtime.unlock(0xbba62f84)
        /home/bradfitz/go-netbsd-386-bootstrap/src/runtime/lock_sema.go:107 +0x97 fp=0x18971484 sp=0x18971468 pc=0x80553c7
internal/poll.runtime_pollOpen(0xb, 0x8442d54, 0x0)
        /home/bradfitz/go-netbsd-386-bootstrap/src/runtime/netpoll.go:120 +0xa2 fp=0x1897149c sp=0x18971484 pc=0x806ae92
internal/poll.(*pollDesc).init(0x18d081d4, 0x18d081c0, 0x18a64001, 0x18d081c0)
        /home/bradfitz/go-netbsd-386-bootstrap/src/internal/poll/fd_poll_runtime.go:37 +0x3a fp=0x189714bc sp=0x1897149c pc=0x80c2cea
internal/poll.(*FD).Init(0x18d081c0, 0x84161bd, 0x4, 0x1, 0x8, 0x18)
        /home/bradfitz/go-netbsd-386-bootstrap/src/internal/poll/fd_unix.go:58 +0x47 fp=0x189714d0 sp=0x189714bc pc=0x80c3787
os.newFile(0xb, 0x841804b, 0x9, 0x1, 0xb)
        /home/bradfitz/go-netbsd-386-bootstrap/src/os/file_unix.go:117 +0xd0 fp=0x189714f8 sp=0x189714d0 pc=0x80cb080
os.OpenFile(0x841804b, 0x9, 0x0, 0x0, 0x8, 0x18, 0x555)
        /home/bradfitz/go-netbsd-386-bootstrap/src/os/file_unix.go:198 +0xc4 fp=0x1897152c sp=0x189714f8 pc=0x80cb274
os.Open(0x841804b, 0x9, 0x57, 0xbba657ac, 0x0)
        /home/bradfitz/go-netbsd-386-bootstrap/src/os/file.go:241 +0x33 fp=0x1897154c sp=0x1897152c pc=0x80c95f3
os/exec.(*Cmd).stdin(0x18a7c000, 0x18bec160, 0x86296a0, 0xbbabe6c8)
        /home/bradfitz/go-netbsd-386-bootstrap/src/os/exec/exec.go:210 +0x3bb fp=0x189715b8 sp=0x1897154c pc=0x81153ab
os/exec.(*Cmd).Start(0x18a7c000, 0x18d260c0, 0x18bec420)
        /home/bradfitz/go-netbsd-386-bootstrap/src/os/exec/exec.go:363 +0xbf fp=0x18971664 sp=0x189715b8 pc=0x8115c5f
os/exec.(*Cmd).Run(0x18a7c000, 0x0, 0x0)
        /home/bradfitz/go-netbsd-386-bootstrap/src/os/exec/exec.go:297 +0x1b fp=0x18971674 sp=0x18971664 pc=0x8115b5b
cmd/go/internal/work.(*Builder).runOut(0x18bb0120, 0x18a3e960, 0x1b, 0x18a65c51, 0x4, 0x0, 0x0, 0x0, 0x18900d20, 0x11, ...)
        /home/bradfitz/go-netbsd-386-bootstrap/src/cmd/go/internal/work/exec.go:1422 +0x5cb fp=0x1897172c sp=0x18971674 pc=0x81f49ab
cmd/go/internal/work.(*Builder).run(0x18bb0120, 0x18ceab00, 0x18a3e960, 0x1b, 0x18a65c51, 0x4, 0x0, 0x0, 0x0, 0x18900d20, ...)
        /home/bradfitz/go-netbsd-386-bootstrap/src/cmd/go/internal/work/exec.go:1363 +0x81 fp=0x18971794 sp=0x1897172c pc=0x81f4091
cmd/go/internal/work.gcToolchain.asm(0x18bb0120, 0x18ceab00, 0x1897e680, 0x1a, 0x1a, 0x18971930, 0x2, 0x2, 0x18971b60, 0x4)
        /home/bradfitz/go-netbsd-386-bootstrap/src/cmd/go/internal/work/gc.go:236 +0x947 fp=0x18971900 sp=0x18971794 pc=0x8200927
cmd/go/internal/work.(*gcToolchain).asm(0x863b438, 0x18bb0120, 0x18ceab00, 0x1897e680, 0x1a, 0x1a, 0x4, 0x8415c20, 0x3, 0x18971ba0, ...)
        <autogenerated>:1 +0x4a fp=0x1897192c sp=0x18971900 pc=0x821194a
cmd/go/internal/work.(*Builder).build(0x18bb0120, 0x18ceab00, 0x0, 0x0)
        /home/bradfitz/go-netbsd-386-bootstrap/src/cmd/go/internal/work/exec.go:598 +0x2710 fp=0x18971f30 sp=0x1897192c pc=0x81ed090
cmd/go/internal/work.(*Builder).Do.func1(0x18ceab00)
        /home/bradfitz/go-netbsd-386-bootstrap/src/cmd/go/internal/work/exec.go:101 +0x56 fp=0x18971f70 sp=0x18971f30 pc=0x820fae6
cmd/go/internal/work.(*Builder).Do.func2(0x18ac47c0, 0x18bb0120, 0x18c3c500)
        /home/bradfitz/go-netbsd-386-bootstrap/src/cmd/go/internal/work/exec.go:159 +0x80 fp=0x18971fe0 sp=0x18971f70 pc=0x820fd40
runtime.goexit()
        /home/bradfitz/go-netbsd-386-bootstrap/src/runtime/asm_386.s:1665 +0x1 fp=0x18971fe4 sp=0x18971fe0 pc=0x8094531
created by cmd/go/internal/work.(*Builder).Do
        /home/bradfitz/go-netbsd-386-bootstrap/src/cmd/go/internal/work/exec.go:146 +0x2dc

Edit: The disassembly of the bootstrap compiler supports that this is the load of mp.nextwaitm.

prattmic · 2021-11-17T19:40:58Z

Offline it was noted that https://golang.org/cl/354757 was submitted around the time this failure ramped up (though not completely before). It is possible that the new CPU type makes some kind of race in our code more likely, or less likely, doesn't work properly with the OS.

Looking more carefully at the lock code, this crash could simply be from calling unlock2 on an already unlocked mutex. i.e., we assume that either l.key == locked (no waiters), or the masked value is an M pointer. If l.key is 0 (unlocked, no waiters), then we will do the nil dereference we see in the crashes.

Normally, that would (well, could) throw "lock count", but that check comes after where this crash occurs.

bcmills · 2021-11-18T14:55:41Z

I think the correlation with updateTimerPMask was just a red herring —there are lots of unlock2 crashes on the new openbsd-386-70 builder that do not appear to involve updateTimerPMask at all. (Maybe updateTimerPMask is just a frequent cause of “acquiring contended locks in the runtime” or something like that?)

prattmic · 2021-11-18T17:40:21Z

So far I've been having significant trouble reproducing these crashes once I added debuglog messages to lock2/unlock2, which is rather annoying but perhaps a good indication that there is a race happening here.

Interestingly, I am still reproducing the scanstack and freeIndex bugs from #49209 (cc @mknyszek).

prattmic · 2021-11-19T20:18:18Z

The current state of my reproduction / investigation is in https://golang.org/cl/365316.

gopherbot · 2021-11-19T20:33:17Z

Change https://golang.org/cl/365316 mentions this issue: DO NOT SUBMIT: investigate unlock2 crashes

mknyszek · 2021-11-19T21:24:32Z

Alongside the unlock2 failures (i.e. same run as an unlock2 failure), both Michael and myself have seen crashes in the stack allocator, like

2021/11/17 23:15:24 loading imports: signal: abort trap (core dumped)
fatal error: unexpected signal during runtime execution
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x8091d0f]

runtime stack:
runtime.throw({0x85e7bdf, 0x2a})
    /tmp/workdir/go/src/runtime/panic.go:992 +0x64 fp=0xaab5dd34 sp=0xaab5dd20 pc=0x807afa4
runtime.sigpanic()
    /tmp/workdir/go/src/runtime/signal_unix.go:781 +0x22b fp=0xaab5dd4c sp=0xaab5dd34 pc=0x808feeb
runtime.stackalloc(0x2000)
    /tmp/workdir/go/src/runtime/stack.go:393 +0x23f fp=0xaab5dd8c sp=0xaab5dd4c pc=0x8091d0f
runtime.copystack(0x8c01d10, 0x2000)
    /tmp/workdir/go/src/runtime/stack.go:871 +0x98 fp=0xaab5deb4 sp=0xaab5dd8c pc=0x8092818
runtime.newstack()
    /tmp/workdir/go/src/runtime/stack.go:1110 +0x444 fp=0xaab5df8c sp=0xaab5deb4 pc=0x8092f14
runtime.morestack()
    /tmp/workdir/go/src/runtime/asm_386.s:449 +0x73 fp=0xaab5df90 sp=0xaab5df8c pc=0x80a5a93

I have a core for this, and digging into it, it looks like it crashes with an address of 0 (nil pointer dereference) but when I look at the value in memory that the register is loaded from ((*mcache).stackalloc[2].list), it's definitely not zero.

Like the freeIndex failures, this again looks like a local variable is getting corrupted in some way. In this specific instance, it's zeroed (which may line up with other unlock2 failures). @prattmic suggested that if this is a kernel bug, it could be that returning from a signal handler isn't correctly restoring registers.

What's interesting here too is that these are crashes in the runtime. If, say, an asynchronous preemption signal lands while a thread is in the runtime, it should just return as a no-op. Maybe the reason why we're not seeing failures outside the runtime is because we do our own register spill and restore by injecting the asynchronous preemption onto the stack. However, I think this might be ruled out because the post-signal-handler spill should also then observe save and restore some bad value obtained by returning from the signal handler.

gopherbot · 2021-11-30T16:33:16Z

Change https://golang.org/cl/367847 mentions this issue: DO NOT SUBMIT: add cputicks after atomics for synchronization

aclements · 2021-12-01T17:15:45Z

We're pretty confident that this has the same root cause as #49209, so closing in favor of the broader issue.

bcmills added NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. release-blocker labels Nov 8, 2021

bcmills added this to the Go1.18 milestone Nov 8, 2021

This was referenced Nov 9, 2021

runtime,cmd/compile: frequent memory corruption on NetBSD and OpenBSD since 2021-10-11 #49209

Closed

x/tools/internal/lsp/source: test failures with diffs on "//@complete" lines #49463

Closed

bcmills changed the title ~~runtime: frequent crashes in unlock2 on NetBSD and OpenBSD since 2021-09-22~~ runtime: frequent crashes in unlock2 on NetBSD and OpenBSD since 2021-10-07 Nov 12, 2021

bcmills changed the title ~~runtime: frequent crashes in unlock2 on NetBSD and OpenBSD since 2021-10-07~~ runtime: frequent crashes in unlock2 via updateTimerPMask on NetBSD and OpenBSD since 2021-10-07 Nov 12, 2021

prattmic self-assigned this Nov 12, 2021

bcmills changed the title ~~runtime: frequent crashes in unlock2 via updateTimerPMask on NetBSD and OpenBSD since 2021-10-07~~ runtime: frequent crashes in unlock2 on NetBSD and OpenBSD since 2021-10-07 Nov 18, 2021

toothrot added the okay-after-beta1 Used by release team to mark a release-blocker issue as okay to resolve either before or after beta1 label Nov 19, 2021

jeremyfaller mentioned this issue Nov 19, 2021

runtime: divide-by-zero panic in (*randomOrder).start #49689

Closed

aclements closed this as completed Dec 1, 2021

prattmic mentioned this issue Dec 2, 2021

syscall: memory corruption when forking on OpenBSD, NetBSD, AIX, and Solaris #34988

Open

thanm mentioned this issue Dec 9, 2021

Go compiler and runtime meeting notes #43930

Open

rsc unassigned prattmic Jun 23, 2022

prattmic self-assigned this Jun 24, 2022

golang locked and limited conversation to collaborators Jun 24, 2023

gopherbot added the FrozenDueToAge label Jun 24, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

runtime: frequent crashes in unlock2 on NetBSD and OpenBSD since 2021-10-07 #49453

runtime: frequent crashes in unlock2 on NetBSD and OpenBSD since 2021-10-07 #49453

bcmills commented Nov 8, 2021

bcmills commented Nov 8, 2021

bcmills commented Nov 12, 2021 •

edited

Loading

bcmills commented Nov 12, 2021

jeremyfaller commented Nov 12, 2021

prattmic commented Nov 12, 2021

prattmic commented Nov 16, 2021

prattmic commented Nov 17, 2021

prattmic commented Nov 17, 2021 •

edited

Loading

prattmic commented Nov 17, 2021

bcmills commented Nov 18, 2021

prattmic commented Nov 18, 2021

prattmic commented Nov 19, 2021

gopherbot commented Nov 19, 2021

mknyszek commented Nov 19, 2021 •

edited

Loading

gopherbot commented Nov 30, 2021

aclements commented Dec 1, 2021

runtime: frequent crashes in unlock2 on NetBSD and OpenBSD since 2021-10-07 #49453

runtime: frequent crashes in unlock2 on NetBSD and OpenBSD since 2021-10-07 #49453

Comments

bcmills commented Nov 8, 2021

bcmills commented Nov 8, 2021

bcmills commented Nov 12, 2021 • edited Loading

bcmills commented Nov 12, 2021

jeremyfaller commented Nov 12, 2021

prattmic commented Nov 12, 2021

prattmic commented Nov 16, 2021

prattmic commented Nov 17, 2021

prattmic commented Nov 17, 2021 • edited Loading

prattmic commented Nov 17, 2021

bcmills commented Nov 18, 2021

prattmic commented Nov 18, 2021

prattmic commented Nov 19, 2021

gopherbot commented Nov 19, 2021

mknyszek commented Nov 19, 2021 • edited Loading

gopherbot commented Nov 30, 2021

aclements commented Dec 1, 2021

bcmills commented Nov 12, 2021 •

edited

Loading

prattmic commented Nov 17, 2021 •

edited

Loading

mknyszek commented Nov 19, 2021 •

edited

Loading