Closed muhlemmer closed 5 months ago
dr2chase
commented
7 months ago Because I fear this might end up being relevant (seems like we'd notice inability to run all.bash on Linux, it happens constantly) could you also supply Linux and Gcc version information? No linker preload or nonstandard path, that sort of thing?
dr2chase
commented
7 months ago @golang/runtime
muhlemmer
commented
7 months ago OS release info:
NAME="openSUSE Tumbleweed"
# VERSION="20240302"
ID="opensuse-tumbleweed"
ID_LIKE="opensuse suse"
VERSION_ID="20240302"
PRETTY_NAME="openSUSE Tumbleweed"
ANSI_COLOR="0;32"
# CPE 2.3 format, boo#1217921
CPE_NAME="cpe:2.3:o:opensuse:tumbleweed:20240302:*:*:*:*:*:*:*"
#CPE 2.2 format
#CPE_NAME="cpe:/o:opensuse:tumbleweed:20240302"
BUG_REPORT_URL="https://bugzilla.opensuse.org"
SUPPORT_URL="https://bugs.opensuse.org"
HOME_URL="https://www.opensuse.org"
DOCUMENTATION_URL="https://en.opensuse.org/Portal:Tumbleweed"
LOGO="distributor-logo-Tumbleweed"GCC info:
echo $LD_PRELOAD return nothing. I'm not sure if OpenSUSE enables this by default, but I for sure didn't do that myself.
muhlemmer
commented
7 months ago Path is non-standard because I need the go paths in there:
/home/tim/go/bin:/home/tim/Repositories/goroot/bin:/home/tim/.local/bin:/home/tim/bin:/usr/local/bin:/usr/bin:/bin
prattmic
commented
7 months ago We are seeing this on our builders as well. For example: https://ci.chromium.org/ui/p/golang/builders/ci/gotip-linux-amd64-staticlockranking/b8752359739889548657/overview
This seems like a recent regression.
prattmic
commented
7 months ago Huh, @muhlemmer reports this on 1.22.1, not tip. On our builders, it looks like a very recent regression. https://ci.chromium.org/ui/test/golang/cmd%2Fcgo%2Finternal%2Ftestsanitizers.TestTSAN%2Ftsan14 shows the first failure was on 2024-03-25 in https://ci.chromium.org/ui/p/golang/builders/try/gotip-linux-amd64-boringcrypto/b8752453947853961217/test-results?sortby=&groupby=.
So maybe there is some external factor here?
gopherbot
commented
6 months ago Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "cmd/cgo/internal/testsanitizers" && test ~ `TestTSAN` && `signal handler spoils errno`Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "cmd/cgo/internal/testsanitizers" && test ~ `TestTSAN` && `signal handler spoils errno`Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "cmd/cgo/internal/testsanitizers" && test ~ `TestTSAN` && `signal handler spoils errno`Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "cmd/cgo/internal/testsanitizers" && test ~ `TestTSAN` && `signal handler spoils errno`Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "cmd/cgo/internal/testsanitizers" && test ~ `TestTSAN` && `signal handler spoils errno`TSAN implementation of errno spoiling: https://github.com/llvm/llvm-project/blob/d5224b73ccd09a6759759791f58426b6acd4a2e2/compiler-rt/lib/tsan/rtl/tsan_interceptors_posix.cpp#L2123
gopherbot
commented
6 months ago Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "cmd/cgo/internal/testsanitizers" && test ~ `TestTSAN` && `signal handler spoils errno`Change https://go.dev/cl/581721 mentions this issue: runtime: debug signal handler spoiling errno
gopherbot
commented
6 months ago Change https://go.dev/cl/581722 mentions this issue: cmd/cgo/internal/testsanitizers: add test case for #66427
cherrymui
commented
6 months ago I wrote CL https://go.dev/cl/581721 to check errno at various stages in the signal handler. Here is one of the failure https://ci.chromium.org/ui/p/golang/builders/try/gotip-linux-amd64/b8749565669963801361/test-results?q=ExactID%3Acmd%2Fcgo%2Finternal%2Ftestsanitizers.TestTSAN%2Ftsan14+VHash%3A59d5ef073852df4a+&sortby=&groupby=
tsan_test.go:78: /home/swarming/.swarming/w/ir/x/t/TestTSAN4105666902/tsan14 exited with exit status 2
errno 22 sig 28 gp 0x7f78c41021c0
fatal error: errno
runtime stack:
runtime.throw({0x5403ee?, 0x0?})
/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/panic.go:1021 +0x48 fp=0x7f790febec20 sp=0x7f790febebf0 pc=0x4dd7e8
runtime.checkErrno(0x1c, 0x7f78c41021c0)
/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/signal_unix.go:430 +0xca fp=0x7f790febec48 sp=0x7f790febec20 pc=0x4f2d2a
runtime.badsignal(0x1c, 0x7f790febecc0, 0x7f78c41021c0)
/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/signal_unix.go:1127 +0xa7 fp=0x7f790febec68 sp=0x7f790febec48 pc=0x4f4747
runtime.sigtrampgo(0x1c, 0x7f791001b640, 0x7f791001b6c0)
/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/signal_unix.go:486 +0x26e fp=0x7f790febece0 sp=0x7f790febec68 pc=0x4f2fae
runtime.sigtramp()
/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/sys_linux_amd64.s:361 +0x46 fp=0x7f790febed30 sp=0x7f790febece0 pc=0x510ac6The errno is changed in the code path that we got a signal on a non-Go thread when it is not executing Go code, and we don't do anything in our signal handler but re-raise the signal. Specifically, errno changed after re-raising the signal at https://cs.opensource.google/go/go/+/master:src/runtime/signal_unix.go;l=1096 .
The signal is 28, a.k.a. SIGWINCH. Where does SIGWINCH come from? I don't know. Our test doesn't send SIGWINCH. Maybe the kernel or the builder recently starts to send SIGWINCH? And that's what changed recently? It also explains why I have not been able to reproduce locally or even on gomote (where I run the tests in a shell under ssh).
The fact that it is failing on a non-Go thread also explains why it fails in tsan13 and tsan14, but not others. Only these two tests create threads in C and call back into Go.
Based on that, I wrote another test, in CL https://go.dev/cl/581722, where it creates a thread in C, calls into Go in a loop, and at same time another thread repeatedly sends SIGWINCH to it. This fails consistently on my machine, as well as on the builders (even non-amd64).
Now that I can reproduce it, I'll keep looking into the fix, and how re-raising the signal could clobber errno... Errno 22 is EINVAL. Potentially re-raising the signal causes some invalid operation, maybe in TSAN's signal handler?
gopherbot
commented
5 months ago Change https://go.dev/cl/582077 mentions this issue: runtime: don't re-raise ignored signal
cherrymui
commented
5 months ago More debugging indicates that errno changes when we uninstall our signal handler before re-raising the signal https://cs.opensource.google/go/go/+/master:src/runtime/signal_unix.go;l=971 . This will call the TSAN-intercepted sigaction. I'm not sure why it would change errno to 22...
At least for the case of SIGWINCH, there is no C signal handler installed, and the signal is by default ignored. In this case re-raising the signal doesn't seem to do anything. Sent CL https://go.dev/cl/582077 to not re-raise signals that are ignored. With this, errno will not change. Not sure if this is the right/best fix. Or maybe the best fix is to snapshot and restore errno around re-raising the signal?
Not sure if there is a (non-default) C signal handler installed (before Go signal handler). I think that can only happen if Go is a library (c-archive or c-shared)? In this case we only install handler for synchronous signals. And we also forward synchronous signals if it lands on a non-Go thread and there is a C handler. Maybe that is fine and we won't get to raisebadsignal?
gopherbot
commented
5 months ago Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "cmd/cgo/internal/testsanitizers" && test ~ `TestTSAN` && `signal handler spoils errno`Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "cmd/cgo/internal/testsanitizers" && test ~ `TestTSAN` && `signal handler spoils errno`@cherrymui Perhaps you can run the test under strace to see if the EINVAL is coming from a system call?
Re: SIGWINCH, the only case I'm aware of using SIGWINCH are window managers when a window changes size. But do these systems even have a window manager?
cherrymui
commented
5 months ago I tried strace and didn't see anything helpful. I wonder that it may be the TSAN interceptor that changes errno to EINVAL before actually making a syscall? Although by reading the TSAN source code I haven't figured out where/whether it does that.
Re: SIGWINCH, the only case I'm aware of using SIGWINCH are window managers when a window changes size. But do these systems even have a window manager?
Yeah, that's pretty weird. Maybe something in the builder changed and it now thinks it has a window manager?...
muhlemmer
commented
5 months ago Re: SIGWINCH, the only case I'm aware of using SIGWINCH are window managers when a window changes size. But do these systems even have a window manager?
That might be the trigger for the original issue I posted. I have a drop-down terminal (yakuake) I run most of my shell stuff in, like the all.bash script. It might send SIGWINCH every-time it collapses / expands? And if done on exactly the wrong moment it might fail the test.
I do remember that particular day I had a bunch of shell stuff to do and I multi-tasked in multiple tabs, while toggling the drop-down terminal on a frequent basis while all.bash was running.
How it applies to pipeline tests, I have no idea.
muhlemmer
commented
5 months ago Yeah, that's pretty weird. Maybe something in the builder changed and it now thinks it has a window manager?...
Do the builders use some kind of terminal-to-web emulator that might be sending such signals?
gopherbot
commented
5 months ago Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "cmd/cgo/internal/testsanitizers" && test ~ `TestTSAN` && `signal handler spoils errno`
Go version
go version go1.22.1 linux/amd64 (go 1.21.7 for bootstrap stage)
Output of
go envin your module/workspace:What did you do?
What did you see happen?
The following test fails sometimes (30-50% of the builds). Usually retrying the
all.bashscript works. I haven't noticed a similar error on the 1.21 tags, but that might have been pure luck, or something was introduced in 1.22 that causes this flakiness.What did you expect to see?
Test to pass each time.
I tried looking if there is already a similar issue, but most issues have to do with sigfaults or other panics. I did not find this specific warning.