x/tools/internal/jsonrpc2_v2: test failures with "goroutine leak detected"

[dmitshur]

#!watchflakes
post <- pkg == "golang.org/x/tools/internal/jsonrpc2_v2" && `goroutine leak detected`

Observed the following test failure on a openbsd-amd64-68 TryBot in https://go-review.googlesource.com/c/tools/+/313097/7#message-05b2ee7a7f430f763806057296bde561b9777f07:

--- FAIL: TestIdleTimeout (2.10s)
    serve_test.go:38: dial tcp 127.0.0.1:1954: connect: connection reset by peer
    stacktest.go:48: goroutine leak detected:
        [IO wait]: $101
        /tmp/workdir/go/src/runtime/netpoll.go:229:                                   runtime_pollWait
        /tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:84:                      (*pollDesc).wait
        /tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:89:                      (*pollDesc).waitRead
        /tmp/workdir/go/src/internal/poll/fd_unix.go:167:                             (*FD).Read
        /tmp/workdir/go/src/net/fd_posix.go:56:                                       (*netFD).Read
        /tmp/workdir/go/src/net/net.go:183:                                           (*conn).Read
        /tmp/workdir/go/src/bufio/bufio.go:101:                                       (*Reader).fill
        /tmp/workdir/go/src/bufio/bufio.go:360:                                       (*Reader).ReadSlice
        /tmp/workdir/go/src/bufio/bufio.go:435:                                       (*Reader).collectFragments
        /tmp/workdir/go/src/bufio/bufio.go:483:                                       (*Reader).ReadString
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/frame.go:122: (*headerReader).Read
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/conn.go:294:  (*Connection).readIncoming
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/conn.go:112:  newConnection
        
        [IO wait]: $125
        /tmp/workdir/go/src/runtime/netpoll.go:229:                                   runtime_pollWait
        /tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:84:                      (*pollDesc).wait
        /tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:89:                      (*pollDesc).waitRead
        /tmp/workdir/go/src/internal/poll/fd_unix.go:167:                             (*FD).Read
        /tmp/workdir/go/src/net/fd_posix.go:56:                                       (*netFD).Read
        /tmp/workdir/go/src/net/net.go:183:                                           (*conn).Read
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/serve.go:187: (*idleCloser).Read
        /tmp/workdir/go/src/bufio/bufio.go:101:                                       (*Reader).fill
        /tmp/workdir/go/src/bufio/bufio.go:360:                                       (*Reader).ReadSlice
        /tmp/workdir/go/src/bufio/bufio.go:435:                                       (*Reader).collectFragments
        /tmp/workdir/go/src/bufio/bufio.go:483:                                       (*Reader).ReadString
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/frame.go:122: (*headerReader).Read
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/conn.go:294:  (*Connection).readIncoming
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/conn.go:112:  newConnection
        
        [chan receive]: $102, $126
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/conn.go:363: (*Connection).manageQueue
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/conn.go:113: newConnection
        
        [chan receive]: $103, $127
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/conn.go:398: (*Connection).deliverMessages
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/conn.go:114: newConnection
        
        [chan receive]: $123
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/jsonrpc2.go:81: (*async).wait
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/conn.go:269:    (*Connection).Wait
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/serve.go:113:   (*Server).run
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/serve.go:70:    Serve
        
        7 goroutines, 5 unique
FAIL
FAIL	golang.org/x/tools/internal/jsonrpc2_v2	2.472s

https://storage.googleapis.com/go-build-log/af6123a8/openbsd-amd64-68_8cf10eb0.log

It did not recur after restarting TryBots a second time. I'm not finding many other instances of this on the build dashboard, so it looks like a rare failure. Reporting in case this is helpful.

CC @ianthehat.

[bcmills]

It's more than once now:
https://storage.googleapis.com/go-build-log/9f8d558c/openbsd-amd64-68_873770c6.log (a TryBot)

[bcmills]

It's also apparently not just this builder. 😕

greplogs --dashboard -md -l -e '(?m)FAIL: TestIdleTimeout.*\n.*goroutine leak detected'

2021-10-02T00:44:24-0ebff1a-afe43f1/openbsd-amd64-68
2021-09-21T03:32:29-fe076c8-abc4f09/netbsd-arm-bsiegert
2021-09-17T08:20:48-1a7ca93-6602c86/netbsd-arm64-bsiegert
2021-09-16T23:13:58-1a7ca93-e09dcc2/freebsd-386-11_4
2021-09-03T19:56:09-d39bbca-04d8d24/freebsd-amd64-11_4
2021-08-17T04:37:32-6932d22-a304273/netbsd-arm-bsiegert
2021-08-16T23:57:10-10bcabd-2a19333/solaris-amd64-oraclerel
2021-08-16T23:03:03-10bcabd-df9c5d8/solaris-amd64-oraclerel
2021-08-12T17:54:49-15a2ab8-5805efc/openbsd-amd64-68
2021-08-04T13:50:16-309db04-16ab7e4/dragonfly-amd64
2021-07-08T21:02:30-64bd808-3d1d066/linux-amd64-wsl
2021-07-08T19:57:21-1c9019e-fb052db/linux-amd64-wsl
2021-06-09T16:53:08-937957b-7677616/freebsd-arm64-dmgk
2021-05-21T18:55:18-2275bb5-e4d7525/illumos-amd64
2021-05-19T14:12:35-a0f4b7b-658b5e6/windows-386-2008
2021-04-30T14:46:28-291330a-06ac303/solaris-amd64-oraclerel
2021-04-29T04:59:52-800adbe-6afa0ae/openbsd-amd64-64

