v0.2.0 Websocket hangs forever

[rsukhodolskyi]

I assume network poller waits for ack message from client which dropped connection what leads to ws stream to be frozen. This bug is only reproducible on v0.2.0 previous version i've used didn't have this issue: v0.0.0-20200429184054-15c2290dcb37

goroutine 716698 [IO wait, 44 minutes]:
internal/poll.runtime_pollWait(0x7f9463665528, 0x77)
	/usr/local/go/src/runtime/netpoll.go:305 +0x89
internal/poll.(*pollDesc).wait(0xc01058b200?, 0xc02dcfc00a?, 0x0)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitWrite(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:93
internal/poll.(*FD).Write(0xc01058b200, {0xc02dcfc00a, 0xbfc, 0xff6})
	/usr/local/go/src/internal/poll/fd_unix.go:391 +0x2c5
net.(*netFD).Write(0xc01058b200, {0xc02dcfc00a?, 0xc0135d8e70?, 0x0?})
	/usr/local/go/src/net/fd_posix.go:96 +0x29
net.(*conn).Write(0xc022fabec0, {0xc02dcfc00a?, 0x1a387c0?, 0x0?})
	/usr/local/go/src/net/net.go:195 +0x45
github.com/gorilla/websocket.(*Conn).write(0xc011896420, 0x1, {0xc0135d8fd0?, 0x7ea729?, 0x0?}, {0xc02dcfc00a, 0xbfc, 0xff6}, {0x0, 0x0, ...})
	/go/pkg/mod/github.com/gorilla/websocket@v1.5.0/conn.go:392 +0x1a4
github.com/gorilla/websocket.(*messageWriter).flushFrame(0xc00f33e7b0, 0x1, {0x0?, 0x0?, 0xc0073ad780?})
	/go/pkg/mod/github.com/gorilla/websocket@v1.5.0/conn.go:621 +0x405
github.com/gorilla/websocket.(*messageWriter).Close(0xc0135d9018?)
	/go/pkg/mod/github.com/gorilla/websocket@v1.5.0/conn.go:731 +0x45
github.com/gorilla/websocket.(*Conn).WriteJSON(0x7de638?, {0x1a387c0, 0xc00f34cb20})
	/go/pkg/mod/github.com/gorilla/websocket@v1.5.0/json.go:29 +0xdf
github.com/sourcegraph/jsonrpc2/websocket.ObjectStream.WriteObject({0x7f9460fd7758?}, {0x1a387c0?, 0xc00f34cb20?})
	/go/pkg/mod/github.com/sourcegraph/jsonrpc2@v0.2.0/websocket/stream.go:25 +0x25

Moreover, because of the shared lock in Close function c.sending.Lock() it's also impossible to drop such client connection:

goroutine 716799 [semacquire, 43 minutes]:
sync.runtime_SemacquireMutex(0xa?, 0x0?, 0x24?)
	/usr/local/go/src/runtime/sema.go:77 +0x25
sync.(*Mutex).lockSlow(0xc026d8a310)
	/usr/local/go/src/sync/mutex.go:171 +0x165
sync.(*Mutex).Lock(...)
	/usr/local/go/src/sync/mutex.go:90
github.com/sourcegraph/jsonrpc2.(*Conn).close(0xc026d8a2d0, {0x0?, 0x0})
	/go/pkg/mod/github.com/sourcegraph/jsonrpc2@v0.2.0/conn.go:169 +0x7d
github.com/sourcegraph/jsonrpc2.(*Conn).Close(...)
	/go/pkg/mod/github.com/sourcegraph/jsonrpc2@v0.2.0/conn.go:69

[keegancsmith]

I assume network poller waits for ack message from client which dropped connection what leads to ws stream to be frozen.

I think you are right, but then this depends on how you configure the code here. IE jsonrpc2 just takes in whatever you give it as a ws.Conn. You need to make it error out when things go wrong. I'm not really sure why this would be different between the two hashes without diving deeper. A reproduction would help a lot here.

Moreover, because of the shared lock in Close function c.sending.Lock() it's also impossible to drop such client connection:

Ouch, nice find. This is indeed a bug since 15c2290. Will take a look.

[keegancsmith]

@rsukhodolskyi latest commit fixes Close not blocking. Do you have a reproduction to help track down the dropped acks?

[Muaytie666]

goroutine 716698 [IO wait, 44 minutes]:
internal/poll.runtime_pollWait(0x7f9463665528, 0x77)
/usr/local/go/src/runtime/netpoll.go:305 +0x89
internal/poll.(*pollDesc).wait(0xc01058b200?, 0xc02dcfc00a?, 0x0)
/usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitWrite(...)
/usr/local/go/src/internal/poll/fd_poll_runtime.go:93
internal/poll.(*FD).Write(0xc01058b200, {0xc02dcfc00a, 0xbfc, 0xff6})
/usr/local/go/src/internal/poll/fd_unix.go:391 +0x2c5
net.(*netFD).Write(0xc01058b200, {0xc02dcfc00a?, 0xc0135d8e70?, 0x0?})
/usr/local/go/src/net/fd_posix.go:96 +0x29
net.(*conn).Write(0xc022fabec0, {0xc02dcfc00a?, 0x1a387c0?, 0x0?})
/usr/local/go/src/net/net.go:195 +0x45
github.com/gorilla/websocket.(*Conn).write(0xc011896420, 0x1, {0xc0135d8fd0?, 0x7ea729?, 0x0?}, {0xc02dcfc00a, 0xbfc, 0xff6}, {0x0, 0x0, ...})
/go/pkg/mod/github.com/gorilla/websocket@v1.5.0/conn.go:392 +0x1a4
github.com/gorilla/websocket.(*messageWriter).flushFrame(0xc00f33e7b0, 0x1, {0x0?, 0x0?, 0xc0073ad780?})
/go/pkg/mod/github.com/gorilla/websocket@v1.5.0/conn.go:621 +0x405
github.com/gorilla/websocket.(*messageWriter).Close(0xc0135d9018?)
/go/pkg/mod/github.com/gorilla/websocket@v1.5.0/conn.go:731 +0x45
github.com/gorilla/websocket.(*Conn).WriteJSON(0x7de638?, {0x1a387c0, 0xc00f34cb20})
/go/pkg/mod/github.com/gorilla/websocket@v1.5.0/json.go:29 +0xdf
github.com/sourcegraph/jsonrpc2/websocket.ObjectStream.WriteObject({0x7f9460fd7758?}, {0x1a387c0?, 0xc00f34cb20?})
/go/pkg/mod/github.com/sourcegraph/jsonrpc2@v0.2.0/websocket/stream.go:25 +0x25

[keegancsmith]

@Muaytie666 I see you are using v0.2.0 and I realised I never published a new version. I just published v0.2.1. Can you try that out. For now I am gonna close this issue out. Please comment here if you still run into issues / open a new issue.

[Muaytie666]

#69

[keegancsmith]

@Muaytie666 I see you like interesting numbers, but maybe you meant to say a little more.