99designs / 99designs/gqlgen

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

Ouverte
#3,713 3 commentaires 0 réactions 0 personnes assignées Voir sur GitHub
websocket
Langage dominant
Go
Étoiles
10.8k
Forks
1.3k
Merge moyen
2 j 36 min
PR mergées (30 j)
26

Description

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

Guide de contribution

Ouvrir le guide de contribution

Évaluation

Cette issue n'a pas encore été évaluée.

Recevez les nouvelles issues par e-mail

Un résumé court des issues GitHub adaptées aux débutants.