net: pipe2: too many open files on S390X

[cherrymui]

Since https://go-review.googlesource.com/c/45815/, the S390X builder starts to fail with

pipe2: too many open files
FAIL	net	3.146s

https://build.golang.org/log/c50cf67a5e81277c308bae6d09f661dbb5ecdef6

cc @ianlancetaylor @mundaym

[ianlancetaylor]

Running using gomote, I see

--- FAIL: TestVariousDeadlines (1.13s)
...
	timeout_test.go:913: for 250ms run 3/3, server in 250.726305ms wrote 395146821: readfrom tcp4 127.0.0.1:35191->127.0.0.1:35775: write tcp4 127.0.0.1:35191->127.0.0.1:35775: write: connection reset by peer
	timeout_test.go:878: 500ms run 1/3
	timeout_test.go:882: dial tcp 127.0.0.1:35191: socket: too many open files
--- PASS: TestTCPSpuriousConnSetupCompletionWithCancel (1.18s)
=== RUN   ExampleIPv4
pipe2: too many open files
exit status 1

I think it must be one of the new tests (TestTCPSpuriousConnSetupCompletion, TestTCPSpuriousConnSetupCompletionWithCancel) that are using up the file descriptors, but at the moment I'm not seeing it.

[ianlancetaylor]

On the s390 gomote ulimit -n reports 1024, as compared to my laptop where it reports 32768. /proc/sys/fs/file-max is 808890 on s390 gomote, 1048576 on my laptop. But running the net test under strace -f doesn't use nearly that many file descriptors. The largest file descriptor number I see is 159.

[ianlancetaylor]

OK, running strace -f on gomote s390 shows that the net test is indeed opening file descriptors up to 1023 before calls to socket start to fail with EMFILE.

[ianlancetaylor]

The pattern I'm seeing is

[pid  7669] socket(PF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP <unfinished ...>
...
[pid  7669] <... socket resumed> )      = 998
...
[pid  7669] setsockopt(998, SOL_SOCKET, SO_BROADCAST, [1], 4 <unfinished ...>
...
[pid  7669] <... setsockopt resumed> )  = 0
...
[pid  7669] connect(998, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, 16 <unfinished ...>
...
[pid  7669] <... connect resumed> )     = 0
...
[pid  7669] close(998 <unfinished ...>
...
[pid  7669] <... close resumed> )       = 0

with longs sequences of other unrelated system calls in the ellipses. 8.8.8.8 is the only address listed in /etc/resolv.conf in the gomote. In other words, we are creating a socket for contacting a UDP DNS server, but then we are closing that socket without writing anything to it. While that socket is open we are opening many more sockets. This pattern repeats over and over.

[ianlancetaylor]

I think I see the problem. TestTCPSpuriousConnSetupCompletionWithCancel works by starting a bunch of connections and canceling them. The connections use a DNS lookup, because connecting to a simple IP address did not recreate the problem the test was testing for. Canceling the connection does not cancel the DNS lookup, but it does cause the singleflight to forget what it was doing. So we wind up stacking up more and more DNS lookups, using up more and more file descriptors.

[gopherbot]

CL https://golang.org/cl/45999 mentions this issue.

[gopherbot]

Change https://golang.org/cl/100840 mentions this issue: net: don't let cancelation of a DNS lookup affect another lookup

[gopherbot]

Change https://golang.org/cl/102787 mentions this issue: [release-branch.go1.10] net: don't let cancelation of a DNS lookup affect another lookup

[gopherbot]

Change https://golang.org/cl/103215 mentions this issue: [release-branch.go1.9] net: don't let cancelation of a DNS lookup affect another lookup