asyncio.streams.IncompleteReadError: 0 bytes read on a total of 2 expected bytes - unclear error reporting

[vgoklani]

I'm not sure how to fix this error:

  Traceback (most recent call last):
    File "/root/src/streamer/stocks_producer.py", line 44, in <module>
      main()
    File "/root/src/streamer/stocks_producer.py", line 40, in main
      streamer.start()
    File "/root/src/streamer/polygon_streamer.py", line 67, in start
      self.loop.run_until_complete(asyncio.gather(*tasks))
    File "uvloop/loop.pyx", line 1451, in uvloop.loop.Loop.run_until_complete
    File "/root/src/streamer/polygon_streamer.py", line 47, in connect
      raise Exception(error_message)
  Exception: resetting connection: ()
  103 - 2019-02-13 15:30:14,095 - streamer.polygon_streamer - ERROR - resetting connection: ('WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason',)
  Traceback (most recent call last):
    File "/opt/conda/lib/python3.7/site-packages/websockets/protocol.py", line 528, in transfer_data
      msg = yield from self.read_message()
    File "/opt/conda/lib/python3.7/site-packages/websockets/protocol.py", line 580, in read_message
      frame = yield from self.read_data_frame(max_size=self.max_size)
    File "/opt/conda/lib/python3.7/site-packages/websockets/protocol.py", line 645, in read_data_frame
      frame = yield from self.read_frame(max_size)
    File "/opt/conda/lib/python3.7/site-packages/websockets/protocol.py", line 710, in read_frame
      extensions=self.extensions,
    File "/opt/conda/lib/python3.7/site-packages/websockets/framing.py", line 100, in read
      data = yield from reader(2)
    File "/opt/conda/lib/python3.7/asyncio/streams.py", line 677, in readexactly
      raise IncompleteReadError(incomplete, n)
  asyncio.streams.IncompleteReadError: 0 bytes read on a total of 2 expected bytes

here is my code snippet, thank you!

async def connect(self):
	while True:
		async with websockets.connect(self.url, max_queue=8 * 2**10,) as websocket:
			await websocket.send(json.dumps({"action": "auth", "params": self._api_key}))
			await websocket.send(json.dumps({"action": "subscribe", "params": self._symbols_str}))
			log.info("connected: {}".format(websocket.remote_address))
			while(True):
				try:
					message_str = await asyncio.wait_for(websocket.recv(), timeout=self._timeout)
					# await self.queue.put(message_str)
					self.queue.put_nowait(message_str)
				except asyncio.TimeoutError:
					log.warn("timeout error - no data in {} seconds, pinging connection".format(self._timeout))
					pong_waiter = await asyncio.wait_for(websocket.ping(data="keepalive"), timeout=self._timeout)
					await asyncio.wait_for(pong_waiter, timeout=2 * self._timeout)
					log.warn('ping/pong received, keeping connection alive...')
				except Exception as e:
					error_message = "resetting connection: {}".format(e.args)
					log.error(error_message)
					raise Exception(error_message)

[aaugustin]

The remote endpoint closed the connection summarily.

I believe you aren't the first person to be confused by this exception. Perhaps we could make it more user-friendly.

[vgoklani]

Thanks for the reply!
How would I validate that the remote endpoint closed the connection?

I spoke with the vendor, and he claims that the issue is on our end.

I also had this same error when pulling data from coinbase, and they also said that the error was on our end.

[lgrahl]

Wouldn't this be a case for reporting status code 1006?

[...] pulling data from coinbase [...]

Be aware of https://websockets.readthedocs.io/en/stable/contributing.html#bitcoin-users

[aaugustin]

Well there's this in the report (line breaks added)

   103 - 2019-02-13 15:30:14,095 - streamer.polygon_streamer - ERROR - resetting connection: 
        ('WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason',)

So the error 1006 is reported.

That said many websockets users aren't familiar with close codes and won't know what 1006 means.

[vgoklani]

thanks for the response @lgrahl and @aaugustin

would it be possible that the remote closed the connection because the server wasn't processing the requests fast enough? i set the max_queue=8 * 2**10 which should be sufficient (?)

is there a way to get additional logging around the error?

btw, no more bitcoin stuff (it's crashing anyway)

[aaugustin]

This may help: https://websockets.readthedocs.io/en/stable/cheatsheet.html#debugging

[lgrahl]

It looks like this exception sometimes fires into a void. From our production servers:

Time:      2019-04-04 11:25:55
Level:     ERROR
Channel:   asyncio
File:      /usr/lib/python3.7/collections/__init__.py:414
Module:    collections
Function:  _replace

Message:

Future exception was never retrieved
future: <Future finished exception=ConnectionClosed('WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason')>
Traceback (most recent call last):
  File "/var/venv/saltyrtc-server/lib/python3.7/site-packages/websockets/protocol.py", line 674, in transfer_data
    message = yield from self.read_message()
  File "/var/venv/saltyrtc-server/lib/python3.7/site-packages/websockets/protocol.py", line 742, in read_message
    frame = yield from self.read_data_frame(max_size=self.max_size)
  File "/var/venv/saltyrtc-server/lib/python3.7/site-packages/websockets/protocol.py", line 815, in read_data_frame
    frame = yield from self.read_frame(max_size)
  File "/var/venv/saltyrtc-server/lib/python3.7/site-packages/websockets/protocol.py", line 884, in read_frame
    extensions=self.extensions,
  File "/var/venv/saltyrtc-server/lib/python3.7/site-packages/websockets/framing.py", line 99, in read
    data = yield from reader(2)
  File "/usr/lib/python3.7/asyncio/streams.py", line 677, in readexactly
    raise IncompleteReadError(incomplete, n)
asyncio.streams.IncompleteReadError: 0 bytes read on a total of 2 expected bytes

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

websockets.exceptions.ConnectionClosed: WebSocket connection is closed: code = 1006 (connection closed abnormally [internal]), no reason

[gslusarek-cic]

any updates here?

I've got the same issue during connection to server in google cloud so I wonder is it ingress fault (connection through regular nginx works like a charm)

here is the log

2019-07-01 15:51:20,838 websockets.protocol DEBUG    client - state = CONNECTING
2019-07-01 15:51:20,856 websockets.protocol DEBUG    client - event = connection_made(<asyncio.sslproto._SSLProtocolTransport object at 0x10f416978>)
2019-07-01 15:51:20,993 websockets.protocol DEBUG    client - state = OPEN
2019-07-01 15:51:41,000 websockets.protocol DEBUG    client > Frame(fin=True, opcode=9, data=b'5u$\x80', rsv1=False, rsv2=False, rsv3=False)
2019-07-01 15:51:41,118 websockets.protocol DEBUG    client < Frame(fin=True, opcode=10, data=b'5u$\x80', rsv1=False, rsv2=False, rsv3=False)
2019-07-01 15:51:41,118 websockets.protocol DEBUG    client - received solicited pong: 35752480
2019-07-01 15:51:42,490 websockets.protocol DEBUG    client < Frame(fin=True, opcode=9, data=b'QUoi', rsv1=False, rsv2=False, rsv3=False)
2019-07-01 15:51:42,490 websockets.protocol DEBUG    client - received ping, sending pong: 51556f69
2019-07-01 15:51:42,490 websockets.protocol DEBUG    client > Frame(fin=True, opcode=10, data=b'QUoi', rsv1=False, rsv2=False, rsv3=False)
2019-07-01 15:51:50,992 websockets.protocol DEBUG    client - event = eof_received()
2019-07-01 15:51:50,993 websockets.protocol DEBUG    client ! failing WebSocket connection in the OPEN state: 1006 [no reason]
2019-07-01 15:51:50,994 websockets.protocol DEBUG    client - event = connection_lost(None)
2019-07-01 15:51:50,994 websockets.protocol DEBUG    client - state = CLOSED
2019-07-01 15:51:50,994 websockets.protocol DEBUG    client x code = 1006, reason = [no reason]
2019-07-01 15:51:50,995 agent        ERROR    Connection error!
Traceback (most recent call last):
  File "/Users/xxxx/.virtualenvs/aaa-PdF-yTXF/lib/python3.7/site-packages/websockets/protocol.py", line 674, in transfer_data
    message = yield from self.read_message()
  File "/Users/xxx/.pyenv/versions/3.7.3/lib/python3.7/asyncio/coroutines.py", line 58, in __next__
    return self.gen.send(None)
  File "/Users/xxx/.virtualenvs/aaa-PdF-yTXF/lib/python3.7/site-packages/websockets/protocol.py", line 742, in read_message
    frame = yield from self.read_data_frame(max_size=self.max_size)
  File "/Users/xxx/.pyenv/versions/3.7.3/lib/python3.7/asyncio/coroutines.py", line 58, in __next__
    return self.gen.send(None)
  File "/Users/xxx/.virtualenvs/aaa-PdF-yTXF/lib/python3.7/site-packages/websockets/protocol.py", line 815, in read_data_frame
    frame = yield from self.read_frame(max_size)
  File "/Users/xxx/.pyenv/versions/3.7.3/lib/python3.7/asyncio/coroutines.py", line 58, in __next__
    return self.gen.send(None)
  File "/Users/xxx/.virtualenvs/aaa-PdF-yTXF/lib/python3.7/site-packages/websockets/protocol.py", line 884, in read_frame
    extensions=self.extensions,
  File "/Users/xxx/.pyenv/versions/3.7.3/lib/python3.7/asyncio/coroutines.py", line 58, in __next__
    return self.gen.send(None)
  File "/Users/xxx/.virtualenvs/aaa-PdF-yTXF/lib/python3.7/site-packages/websockets/framing.py", line 99, in read
    data = yield from reader(2)
  File "/Users/xxx/.pyenv/versions/3.7.3/lib/python3.7/asyncio/streams.py", line 677, in readexactly
    raise IncompleteReadError(incomplete, n)
asyncio.streams.IncompleteReadError: 0 bytes read on a total of 2 expected bytes

[aaugustin]

I'm not sure which circumstances produce this. It requires investigating.

A deterministic way to reproduce the error would be most helpful, but I know it's an ambitious thing to ask...

[aaugustin]

@gslusarek-cic The TCP connection drops after 30 seconds exactly: it opens at 15:51:20,993 and closes at 15:51:50,992. This can't be an accident. It looks like you're connecting through something that doesn't allow long-lived HTTP connections. 30 seconds is a very common threshold is such cases.

---

@vgoklani If you're able to turn on debug logs like gslusarek-cic did, we could get a hint. Otherwise, if you don't believe me, you can inspect network traffic with wireshark and check that you receive a TCP FIN or RST.

---

@lgrahl Unlike the two other situations discussed here which are on the client side, you are on the server side. I'm going to move it to a separate issue.

---

To sup up, possible next steps on this ticket include:

1. figuring out why this traceback is printed: it should only be recorded in transfer_data_exc and added as the __cause__ of a ConnectionClosed exception.
2. clarifying the error report in that case
3. explaining that situation in the FAQ