Websocket connection timing-out

[sunny-g]

I'm pretty fresh when it comes to programming outside of the standard lib so bear with me:

I instantiated Remote with 'ws://127.0.0.1:6006' as my url and the root's secret as the secret == 'snoPBrXtMeMyMHUVTgbuqAfg1SUTb'

After a few seconds I get this error message:

  File "/usr/local/lib/python2.7/dist-packages/ripple/client.py", line 193, in _read
_proc
    msg = json.loads(self.conn.recv())
  File "/usr/local/lib/python2.7/dist-packages/websocket/__init__.py", line 633, in
recv
    opcode, data = self.recv_data()
  File "/usr/local/lib/python2.7/dist-packages/websocket/__init__.py", line 646, in
recv_data
    frame = self.recv_frame()
  File "/usr/local/lib/python2.7/dist-packages/websocket/__init__.py", line 720, in
recv_frame
    self._frame_header = self._recv_strict(2)
  File "/usr/local/lib/python2.7/dist-packages/websocket/__init__.py", line 829, in
_recv_strict
    bytes = self._recv(shortage)
  File "/usr/local/lib/python2.7/dist-packages/websocket/__init__.py", line 815, in
_recv
    raise WebSocketTimeoutException(e.message)
WebSocketTimeoutException: timed out

Exception in thread Thread-2:
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 551, in __bootstrap_inner
    self.run()
  File "/usr/lib/python2.7/threading.py", line 504, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/usr/local/lib/python2.7/dist-packages/ripple/client.py", line 380, in _read
_proc
    msg = queue.get(timeout=0.2)
  File "/usr/local/lib/python2.7/dist-packages/ripple/client.py", line 88, in get
    raise result
WebSocketTimeoutException: timed out

Calling any method of the Remote object after this error gives me the following error, which I assume has to do with the connection being lost/timed out:

>>> cliobj.account_info(rootAddress)
Traceback (most recent call last):
  File "<input>", line 1, in <module>
  File "/usr/local/lib/python2.7/dist-packages/ripple/client.py", line 428, in accou
nt_info
    info = self.client.request_account_info(account)
  File "/usr/local/lib/python2.7/dist-packages/ripple/client.py", line 307, in reque
st_account_info
    return self.execute("account_info", account=account)['account_data']
  File "/usr/local/lib/python2.7/dist-packages/ripple/client.py", line 244, in execu
te
    self.conn.send(json.dumps(data, cls=RippleEncoder))
  File "/usr/local/lib/python2.7/dist-packages/websocket/__init__.py", line 579, in
send
    return self.send_frame(frame)
  File "/usr/local/lib/python2.7/dist-packages/websocket/__init__.py", line 603, in
send_frame
    l = self._send(data)
  File "/usr/local/lib/python2.7/dist-packages/websocket/__init__.py", line 802, in
_send
    return self.sock.send(data)
  File "/usr/lib/python2.7/socket.py", line 170, in _dummy
    raise error(EBADF, 'Bad file descriptor')
error: [Errno 9] Bad file descriptor

I'm still learning the ropes of reading through code and documentation to come up with fixes (it took me a while just to figure out the right url), but this is a little over my head, or at least I don't know how to approach it.

Any help at all would be greatly appreciated.

[miracle2k]

