search

Danielhiversen / PyGraphqlWebsocketManager

Python code for graphql websocket client
GNU General Public License v3.0
0 stars 2 forks source link

Possible endless loop #32

Closed ztamas83 closed 1 year ago

ztamas83 commented 1 year ago

I found a possible endless loop in the subscription manager.

For some reason in _init_web_socket() function the websocket can remain unassigned. In this case https://github.com/Danielhiversen/PyGraphqlWebsocketManager/blob/ee7b05f5485cacdbe03b02fd262cebcc514c87ad/graphql_subscription_manager/__init__.py#L88 raises exception and we hit https://github.com/Danielhiversen/PyGraphqlWebsocketManager/blob/ee7b05f5485cacdbe03b02fd262cebcc514c87ad/graphql_subscription_manager/__init__.py#L97 in STATE_STARTING. It is a noop case and the loop just continues, no exit.

ztamas83 commented 1 year ago

This leads to similar observations as in https://github.com/home-assistant/core/issues/76491

ztamas83 commented 1 year ago

I could reproduce the issue by breaking the network connection. The retry() is triggered but there are scheduled running() tasks and since the state is STARTING without a valid self.websocket option there will be a very heavy loop trying to recv().

I believe a solution is to break this loop until the reconnect is actually completed, i.e. the start() is called from within retry().

I introduced STATE_WAIT_RETRY that helps to identify the retry case:

