ping pong over websocket in ringserver

crotwell commented 3 years ago

Default python websockets send a PING periodically to keep a websocket connection alive. When this happens, ringserver appears to close the connection.

Would be nice if ringserver dali over websocket allowed PING-PONG.

Spec stuff here: https://www.rfc-editor.org/rfc/rfc6455.html#section-5.5.2

If not, would be good if it could log the close with a reason in the server side logging. Currently I get a disconnet but no reason or even info that that a bad command was sent:

Tue Oct 26 15:42:56 2021 - Server thread (Listen) 6094106624 Flags: ACTIVE
Tue Oct 26 15:42:56 2021 - Server thread (Listen) 6094680064 Flags: ACTIVE
Tue Oct 26 15:42:56 2021 - Client thread 6095253504 Flags: ACTIVE
Tue Oct 26 15:42:56 2021 - Client connections: 1
Tue Oct 26 15:42:56 2021 - Client disconnected: localhost
Tue Oct 26 15:42:57 2021 - Server thread (Listen) 6094106624 Flags: ACTIVE
Tue Oct 26 15:42:57 2021 - Server thread (Listen) 6094680064 Flags: ACTIVE
Tue Oct 26 15:42:57 2021 - Client thread 6095253504 Flags: CLOSED
Tue Oct 26 15:42:57 2021 - Removing client thread 6095253504 from the cthreads list
Tue Oct 26 15:42:57 2021 - Client connections: 0

and on the python side I get a frame error, I think because the websocket doesn't go through a normal shutdown sequence.


Stream
DEBUG:websockets.client:%% sending keepalive ping
DEBUG:websockets.client:> PING 4e 49 9a 74 [binary, 4 bytes]
DEBUG:websockets.client:! failing connection with code 1002
DEBUG:websockets.client:= connection is CLOSING
DEBUG:websockets.client:> CLOSE 1002 (protocol error) [2 bytes]
DEBUG:websockets.client:= connection is CLOSED
Traceback (most recent call last):
  File "/opt/homebrew/Caskroom/miniforge/base/envs/simpledali/lib/python3.9/site-packages/websockets/legacy/protocol.py", line 944, in transfer_data
    message = await self.read_message()
  File "/opt/homebrew/Caskroom/miniforge/base/envs/simpledali/lib/python3.9/site-packages/websockets/legacy/protocol.py", line 1013, in read_message
    frame = await self.read_data_frame(max_size=self.max_size)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/simpledali/lib/python3.9/site-packages/websockets/legacy/protocol.py", line 1089, in read_data_frame
    frame = await self.read_frame(max_size)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/simpledali/lib/python3.9/site-packages/websockets/legacy/protocol.py", line 1144, in read_frame
    frame = await Frame.read(
  File "/opt/homebrew/Caskroom/miniforge/base/envs/simpledali/lib/python3.9/site-packages/websockets/legacy/framing.py", line 85, in read
    raise ProtocolError("incorrect masking")
websockets.exceptions.ProtocolError: incorrect masking

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

Traceback (most recent call last):
  File "/Users/crotwell/dev/seis/simple-dali/example/readdali.py", line 91, in <module>
    asyncio.run(main(host, port, verbose=True), debug=debug)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/simpledali/lib/python3.9/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/simpledali/lib/python3.9/asyncio/base_events.py", line 642, in run_until_complete
    return future.result()
  File "/Users/crotwell/dev/seis/simple-dali/example/readdali.py", line 84, in main
    await stream_data(dali)
  File "/Users/crotwell/dev/seis/simple-dali/example/readdali.py", line 24, in stream_data
    daliPacket = await dali.parseResponse()
  File "/opt/homebrew/Caskroom/miniforge/base/envs/simpledali/lib/python3.9/site-packages/simpledali/websocketdali.py", line 50, in parseResponse
    response = await self.ws.recv()
  File "/opt/homebrew/Caskroom/miniforge/base/envs/simpledali/lib/python3.9/site-packages/websockets/legacy/protocol.py", line 552, in recv
    await self.ensure_open()
  File "/opt/homebrew/Caskroom/miniforge/base/envs/simpledali/lib/python3.9/site-packages/websockets/legacy/protocol.py", line 929, in ensure_open
    raise self.connection_closed_exc()
websockets.exceptions.ConnectionClosedError: sent 1002 (protocol error); no close frame received

Note this is in STREAM mode, but where no data is flowing. The Datalink protocol says:

No client commands are accepted in streaming mode except ID requests

so techinically this is ok by websockets, but prohibited by datalink. I think it would be good to handle when doing web sockets, and maybe allow PING-PONG for normal sockets would be useful too?

chad-earthscope commented 3 years ago

I think it would be good to handle when doing web sockets,

Agreed. Got a repeatable test?

and maybe allow PING-PONG for normal sockets would be useful too?

That is why the ID is an exception, i.e so it can be used for pings.

crotwell commented 3 years ago

Yep, what I meant was once you enable it for websockets, it should be trivial to let a regular socket use the same PING PONG messages. I agree it doesn;t really do anything that ID doesn't, just for consistency between the two types of connections.

crotwell commented 3 years ago

Actually, ping-pong, because it is embedded in the websocket frame doesn't really make sense for plain sockets. Pretend I never said anything about it...

crotwell commented 2 years ago

Repeatable test case would be like readdali.py

Start up an otherwise empty ringserver, edit connection params in readdali.py to connect to it (ie host and port), change line 18-19 in readdali.py so that ping_interval is not None, like ping_interval=5

run readdali.py and wait for 5 seconds, barf will occur.

EarthScope / ringserver

ping pong over websocket in ringserver #33