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

runtime: timeouts in TestSUID #63735

Open
gopherbot opened this issue Oct 25, 2023 · 7 comments
Open

runtime: timeouts in TestSUID #63735

gopherbot opened this issue Oct 25, 2023 · 7 comments
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. help wanted NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Backlog

Comments

@gopherbot
Copy link

gopherbot commented Oct 25, 2023 •
edited by bcmills 

#!watchflakes
post <- pkg == "runtime" && test == "TestSUID" && `panic: test timed out`

Issue created automatically to collect these failures.

Example (log):

panic: test timed out after 3m0s
running tests:
	TestSUID (2m40s)

runtime.gopark(0xc00006fad0?, 0x4740ee?, 0xa0?, 0x9b?, 0xc00006fb60?)
	/tmp/workdir/go/src/runtime/proc.go:400 +0xce fp=0xc00006fa90 sp=0xc00006fa70 pc=0x43f82e
runtime.chanrecv(0xc0009806c0, 0xc00006fb88, 0x1)
	/tmp/workdir/go/src/runtime/chan.go:583 +0x3bf fp=0xc00006fb08 sp=0xc00006fa90 pc=0x4097df
runtime.chanrecv1(0xc00080d520?, 0x409c40?)
	/tmp/workdir/go/src/runtime/chan.go:442 +0x12 fp=0xc00006fb30 sp=0xc00006fb08 pc=0x4093f2
os/exec.(*Cmd).awaitGoroutines(0xc000204840, 0x0)
	/tmp/workdir/go/src/os/exec/exec.go:948 +0x1fa fp=0xc00006fc00 sp=0xc00006fb30 pc=0x53f4da
os/exec.(*Cmd).Wait(0xc000204840)
	/tmp/workdir/go/src/os/exec/exec.go:915 +0x16c fp=0xc00006fc60 sp=0xc00006fc00 pc=0x53f1ac
os/exec.(*Cmd).Run(0xc000204840)
	/tmp/workdir/go/src/os/exec/exec.go:607 +0x2d fp=0xc00006fc78 sp=0xc00006fc60 pc=0x53dced
os/exec.(*Cmd).CombinedOutput(0xc000204840)
	/tmp/workdir/go/src/os/exec/exec.go:1012 +0x85 fp=0xc00006fca0 sp=0xc00006fc78 pc=0x53f945
runtime_test.privesc({0x85bf21, 0x5}, {0xc00006fde8?, 0x2, 0x2})
	/tmp/workdir/go/src/runtime/security_test.go:35 +0x1cb fp=0xc00006fd78 sp=0xc00006fca0 pc=0x7792eb
runtime_test.setSetuid(0xc0009a6000, {0x85c615, 0x6}, {0xc0004c81e0, 0x30})
	/tmp/workdir/go/src/runtime/security_test.go:55 +0x1ac fp=0xc00006fe18 sp=0xc00006fd78 pc=0x77952c
runtime_test.TestSUID(0xc0009a6000)
	/tmp/workdir/go/src/runtime/security_test.go:95 +0x1b3 fp=0xc00006ff70 sp=0xc00006fe18 pc=0x779813
testing.tRunner(0xc0009a6000, 0x888a98)

— watchflakes
@gopherbot gopherbot added NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. compiler/runtime Issues related to the Go compiler and/or runtime. labels Oct 25, 2023
@gopherbot
Copy link
Author

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "runtime" && test == "TestSUID"
2023-10-16 03:29 dragonfly-amd64-622 go@5873bd1d runtime.TestSUID (log) 
panic: test timed out after 3m0s
running tests:
	TestSUID (2m40s)

runtime.gopark(0xc00006fad0?, 0x4740ee?, 0xa0?, 0x9b?, 0xc00006fb60?)
	/tmp/workdir/go/src/runtime/proc.go:400 +0xce fp=0xc00006fa90 sp=0xc00006fa70 pc=0x43f82e
runtime.chanrecv(0xc0009806c0, 0xc00006fb88, 0x1)
	/tmp/workdir/go/src/runtime/chan.go:583 +0x3bf fp=0xc00006fb08 sp=0xc00006fa90 pc=0x4097df
runtime.chanrecv1(0xc00080d520?, 0x409c40?)
	/tmp/workdir/go/src/runtime/chan.go:442 +0x12 fp=0xc00006fb30 sp=0xc00006fb08 pc=0x4093f2
os/exec.(*Cmd).awaitGoroutines(0xc000204840, 0x0)
	/tmp/workdir/go/src/os/exec/exec.go:948 +0x1fa fp=0xc00006fc00 sp=0xc00006fb30 pc=0x53f4da
os/exec.(*Cmd).Wait(0xc000204840)
	/tmp/workdir/go/src/os/exec/exec.go:915 +0x16c fp=0xc00006fc60 sp=0xc00006fc00 pc=0x53f1ac
