99designs / 99designs/gqlgen

Websocket close via context cancel sometimes results in complete event before closure

未关闭
#3,713 3 条评论 0 个 reaction 已指派 0 人 在 GitHub 查看
websocket
主要语言
Go
星标
10.8k
派生
1.3k
平均合并
2 天 36 分钟
30 天内合并 PR
26

描述

To illustrate the issue, some dumps from `websocat` for the messages sent by Apollo Server vs gqlgen. In both cases, the server has been closed externally on message 5. Importantly, this result is flaky, sometimes it only sends Close(1000) and not the complete event, so I believe it has to do with a race somewhere in the transport module.

### Apollo Server
```
[INFO websocat::lints] Auto-inserting the line mode
[DEBUG websocat] Done third phase of interpreting options.
[DEBUG websocat] Done fourth phase of interpreting options.
[DEBUG websocat] Preparation done. Now actually starting.
[DEBUG websocat::sessionserve] Underlying connection established
[INFO websocat::ws_client_peer] get_ws_client_peer
[DEBUG websocat::net_peer] Setting up a race between multiple TCP client sockets. Who connects the first?
[INFO websocat::net_peer] Connected to TCP [::1]:4025
[INFO websocat::ws_client_peer] Connected to ws
[DEBUG websocat::my_copy] zero len
[DEBUG websocat::my_copy] read_done
[DEBUG websocat::my_copy] done
[INFO websocat::sessionserve] Forward finished
[DEBUG websocat::sessionserve] Forward shutdown finished
[DEBUG websocat::ws_peer] drop WsWriteWrapper
[DEBUG websocat::ws_peer] incoming text
[DEBUG websocat::readdebt] Fulfilling the debt of 25 bytes
{"type":"connection_ack"}
[DEBUG websocat::ws_peer] incoming text
[DEBUG websocat::readdebt] Fulfilling the debt of 93 bytes
{"id":"2e862669-e831-4a9f-9477-0802bb4cf8c3","type":"next","payload":{"data":{"countEmp":1}}}
[DEBUG websocat::ws_peer] incoming text
[DEBUG websocat::readdebt] Fulfilling the debt of 93 bytes
{"id":"2e862669-e831-4a9f-9477-0802bb4cf8c3","type":"next","payload":{"data":{"countEmp":2}}}
[DEBUG websocat::ws_peer] incoming text
[DEBUG websocat::readdebt] Fulfilling the debt of 93 bytes
{"id":"2e862669-e831-4a9f-9477-0802bb4cf8c3","type":"next","payload":{"data":{"countEmp":3}}}
[DEBUG websocat::ws_peer] incoming text
[DEBUG websocat::readdebt] Fulfilling the debt of 93 bytes
{"id":"2e862669-e831-4a9f-9477-0802bb4cf8c3","type":"next","payload":{"data":{"countEmp":4}}}
[DEBUG websocat::ws_peer] incoming text
[DEBUG websocat::readdebt] Fulfilling the debt of 93 bytes
{"id":"2e862669-e831-4a9f-9477-0802bb4cf8c3","type":"next","payload":{"data":{"countEmp":5}}}
[INFO websocat::ws_peer] Received WebSocket close message
[DEBUG websocat::ws_peer] The close message is Some(CloseData { status_code: 1001, reason: "Going away" })
[DEBUG websocat::my_copy] BrokenPipe: read_done
[DEBUG websocat::my_copy] done
[INFO websocat::sessionserve] Reverse finished
[DEBUG websocat::sessionserve] Reverse shutdown finished
[INFO websocat::sessionserve] Both directions finished
```

Or, distilled down a bit:

```
{"type":"connection_ack"}
{"id":"2e862669-e831-4a9f-9477-0802bb4cf8c3","type":"next","payload":{"data":{"countEmp":1}}}
{"id":"2e862669-e831-4a9f-9477-0802bb4cf8c3","type":"next","payload":{"data":{"countEmp":2}}}
{"id":"2e862669-e831-4a9f-9477-0802bb4cf8c3","type":"next","payload":{"data":{"countEmp":3}}}
{"id":"2e862669-e831-4a9f-9477-0802bb4cf8c3","type":"next","payload":{"data":{"countEmp":4}}}
{"id":"2e862669-e831-4a9f-9477-0802bb4cf8c3","type":"next","payload":{"data":{"countEmp":5}}}
[INFO websocat::ws_peer] Received WebSocket close message
[DEBUG websocat::ws_peer] The close message is Some(CloseData { status_code: 1001, reason: "Going away" })
```

The Apollo server used is very standard, and uses `graphql-ws`'s Dispose function to clean up on shutdown.

