os: apparent deadlock in TestFdReadRace on Solaris-derivative builders

[bcmills]

2021-03-05T09:24:34-2217e89/illumos-amd64

goroutine 260 [semacquire, 2 minutes]:
sync.runtime_Semacquire(0xc00031f4a8)
	/var/tmp/workdir-host-illumos-amd64-jclulow/go/src/runtime/sema.go:56 +0x45
sync.(*WaitGroup).Wait(0xc00031f4a0)
	/var/tmp/workdir-host-illumos-amd64-jclulow/go/src/sync/waitgroup.go:130 +0x65
os_test.TestFdReadRace(0xc000453080)
	/var/tmp/workdir-host-illumos-amd64-jclulow/go/src/os/pipe_test.go:474 +0x1e9
testing.tRunner(0xc000453080, 0x5e5358)
	/var/tmp/workdir-host-illumos-amd64-jclulow/go/src/testing/testing.go:1194 +0xef
created by testing.(*T).Run
	/var/tmp/workdir-host-illumos-amd64-jclulow/go/src/testing/testing.go:1239 +0x2b3

…

goroutine 383 [syscall, 2 minutes]:
syscall.read(0x6, 0xc000445786, 0xa, 0xa, 0x0, 0x405ba5, 0xc000051260)
	/var/tmp/workdir-host-illumos-amd64-jclulow/go/src/syscall/zsyscall_solaris_amd64.go:766 +0x8d
syscall.Read(...)
	/var/tmp/workdir-host-illumos-amd64-jclulow/go/src/syscall/syscall_unix.go:188
internal/poll.ignoringEINTRIO(...)
	/var/tmp/workdir-host-illumos-amd64-jclulow/go/src/internal/poll/fd_unix.go:582
internal/poll.(*FD).Read(0xc00004ef00, 0xc000445786, 0xa, 0xa, 0x0, 0x0, 0x0)
	/var/tmp/workdir-host-illumos-amd64-jclulow/go/src/internal/poll/fd_unix.go:163 +0x14e
os.(*File).read(...)
	/var/tmp/workdir-host-illumos-amd64-jclulow/go/src/os/file_posix.go:32
os.(*File).Read(0xc000010270, 0xc000445786, 0xa, 0xa, 0x0, 0x0, 0x6fdee0)
	/var/tmp/workdir-host-illumos-amd64-jclulow/go/src/os/file.go:119 +0x77
os_test.TestFdReadRace.func1(0xc00031f4a0, 0xc000010270, 0xc000051260, 0xc000453080)
	/var/tmp/workdir-host-illumos-amd64-jclulow/go/src/os/pipe_test.go:453 +0xf2
created by os_test.TestFdReadRace
	/var/tmp/workdir-host-illumos-amd64-jclulow/go/src/os/pipe_test.go:448 +0x18a

2020-04-23T19:40:07-6303c34/solaris-amd64-oraclerel

goroutine 194 [semacquire, 2 minutes]:
sync.runtime_Semacquire(0xc00007e008)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/runtime/sema.go:56 +0x42
sync.(*WaitGroup).Wait(0xc00007e000)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/sync/waitgroup.go:130 +0x64
os_test.TestFdReadRace(0xc0006c2140)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/os/pipe_test.go:454 +0x1da
testing.tRunner(0xc0006c2140, 0x5b0c00)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/testing/testing.go:1027 +0xdc
created by testing.(*T).Run
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/testing/testing.go:1078 +0x355

…

