PeerConnectionLost during stream_transport_messages

[carver]

What is wrong?

Similar to but distinct from #1767 :

   DEBUG  07-06 22:15:20  async_process_runner.py  b'  Traceback (most recent call last):\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'    File "/home/circleci/repo/p2p/transport.py", line 236, in read\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'      return await asyncio.wait_for(self._reader.readexactly(n), timeout=CONN_IDLE_TIMEOUT)\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'    File "/usr/local/lib/python3.7/asyncio/tasks.py", line 442, in wait_for\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'      return fut.result()\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'    File "/usr/local/lib/python3.7/asyncio/streams.py", line 677, in readexactly\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'      raise IncompleteReadError(incomplete, n)\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'  asyncio.streams.IncompleteReadError: 0 bytes read on a total of 32 expected bytes\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'  The above exception was the direct cause of the following exception:\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'  Traceback (most recent call last):\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'    File "/home/circleci/repo/.tox/py37-wheel-cli/lib/python3.7/site-packages/async_service/base.py", line 300, in _run_and_manage_task\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'      await task.run()\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'    File "/home/circleci/repo/.tox/py37-wheel-cli/lib/python3.7/site-packages/async_service/asyncio.py", line 35, in run\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'      await self._async_fn(*self._async_fn_args)\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'    File "/home/circleci/repo/p2p/connection.py", line 187, in _feed_protocol_handlers\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'      async for cmd in self._multiplexer.stream_protocol_messages(protocol):\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'    File "/home/circleci/repo/p2p/multiplexer.py", line 273, in _stream_protocol_messages\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'      self.raise_if_streaming_error()\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'    File "/home/circleci/repo/p2p/multiplexer.py", line 314, in raise_if_streaming_error\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'      raise err\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'    File "/home/circleci/repo/.tox/py37-wheel-cli/lib/python3.7/site-packages/async_service/base.py", line 300, in _run_and_manage_task\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'      await task.run()\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'    File "/home/circleci/repo/.tox/py37-wheel-cli/lib/python3.7/site-packages/async_service/asyncio.py", line 35, in run\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'      await self._async_fn(*self._async_fn_args)\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'    File "/home/circleci/repo/p2p/connection.py", line 187, in _feed_protocol_handlers\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'      async for cmd in self._multiplexer.stream_protocol_messages(protocol):\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'    File "/home/circleci/repo/p2p/multiplexer.py", line 273, in _stream_protocol_messages\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'      self.raise_if_streaming_error()\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'    File "/home/circleci/repo/p2p/multiplexer.py", line 314, in raise_if_streaming_error\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'      raise err\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'    File "/home/circleci/repo/p2p/multiplexer.py", line 328, in _do_multiplexing\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'      await self._handle_commands(msg_stream)\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'    File "/home/circleci/repo/p2p/multiplexer.py", line 340, in _handle_commands\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'      async for protocol, cmd in msg_stream:\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'    File "/home/circleci/repo/p2p/multiplexer.py", line 56, in stream_transport_messages\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'      msg = await transport.recv()\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'    File "/home/circleci/repo/p2p/transport.py", line 244, in recv\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'      header_bytes = await self.read(HEADER_LEN + MAC_LEN)\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'    File "/home/circleci/repo/p2p/transport.py", line 238, in read\n'
   DEBUG  07-06 22:15:20  async_process_runner.py  b'      raise PeerConnectionLost(f"Lost connection to {self.remote}") from err\n'

from this PR run.

#1750 seems to touch similar code, so maybe it's related?

How can it be fixed

🤷‍♂️ I guess catch the connection lost in Multiplexer._do_multiplexing() next to the TimeoutError. It doesn't seem like a big problem, and that we can just stop streaming the messages, but I may be missing something:

trinity/p2p/multiplexer.py

Lines 327 to 334 in e7f3a27

	try:
	await self._handle_commands(msg_stream)
	except asyncio.TimeoutError as exc:
	self.logger.warning(
	"Timed out waiting for command from %s, exiting...", self,)
	self.logger.debug("Timeout %r: %s", self, exc, exc_info=True)
	finally:
	await self.close()

[carver]

Thoughts @gsalgado ?

[carver]

I added 7214f67 to #1844 which is the PR where I first noticed the error in CI.

[gsalgado]

I think it'd make more sense to catch it in

trinity/p2p/multiplexer.py

Line 56 in 1f50ff8

msg = await transport.recv()

and return. That has the same effect but will also ensure other callsites of stream_transport_messages() won't have the same issue