os: (*Process).Wait sometimes hangs on netbsd

[bcmills]

greplogs --dashboard -md -l -e 'panic: test timed out.*\n\n(?:goroutine .*:\n(?:.+\n\t.+\n)+\n)*goroutine \d+ \[syscall, \d+ minutes\]:\n(?:.+\n\t.+\n)*os\.\(\*Process\)\.Wait(?:.*\n)+FAIL\s+cmd/link'

2021-12-12T06:14:07-9c6e8f6/netbsd-386-9_0-n2

goroutine 29 [syscall, 2 minutes]:
syscall.Syscall6(0x21a8, 0x892ee8c, 0x0, 0x8a2c1e0, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/syscall/asm_unix_386.s:43 +0x5 fp=0x892ee38 sp=0x892ee34 pc=0x80b9605
syscall.wait4(0x21a8, 0x892ee8c, 0x0, 0x8a2c1e0)
	/tmp/workdir/go/src/syscall/zsyscall_netbsd_386.go:34 +0x5b fp=0x892ee70 sp=0x892ee38 pc=0x80b737b
syscall.Wait4(0x21a8, 0x892eeb0, 0x0, 0x8a2c1e0)
	/tmp/workdir/go/src/syscall/syscall_bsd.go:144 +0x3b fp=0x892ee94 sp=0x892ee70 pc=0x80b558b
os.(*Process).wait(0x8a04660)
	/tmp/workdir/go/src/os/exec_unix.go:43 +0x82 fp=0x892eec8 sp=0x892ee94 pc=0x80de982
os.(*Process).Wait(...)
	/tmp/workdir/go/src/os/exec.go:132
os/exec.(*Cmd).Wait(0x8a18fd0)
	/tmp/workdir/go/src/os/exec/exec.go:507 +0x4d fp=0x892ef0c sp=0x892eec8 pc=0x816b07d
os/exec.(*Cmd).Run(0x8a18fd0)
	/tmp/workdir/go/src/os/exec/exec.go:341 +0x43 fp=0x892ef1c sp=0x892ef0c pc=0x816a463
os/exec.(*Cmd).CombinedOutput(0x8a18fd0)
	/tmp/workdir/go/src/os/exec/exec.go:567 +0x89 fp=0x892ef30 sp=0x892ef1c pc=0x816b549
cmd/link.TestContentAddressableSymbols(0x89290e0)
	/tmp/workdir/go/src/cmd/link/link_test.go:879 +0x136 fp=0x892ef9c sp=0x892ef30 pc=0x83824b6
testing.tRunner(0x89290e0, 0x842c054)
	/tmp/workdir/go/src/testing/testing.go:1410 +0x10d fp=0x892efe4 sp=0x892ef9c pc=0x813d19d
testing.(*T).Run.func1()
	/tmp/workdir/go/src/testing/testing.go:1457 +0x28 fp=0x892eff0 sp=0x892efe4 pc=0x813df78
runtime.goexit()
	/tmp/workdir/go/src/runtime/asm_386.s:1311 +0x1 fp=0x892eff4 sp=0x892eff0 pc=0x80ab211
created by testing.(*T).Run
	/tmp/workdir/go/src/testing/testing.go:1457 +0x36e

2021-10-29T18:34:24-903f313/netbsd-amd64-9_0
2021-10-01T15:59:38-e5ad363/netbsd-arm-bsiegert

goroutine 28 [syscall, 27 minutes]:
syscall.Syscall6(0x1c1, 0xd1f, 0xa09db4, 0x0, 0x9b27e0, 0x0, 0x0)
	/var/gobuilder/buildlet/go/src/syscall/asm_netbsd_arm.s:39 +0x8 fp=0xa09d5c sp=0xa09d58 pc=0x8d3f8
syscall.wait4(0xd1f, 0xa09db4, 0x0, 0x9b27e0)
	/var/gobuilder/buildlet/go/src/syscall/zsyscall_netbsd_arm.go:35 +0x54 fp=0xa09d94 sp=0xa09d5c pc=0x8a694
syscall.Wait4(0xd1f, 0xa09dd8, 0x0, 0x9b27e0)
	/var/gobuilder/buildlet/go/src/syscall/syscall_bsd.go:145 +0x3c fp=0xa09db8 sp=0xa09d94 pc=0x88c58
os.(*Process).wait(0x983290)
	/var/gobuilder/buildlet/go/src/os/exec_unix.go:44 +0x100 fp=0xa09df0 sp=0xa09db8 pc=0xb4f1c
os.(*Process).Wait(...)
	/var/gobuilder/buildlet/go/src/os/exec.go:132
os/exec.(*Cmd).Wait(0x98cc60)
	/var/gobuilder/buildlet/go/src/os/exec/exec.go:507 +0x50 fp=0xa09e2c sp=0xa09df0 pc=0x1482d0
os/exec.(*Cmd).Run(0x98cc60)
	/var/gobuilder/buildlet/go/src/os/exec/exec.go:341 +0x48 fp=0xa09e3c sp=0xa09e2c pc=0x147810
os/exec.(*Cmd).CombinedOutput(0x98cc60)
	/var/gobuilder/buildlet/go/src/os/exec/exec.go:567 +0x98 fp=0xa09e50 sp=0xa09e3c pc=0x14882c
cmd/link.TestIssue33979.func2({0x983200, 0x21}, {0x9ea0a0, 0x9, 0x9})
	/var/gobuilder/buildlet/go/src/cmd/link/link_test.go:199 +0x90 fp=0xa09ea8 sp=0xa09e50 pc=0x368e14
cmd/link.TestIssue33979.func3({0x9ea0a0, 0x9, 0x9})
	/var/gobuilder/buildlet/go/src/cmd/link/link_test.go:206 +0x60 fp=0xa09ecc sp=0xa09ea8 pc=0x368d5c
cmd/link.TestIssue33979(0x8834a0)
	/var/gobuilder/buildlet/go/src/cmd/link/link_test.go:239 +0x3bc fp=0xa09f98 sp=0xa09ecc pc=0x368790
testing.tRunner(0x8834a0, 0x41871c)
	/var/gobuilder/buildlet/go/src/testing/testing.go:1389 +0x118 fp=0xa09fe0 sp=0xa09f98 pc=0x1195d4
testing.(*T).Run.func1()
	/var/gobuilder/buildlet/go/src/testing/testing.go:1436 +0x30 fp=0xa09fec sp=0xa09fe0 pc=0x11a448
runtime.goexit()
	/var/gobuilder/buildlet/go/src/runtime/asm_arm.s:824 +0x4 fp=0xa09fec sp=0xa09fec pc=0x7d028
created by testing.(*T).Run
	/var/gobuilder/buildlet/go/src/testing/testing.go:1436 +0x3a0

2021-09-21T20:39:31-48cf96c/netbsd-arm-bsiegert
2021-09-14T14:27:57-181e8cd/netbsd-arm-bsiegert
2021-04-29T15:47:16-12eaefe/freebsd-amd64-11_4
2021-04-28T13:49:52-4fe324d/netbsd-386-9_0
2021-03-05T02:30:31-b62da08/netbsd-386-9_0
2021-02-19T00:40:05-95a44d2/netbsd-arm64-bsiegert
2019-09-04T21:52:18-aae0b5b/linux-ppc64le-power9osu

#44801 may be closely related.

Note that many of this failures are on architectures not believed to be affected by #49209.

@bsiegert, @coypoop: any ideas?

[bcmills]

Could also be related to #48789.

[bcmills]

The stuck calls appear to be running go run, go tool link, etc. Since these are Go binaries, probably a good starting point would be to send the stuck processes SIGQUIT to try to get goroutine dumps, and then to send them SIGKILL if they still don't respond.

That would at least help us to determine whether the hang is in the subprocess or the parent process.

(I think @aclements and @mknyszek were working on retrofitting that logic to various tests?)

[cherrymui]

The arm and arm64 ones may be due to slow machine.

Yeah, sending a SIGQUIT at timeout is probably a good idea.

[aclements]

I have CL 370665 to apply timeouts to nearly every subprocess invocation in the runtime test (though wasn't planning to land that until the tree opens). These failures are all in cmd/link or cmd/link/internal/ld. I could roll a CL to use RunWithTimeout in those tests.

[bcmills]

Looks like the same failure mode in go/internal/gcimporter too: https://build.golang.org/log/0e1b9a393109ba16005d18ff9faca47c50728a8f

goroutine 167 [syscall, 2 minutes]:
syscall.Syscall6(0x1a4b, 0x8853cf0, 0x0, 0x8d7c320, 0x0, 0x0, 0x0)
	/tmp/workdir/go/src/syscall/asm_unix_386.s:43 +0x5 fp=0x8853c9c sp=0x8853c98 pc=0x80b4015
syscall.wait4(0x1a4b, 0x8853cf0, 0x0, 0x8d7c320)
	/tmp/workdir/go/src/syscall/zsyscall_netbsd_386.go:34 +0x5b fp=0x8853cd4 sp=0x8853c9c pc=0x80b28db
syscall.Wait4(0x1a4b, 0x8853d14, 0x0, 0x8d7c320)
	/tmp/workdir/go/src/syscall/syscall_bsd.go:144 +0x3b fp=0x8853cf8 sp=0x8853cd4 pc=0x80b269b
os.(*Process).wait(0x89d1530)
	/tmp/workdir/go/src/os/exec_unix.go:43 +0x82 fp=0x8853d2c sp=0x8853cf8 pc=0x80c9d32
os.(*Process).Wait(...)
	/tmp/workdir/go/src/os/exec.go:132
os/exec.(*Cmd).Wait(0x89549a0)
	/tmp/workdir/go/src/os/exec/exec.go:507 +0x4d fp=0x8853d70 sp=0x8853d2c pc=0x8139b7d
os/exec.(*Cmd).Run(0x89549a0)
	/tmp/workdir/go/src/os/exec/exec.go:341 +0x43 fp=0x8853d80 sp=0x8853d70 pc=0x8138f63
os/exec.(*Cmd).CombinedOutput(0x89549a0)
	/tmp/workdir/go/src/os/exec/exec.go:567 +0x89 fp=0x8853d94 sp=0x8853d80 pc=0x813a049
go/internal/gcimporter_test.compile(0x8801b30, {0x88c4300, 0x1e}, {0x88aaa80, 0xe}, {0x89d1500, 0x27})
	/tmp/workdir/go/src/go/internal/gcimporter/gcimporter_test.go:50 +0x28d fp=0x8853e18 sp=0x8853d94 pc=0x822216d
go/internal/gcimporter_test.TestImportTypeparamTests.func1(0x8801b30)
	/tmp/workdir/go/src/go/internal/gcimporter/gcimporter_test.go:201 +0x406 fp=0x8853f9c sp=0x8853e18 pc=0x8223a86
testing.tRunner(0x8801b30, 0x8970ca0)
	/tmp/workdir/go/src/testing/testing.go:1440 +0x10d fp=0x8853fe4 sp=0x8853f9c pc=0x8109a0d
testing.(*T).Run.func1()
	/tmp/workdir/go/src/testing/testing.go:1487 +0x28 fp=0x8853ff0 sp=0x8853fe4 pc=0x810a7e8
runtime.goexit()
	/tmp/workdir/go/src/runtime/asm_386.s:1311 +0x1 fp=0x8853ff4 sp=0x8853ff0 pc=0x80a8a51
created by testing.(*T).Run
	/tmp/workdir/go/src/testing/testing.go:1487 +0x36e

[bcmills]

greplogs --dashboard -md -l -e 'panic: test timed out.*\n\n(?:goroutine .*:\n(?:.+\n\t.+\n)+\n)*goroutine \d+ \[syscall, \d+ minutes\]:\n(?:.+\n\t.+\n)*os\.\(\*Process\)\.Wait(?:.*\n)+FAIL\s+cmd/link' --since=2022-01-08

2022-03-10T09:12:04-5a040c5/netbsd-amd64-9_0

[bcmills]

Broadening the regexp to search for os.(*Process).Wait generally, since this symptom does not appear to be specific to cmd/link as far as I can see.

greplogs --dashboard -md -l -e '\Anetbsd-(.*\n)*panic: test timed out.*\n\n(?:goroutine .*:\n(?:.+\n\t.+\n)+\n)*goroutine \d+ \[syscall, \d+ minutes\]:\n(?:.+\n\t.+\n)*os\.\(\*Process\)\.Wait' --since=2022-01-01

• 2022-04-05T17:54:15-de8a882-9839668/netbsd-386-9_0
  • 9 minutes, stuck in git-codereview.TestSubmit on a git fetch to a local server hosted in the test process, and the server appears to be idle
• 2022-03-31T06:40:26-ebe624d/netbsd-arm-bsiegert
  • 29 minutes, stuck in gcimporter_test.TestImportTypeparamTests on go tool compile
• 2022-03-10T09:12:04-5a040c5/netbsd-amd64-9_0
  • 2 minutes, stuck in link.TestIssue21703 on go tool compile
• 2022-02-14T17:30:31-6c99688-3d7f836/netbsd-386-9_0
  • 9 minutes, same git fetch in git-codereview.TestSubmit
• 2022-01-13T19:25:50-ce01afe/netbsd-arm64-bsiegert
  • 29 minutes, stuck in pprof.TestMapping on go run of a test program that sleeps for 200ms before exiting
• 2022-01-11T15:28:40-c7fa661/netbsd-arm-bsiegert
  • 29 minutes, stuck in cmd/compile/internal/test.TestReproducibleBuilds on go tool compile
• 2022-01-06T21:38:57-c5540e5/netbsd-386-9_0-n2
  • 2 minutes, same go tool compile in gcimporter_test.TestImportTypeparamTests

[bcmills]

greplogs --dashboard -md -l -e '\Anetbsd-(.*\n)*panic: test timed out.*\n\n(?:goroutine .*:\n(?:.+\n\t.+\n)+\n)*goroutine \d+ \[syscall, \d+ minutes\]:\n(?:.+\n\t.+\n)*os\.\(\*Process\)\.Wait' --since=2022-04-06

2022-04-18T22:07:54-f49e802/netbsd-arm-bsiegert

• 29 minutes, stuck in cmd/link/internal/ld.TestMemProfileCheck on go run of a test program that prints runtime.MemProfileRate and then exits.