Frequent subscription closing with unknown reason

[toini]

I'm unsure how to classify this issue as I don't really know if it's a client or server issue. Anyhow, firstly I'd like to thank for the great support I've seen happen here by the maintainer @enisdenjo!

Our issue has to do with growing number of users connecting to our websocket servers (running on several Docker continainers on AWS ECS) causing stability issues which we decided to try mitigate by switching sub protocol from Apollo's graphql-ws to this new one graphql-transport-ws.

Our initial concerns were related to memory leaks and lack of maintenance for the the older protocol, though we were unable to confirm our problems were related to websockets as the Graphql service we have been running also serves regular queries. Currently, we are at at migration period to separate the servers and adjusting clients to connect to a new endpoint serving only websocket traffic and only the new sub protocol.

Since the new server has very few connected clients I wanted to make sure we understand everything that is happening under the hood. One of the things we thought might be adding to CPU usage was constant reconnects occurring according to logs (though we cant confirm whether really is an issue). We thought the problem would mostly affect unmaintained clients connecting with old libraries/old platforms/bad network. However, after selecting some newer clients for testing with the new server we noticed same frequent reconnect behaviour.

I'll share a log to shed light on it. Typically, the server would be sending datagrams every 2-10 seconds depending on the hardware behind.

2022-10-24T16:10:16.379Z INFO [websocket] on next; userIp 213.204.232.45; userAgent Homey/8.0.8 com.tibber/1.8.1
2022-10-24T16:10:26.177Z INFO [websocket] on next; userIp 213.204.232.45; userAgent Homey/8.0.8 com.tibber/1.8.1
2022-10-24T16:10:42.935Z INFO [websocket] on disconnect; token count 0; userId 39cc9b91-fad3-4a5e-abc8-57b63884806e; userIp 213.204.232.45; userAgent Homey/8.0.8 com.tibber/1.8.1
2022-10-24T16:10:42.935Z INFO [websocket] on close; code 1006; reason ; userIp 213.204.232.45; userAgent Homey/8.0.8 com.tibber/1.8.1
2022-10-24T16:10:46.590Z INFO 45e56241d6c340d93b180f86ece9dca9 [websocket] on upgrade; protocol graphql-transport-ws; user ip 213.204.232.45; user-agent Homey/8.0.8 com.tibber/1.8.1
2022-10-24T16:10:46.640Z INFO [websocket] client connected; verified token for user 39cc9b91-fad3-4a5e-abc8-57b63884806e; Homey/8.0.8 com.tibber/1.8.1; 213.204.232.45; count 1
2022-10-24T16:11:43.188Z INFO [websocket] on next; userIp 213.204.232.45; userAgent Homey/8.0.8 com.tibber/1.8.1
2022-10-24T16:11:43.682Z INFO [websocket] on next; userIp 213.204.232.45; userAgent Homey/8.0.8 com.tibber/1.8.1

...

2022-10-24T16:59:26.246Z INFO [websocket] on next; userIp 213.204.232.45; userAgent Homey/8.0.8 com.tibber/1.8.1
2022-10-24T16:59:36.529Z INFO [websocket] on next; userIp 213.204.232.45; userAgent Homey/8.0.8 com.tibber/1.8.1
2022-10-24T16:59:58.624Z INFO [websocket] on disconnect; token count 0; userId 39cc9b91-fad3-4a5e-abc8-57b63884806e; userIp 213.204.232.45; userAgent Homey/8.0.8 com.tibber/1.8.1
2022-10-24T16:59:58.624Z INFO [websocket] on close; code 1006; reason ; userIp 213.204.232.45; userAgent Homey/8.0.8 com.tibber/1.8.1
2022-10-24T17:00:01.590Z INFO 6c958aed097bbaf2a7182d4b9d539c76 [websocket] on upgrade; protocol graphql-transport-ws; user ip 213.204.232.45; user-agent Homey/8.0.8 com.tibber/1.8.1
2022-10-24T17:00:01.638Z INFO [websocket] client connected; verified token for user 39cc9b91-fad3-4a5e-abc8-57b63884806e; Homey/8.0.8 com.tibber/1.8.1; 213.204.232.45; count 1
2022-10-24T17:00:53.839Z INFO [websocket] on next; userIp 213.204.232.45; userAgent Homey/8.0.8 com.tibber/1.8.1
2022-10-24T17:00:54.320Z INFO [websocket] on next; userIp 213.204.232.45; userAgent Homey/8.0.8 com.tibber/1.8.1

...

