transport-manager: Unknown connection opened

[lexnv]

Investigate the following errors:

    "2024-07-06 04:53:54.449  WARN tokio-runtime-worker litep2p::transport-manager: unknown connection opened as secondary connection, discarding peer=PeerId(\"12D3KooWB9DVNyi6TQUhHeyq4LyBLVykybXUmcNmEUD9tcKEaYq1\") connection_id=ConnectionId(246958) address=\"/ip6/*/tcp/51326/ws/p2p/12D3KooWB9DVNyi6TQUhHeyq4LyBLVykybXUmcNmEUD9tcKEaYq1\" dial_record=AddressRecord { score: 100, address: \"/ip4/1*/tcp/31334/ws/p2p/12D3KooWB9DVNyi6TQUhHeyq4LyBLVykybXUmcNmEUD9tcKEaYq1\", connection_id: Some(ConnectionId(246946)) }",
    "2024-07-06 04:53:54.450  WARN tokio-runtime-worker litep2p::transport-manager: non-primary connection was closed but secondary connection doesn't exist peer=PeerId(\"12D3KooWB9DVNyi6TQUhHeyq4LyBLVykybXUmcNmEUD9tcKEaYq1\") connection_id=ConnectionId(246958)",
    "2024-07-06 04:53:54.450 ERROR tokio-runtime-worker litep2p::transport-manager: failed to handle closed connection error=InvalidState",
    "2024-07-06 04:54:04.058  WARN tokio-runtime-worker litep2p::transport-manager: non-primary connection was closed but secondary connection doesn't exist peer=PeerId(\"12D3KooWB9DVNyi6TQUhHeyq4LyBLVykybXUmcNmEUD9tcKEaYq1\") connection_id=ConnectionId(246953)",
    "2024-07-06 04:54:04.058 ERROR tokio-runtime-worker litep2p::transport-manager: failed to handle closed connection error=InvalidState",

Data collected from a long running litep2p substrate node in kusama

Tasks

Beta Give feedback

1. transport: Reject secondary connections with different connection IDs #176
   +0
   
2. transport: Fix double lock and state overwrite on disconnected peers #179
   +0
   

[altonen]

The issue could be that after receiving an unknown unknown connection, TransportManager wants to discard it:

litep2p/src/transport/manager/mod.rs

Lines 980 to 987 in a27d007

	Some(record) => tracing::warn!(
	target: LOG_TARGET,
	?peer,
	connection_id = ?endpoint.connection_id(),
	address = ?endpoint.address(),
	dial_record = ?record,
	"unknown connection opened as secondary connection, discarding",
	),

but that branch actually doesn't return early with ConnectionEstablishedResult::Reject but instead drops down to the default case at the end of the function which returns ConnectionEstablishedResult::Accept for all cases. This would explain why later on when the connection is closed, TransportManager doesn't recognize it.

[lexnv]

Its been a tricky edge-case, will keep an eye for triaging since we might have other minor gaps causing this state reset

Detailed repro case

• T0: Dial address A connection ID 1 -> State : Dialing { in-flight-1 }
• T1: Connection is established by remote address C connection ID 3 -> State : Connected { in-flight-dial 1 }
• T2: Closed connection established in T2 -> State : Disconnected { in-flight-dial 1}

// This is where the state was wrongfully overwritten

• T3: Dial address B connection ID 2 -> State: Dialing { in-flight-2 }

• T4: Connection is established by remote address C connection ID 3 -> State : Connected { in-flight-dial 2 }

// The issue was detected here

• T5: Dial from T0 receives a response however it expects in-flight-dial 1 and the state has in-flight-dial 2