os/exec.(*Cmd).Run(0xc000204840)
	/tmp/workdir/go/src/os/exec/exec.go:607 +0x2d fp=0xc00006fc78 sp=0xc00006fc60 pc=0x53dced
os/exec.(*Cmd).CombinedOutput(0xc000204840)
	/tmp/workdir/go/src/os/exec/exec.go:1012 +0x85 fp=0xc00006fca0 sp=0xc00006fc78 pc=0x53f945
runtime_test.privesc({0x85bf21, 0x5}, {0xc00006fde8?, 0x2, 0x2})
	/tmp/workdir/go/src/runtime/security_test.go:35 +0x1cb fp=0xc00006fd78 sp=0xc00006fca0 pc=0x7792eb
runtime_test.setSetuid(0xc0009a6000, {0x85c615, 0x6}, {0xc0004c81e0, 0x30})
	/tmp/workdir/go/src/runtime/security_test.go:55 +0x1ac fp=0xc00006fe18 sp=0xc00006fd78 pc=0x77952c
runtime_test.TestSUID(0xc0009a6000)
	/tmp/workdir/go/src/runtime/security_test.go:95 +0x1b3 fp=0xc00006ff70 sp=0xc00006fe18 pc=0x779813
testing.tRunner(0xc0009a6000, 0x888a98)
2023-10-23 22:56 ios-arm64-corellium go@f09db2bb runtime.TestSUID (log) 
panic: test timed out after 3m0s
running tests:
	TestSUID (26s)

syscall.syscall6(0x4?, 0x10544f9b0?, 0x102866a40?, 0x10213089c?, 0x10544f9c8?, 0x10001000109fc?, 0x104c25f40?)
	/tmp/workdir-host-ios-arm64-corellium-ios/go/src/runtime/sys_darwin.go:45 +0x68 fp=0x10544f8e0 sp=0x10544f820 pc=0x102197b48
syscall.wait4(0x10544f978?, 0x1021c9398?, 0x90?, 0x1025d05c0?)
	/tmp/workdir-host-ios-arm64-corellium-ios/go/src/syscall/zsyscall_darwin_arm64.go:43 +0x4c fp=0x10544f940 sp=0x10544f8e0 pc=0x1021a85dc
syscall.Wait4(0x130528060?, 0x10544f9b4, 0x13174a020?, 0x102130544?)
	/tmp/workdir-host-ios-arm64-corellium-ios/go/src/syscall/syscall_bsd.go:144 +0x28 fp=0x10544f980 sp=0x10544f940 pc=0x1021a6d48
...
	/tmp/workdir-host-ios-arm64-corellium-ios/go/src/runtime/crash_test.go:154 +0x2e8 fp=0x10544fc90 sp=0x10544faa0 pc=0x1023e23f8
sync.(*Once).doSlow(0x10256e500?, 0x1300bacc0?)
	/tmp/workdir-host-ios-arm64-corellium-ios/go/src/sync/once.go:74 +0x100 fp=0x10544fcf0 sp=0x10544fc90 pc=0x1021a3020
sync.(*Once).Do(...)
	/tmp/workdir-host-ios-arm64-corellium-ios/go/src/sync/once.go:65
runtime_test.buildTestProg(0x10552c000, {0x10247f914, 0x8}, {0x0?, 0x0, 0x0})
	/tmp/workdir-host-ios-arm64-corellium-ios/go/src/runtime/crash_test.go:139 +0x48c fp=0x10544fe00 sp=0x10544fcf0 pc=0x1023e20ac
runtime_test.TestSUID(0x10552c000)
	/tmp/workdir-host-ios-arm64-corellium-ios/go/src/runtime/security_test.go:82 +0x9c fp=0x10544ff60 sp=0x10544fe00 pc=0x10245411c
testing.tRunner(0x10552c000, 0x1025df7f0)

— watchflakes

@bcmills bcmills changed the title runtime: TestSUID failures runtime: timeouts in TestSUID Oct 25, 2023
@mknyszek
Copy link
Contributor

mknyszek commented Nov 1, 2023

The iOS failure is probably different from the Dragonfly failure. It's timing out on buildTestProg, and with only 26s of run time.

The Dragonfly issue seems possibly real. CC @golang/dragonfly

@mknyszek mknyszek added this to the Backlog milestone Nov 1, 2023
@tuxillo
Copy link
Contributor

tuxillo commented Nov 2, 2023

Any local test program I can run to verify the issue?

@mknyszek mknyszek mentioned this issue Nov 30, 2023
Open
@prattmic
Copy link
Member

prattmic commented Jan 5, 2024

The same symptom as the dragonfly failure above appeared on a 1.20 release branch test, on go1.20-openbsd-amd64:

