websocket close after x-times

[cuongitl]

debug log:

[cuongitl]

{"type": "info", "code": 20001, "msg": "Server restarting, please reconnect"}

[Drotak]

I also stumbled across this and realized after some debugging that there are a view issues here. For debugging I just simulated a connection loss with removing my lan cable.

First thing is, that _after_reconnect() method gets called directly after connect() is called in the _run_reconnect() method.
This occurs in an endless loop because inside the send_msg() method self.ws is None and therefore it sleeps forever.

Also inside the _readloop() method the code runs directly into the second if after the first reconnect try (which fails with a RuntimeError which is not network related) and in _wait_for_reconnect() we have again a endless sleeping loop.

if self.ws_state == WSListenerState.RECONNECTING:
    await self._run_reconnect()
if not self.ws or self.ws_state != WSListenerState.STREAMING:
    await self._wait_for_reconnect()
    break

[Drotak]

debug log:

This error seems to occur when the TCP connection was lost, please see: https://websockets.readthedocs.io/en/latest/howto/faq.html#what-does-connectionclosederror-no-close-frame-received-or-sent-mean

But as you can see my message above, the reconnecting of the library has some bugs.

[Drotak]

@wanth1997
Okay, so far I have found that an exception gets raised and it doesn't matter if I'm connected to the internet or not.

The exception is raised in line 83 in the connect() method, when trying to call __aenter__ from the websocket:

83    self.ws = await self._conn.__aenter__()

I get an RuntimeError: cannot schedule new futures after shutdown Error and I'm unsure why this is happening...

[cuongitl]

This code stream.py similar to python-binance package, but that package didn't have the issue like this.
So, I think the problem by ftx-api, they disconnected the connection after x-times.
I'm trying caching more logs to debug this, I'm sure this issue's not related to network because I'm try websocket with some accounts at same time, the issue with one of them, not all.

[wanth1997]

Do you guys use the latest version of python-ftx?
I can not reproduce this issue.

My test code:

from ftx import ThreadedWebsocketManager

def on_read(payload):
    print(payload)


API = ""
SECRET = ""

wsm = ThreadedWebsocketManager(API, SECRET)
wsm.start()

# Un-auth subscribe
name = "market_connection"
wsm.start_socket(on_read, socket_name=name)
wsm.subscribe(name, channel="ticker", op="subscribe", market="BTC/USDT")

And I disconnect WebSocket by

$ ps ax | grep <test_code_process>
$ netstat --all --program | grep <pid>
$ sudo tcpkill port <port>

After disconnection, debug log pop out and python-ftx package will resend subscribe request again.

This package used to have reconnecting issue due to the difference in ws connection between Binance and FTX.

[cuongitl]

1/ Yes, latest your packages and FTX sample code have same as this issue.

2/ Please test with private endpoint - need authen. It's diff with public endpoint, it's more than rate-limit.

I'm trying debug this issues more times with a lot of accounts at the same time, because it didn't reproduce so it's not easy to debug.
In my program, I've send the error code via websockets, with a different message - depending on the error code. I'll kill the program and start again if error_code = 1006

I don't know FTX's api have an event like Event: User Data Stream Expired (binance), it's disconnect ws and can't re-connect again?
keep tracking...

[Drotak]

Do you guys use the latest version of python-ftx? I can not reproduce this issue.

My test code:

from ftx import ThreadedWebsocketManager

def on_read(payload):
    print(payload)


API = ""
SECRET = ""

wsm = ThreadedWebsocketManager(API, SECRET)
wsm.start()

# Un-auth subscribe
name = "market_connection"
wsm.start_socket(on_read, socket_name=name)
wsm.subscribe(name, channel="ticker", op="subscribe", market="BTC/USDT")

And I disconnect WebSocket by

$ ps ax | grep <test_code_process>
$ netstat --all --program | grep <pid>
$ sudo tcpkill port <port>

After disconnection, debug log pop out and python-ftx package will resend subscribe request again.

This package used to have reconnecting issue due to the difference in ws connection between Binance and FTX.

