BadAckMessage: Auth ack msg too short: 0

[carver]

What is wrong?

    INFO  06-12 13:10:22        peer  Adding peer: LESPeer <Node(0x053d@79.98.29.154)>
   DEBUG  06-12 13:10:22        peer  Connecting to <Node(0x94c1@192.81.208.223)>...
   DEBUG  06-12 13:10:24  lightchain  fetched headers from 1 to 192
    INFO  06-12 13:10:24        peer  Got bad Ack during peer connection
   DEBUG  06-12 13:10:24        peer  Got bad Ack during peer connection
Traceback (most recent call last):
  File "/home/jcarver/code/py-evm/p2p/peer.py", line 654, in connect
    self.cancel_token))
  File "/home/jcarver/code/py-evm/p2p/service.py", line 32, in wait
    return await self.wait_first(awaitable, token=token, timeout=timeout)
  File "/home/jcarver/code/py-evm/p2p/service.py", line 51, in wait_first
    return await wait_with_token(*awaitables, token=token_chain, timeout=timeout)
  File "/home/jcarver/code/py-evm/p2p/cancel_token.py", line 119, in wait_with_token
    return done.pop().result()
  File "/home/jcarver/code/py-evm/p2p/peer.py", line 126, in handshake
    ) = await auth.handshake(remote, privkey, token)
  File "/home/jcarver/code/py-evm/p2p/auth.py", line 59, in handshake
    initiator, reader, writer, token)
  File "/home/jcarver/code/py-evm/p2p/auth.py", line 81, in _handshake
    ephemeral_pubkey, responder_nonce = initiator.decode_auth_ack_message(auth_ack)
  File "/home/jcarver/code/py-evm/p2p/auth.py", line 195, in decode_auth_ack_message
    raise BadAckMessage("Auth ack msg too short: {}".format(len(ciphertext)))
p2p.exceptions.BadAckMessage: Auth ack msg too short: 0

How can it be fixed

🤷‍♂️

#885 fixed a similar-sounding bug. I was running from 0fe47ac which includes that merge.

@gsalgado probably has a better idea where to start

[veox]

It is a Parity node with no matching capabilities:

   DEBUG  06-12 23:32:48        peer  Connecting to <Node(0x94c1@192.81.208.223)>...
   DEBUG  06-12 23:32:48  lightchain  fetched headers from 0 to 191
   DEBUG  06-12 23:32:48        peer  Could not complete handshake with <Node(0x94c1@192.81.208.223)>: HandshakeFailure("No matching capabilities between us ([('les', 1), ('les', 2)]) and <Node(0x94c1@192.81.208.223)> ((('eth', 62), ('eth', 63), ('par', 1), ('par', 2), ('pip', 1))), disconnecting",)

This with trinity-v0.1.0-alpha.11-33-g4958c6a.

With trinity-v0.1.0-alpha.11-34-g0fe47ac - after merge of #889; same commit as in your case! - I get the same HandshakeFailure behaviour.

[gsalgado]

The Bad ack log msg is from connecting to a different peer -- it is generated by the auth handshake, which happens before the actual P2P handshake. We need to log more info about the peer when we get those bad acks

[gsalgado]

Ok, I was wrong, it is actually that node that is giving us a BadAck, and that seems to happen only when it has seen our node ID before and knows we don't have matching protocols. When I used my trinity node ID to connect to it, I got a BadAck as well:

INFO  06-13 09:58:31        peer  Got bad auth ack from <Node(0x94c15d1b9e2fe7ce56e458b9a3b672ef11894ddedd0c6f247e0f1d3487f52b66208fb4aeb8179fce6e3a749ea93ed147c37976d67af557508d199d9594c35f09@192.81.208.223:30303)>

When I used a different node ID and had matching protocols, I was able to connect just fine:

2018-06-13 10:06:36,139 DEBUG: Successfully decoded Status (cmd_id=16) msg: {'protocol_version': 63, 'network_id': 3, 'td': 7977346058529846, 'best_hash': b'S\xd5\xfdu\xa2\x9c)\xca\x95x<\xf8\xa9\x80\xfb\x94\xdbtU\x9e\x1dX\x06\xcc\xed\xc9\xdba\x0fs\x82\x98', 'genesis_hash': b'A\x94\x10#h\t#\xe0\xfeMt\xa3K\xda\xc8\x14\x1f%@\xe3\xae\x90b7\x18\xe4}f\xd1\xcaJ-'}
2018-06-13 10:06:36,145 DEBUG: Finished (eth, 63) handshake with <Node(0x94c1@192.81.208.223)>

Finally, with a different node ID and no matching protocols, the first time it does the auth dance and sends us a Hello msg, but the second time it already knows we don't have a matching protocol so it closes the connection before sending any data, which causes the BadAck:

2018-06-13 10:12:42,200 DEBUG: Waiting for 192 bytes from <Node(0x94c1@192.81.208.223)>
2018-06-13 10:12:42,205 DEBUG: Got msg with cmd_id: 0
2018-06-13 10:12:42,205 DEBUG: Successfully decoded Hello (cmd_id=0) msg: {'version': 5, 'client_version_string': 'Parity/v1.9.2-beta-0feb0bb-20180201/x86_64-linux-gnu/rustc1.23.0', 'capabilities': (('eth', 62), ('eth', 63), ('par', 1), ('par', 2), ('pip', 1)), 'listen_port': 30303, 'remote_pubkey': b'\x94\xc1]\x1b\x9e/\xe7\xceV\xe4X\xb9\xa3\xb6r\xef\x11\x89M\xde\xdd\x0co$~\x0f\x1d4\x87\xf5+f \x8f\xb4\xae\xb8\x17\x9f\xcen:t\x9e\xa9>\xd1G\xc3yv\xd6z\xf5WP\x8d\x19\x9d\x95\x94\xc3_\t'}
2018-06-13 10:12:42,206 DEBUG: Sending msg with cmd_id: 1
2018-06-13 10:12:42,209 DEBUG: Could not complete handshake with <Node(0x94c15d1b9e2fe7ce56e458b9a3b672ef11894ddedd0c6f247e0f1d3487f52b66208fb4aeb8179fce6e3a749ea93ed147c37976d67af557508d199d9594c35f09@192.81.208.223:30303)>: HandshakeFailure("No matching capabilities between us ([('les', 1), ('les', 2)]) and <Node(0x94c1@192.81.208.223)> ((('eth', 62), ('eth', 63), ('par', 1), ('par', 2), ('pip', 1))), disconnecting",)
[...]
2018-06-13 10:12:42,209 DEBUG: Connecting to <Node(0x94c1@192.81.208.223)>...
2018-06-13 10:12:43,164 INFO: Got bad auth ack from <Node(0x94c15d1b9e2fe7ce56e458b9a3b672ef11894ddedd0c6f247e0f1d3487f52b66208fb4aeb8179fce6e3a749ea93ed147c37976d67af557508d199d9594c35f09@192.81.208.223:30303)>