Does it receive any messages successfully before the error comes up? I wonder if the server returns an error like "too busy" before cutting the connection, but for some reason you don't output it and/or the library doesn't recognize it right. You could try to enable the debug log to see this (https://github.com/miracle2k/ripple-python/blob/master/ripple/client.py#L199), if not already the case.

[sunny-g]

Yes, if you send the account_info command before the timeout message, it returns the correct response. Then, if you run it again after the error, you get the same aforementioned error.

I don't know exactly what you mean about enabling the debug log with that line, but if I create a Client object with the same url and run cliobj._read_proc(), it hangs for exactly 30 seconds and then returns the same WebsocketTimeoutException error, followed by this error:

Traceback (most recent call last):
  File "<input>", line 1, in <module>
  File "/usr/local/lib/python2.7/dist-packages/ripple/client.py", line 193, in _read
_proc
    msg = json.loads(self.conn.recv())
  File "/usr/local/lib/python2.7/dist-packages/websocket/__init__.py", line 633, in
recv
    opcode, data = self.recv_data()
  File "/usr/local/lib/python2.7/dist-packages/websocket/__init__.py", line 646, in
recv_data
    frame = self.recv_frame()
  File "/usr/local/lib/python2.7/dist-packages/websocket/__init__.py", line 720, in
recv_frame
    self._frame_header = self._recv_strict(2)
  File "/usr/local/lib/python2.7/dist-packages/websocket/__init__.py", line 829, in
_recv_strict
    bytes = self._recv(shortage)
  File "/usr/local/lib/python2.7/dist-packages/websocket/__init__.py", line 822, in
_recv
    raise WebSocketConnectionClosedException()
WebSocketConnectionClosedException

I enabled "debug" logging in the rippled.cfg, and got this in the rippled prompt after I created cliobj:

2014-May-14 21:45:17 WebSocket:DBG WebSocket Connection 127.0.0.1:39639 v13 NULL / 101
2014-May-14 21:45:17 ResourceManager:DBG New admin endpoint "127.0.0.1:39639"
2014-May-14 21:45:17 WSConnection:DBG Websocket connection from 127.0.0.1:39639
2014-May-14 21:45:17 WSServerHandler:DBG Ws:: on_open(127.0.0.1:39639)
2014-May-14 21:45:47 WSServerHandler:DBG Ws:: on_close(127.0.0.1:39639) found
2014-May-14 21:45:47 WebSocket:DBG Disconnect  close local:[1000] remote:[1000]
2014-May-14 21:45:47 ResourceManager:DBG Inactive "127.0.0.1:39639"

The same occurs if cliobj is an instance of ripple.Remote, but with some additional messages:

2014-May-14 21:59:03 WebSocket:DBG WebSocket Connection 127.0.0.1:39644 v13 NULL / 101
2014-May-14 21:59:03 ResourceManager:DBG New admin endpoint "127.0.0.1:39644"
2014-May-14 21:59:03 WSConnection:DBG Websocket connection from 127.0.0.1:39644
2014-May-14 21:59:03 WSServerHandler:DBG Ws:: on_open(127.0.0.1:39644)
2014-May-14 21:59:03 WSServerHandler:DBG Ws:: Receiving(127.0.0.1:39644) '{"streams": ["server", "transactions"], "command": "subscribe", "id": 1}'
2014-May-14 21:59:03 WSServerHandler:DBG Ws:: Sending '{"id":1,"result":{"load_base":256,"load_factor":256,"random":"9AC49F12E0F6F64AECDC6D368145233A68AC14810F4965090E6E40F9E1843A05","server_status":"full","stand_alone":true},"status":"success","type":"response"}'
2014-May-14 21:59:33 WSServerHandler:DBG Ws:: on_close(127.0.0.1:39644) found
2014-May-14 21:59:33 WebSocket:DBG Disconnect  close local:[1000] remote:[1000]
2014-May-14 21:59:33 ResourceManager:DBG Inactive "127.0.0.1:39644"

Where would rippled be receiving the on_close command from?

[sunny-g]

As it turns out (in retrospect, pretty obviously) that when we create a object of class Client, we set a 30 second timeout on the websocket connection, which would trigger an on_close event. I see that you've left a comment about dealing with pinging and timeouts later; so for now, what would be the danger in removing the timeout since receiving requests and responses within the timeout time doesn't stop the connection from closing?

[miracle2k]

I don't remember why I picked 30. I might have only wanted a connect timeout. I find it strange though that the timeout would be triggered despite traffic.

In any case, I want significantly refactor the whole thing in the near future, and would probably look closer at the issue then.

[sunny-g]

Sounds good, thanks for getting back to me. If I can help in any way, let me know.