MalformedMessage during handshake on seemingly valid Hello msg
gsalgado opened this issue · 6 comments
I'm seeing lots of unexpected errors during handshake like the following:
WARNING 2020-09-21 08:39:19,080 Transport Deserializing list length (1) does not match sedes (2) decoding header (b'\x00\x00\xa2\xc1\x80\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00'), (body=b'\x80\xf8\x9f\x05\xb8>Nethermind/v1.8.103-0-6bc67f44b-20200917/X64-Windows/Core3.1.5\xd8\xc5\x83eth>\xc5\x83eth?\xc5\x83eth@\xc5\x83ethA\x82v_\xb8@7\x1a\xe0\xd0\x073\x88\xeb\xd2\xb1\xa5e\xc2]\x145\x1e}\xdd\xbb\x8ee[\x8a*\x12\xbe\xda\xc2^\x1e\x1c\x94\x1f\xf3}\x89\xb2\xfd\xa1+J\xc7\x8b\x18c\x7f\xff\xf8Ub\xe3/\xf0\xc5\x1a\xd8\xbd\xc0t\xa0\x97\xae\xb1'), command_id=0)
ERROR 2020-09-21 08:39:19,080 FullServer Unexpected error handling handshake with ('82.26.85.206', 65335)
Traceback (most recent call last):
File "/home/salgado/src/snakecharmers/trinity/p2p/transport.py", line 264, in recv
header_data = _decode_header_data(padded_header[3:])
File "/home/salgado/src/snakecharmers/trinity/p2p/transport.py", line 59, in _decode_header_data
header_data = rlp.decode(data, sedes=HEADER_DATA_SEDES, strict=False)
File "/home/salgado/virtualenvs/trinity/lib/python3.8/site-packages/rlp/codec.py", line 228, in decode
obj = sedes.deserialize(item, **kwargs)
File "/home/salgado/virtualenvs/trinity/lib/python3.8/site-packages/eth_utils/functional.py", line 45, in inner
return callback(fn(*args, **kwargs))
File "/home/salgado/virtualenvs/trinity/lib/python3.8/site-packages/rlp/sedes/lists.py", line 86, in deserialize
raise ListDeserializationError(
rlp.exceptions.ListDeserializationError: Deserializing list length (1) does not match sedes (2)
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/home/salgado/src/snakecharmers/trinity/trinity/server.py", line 132, in receive_handshake
await self._receive_handshake(reader, writer)
File "/home/salgado/src/snakecharmers/trinity/trinity/server.py", line 152, in _receive_handshake
connection = await receive_dial_in(
File "/home/salgado/src/snakecharmers/trinity/p2p/handshake.py", line 373, in receive_dial_in
multiplexer, devp2p_receipt, protocol_receipts = await negotiate_protocol_handshakes(
File "/home/salgado/src/snakecharmers/trinity/p2p/handshake.py", line 229, in negotiate_protocol_handshakes
devp2p_receipt, base_protocol = await _do_p2p_handshake(
File "/home/salgado/src/snakecharmers/trinity/p2p/handshake.py", line 138, in _do_p2p_handshake
async for _, cmd in stream_transport_messages(transport, base_protocol):
File "/home/salgado/src/snakecharmers/trinity/p2p/multiplexer.py", line 64, in stream_transport_messages
msg = await transport.recv()
File "/home/salgado/src/snakecharmers/trinity/p2p/transport.py", line 270, in recv
raise MalformedMessage(*err.args) from err
p2p.exceptions.MalformedMessage: Deserializing list length (1) does not match sedes (2)
However, if we skip the decoding/re-encoding of the header data (
Lines 262 to 266 in 46067fd
>>> proto = BaseP2PProtocol(None, 0, False)
>>> cmd_type = proto.get_command_type_for_command_id(0)
>>> m = Message(b'\x00\x00\xa0\xc1\x80\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00', b'\x80\xf8\x9d\x05\xb8<Nethermind/v1.8.105-0-bb0125f1a-20200920/X64-Linux/Core3.1.5\xd8\xc5\x83eth>\xc5\x83eth?\xc5\x83eth@\xc5\x83ethA\x82v_\xb8@\xa1\x11\xcc\xbf\xedJ\x06`\xf9\x86Ux\xaf\xd3~\xc0s0\xc7\xe0$\xe9\x18\x0c\xf8\xe5\x13)\x1a\xec4\xc3\xcc\xf4\x87\xfc>\x0c\xc0{\x0b\xb0\xb6\xc5\xe0l\xea\x01\xe8\xa2w)\x1b\xedY\xe9\x1e-\xba\x17\xf8\xebm\xbd')
>>> cmd_type.decode(m, False)
<class 'p2p.p2p_proto.Hello'>(payload=HelloPayload(version=5, client_version_string='Nethermind/v1.8.105-...
Yes, we seem to have this problem with Nethermind nodes. I noticed it a while ago with one of the Goerli bootnodes (so it is easy to reproduce there). #1784
Not specific to Nethermind, btw:
WARNING 2020-09-21 09:17:50,814 Transport Deserializing list length (1) does not match sedes (2) decoding header (b'\x00\x00~\xc1\x80\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00'), (body=b'\x80\xf8{\x05\xa7Geth/v1.8.23-stable/linux-amd64/go1.9.4\xcc\xc5\x83eth>\xc5\x83eth?\x82u1\xb8@\xdc\xe9HT\x12\xcb\xc6\xe0\x04\xee\xc2\xa9\x169\xe0\x8fp#\xd5\x95|\x95#\xb1\x07\x04\xde}\xb4\xd6\x15\x014\x94\x13g\xfd\xce\x82\rX\rR\x9fP\x91L-_0\xf7\xf5C4\x0f\x1f\x13\x7f\x833A\x92cH'), command_id=0)
So, this always happens on the Hello msg coming from Nethermind (various versions) or Gethv1.8.23-stable
If I'm reading the spec (https://github.com/ethereum/devp2p/blob/master/rlpx.md#framing) right, the header data should always be [0,0] (RLP: b'\xc2\x80\x80'), but those peers are sending us [0] (RLP: b'\xc1\x80')
Maybe the best alternative is to suppress the DeserializationError (logging a warning, though) when the header data is b'\xc1\x80'?
Looks like those peers implement the previous version of the spec (ethereum/devp2p@04ee80c#diff-9999caa615e6404632c336aa8177c9edL117). Guess we could support that too
Since it's a deprecated version, and old clients will necessarily fall off the network as new forks go live, my instinct is to catch/log as debug, and leave an issue to remove the catch/log at the next network fork. At that point, we can catch & disconnect since it will be no longer supported. (still with a debug log explaining the reason, of course)
No strong feelings though, just a suggestion if you're on the fence.