=== RUN   TestSUID
    crash_test.go:138: running go build -o /home/swarming/.swarming/w/ir/x/t/go-build88073405/testsuid.exe 
panic: test timed out after 10m0s
running tests:
	TestSUID (7m13s)

...

goroutine 23727 [chan receive, 7 minutes]:
runtime.gopark(0x0?, 0xc00006c800?, 0x90?, 0xaa?, 0x474eeb?)
	/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/proc.go:381 +0xd6 fp=0xc0002daa60 sp=0xc0002daa40 pc=0x43e416
runtime.chanrecv(0xc000982420, 0xc0002dab80, 0x1)
	/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/chan.go:583 +0x49d fp=0xc0002daaf0 sp=0xc0002daa60 pc=0x40945d
runtime.chanrecv1(0x18?, 0xc001604ea0?)
	/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/chan.go:442 +0x18 fp=0xc0002dab18 sp=0xc0002daaf0 pc=0x408f58
os/exec.(*Cmd).awaitGoroutines(0xc000088000, 0x0)
	/home/swarming/.swarming/w/ir/x/w/goroot/src/os/exec/exec.go:941 +0x233 fp=0xc0002dabf0 sp=0xc0002dab18 pc=0x539fb3
os/exec.(*Cmd).Wait(0xc000088000)
	/home/swarming/.swarming/w/ir/x/w/goroot/src/os/exec/exec.go:908 +0x175 fp=0xc0002dac58 sp=0xc0002dabf0 pc=0x539c35
os/exec.(*Cmd).Run(0x3?)
	/home/swarming/.swarming/w/ir/x/w/goroot/src/os/exec/exec.go:590 +0x39 fp=0xc0002dac78 sp=0xc0002dac58 pc=0x538619
os/exec.(*Cmd).CombinedOutput(0xc000088000)
	/home/swarming/.swarming/w/ir/x/w/goroot/src/os/exec/exec.go:1005 +0xa8 fp=0xc0002daca0 sp=0xc0002dac78 pc=0x53a468
runtime_test.privesc({0x8163bd, 0x5}, {0xc0002dade8, 0x2, 0x2})
	/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/security_test.go:33 +0x1dd fp=0xc0002dad78 sp=0xc0002daca0 pc=0x74501d
runtime_test.setSetuid(0xc000fc2000, {0x8169a5, 0x6}, {0xc0000282d0, 0x41})
	/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/security_test.go:49 +0xbc fp=0xc0002dae18 sp=0xc0002dad78 pc=0x74517c
runtime_test.TestSUID(0xc000fc2000)
	/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/security_test.go:93 +0x1c5 fp=0xc0002daf70 sp=0xc0002dae18 pc=0x745585
testing.tRunner(0xc000fc2000, 0x840b30)
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:1576 +0x10b fp=0xc0002dafc0 sp=0xc0002daf70 pc=0x4ffeeb
testing.(*T).Run.func1()
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:1629 +0x2a fp=0xc0002dafe0 sp=0xc0002dafc0 pc=0x500f2a
runtime.goexit()
	/home/swarming/.swarming/w/ir/x/w/goroot/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc0002dafe8 sp=0xc0002dafe0 pc=0x478321
created by testing.(*T).Run
	/home/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:1629 +0x3ea

cc @golang/openbsd

@prattmic
Copy link
Member

prattmic commented Jan 5, 2024

@tuxillo In theory go test -run=TestSUID runtime, but the failure seems quite rare, so I'm not sure it will reproduce.

@bcmills
Copy link
Contributor

bcmills commented Jan 5, 2024 •
edited

@prattmic, that failure mode looks disturbingly similar to the darwin hangs tracked in #63937. Maybe we're looking at a general kqueue poller bug?

dragonfly, openbsd, and darwin all use the same implementation:
https://cs.opensource.google/go/go/+/master:src/runtime/netpoll_kqueue.go;l=5;drc=1f3f851a6e965a867979a74f7ebefd03381505c0

(CC @panjf2000)

@panjf2000
Copy link
Member

panjf2000 commented Jan 8, 2024 •
edited

Unfortunately, I'm afraid that this issue and #63937 share the same root cause: uncanny blocking pipes in kqueue, TestSUID and test flakes in #63937 were suspiciously blocking at:

go/src/os/exec/exec.go

Line 577 in 8db1310

_, err := io.Copy(w, pr)
, that would be executed in a goroutine which might be goparked, and was expected to be waked by kevent in runtime.netpoll later, but it never did, I can now assume that in hindsight.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. help wanted NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
Go Compiler / Runtime
Status: Todo
Test Flakes
Status: No status
Milestone
Backlog
Development

No branches or pull requests
6 participants
@tuxillo @mknyszek @prattmic @bcmills @panjf2000 @gopherbot