2022-10-24T17:05:56.660Z INFO [websocket] on next; userIp 213.204.232.45; userAgent Homey/8.0.8 com.tibber/1.8.1
2022-10-24T17:06:06.466Z INFO [websocket] on next; userIp 213.204.232.45; userAgent Homey/8.0.8 com.tibber/1.8.1
2022-10-24T17:06:13.594Z INFO [websocket] on disconnect; token count 0; userId 39cc9b91-fad3-4a5e-abc8-57b63884806e; userIp 213.204.232.45; userAgent Homey/8.0.8 com.tibber/1.8.1
2022-10-24T17:06:13.594Z INFO [websocket] on close; code 1006; reason ; userIp 213.204.232.45; userAgent Homey/8.0.8 com.tibber/1.8.1
2022-10-24T17:06:16.004Z INFO bc1bfa7b08b49d27a0a4f8c59e47f42d [websocket] on upgrade; protocol graphql-transport-ws; user ip 213.204.232.45; user-agent Homey/8.0.8 com.tibber/1.8.1
2022-10-24T17:06:16.061Z INFO [websocket] client connected; verified token for user 39cc9b91-fad3-4a5e-abc8-57b63884806e; Homey/8.0.8 com.tibber/1.8.1; 213.204.232.45; count 1
2022-10-24T17:06:16.304Z INFO [websocket] on next; userIp 213.204.232.45; userAgent Homey/8.0.8 com.tibber/1.8.1
2022-10-24T17:06:26.591Z INFO [websocket] on next; userIp 213.204.232.45; userAgent Homey/8.0.8 com.tibber/1.8.1

Here you can see disconnects with code 1006 occur quite randomly without reason that would indicate why it happened. Was it the client that chose to close the connection?

The code to setup server follows the use server recipe at graphql-ws/lib/use/ws

Client sets up connection like this (https://github.com/tibber/com.tibber.athom/blob/master/lib/tibber.ts#L360):

const webSocketClient = createClient({
  url: websocketSubscriptionUrl,

  connectionParams: {
	token: this.#token,
  },
  webSocketImpl: UserAgentWebSocket,
});

const wsLink = new GraphQLWsLink(webSocketClient);

const apolloClient = new ApolloClient({
  link: wsLink,
  cache: new InMemoryCache() as any,
});

return apolloClient.subscribe({
  query: queries.getSubscriptionQuery(this.#homeId!),
  variables: {},
});

Would you happen to have any ideas how to troubleshoot the constant reconnects? Any help much appreciated!

[enisdenjo]

Hey there, code 1006 is reserved for unexpected or abrupt closures - it can mean anything: client's browser connection abruptly failed, or a gateway terminated the connection, or a server had issues with the TCP connection, or internet wen down, many things...

Was it happening with subscriptions-transport-ws before?

[toini]

Yes, I'm quite sure similar things happened with subscriptions-transport-ws before. We had to add a naive implementation (in-memory, doesnt work with multiple instances we now have) to track sockets to avoid multiple sockets getting opened for the same user. It seemed that some clients tried to open new sockets while old ones were still open.

Now that we are switching the endpoint and getting rid of the old protocol I'm trying to squeeze out all errors and polish the solution. We're also intially always blamed the troubles on internet connection but this is happening so often with quite a many devices I'm not sure if I buy that anymore. But if that was the case, could there be ways to mitigate it? Any ideas?

[toini]

Do we know that 1006 means it is the client that closed the connection? Wondering if there could be any way to get to see what exactly happened at networking level. Was there a tcp package that triggered closing? If not, it should stay open, right?

[toini]

These devices are home automation hubs so any internet connection strength should typically stay same. I get sometimes conditions are bad but here the reconnect rate is suspiciously high.

[toini]

If the reason is, say, #user's internet router would the proper mitigation be enabling keep alive? Is that generally a good idea when we send data 1 - 10 second intervals anyways. We havent tried that. Any considerations there? I guess we would expect some increase in traffic at least.

[enisdenjo]

Receiving a close with code 1006 often means you should look elsewhere, graphql-ws close codes start with 4 for easily distinguishing internal vs user-land errors.

Do we know that 1006 means it is the client that closed the connection?

1006 can mean both the client or the server or the proxy or gateway may've closed the connection.

Wondering if there could be any way to get to see what exactly happened at networking level. Was there a tcp package that triggered closing? If not, it should stay open, right?

You might go with inspecting the actual network, but with 1006 you can be quite sure the the package doesn't come from a WebSocket frame but rather an abrupt termination.

If the reason is, say, #user's internet router would the proper mitigation be enabling keep alive? Is that generally a good idea when we send data 1 - 10 second intervals anyways. We haven't tried that. Any considerations there?

Well you could try at least to see whether the routers might be causing the disconnects. The 1006 close code is a good indicator that something external is terminating the connection.

It is a bit suspicious though that you communicate with the clients often and yet a firewall in the router would mark the connection as stale and terminate it.

Could it be that the home bus themselves are somehow causing the abrupt disconnects? On OS level or something alike?