### gqlgen
```
[INFO websocat::lints] Auto-inserting the line mode
[DEBUG websocat] Done third phase of interpreting options.
[DEBUG websocat] Done fourth phase of interpreting options.
[DEBUG websocat] Preparation done. Now actually starting.
[INFO websocat::stdio_threaded_peer] get_stdio_peer (threaded)
[DEBUG websocat::sessionserve] Underlying connection established
[INFO websocat::ws_client_peer] get_ws_client_peer
[DEBUG websocat::net_peer] Setting up a race between multiple TCP client sockets. Who connects the first?
[INFO websocat::net_peer] Connected to TCP [::1]:4001
[INFO websocat::ws_client_peer] Connected to ws
[DEBUG websocat::my_copy] zero len
[DEBUG websocat::my_copy] read_done
[DEBUG websocat::my_copy] done
[INFO websocat::sessionserve] Forward finished
[DEBUG websocat::sessionserve] Forward shutdown finished
[DEBUG websocat::ws_peer] drop WsWriteWrapper
[DEBUG websocat::ws_peer] incoming text
[DEBUG websocat::readdebt] Fulfilling the debt of 39 bytes
{"payload":{},"type":"connection_ack"}
[DEBUG websocat::ws_peer] incoming text
[DEBUG websocat::readdebt] Fulfilling the debt of 94 bytes
{"payload":{"data":{"countEmp":0}},"id":"4afc853a-5edd-4f8d-b54d-f06e9b23bc8c","type":"next"}
[DEBUG websocat::ws_peer] incoming text
[DEBUG websocat::readdebt] Fulfilling the debt of 94 bytes
{"payload":{"data":{"countEmp":1}},"id":"4afc853a-5edd-4f8d-b54d-f06e9b23bc8c","type":"next"}
[DEBUG websocat::ws_peer] incoming text
[DEBUG websocat::readdebt] Fulfilling the debt of 94 bytes
{"payload":{"data":{"countEmp":2}},"id":"4afc853a-5edd-4f8d-b54d-f06e9b23bc8c","type":"next"}
[DEBUG websocat::ws_peer] incoming text
[DEBUG websocat::readdebt] Fulfilling the debt of 94 bytes
{"payload":{"data":{"countEmp":3}},"id":"4afc853a-5edd-4f8d-b54d-f06e9b23bc8c","type":"next"}
[DEBUG websocat::ws_peer] incoming text
[DEBUG websocat::readdebt] Fulfilling the debt of 94 bytes
{"payload":{"data":{"countEmp":4}},"id":"4afc853a-5edd-4f8d-b54d-f06e9b23bc8c","type":"next"}
[DEBUG websocat::ws_peer] incoming text
[DEBUG websocat::readdebt] Fulfilling the debt of 94 bytes
{"payload":{"data":{"countEmp":5}},"id":"4afc853a-5edd-4f8d-b54d-f06e9b23bc8c","type":"next"}
[DEBUG websocat::ws_peer] incoming text
[DEBUG websocat::readdebt] Fulfilling the debt of 64 bytes
{"id":"4afc853a-5edd-4f8d-b54d-f06e9b23bc8c","type":"complete"}
[INFO websocat::ws_peer] Received WebSocket close message
[DEBUG websocat::ws_peer] The close message is Some(CloseData { status_code: 1000, reason: "terminated" })
[DEBUG websocat::my_copy] BrokenPipe: read_done
[DEBUG websocat::my_copy] done
[INFO websocat::sessionserve] Reverse finished
[DEBUG websocat::sessionserve] Reverse shutdown finished
[INFO websocat::sessionserve] Both directions finished
```

Or:

```
{"payload":{},"type":"connection_ack"}
{"payload":{"data":{"countEmp":0}},"id":"4afc853a-5edd-4f8d-b54d-f06e9b23bc8c","type":"next"}
{"payload":{"data":{"countEmp":1}},"id":"4afc853a-5edd-4f8d-b54d-f06e9b23bc8c","type":"next"}
{"payload":{"data":{"countEmp":2}},"id":"4afc853a-5edd-4f8d-b54d-f06e9b23bc8c","type":"next"}
{"payload":{"data":{"countEmp":3}},"id":"4afc853a-5edd-4f8d-b54d-f06e9b23bc8c","type":"next"}
{"payload":{"data":{"countEmp":4}},"id":"4afc853a-5edd-4f8d-b54d-f06e9b23bc8c","type":"next"}
{"payload":{"data":{"countEmp":5}},"id":"4afc853a-5edd-4f8d-b54d-f06e9b23bc8c","type":"next"}
{"id":"4afc853a-5edd-4f8d-b54d-f06e9b23bc8c","type":"complete"}
[INFO websocat::ws_peer] Received WebSocket close message
[DEBUG websocat::ws_peer] The close message is Some(CloseData { status_code: 1000, reason: "terminated" })
```

The gqlgen server attempts to gracefully shutdown with code like this:

```go
inflightWs := sync.WaitGroup{}
srv.AddTransport(transport.Websocket{
KeepAlivePingInterval: 10 * time.Second,
Upgrader: websocket.Upgrader{
CheckOrigin: func(r *http.Request) bool {
return true
},
},
InitFunc: func(ctx context.Context, initPayload transport.InitPayload) (context.Context, *transport.InitPayload, error) {
ctx, cancel := context.WithCancel(ctx)

go func() {
<-rootCtx.Done()
cancel()
}()

inflightWs.Add(1)

return ctx, &initPayload, nil
},
CloseFunc: func(ctx context.Context, closeCode int) {
inflightWs.Done()
},
})
```

During shutdown, `rootCtx` is cancelled, and `inflightWs` is waited on, before closing the http server or process.

#### Suggested solution

Don't send the complete event before closing, and perhaps send `1001` instead of `1000` to be consistent with the WS spec: 7.4.1 of https://www.rfc-editor.org/rfc/rfc6455

贡献指南

打开贡献指南

评估

这个 Issue 还没有评估数据。

把新 issue 发到你的邮箱

精选适合新手参与的 GitHub issue 摘要。