[bcmills]

greplogs --dashboard -md -l -e '(?m)FAIL: TestIdleTimeout.*\n.*goroutine leak' --since=2021-10-05

2021-11-05T00:52:09-6f75aad-bd580a0/openbsd-386-68
2021-11-03T21:45:33-84e69e7-d3f5dd5/openbsd-386-68
2021-11-03T00:07:38-714668c-49a0063/freebsd-amd64-11_4
2021-11-03T00:07:38-714668c-49a0063/openbsd-386-68
2021-11-02T20:49:06-6561d8c-b246873/openbsd-386-68
2021-10-21T15:45:05-9b675d0-6ec9a1d/openbsd-386-68
2021-10-12T22:26:24-074820e-2ac3bdf/openbsd-amd64-64
2021-10-06T23:01:01-d477ef3-4ffa2f1/openbsd-amd64-68
2021-10-05T20:35:54-2dc2755-990c9c6/openbsd-amd64-68

[gopherbot]

Change https://go.dev/cl/388598 mentions this issue: internal/jsonrpc2_v2: eliminate arbitrary timeouts in tests

[gopherbot]

Change https://go.dev/cl/388597 mentions this issue: internal/jsonrpc2_v2: refactor concurrency in idleListener

[gopherbot]

Change https://go.dev/cl/388599 mentions this issue: internal/jsonrpc2_v2: close the underlying connection if Wait is called instead of Close

[gopherbot]

Change https://go.dev/cl/388774 mentions this issue: internal/jsonrpc2_v2: eliminate a temporary connection leak in (*Server).run

[gopherbot]

Change https://go.dev/cl/388775 mentions this issue: internal/jsonrpc2_v2: error out in-flight client calls when the reader breaks

[cherrymui]

2022-07-25T14:31:12-6ec939a-64f2829/openbsd-386-68
2022-07-21T22:58:07-ec1f924-076c3d7/openbsd-amd64-68
This is in TestServe but the failure is quite similar

--- FAIL: TestServe (1.24s)
    --- FAIL: TestServe/tcp (0.12s)
        serve_test.go:137: close tcp 127.0.0.1:40864: use of closed network connection
    stacktest.go:48: goroutine leak detected:
        [IO wait]: $221
        /tmp/workdir/go/src/runtime/netpoll.go:305:                                   runtime_pollWait
        /tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:84:                      (*pollDesc).wait
        /tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:89:                      (*pollDesc).waitRead
        /tmp/workdir/go/src/internal/poll/fd_unix.go:167:                             (*FD).Read
        /tmp/workdir/go/src/net/fd_posix.go:55:                                       (*netFD).Read
        /tmp/workdir/go/src/net/net.go:183:                                           (*conn).Read
        /tmp/workdir/go/src/bufio/bufio.go:106:                                       (*Reader).fill
        /tmp/workdir/go/src/bufio/bufio.go:372:                                       (*Reader).ReadSlice
        /tmp/workdir/go/src/bufio/bufio.go:447:                                       (*Reader).collectFragments
        /tmp/workdir/go/src/bufio/bufio.go:495:                                       (*Reader).ReadString
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/frame.go:120: (*headerReader).Read
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/conn.go:295:  (*Connection).readIncoming
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/conn.go:112:  newConnection
        
        [IO wait]: $112
        /tmp/workdir/go/src/runtime/netpoll.go:305:                                   runtime_pollWait
        /tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:84:                      (*pollDesc).wait
        /tmp/workdir/go/src/internal/poll/fd_poll_runtime.go:89:                      (*pollDesc).waitRead
        /tmp/workdir/go/src/internal/poll/fd_unix.go:167:                             (*FD).Read
        /tmp/workdir/go/src/net/fd_posix.go:55:                                       (*netFD).Read
        /tmp/workdir/go/src/net/net.go:183:                                           (*conn).Read
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/serve.go:204: (*idleCloser).Read
        /tmp/workdir/go/src/bufio/bufio.go:106:                                       (*Reader).fill
        /tmp/workdir/go/src/bufio/bufio.go:372:                                       (*Reader).ReadSlice
        /tmp/workdir/go/src/bufio/bufio.go:447:                                       (*Reader).collectFragments
        /tmp/workdir/go/src/bufio/bufio.go:495:                                       (*Reader).ReadString
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/frame.go:120: (*headerReader).Read
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/conn.go:295:  (*Connection).readIncoming
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/conn.go:112:  newConnection
        
        [chan receive]: $113, $222
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/conn.go:364: (*Connection).manageQueue
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/conn.go:113: newConnection
        
        [chan receive]: $226, $223
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/conn.go:399: (*Connection).deliverMessages
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/conn.go:114: newConnection
        
        [chan receive]: $219
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/jsonrpc2.go:113: (*async).wait
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/conn.go:270:     (*Connection).Wait
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/serve.go:115:    (*Server).run
        /tmp/workdir/gopath/src/golang.org/x/tools/internal/jsonrpc2_v2/serve.go:72:     Serve
        
        7 goroutines, 5 unique
FAIL
FAIL	golang.org/x/tools/internal/jsonrpc2_v2	1.821s