Skip to content
This repository was archived by the owner on Oct 28, 2021. It is now read-only.
This repository was archived by the owner on Oct 28, 2021. It is now read-only.

Aleth tries to initiate another connection to node while RLPX handshake is still in progress #5600

@halfalicious

Description

@halfalicious

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

Metadata

Metadata

Assignees

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions