Exception Occurred while using subscriptions API after running for approx 1 hour

[jnitin]

Hi

Thanks for this wonderful package . I am using subscriptions API from this package and it works fine ..
However after running for 1 hr , below exceptions is raised. Please let me know how to avoid this exception .

Traceback (most recent call last):
File "/usr/lib/python3.6/threading.py", line 916, in _bootstrap_inner
self.run()
File "/usr/lib/python3.6/threading.py", line 864, in run
self._target(self._args, **self._kwargs)
File "/home//jsondatasource/venv/lib/python3.6/site-packages/pygqlc/GraphQLClient.py", line 222, in _sub_routing_loop
message = json.loads(self._conn.recv())
File "/home//jsondatasource/venv/lib/python3.6/site-packages/websocket/_core.py", line 310, in recv
opcode, data = self.recv_data()
File "/home//jsondatasource/venv/lib/python3.6/site-packages/websocket/_core.py", line 327, in recv_data
opcode, frame = self.recv_data_frame(control_frame)
File "/home//jsondatasource/venv/lib/python3.6/site-packages/websocket/_core.py", line 340, in recv_data_frame
frame = self.recv_frame()
File "/home//jsondatasource/venv/lib/python3.6/site-packages/websocket/_core.py", line 374, in recv_frame
return self.frame_buffer.recv_frame()
File "/home//jsondatasource/venv/lib/python3.6/site-packages/websocket/_abnf.py", line 361, in recv_frame
self.recv_header()
File "/home//jsondatasource/venv/lib/python3.6/site-packages/websocket/_abnf.py", line 309, in recv_header
header = self.recv_strict(2)
File "/home//jsondatasource/venv/lib/python3.6/site-packages/websocket/abnf.py", line 396, in recv_strict
bytes = self.recv(min(16384, shortage))
File "/home//jsondatasource/venv/lib/python3.6/site-packages/websocket/_core.py", line 449, in _recv
return recv(self.sock, bufsize)
File "/home/*/jsondatasource/venv/lib/python3.6/site-packages/websocket/_socket.py", line 94, in recv
"Connection is already closed.")
websocket._exceptions.WebSocketConnectionClosedException: Connection is already closed.

[barucAlmaguer]

Hi @jnitin, could you provide a reproduction environment so we can check it out faster?
A repo with a minimal setup to reproduce the bug
It seems like the server closed the connection, but I have to do some tests to be sure.

Also, Do you have additional information about the environment in which this issue arised?
I had this kind of issues when my computer went to sleep or I enabled / disabled the internet access and they were solved.
Maybe you can find a way to reproduce the bug without having to wait that much time

[jnitin]

Apologies for late response.

Few Details:-

OS :- Ubuntu 18.04
Python :- 3.6

Regarding server access it may not be possible but i can try to debug . Please inform me what details i need to collect to further debug this issue.

Now it is getting reproduced very frequently within 10-15 mins .

Maybe server closed the connection . But as per understanding client should try to reconnect to the server again since this issue is not reproduced with Altair client .

https://altair.sirmuel.design/

Query :-
As application subscribes to the event callbacks , and exception occurs internally , is it possible to propagate the exception to application so that application can try to again reconnect ?

Thanks for response .

Regards

[jnitin]

Hi

After further debugging , it seems that _bytes = 0 because server closed the connection and because of that exception is raised.

def recv(sock, bufsize):

bytes_ = sock.recv(bufsize)
....

if not bytes_:
    **raise WebSocketConnectionClosedException(
        "Connection is already closed.")**

However WebSocketConnectionClosedException is not handled in def _sub_routing_loop(self): function at below place:-

  try:
    message = json.loads(self._conn.recv())
  except TimeoutError as e:
    print('Timeout for WSS message exceeded...')
    print(f'original message: {e}')
    self.wss_conn_halted = True
    continue
  **except websocket.WebSocketConnectionClosedException as e:
    print(f'original message: {e}')
    self.wss_conn_halted = True
    continue**

Here even though TimeoutError is handled but WebSocketConnectionClosedException is not handled .

For Timeout error as we are trying to reconnect to the server , can we do similar handling in case of WebSocketConnectionClosedException as well .

I tried and it seems it works but need confirmation as shown below:-

234.71
227.78
238.3 --> Fine
original message: Connection is already closed. -------> Break . Connection Closed.
Connection halted, attempting reconnection...
WSS Reconnection succeeded, attempting resubscription to lost subs
killing halted subscription (id=1)
stopping subscription 1 on Unsubscribe
Subscription 1 stopped
finished resubscriptions
original message: Connection is already closed.
Connection halted, attempting reconnection...
WSS Reconnection succeeded, attempting resubscription to lost subs --> Reconnection
killing halted subscription (id=1)
stopping subscription 1 on Unsubscribe
Subscription 1 stopped
finished resubscriptions
221.02 -- > Again subscriptions started .
229.48
238.3

Please let me know it this approach is fine or does it have any side effects.

Also is there any way to stop print messages from GraphQLClient.py and instead to redirect to logs .

Best Regards/

[jnitin]

With the above change tested continuously for more than 5 hours and even though multiple times closed connection is observed but every time reconnected and working fine now .

Also this issue was observed on Windows as well and not platform specific.

Is it possible to disable print logs ?

Regards

[barucAlmaguer]

@jnitin Hi, sorry for the late response,
yesterday we released a new version including the websocket.WebSocketConnectionClosedException being handled,
can you try to update to version 1.2.0 and let us know if this solves the issue for you?

Just instead of:

except TimeoutError as e:
    print('Timeout for WSS message exceeded...')
    print(f'original message: {e}')
    self.wss_conn_halted = True
    continue
  except websocket.WebSocketConnectionClosedException as e:
    print(f'original message: {e}')
    self.wss_conn_halted = True
    continue

as you suggested, we did:

except (TimeoutError, websocket.WebSocketConnectionClosedException) as e:
    print('Timeout for WSS message exceeded...')
    print(f'original message: {e}')
    self.wss_conn_halted = True
    continue

Which is practically the same behaviour

[barucAlmaguer]

Also, thanks for the suggestion about enabling / disabling the logs, I'll add it to the backlog, and come back to you when implemented.

It's not a priority for us, but it would help in make the project which use this library have cleaner logs.

What I was thinking would be a nice implementation would be an optional logger parameter in the constructor, which could be None by default (no prints at all), or a function which would be called to print the messages (simplest one, the print function).

As long as the function receives a string as first parameter, it should work great (we use custom Logging functions in other projects, which prepend the current Date and other information, and making this library compatible with those loggers would be great)