I have tried exactly your code, and also downloaded and replaced all files from the python-ftx package, killed the tcp port with your command and it works if you terminate the tcpkill immediately after execution, but it still won't work if you let the tcpkill run for multiple seconds (greater then _get_reconnect_wait time).
I'm using python 3.9 and a venv environment, also tried it with python 3.8 and it doesn't work there either.
I would expect that the connection gets established again, even if my connection was lost for multiple minutes. I have debugged the code and it runs into an endless loop in line 98 and 99 when the connection was lost for more seconds then defined in _get_reconnect_wait.

[Drotak]

I recognized now that even the reconnect inside the x seconds from get_reconnect_wait does not work with python3.9 but with python3.8 it works - the issue after the x seconds is the same for both versions

$ python3.8 --version
python 3.8.10
$ python3.8 -m venv .env-3.8
$ source .env-3.8/bin/activate
$ python3.8 -m pip install pip --upgrade
$ python3.8 -m pip install python-ftx
Collecting python-ftx
  Using cached python_ftx-0.1.0-py3-none-any.whl (9.6 kB)
$ python3.8 test_python_ftx.py

(.env-3.8) x@y:~$ python3.8 test_python_ftx.py 
{'type': 'subscribed', 'channel': 'ticker', 'market': 'BTC/USDT'}
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30112.0, 'ask': 30113.0, 'bidSize': 0.0484, 'askSize': 1.088, 'last': 30112.0, 'time': 1654779701.4490976}}
...
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30116.0, 'ask': 30117.0, 'bidSize': 0.173, 'askSize': 0.905, 'last': 30112.0, 'time': 1654779705.8852828}}
2022-06-09 15:01:46.034 | DEBUG    | ftx.streams:_read_loop:154 - connection close error (no close frame received or sent)
2022-06-09 15:01:46.035 | DEBUG    | ftx.streams:_run_reconnect:175 - websocket reconnecting. 4 reconnects left - waiting 1
{'type': 'subscribed', 'channel': 'ticker', 'market': 'BTC/USDT'}
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30116.0, 'ask': 30117.0, 'bidSize': 0.173, 'askSize': 0.905, 'last': 30116.0, 'time': 1654779708.2324839}}
...
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30116.0, 'ask': 30117.0, 'bidSize': 0.173, 'askSize': 0.905, 'last': 30116.0, 'time': 1654779709.9822464}}
2022-06-09 15:01:50.388 | DEBUG    | ftx.streams:_read_loop:154 - connection close error (no close frame received or sent)
2022-06-09 15:01:50.389 | DEBUG    | ftx.streams:_run_reconnect:175 - websocket reconnecting. 4 reconnects left - waiting 2
^CException ignored in: <module 'threading' from '/usr/lib/python3.8/threading.py'>
Traceback (most recent call last):
  File "/usr/lib/python3.8/threading.py", line 1388, in _shutdown
    lock.acquire()
KeyboardInterrupt: 
(.env-3.8) x@y:~$

After the first reconnect I terminated tcpkill in less then a second, at the second reconnect attempt I terminated it somewhere after 2 seconds.

I also added a debug line inside the endless loop to show you what I mean:

(.env-3.8) x@y:~$$ python3.8 test_python_ftx.py 
2022-06-09 15:08:17.673 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:08:17.773 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:08:17.874 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:08:17.975 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:08:18.076 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:08:18.177 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:08:18.278 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:08:18.378 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:08:18.479 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:08:18.580 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:08:18.681 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:08:18.782 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
{'type': 'subscribed', 'channel': 'ticker', 'market': 'BTC/USDT'}
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30106.0, 'ask': 30107.0, 'bidSize': 0.205, 'askSize': 0.3713, 'last': 30100.0, 'time': 1654780098.987818}}
...
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30091.0, 'ask': 30092.0, 'bidSize': 0.183, 'askSize': 0.6766, 'last': 30095.0, 'time': 1654780121.1944351}}
2022-06-09 15:08:41.367 | DEBUG    | ftx.streams:_read_loop:155 - connection close error (no close frame received or sent)
2022-06-09 15:08:41.368 | DEBUG    | ftx.streams:_run_reconnect:176 - websocket reconnecting. 4 reconnects left - waiting 2
{'type': 'subscribed', 'channel': 'ticker', 'market': 'BTC/USDT'}
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30089.0, 'ask': 30090.0, 'bidSize': 0.0003, 'askSize': 1.0406, 'last': 30090.0, 'time': 1654780124.601516}}
...
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30089.0, 'ask': 30090.0, 'bidSize': 0.0003, 'askSize': 1.0406, 'last': 30090.0, 'time': 1654780127.859942}}
2022-06-09 15:08:48.052 | DEBUG    | ftx.streams:_read_loop:155 - connection close error (no close frame received or sent)
2022-06-09 15:08:48.053 | DEBUG    | ftx.streams:_run_reconnect:176 - websocket reconnecting. 4 reconnects left - waiting 2
2022-06-09 15:08:50.330 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:08:50.431 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
...
2022-06-09 15:08:54.967 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:08:55.067 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
^CException ignored in: <module 'threading' from '/usr/lib/python3.8/threading.py'>
Traceback (most recent call last):
  File "/usr/lib/python3.8/threading.py", line 1388, in _shutdown
    lock.acquire()