goroutine 417 [syscall, 2 minutes]:
syscall.read(0xd, 0xc00029e786, 0xa, 0xa, 0x0, 0xc0007c2000, 0xc0000801e0)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/syscall/zsyscall_solaris_amd64.go:765 +0x90
syscall.Read(...)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/syscall/syscall_unix.go:189
internal/poll.(*FD).Read(0xc0000800c0, 0xc00029e786, 0xa, 0xa, 0x0, 0x0, 0x0)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/internal/poll/fd_unix.go:156 +0x133
os.(*File).read(...)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/os/file_posix.go:31
os.(*File).Read(0xc0003b0000, 0xc00029e786, 0xa, 0xa, 0x0, 0x0, 0x6f65e0)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/os/file.go:116 +0x71
os_test.TestFdReadRace.func1(0xc00007e000, 0xc0003b0000, 0xc0007c2000, 0xc0006c2140)
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/os/pipe_test.go:433 +0xed
created by os_test.TestFdReadRace
	/tmp/workdir-host-solaris-oracle-amd64-oraclerel/go/src/os/pipe_test.go:428 +0x17f

It's not obvious to me whether this in a bug in the test, the os package, the Go runtime, or a longstanding bug in Solaris-based kernels.

CC @jclulow @ianlancetaylor @bradfitz

[bcmills]

2021-05-01T11:43:19-879db69/solaris-amd64-oraclerel
2021-04-12T15:17:33-117b1c8/solaris-amd64-oraclerel
2021-03-15T12:30:38-4350e49/solaris-amd64-oraclerel
2021-03-11T02:32:05-68f3344/illumos-amd64
2021-03-05T23:32:44-87d2993/illumos-amd64
2021-03-05T22:14:48-a829114/illumos-amd64
2021-03-05T18:45:59-70b277c/illumos-amd64
2021-03-05T09:24:34-2217e89/illumos-amd64
2021-03-01T21:11:10-a69c452/solaris-amd64-oraclerel
2020-04-23T19:40:07-6303c34/solaris-amd64-oraclerel

[bcmills]

Given the sudden increase in the failure rate at the beginning of March, I think this needs to be a release-blocker at least until we can figure out whether it is a symptom of a 1.17 regression in the os package.

[toothrot]

Also /cc'ing @griesemer as an owner of os

[heschi]

Weekly check-in: this needs to be investigated before beta 1.

[dmitshur]

Another weekly ping as this is a release blocking issue.

[ianlancetaylor]

I think I see a possible sequence of events that can lead to this. TestFdReadRace is making a concurrent call to Read in one goroutine and to Fd and Close in a different goroutine. The call to Fd is interesting because it puts the descriptor into blocking mode. I think that this can happen:

• goroutine 2 calls Fd
  • Fd calls the fcntl system call to put the descriptor into blocking mode
• goroutine 1 calls Read
  • Read calls readLock which adds a reference to the associated fdMutex
  • Read calls the read system call, which blocks, because the descriptor is in blocking mode
• goroutine 2 calls Close
  • Close calls increfAndClose which adds a reference and sets mutexClosed in the fdMutex
  • Close calls evict to unblock any I/O waiting in the poller, but there is none
  • Close calls decref, which removes a reference, leaving the one added by Read
  • Close sees that the FD is in blocking mode, so it returns

At this point goroutine 2 has returned and exited, and goroutine 1 is sitting in a blocked call to read which will never wake up. This is consistent with the stack traces in the test failures.

As far as I can tell this could happen on any system. I don't know why we only see the problem on Solaris. The test has a 10 millisecond wait to let goroutine 1 call Read before goroutine 2 calls Fd. If Read is called before the descriptor is put into blocking mode, the problem described here won't happen. It is possible that on Solaris the timeout is not enough for goroutine 1 to call Read, but I don't know why Solaris would be significantly different here.

So I'm not sure that this analysis is correct. Maybe I'm missing something. If this is correct, I don't see a way to fix it. Concurrent calls to Fd and Read will always carry the possibility of a blocking read system call that never returns. This is not a likely sequence of events. But see https://golang.org/cl/123176, which was written because of an internal Google test case that did exactly that (internal Google reference 111218325).

[gopherbot]

Change https://golang.org/cl/322893 mentions this issue: os: deflake TestFdReadRace