-
Notifications
You must be signed in to change notification settings - Fork 2.2k
Aleth tries to initiate another connection to node while RLPX handshake is still in progress #5600
Description
Aleth tries to initiate a connection to a node while an RLPX handshake is already in progress with that same node. For example, take bootnode 865a6325 in the following log...Aleth opens the TCP socket to 865a6325 and then starts the RLPX handshake:
TRACE 05-12 20:42:35 p2p net Attempting connection to ##15ac307a…@52.176.7.10:30303 from ##a6abf591…
TRACE 05-12 20:42:35 p2p net Attempting connection to ##a979fb57…@52.16.188.185:30303 from ##a6abf591…
TRACE 05-12 20:42:35 p2p net Attempting connection to ##865a6325…@52.176.100.77:30303 from ##a6abf591…
TRACE 05-12 20:42:35 p2p net Attempting connection to ##3f1d1204…@13.93.211.84:30303 from ##a6abf591…
TRACE 05-12 20:42:35 p2p net Attempting connection to ##78de8a09…@191.235.84.50:30303 from ##a6abf591…
...
TRACE 05-12 20:42:35 p2p net Starting RLPX handshake with ##15ac307a…@52.176.7.10:30303
TRACE 05-12 20:42:35 p2p rlpx egress auth to ##15ac307a…@52.176.7.10:30303
TRACE 05-12 20:42:35 p2p rlpx egress ack from ##aa36fdf3…@13.93.211.84:30303
TRACE 05-12 20:42:35 p2p net Starting RLPX handshake with ##865a6325…@52.176.100.77:30303
TRACE 05-12 20:42:35 p2p rlpx egress auth to ##865a6325…@52.176.100.77:30303
TRACE 05-12 20:42:35 p2p rlpx egress ack from ##3f1d1204…@13.93.211.84:30303
The node then gets added to the node table via discovery (which means that a node table NodeEntryAdded event is generated which means that when the host processes the event - in Host::onNodeTableEvent - it calls Host::connect on that node) and Aleth creates another TCP connection to the node and initiates another RLPX handshake:
TRACE 05-12 20:42:35 p2p rlpx egress ack from ##78de8a09…@191.235.84.50:30303
TRACE 05-12 20:42:35 p2p rlpx egress ack from ##1118980b…@52.74.57.123:30303
DEBUG 05-12 20:42:35 p2p net p2p.host.nodeTable.events.nodeEntryAdded ##865a6325…
TRACE 05-12 20:42:35 p2p net Attempting connection to ##865a6325…@52.176.100.77:30303 from ##a6abf591…
TRACE 05-12 20:42:35 p2p net Starting RLPX handshake with ##865a6325…@52.176.100.77:30303
TRACE 05-12 20:42:35 p2p rlpx egress auth to ##865a6325…@52.176.100.77:30303
The first handshake completes and we start a new session with that peer. The second handshake completes and we try to start another new session but detect that we already have a session with that peer so we disconnect:
TRACE 05-12 20:42:37 p2p rlpx egress Frame body from ##865a6325…@52.176.100.77:30303
TRACE 05-12 20:42:37 p2p rlpx egress Hello verified. Starting session with ##865a6325…@52.176.100.77:30303
DEBUG 05-12 20:42:37 p2p net Starting peer session with Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 V[5] ##865a6325… (eth,63) 30303
DEBUG 05-12 20:42:37 p2p net Session already exists for peer with id ##865a6325…
TRACE 05-12 20:42:37 p2p net Disconnecting (our reason: Peer was already connected.) from ##865a6325…@52.176.100.77:30303
TRACE 05-12 20:42:37 p2p net Sending Disconnect to ##865a6325…@52.176.100.77:30303
TRACE 05-12 20:42:37 p2p net Closing 52.176.100.77:30303 (Peer was already connected.)
DEBUG 05-12 20:42:37 p2p net 865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 Closing peer session :-(
However, then the peer disconnects from us (I'm assuming because we sent a disconnect p2p capability packet to them to disconnect the duplicate session) so we presumably end up with no connection to the node:
TRACE 05-12 20:42:38 p2p net 865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 Error reading: An existing connection was forcibly closed by the remote host
TRACE 05-12 20:42:38 p2p net 865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 Closing 52.176.100.77:30303 (Low-level TCP communication error.)
DEBUG 05-12 20:42:38 p2p net 865a6325…|Parity-Ethereum/v2.2.9-stable-5d5b372-20190203/x86_64-linux-gnu/rustc1.31.1 Closing peer session :-(
We eventually start trying to connect to the node again (since it's a bootnode and therefore a required peer):
TRACE 05-12 20:42:40 p2p rlpx egress ack from ##a979fb57…@52.16.188.185:30303
TRACE 05-12 20:42:41 p2p net Attempting connection to ##865a6325…@52.176.100.77:30303 from ##a6abf591…
TRACE 05-12 20:42:41 p2p net Attempting connection to ##669f45b6…@52.74.57.123:30303 from ##a6abf591…
TRACE 05-12 20:42:41 p2p net Starting RLPX handshake with ##865a6325…@52.176.100.77:30303
Full log: duplicate_connection.txt