KeyboardInterrupt: 
(.env-3.8) x@y:~$$

I did also the same for 3.9:

$ python --version
Python 3.9.5
$ python -m venv .env-3.9
$ source .env-3.9/bin/activate
$ python -m pip install pip --upgrade
$ python -m pip install python-ftx
Collecting python-ftx
  Using cached python_ftx-0.1.0-py3-none-any.whl (9.6 kB)
$ python test_python_ftx.py

(.env-3.9) x@y:~$ python test_python_ftx.py
2022-06-09 15:32:20.517 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:20.618 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:20.719 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:20.819 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:20.920 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:21.020 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:21.121 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:21.222 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:21.323 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:21.424 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:21.524 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
{'type': 'subscribed', 'channel': 'ticker', 'market': 'BTC/USDT'}
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30156.0, 'ask': 30166.0, 'bidSize': 1.055, 'askSize': 0.3794, 'last': 30165.0, 'time': 1654781541.670454}}
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30156.0, 'ask': 30165.0, 'bidSize': 1.055, 'askSize': 2.42, 'last': 30165.0, 'time': 1654781541.712883}}
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30156.0, 'ask': 30163.0, 'bidSize': 0.0985, 'askSize': 0.315, 'last': 30165.0, 'time': 1654781541.7540214}}
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30156.0, 'ask': 30163.0, 'bidSize': 0.0985, 'askSize': 0.63, 'last': 30165.0, 'time': 1654781541.8063982}}
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30156.0, 'ask': 30162.0, 'bidSize': 0.0985, 'askSize': 0.205, 'last': 30165.0, 'time': 1654781541.8488243}}
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30156.0, 'ask': 30162.0, 'bidSize': 0.0985, 'askSize': 0.205, 'last': 30165.0, 'time': 1654781541.8745914}}
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30156.0, 'ask': 30162.0, 'bidSize': 0.0985, 'askSize': 0.205, 'last': 30165.0, 'time': 1654781541.8952937}}
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30155.0, 'ask': 30162.0, 'bidSize': 0.183, 'askSize': 0.205, 'last': 30165.0, 'time': 1654781541.9145646}}
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30157.0, 'ask': 30161.0, 'bidSize': 0.205, 'askSize': 0.183, 'last': 30165.0, 'time': 1654781541.9410224}}
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30157.0, 'ask': 30161.0, 'bidSize': 0.205, 'askSize': 0.183, 'last': 30165.0, 'time': 1654781541.9665794}}
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30157.0, 'ask': 30161.0, 'bidSize': 0.205, 'askSize': 0.183, 'last': 30165.0, 'time': 1654781541.9910307}}
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30157.0, 'ask': 30160.0, 'bidSize': 0.205, 'askSize': 0.205, 'last': 30165.0, 'time': 1654781542.0156908}}
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30157.0, 'ask': 30160.0, 'bidSize': 0.205, 'askSize': 0.205, 'last': 30165.0, 'time': 1654781542.0468142}}
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30157.0, 'ask': 30160.0, 'bidSize': 0.205, 'askSize': 0.205, 'last': 30165.0, 'time': 1654781542.0661697}}
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30157.0, 'ask': 30160.0, 'bidSize': 0.205, 'askSize': 0.205, 'last': 30165.0, 'time': 1654781542.1153436}}
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30157.0, 'ask': 30160.0, 'bidSize': 0.205, 'askSize': 0.205, 'last': 30165.0, 'time': 1654781542.1662219}}
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30157.0, 'ask': 30160.0, 'bidSize': 0.205, 'askSize': 0.205, 'last': 30165.0, 'time': 1654781542.1902475}}
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30157.0, 'ask': 30160.0, 'bidSize': 0.205, 'askSize': 0.205, 'last': 30165.0, 'time': 1654781542.214468}}
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30157.0, 'ask': 30160.0, 'bidSize': 0.205, 'askSize': 0.205, 'last': 30165.0, 'time': 1654781542.2381294}}
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30157.0, 'ask': 30160.0, 'bidSize': 0.205, 'askSize': 0.205, 'last': 30165.0, 'time': 1654781542.3152568}}
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30155.0, 'ask': 30160.0, 'bidSize': 0.183, 'askSize': 0.205, 'last': 30165.0, 'time': 1654781542.3401287}}
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30155.0, 'ask': 30160.0, 'bidSize': 0.183, 'askSize': 0.205, 'last': 30165.0, 'time': 1654781542.390056}}
{'channel': 'ticker', 'market': 'BTC/USDT', 'type': 'update', 'data': {'bid': 30156.0, 'ask': 30159.0, 'bidSize': 0.0033, 'askSize': 0.945, 'last': 30165.0, 'time': 1654781542.4241927}}
2022-06-09 15:32:22.581 | DEBUG    | ftx.streams:_read_loop:155 - connection close error (no close frame received or sent)
2022-06-09 15:32:22.582 | DEBUG    | ftx.streams:_run_reconnect:176 - websocket reconnecting. 4 reconnects left - waiting 2
2022-06-09 15:32:24.685 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:24.786 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:24.886 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:24.987 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:25.088 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:25.189 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:25.290 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:25.391 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:25.491 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:25.592 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:25.693 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:25.794 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:25.894 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:25.995 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:26.096 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:26.197 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:26.298 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:26.398 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:26.499 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:26.600 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:26.701 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:26.802 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:26.902 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:27.003 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:27.104 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:27.205 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:27.306 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:27.406 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:27.507 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:27.607 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
2022-06-09 15:32:27.708 | DEBUG    | ftx.streams:send_msg:100 - endless loop...
^CException ignored in: <module 'threading' from '/usr/lib/python3.9/threading.py'>
Traceback (most recent call last):
  File "/usr/lib/python3.9/threading.py", line 1428, in _shutdown
    lock.acquire()