2022-11-09 09:12:17,048 - asyncio - DEBUG - Using selector: EpollSelector
2022-11-09 09:12:17,049 - graphql_subscription_manager - DEBUG - Start state None.
2022-11-09 09:12:17,049 - graphql_subscription_manager - DEBUG - Starting
2022-11-09 09:12:17,168 - websockets.client - DEBUG - = connection is CONNECTING
2022-11-09 09:12:17,259 - websockets.client - DEBUG - > GET /v1-beta/gql/subscriptions HTTP/1.1
2022-11-09 09:12:17,259 - websockets.client - DEBUG - > Host: websocket-api.tibber.com
2022-11-09 09:12:17,260 - websockets.client - DEBUG - > Upgrade: websocket
2022-11-09 09:12:17,260 - websockets.client - DEBUG - > Connection: Upgrade
2022-11-09 09:12:17,260 - websockets.client - DEBUG - > Sec-WebSocket-Key: OLjS9tvjTMsojW1VeLdADg==
2022-11-09 09:12:17,260 - websockets.client - DEBUG - > Sec-WebSocket-Version: 13
2022-11-09 09:12:17,260 - websockets.client - DEBUG - > Sec-WebSocket-Extensions: permessage-deflate; client_max_window_bits
2022-11-09 09:12:17,260 - websockets.client - DEBUG - > Sec-WebSocket-Protocol: graphql-transport-ws
2022-11-09 09:12:17,260 - websockets.client - DEBUG - > User-Agent: subscription_tests graphql-subscription-manager/0.6.1
2022-11-09 09:12:17,985 - websockets.client - DEBUG - < HTTP/1.1 101 Switching Protocols
2022-11-09 09:12:17,985 - websockets.client - DEBUG - < Date: Wed, 09 Nov 2022 08:12:17 GMT
2022-11-09 09:12:17,985 - websockets.client - DEBUG - < Connection: upgrade
2022-11-09 09:12:17,985 - websockets.client - DEBUG - < Upgrade: websocket
2022-11-09 09:12:17,985 - websockets.client - DEBUG - < Sec-WebSocket-Accept: Pkb2sHq9kI0Sl6ACAk/mXvK9OD4=
2022-11-09 09:12:17,986 - websockets.client - DEBUG - < Sec-WebSocket-Protocol: graphql-transport-ws
2022-11-09 09:12:17,986 - websockets.client - DEBUG - = connection is OPEN
2022-11-09 09:12:17,987 - websockets.client - DEBUG - > TEXT '{"type": "connection_init", "payload": {"token"...F6kJXPVf7eQYggo8ebAE"}}' [96 bytes]
2022-11-09 09:12:18,032 - websockets.client - DEBUG - < TEXT '{"type":"connection_ack"}' [25 bytes]
2022-11-09 09:12:18,033 - graphql_subscription_manager - DEBUG - Connection ACK received, running
2022-11-09 09:12:18,053 - websockets.client - DEBUG - > TEXT '{"payload": {"query": "\\n            subscript..."subscribe", "id": "0"}' [302 bytes]
2022-11-09 09:12:18,054 - graphql_subscription_manager - DEBUG - New subscription 0
Subscribed: 0
2022-11-09 09:12:18,971 - websockets.client - DEBUG - < TEXT '{"id":"0","type":"next","payload":{"data":{"liv...09:12:21.000+01:00"}}}}' [164 bytes]
2022-11-09 09:12:18,971 - graphql_subscription_manager - DEBUG - Received data {'data': {'liveMeasurement': {'lastMeterConsumption': 36154.134, 'signalStrength': None, 'timestamp': '2022-11-09T09:12:21.000+01:00'}}}
{'data': {'liveMeasurement': {'lastMeterConsumption': 36154.134, 'signalStrength': None, 'timestamp': '2022-11-09T09:12:21.000+01:00'}}}
2022-11-09 09:12:19,055 - root - DEBUG - Sleeping...
2022-11-09 09:12:19,780 - websockets.client - DEBUG - < TEXT '{"id":"0","type":"next","payload":{"data":{"liv...09:12:22.000+01:00"}}}}' [164 bytes]
2022-11-09 09:12:19,780 - graphql_subscription_manager - DEBUG - Received data {'data': {'liveMeasurement': {'lastMeterConsumption': 36154.134, 'signalStrength': None, 'timestamp': '2022-11-09T09:12:22.000+01:00'}}}
{'data': {'liveMeasurement': {'lastMeterConsumption': 36154.134, 'signalStrength': None, 'timestamp': '2022-11-09T09:12:22.000+01:00'}}}
2022-11-09 09:12:20,056 - root - DEBUG - Sleeping...
2022-11-09 09:12:20,779 - websockets.client - DEBUG - < TEXT '{"id":"0","type":"next","payload":{"data":{"liv...09:12:23.000+01:00"}}}}' [164 bytes]
2022-11-09 09:12:20,779 - graphql_subscription_manager - DEBUG - Received data {'data': {'liveMeasurement': {'lastMeterConsumption': 36154.134, 'signalStrength': None, 'timestamp': '2022-11-09T09:12:23.000+01:00'}}}
{'data': {'liveMeasurement': {'lastMeterConsumption': 36154.134, 'signalStrength': None, 'timestamp': '2022-11-09T09:12:23.000+01:00'}}}
2022-11-09 09:12:21,057 - root - DEBUG - Sleeping...
2022-11-09 09:12:22,058 - root - DEBUG - Sleeping...
2022-11-09 09:12:23,060 - root - DEBUG - Sleeping...
2022-11-09 09:12:24,061 - root - DEBUG - Sleeping...
2022-11-09 09:12:25,063 - root - DEBUG - Sleeping...
2022-11-09 09:12:26,064 - root - DEBUG - Sleeping...
2022-11-09 09:12:27,066 - root - DEBUG - Sleeping...
2022-11-09 09:12:28,067 - root - DEBUG - Sleeping...
2022-11-09 09:12:29,068 - root - DEBUG - Sleeping...
2022-11-09 09:12:30,070 - root - DEBUG - Sleeping...
2022-11-09 09:12:31,071 - root - DEBUG - Sleeping...
2022-11-09 09:12:32,073 - root - DEBUG - Sleeping...
2022-11-09 09:12:33,074 - root - DEBUG - Sleeping...
2022-11-09 09:12:34,075 - root - DEBUG - Sleeping...
2022-11-09 09:12:35,077 - root - DEBUG - Sleeping...
2022-11-09 09:12:36,078 - root - DEBUG - Sleeping...
2022-11-09 09:12:37,079 - root - DEBUG - Sleeping...
2022-11-09 09:12:37,988 - websockets.client - DEBUG - % sending keepalive ping
2022-11-09 09:12:37,988 - websockets.client - DEBUG - > PING 83 e2 54 3c [binary, 4 bytes]
2022-11-09 09:12:38,058 - websockets.client - DEBUG - = connection is CLOSED
2022-11-09 09:12:38,058 - websockets.client - DEBUG - ! failing connection with code 1006
2022-11-09 09:12:38,058 - websockets.client - DEBUG - x closing TCP connection
2022-11-09 09:12:38,058 - graphql_subscription_manager - WARNING - Unexpected exception, retrying.
Traceback (most recent call last):
  File "/home/ztamas/.local/lib/python3.9/site-packages/websockets/legacy/protocol.py", line 968, in transfer_data
    message = await self.read_message()
  File "/home/ztamas/.local/lib/python3.9/site-packages/websockets/legacy/protocol.py", line 1038, in read_message
    frame = await self.read_data_frame(max_size=self.max_size)
  File "/home/ztamas/.local/lib/python3.9/site-packages/websockets/legacy/protocol.py", line 1113, in read_data_frame
    frame = await self.read_frame(max_size)
  File "/home/ztamas/.local/lib/python3.9/site-packages/websockets/legacy/protocol.py", line 1170, in read_frame
    frame = await Frame.read(
  File "/home/ztamas/.local/lib/python3.9/site-packages/websockets/legacy/framing.py", line 69, in read
    data = await reader(2)
  File "/usr/lib/python3.9/asyncio/streams.py", line 723, in readexactly
    await self._wait_for_data('readexactly')
  File "/usr/lib/python3.9/asyncio/streams.py", line 517, in _wait_for_data
    await self._waiter
  File "/usr/lib/python3.9/asyncio/selector_events.py", line 856, in _read_ready__data_received
    data = self._sock.recv(self.max_size)
ConnectionResetError: [Errno 104] Connection reset by peer

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/home/ztamas/src/github/PyGraphqlWebsocketManager/graphql_subscription_manager/__init__.py", line 88, in running
    msg = await asyncio.wait_for(self.websocket.recv(), timeout=60)
  File "/usr/lib/python3.9/asyncio/tasks.py", line 481, in wait_for
    return fut.result()
  File "/home/ztamas/.local/lib/python3.9/site-packages/websockets/legacy/protocol.py", line 568, in recv
    await self.ensure_open()
  File "/home/ztamas/.local/lib/python3.9/site-packages/websockets/legacy/protocol.py", line 944, in ensure_open
    raise self.connection_closed_exc()
websockets.exceptions.ConnectionClosedError: no close frame received or sent
2022-11-09 09:12:38,072 - graphql_subscription_manager - DEBUG - Retry, state: running
2022-11-09 09:12:38,072 - graphql_subscription_manager - DEBUG - Close websocket
2022-11-09 09:12:38,072 - graphql_subscription_manager - DEBUG - Restart
2022-11-09 09:12:38,072 - graphql_subscription_manager - DEBUG - Reconnecting to server after 34 seconds; jitter 33; backoff 1
2022-11-09 09:12:38,080 - root - DEBUG - Sleeping...
2022-11-09 09:12:39,082 - root - DEBUG - Sleeping...
2022-11-09 09:12:40,083 - root - DEBUG - Sleeping...
2022-11-09 09:12:41,085 - root - DEBUG - Sleeping...
2022-11-09 09:12:42,086 - root - DEBUG - Sleeping...
2022-11-09 09:12:43,087 - root - DEBUG - Sleeping...
2022-11-09 09:12:44,089 - root - DEBUG - Sleeping...
2022-11-09 09:12:45,090 - root - DEBUG - Sleeping...
2022-11-09 09:12:46,092 - root - DEBUG - Sleeping...
2022-11-09 09:12:47,093 - root - DEBUG - Sleeping...
2022-11-09 09:12:48,094 - root - DEBUG - Sleeping...
2022-11-09 09:12:49,097 - root - DEBUG - Sleeping...
2022-11-09 09:12:50,099 - root - DEBUG - Sleeping...
2022-11-09 09:12:51,100 - root - DEBUG - Sleeping...
2022-11-09 09:12:52,101 - root - DEBUG - Sleeping...
2022-11-09 09:12:53,103 - root - DEBUG - Sleeping...
2022-11-09 09:12:54,104 - root - DEBUG - Sleeping...
2022-11-09 09:12:55,106 - root - DEBUG - Sleeping...
2022-11-09 09:12:56,107 - root - DEBUG - Sleeping...
2022-11-09 09:12:57,108 - root - DEBUG - Sleeping...
2022-11-09 09:12:58,110 - root - DEBUG - Sleeping...
2022-11-09 09:12:59,111 - root - DEBUG - Sleeping...
2022-11-09 09:13:00,113 - root - DEBUG - Sleeping...
2022-11-09 09:13:01,114 - root - DEBUG - Sleeping...
2022-11-09 09:13:02,116 - root - DEBUG - Sleeping...
2022-11-09 09:13:03,117 - root - DEBUG - Sleeping...
2022-11-09 09:13:04,118 - root - DEBUG - Sleeping...
2022-11-09 09:13:05,120 - root - DEBUG - Sleeping...
2022-11-09 09:13:06,121 - root - DEBUG - Sleeping...
2022-11-09 09:13:07,123 - root - DEBUG - Sleeping...
2022-11-09 09:13:08,124 - root - DEBUG - Sleeping...
2022-11-09 09:13:09,125 - root - DEBUG - Sleeping...
2022-11-09 09:13:10,127 - root - DEBUG - Sleeping...
2022-11-09 09:13:11,128 - root - DEBUG - Sleeping...
2022-11-09 09:13:12,075 - graphql_subscription_manager - DEBUG - Start state retry.
2022-11-09 09:13:12,076 - graphql_subscription_manager - DEBUG - Removed, 0
2022-11-09 09:13:12,076 - graphql_subscription_manager - DEBUG - Add subscription <function callback_sub at 0x7f5ac46d0160>
2022-11-09 09:13:12,076 - graphql_subscription_manager - DEBUG - Starting
2022-11-09 09:13:12,129 - root - DEBUG - Sleeping...
2022-11-09 09:13:12,160 - websockets.client - DEBUG - = connection is CONNECTING
2022-11-09 09:13:12,247 - websockets.client - DEBUG - > GET /v1-beta/gql/subscriptions HTTP/1.1
2022-11-09 09:13:12,247 - websockets.client - DEBUG - > Host: websocket-api.tibber.com
2022-11-09 09:13:12,248 - websockets.client - DEBUG - > Upgrade: websocket
2022-11-09 09:13:12,248 - websockets.client - DEBUG - > Connection: Upgrade
2022-11-09 09:13:12,248 - websockets.client - DEBUG - > Sec-WebSocket-Key: QzSyW2LONXfv5MWKNawyCA==
2022-11-09 09:13:12,248 - websockets.client - DEBUG - > Sec-WebSocket-Version: 13
2022-11-09 09:13:12,248 - websockets.client - DEBUG - > Sec-WebSocket-Extensions: permessage-deflate; client_max_window_bits
2022-11-09 09:13:12,248 - websockets.client - DEBUG - > Sec-WebSocket-Protocol: graphql-transport-ws
2022-11-09 09:13:12,248 - websockets.client - DEBUG - > User-Agent: subscription_tests graphql-subscription-manager/0.6.1
2022-11-09 09:13:12,352 - websockets.client - DEBUG - < HTTP/1.1 101 Switching Protocols
2022-11-09 09:13:12,353 - websockets.client - DEBUG - < Date: Wed, 09 Nov 2022 08:13:12 GMT
2022-11-09 09:13:12,353 - websockets.client - DEBUG - < Connection: upgrade
2022-11-09 09:13:12,353 - websockets.client - DEBUG - < Upgrade: websocket
2022-11-09 09:13:12,353 - websockets.client - DEBUG - < Sec-WebSocket-Accept: az69Dr97OQB7B60f+7Ey5JDX9Ag=
2022-11-09 09:13:12,353 - websockets.client - DEBUG - < Sec-WebSocket-Protocol: graphql-transport-ws
2022-11-09 09:13:12,353 - websockets.client - DEBUG - = connection is OPEN
2022-11-09 09:13:12,354 - websockets.client - DEBUG - > TEXT '{"type": "connection_init", "payload": {"token"...F6kJXPVf7eQYggo8ebAE"}}' [96 bytes]
2022-11-09 09:13:12,396 - websockets.client - DEBUG - < TEXT '{"type":"connection_ack"}' [25 bytes]
2022-11-09 09:13:12,397 - graphql_subscription_manager - DEBUG - Connection ACK received, running
2022-11-09 09:13:12,479 - websockets.client - DEBUG - > TEXT '{"payload": {"query": "\\n            subscript..."subscribe", "id": "1"}' [302 bytes]
2022-11-09 09:13:12,480 - graphql_subscription_manager - DEBUG - New subscription 1
2022-11-09 09:13:12,691 - websockets.client - DEBUG - < TEXT '{"id":"1","type":"next","payload":{"data":{"liv...09:13:15.000+01:00"}}}}' [164 bytes]
2022-11-09 09:13:12,691 - graphql_subscription_manager - DEBUG - Received data {'data': {'liveMeasurement': {'lastMeterConsumption': 36154.135, 'signalStrength': None, 'timestamp': '2022-11-09T09:13:15.000+01:00'}}}
{'data': {'liveMeasurement': {'lastMeterConsumption': 36154.135, 'signalStrength': None, 'timestamp': '2022-11-09T09:13:15.000+01:00'}}}
2022-11-09 09:13:13,130 - root - DEBUG - Sleeping...
2022-11-09 09:13:13,660 - websockets.client - DEBUG - < TEXT '{"id":"1","type":"next","payload":{"data":{"liv...09:13:16.000+01:00"}}}}' [164 bytes]
2022-11-09 09:13:13,660 - graphql_subscription_manager - DEBUG - Received data {'data': {'liveMeasurement': {'lastMeterConsumption': 36154.135, 'signalStrength': None, 'timestamp': '2022-11-09T09:13:16.000+01:00'}}}
{'data': {'liveMeasurement': {'lastMeterConsumption': 36154.135, 'signalStrength': None, 'timestamp': '2022-11-09T09:13:16.000+01:00'}}}
2022-11-09 09:13:14,131 - root - DEBUG - Sleeping...
ztamas83 commented 1 year ago

Fixed in #36 Possible further enhancement in #34 , @Danielhiversen should decide if it's needed at all.