KeyboardInterrupt: 
(.env-3.9) x@y:~$

I terminated tcpkill in less then a second, but no reconnection was established

[Drotak]

Just for clarification, this is inside test_python_ftx.py:

from ftx import ThreadedWebsocketManager

def on_read(payload):
    print(payload)


API = ""
SECRET = ""

wsm = ThreadedWebsocketManager(API, SECRET)
wsm.start()

# Un-auth subscribe
name = "market_connection"
wsm.start_socket(on_read, socket_name=name)
wsm.subscribe(name, channel="ticker", op="subscribe", market="BTC/USDT")

[cuongitl]

Python's env for test:

• python 3.10.0
• python 3.9.13
• python 3.8.12

OS:

• Windows 11
• Rocky Linux release 8.4 (Green Obsidian)

FTX's api:

• Auth subscribe: private_connection
• channel:
  • orders
  • fills

Number of FTX's accounts: 12

All of them(env/os/accounts...) have the same this issue, but it doesn't happen often so it's hard to debug.

p/s: I'm developing copytrade system so I need to test a lot.

[wanth1997]

@Drotak
Plz test with the latest version 0.1.1
https://pypi.org/project/python-ftx/0.1.1/

[Drotak]

@Drotak Plz test with the latest version 0.1.1 https://pypi.org/project/python-ftx/0.1.1/

I have installed v0.1.2 now and tested it with your example. Now it seems to work like expected!
I'll test it with my program for the next week and I'll report back if I recognize any issues.