libp2p may be falsely re-establishing connections for reserved peers, or dropping messages

[rphmeier]

In testing the Polkadot collator-protocol for asynchronous backing, we have noticed some anomalous behavior, where collators are sometimes unable to broadcast their collations to validators because validators don't send them a ViewUpdate message (which they are supposed to do upon initiating the connection).

The behavior that we're seeing, repeatedly, is that collators initiating a connection immediately following a disconnection appear to open up a substream that is at least initially one-sided: the collator sends its view message, but receives nothing in return and therefore does not advertise its collation.

The underlying code is using ProtocolHandle::set_reserved_peers with some validators to connect to. The (collator) node is not a validator, and the validators do not put this node in their reserved_peers. The validators also disconnect the collator after some time, after which the collator is likely to initiate a reconnect. This reconnection is what appears tenuous. Versi is currently running #1410, which contains the debugging logs seen in the Grafana links here.

https://grafana.teleport.parity.io/goto/X-qj7ViIR?orgId=1 This is the general query I have been using for debugging.

Between XX:48:00.083 and XX:48:06 in the following Grafana query you can see an example of this - the validators disconnect, the collator sees an immediate reconnect, but no view message is propagated https://grafana.teleport.parity.io/goto/2K9d44mSR?orgId=1 .

Reproduced here

2023-09-11T19:48:06-05:00	2023-09-12 00:48:06.006 DEBUG tokio-runtime-worker parachain::provisioner: bitfields count before selection bitfields_count=30 leaf_hash=0x28bb60d46950f54bc37edaeed644b785955b8988dd3d5aa2d6066b0966fbcfa6
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.087 DEBUG tokio-runtime-worker parachain::validator-discovery: [Relaychain] New ConnectToValidators resolved request peer_set=Collation num_peers=6 removed=0
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.087 DEBUG tokio-runtime-worker parachain::validator-discovery: [Relaychain] New ConnectToValidators request peer_set=Collation requested=6 failed_to_resolve=0
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.086 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Accepted collation, connecting to validators. para_id=501 candidate_relay_parent=0x3362…0e53 relay_parent_mode=Enabled { max_candidate_depth: 3, allowed_ancestry_len: 2 } candidate_hash=0x92387faecb5f1fcfa67e44d0c67369cf9f5e7e342c0e134ac8569dbb6ccbb669 pov_hash=0xc73fe48bc046ba53199c8faba99a752b20f8f6d647eec174db1e0182900f650a core=CoreIndex(0) current_validators=[Public(14fb42862c12d4676b60ce1e24b6c1ef814e0bf2845287ed6a0125aa061cbd3b (5CYDTKc9...)), Public(261f8cd2fe601c22a2792e5385ad2fb72d920954d0775007038b445d8e49121d (5Cvh3oUZ...)), Public(80cdef345604b0ed161800af8fdc1bde9248da3d4aeb498ad3beee00d826197d (5EybALCL...)), Public(363612c9b6a48afac272622c84876240324223caf9cd6b5f5dce807d1d56e305 (5DHnWJjE...)), Public(c2220ceedfb0bc06b2b66023beec32efb9ec2be9c1f17de34b66ed8188322e34 (5GTFG9KW...)), Public(c0cbfb352384c1986e702dfc24efa84717641628b8ae8740a3d84ff2ce056e74 (5GRVeRoY...))] traceID=194360645723336064205722654233368685007
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.086 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Received session info session_index=3330
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.067 DEBUG tokio-runtime-worker parachain::prospective-parachains: Creating fragment tree relay_parent=0x3362519ec9ae3ec65bc6f0b0cd7ee6676fc5cf828c32e9ad2928692f13be0e53 min_relay_parent=66473 para_id=Id(501)
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.064 DEBUG tokio-runtime-worker parachain::availability-store: Candidate backed candidate_hash=0x22d4d68bcc317e4f8b214d0fa25de9db8bcafb7271897501a35fb53ee3a03948 traceID=46298870302261069930402068708525468123
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.061  INFO tokio-runtime-worker substrate: ✨ Imported #66475 (0x3362…0e53)    
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.044 DEBUG tokio-runtime-worker parachain::prospective-parachains: Creating fragment tree relay_parent=0x28bb60d46950f54bc37edaeed644b785955b8988dd3d5aa2d6066b0966fbcfa6 min_relay_parent=66473 para_id=Id(501)
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.042 DEBUG tokio-runtime-worker parachain::availability-store: Candidate backed candidate_hash=0x22d4d68bcc317e4f8b214d0fa25de9db8bcafb7271897501a35fb53ee3a03948 traceID=46298870302261069930402068708525468123
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.037  INFO tokio-runtime-worker substrate: ✨ Imported #66475 (0x28bb…cfa6)    
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.082 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Peer view change peer_id=PeerId("12D3KooWLQNS8ULhha5LLTWnSV3DHeXBfUFqr8vjNPGM9SAzBdgu") view=View { heads: [], finalized_number: 0 }
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.082 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Peer connected peer_id=PeerId("12D3KooWLQNS8ULhha5LLTWnSV3DHeXBfUFqr8vjNPGM9SAzBdgu") observed_role=Authority maybe_authority=Some({Public(c2220ceedfb0bc06b2b66023beec32efb9ec2be9c1f17de34b66ed8188322e34 (5GTFG9KW...))})
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.082 DEBUG tokio-runtime-worker parachain::network-bridge-rx: [Relaychain] Informing collation peer of our view action="PeerConnected" peer=PeerId("12D3KooWLQNS8ULhha5LLTWnSV3DHeXBfUFqr8vjNPGM9SAzBdgu") local_view=View { heads: [0x28bb60d46950f54bc37edaeed644b785955b8988dd3d5aa2d6066b0966fbcfa6, 0x3362519ec9ae3ec65bc6f0b0cd7ee6676fc5cf828c32e9ad2928692f13be0e53], finalized_number: 66472 }
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.082 DEBUG tokio-runtime-worker parachain::network-bridge-rx: [Relaychain] action="PeerConnected" peer_set=Collation version=2 peer=PeerId("12D3KooWLQNS8ULhha5LLTWnSV3DHeXBfUFqr8vjNPGM9SAzBdgu") role=Authority
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.078 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Peer view change peer_id=PeerId("12D3KooWSj4FWbJSdtAQR1NhE8S7V5792Z6rxddvAgUiwZJ4bZcu") view=View { heads: [], finalized_number: 0 }
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.078 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Peer connected peer_id=PeerId("12D3KooWSj4FWbJSdtAQR1NhE8S7V5792Z6rxddvAgUiwZJ4bZcu") observed_role=Authority maybe_authority=Some({Public(c0cbfb352384c1986e702dfc24efa84717641628b8ae8740a3d84ff2ce056e74 (5GRVeRoY...))})
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.077 DEBUG tokio-runtime-worker parachain::network-bridge-rx: [Relaychain] Informing collation peer of our view action="PeerConnected" peer=PeerId("12D3KooWSj4FWbJSdtAQR1NhE8S7V5792Z6rxddvAgUiwZJ4bZcu") local_view=View { heads: [0x28bb60d46950f54bc37edaeed644b785955b8988dd3d5aa2d6066b0966fbcfa6, 0x3362519ec9ae3ec65bc6f0b0cd7ee6676fc5cf828c32e9ad2928692f13be0e53], finalized_number: 66472 }
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.077 DEBUG tokio-runtime-worker parachain::network-bridge-rx: [Relaychain] action="PeerConnected" peer_set=Collation version=2 peer=PeerId("12D3KooWSj4FWbJSdtAQR1NhE8S7V5792Z6rxddvAgUiwZJ4bZcu") role=Authority
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.077 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Peer view change peer_id=PeerId("12D3KooWDs275UdeFaprVeRS4QyB43dJnLfZPrVWigryKi6Zzrp7") view=View { heads: [], finalized_number: 0 }
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.077 DEBUG tokio-runtime-worker parachain::network-bridge-rx: [Relaychain] Informing collation peer of our view action="PeerConnected" peer=PeerId("12D3KooWDs275UdeFaprVeRS4QyB43dJnLfZPrVWigryKi6Zzrp7") local_view=View { heads: [0x28bb60d46950f54bc37edaeed644b785955b8988dd3d5aa2d6066b0966fbcfa6, 0x3362519ec9ae3ec65bc6f0b0cd7ee6676fc5cf828c32e9ad2928692f13be0e53], finalized_number: 66472 }
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.077 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Peer connected peer_id=PeerId("12D3KooWDs275UdeFaprVeRS4QyB43dJnLfZPrVWigryKi6Zzrp7") observed_role=Authority maybe_authority=Some({Public(363612c9b6a48afac272622c84876240324223caf9cd6b5f5dce807d1d56e305 (5DHnWJjE...))})
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.077 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Peer view change peer_id=PeerId("12D3KooWHScCvPM5MeaF14t4DmP2RWhGoC6M1fmiinkZcVeTh8JG") view=View { heads: [], finalized_number: 0 }
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.076 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Peer connected peer_id=PeerId("12D3KooWHScCvPM5MeaF14t4DmP2RWhGoC6M1fmiinkZcVeTh8JG") observed_role=Authority maybe_authority=Some({Public(14fb42862c12d4676b60ce1e24b6c1ef814e0bf2845287ed6a0125aa061cbd3b (5CYDTKc9...))})
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.076 DEBUG tokio-runtime-worker parachain::network-bridge-rx: [Relaychain] action="PeerConnected" peer_set=Collation version=2 peer=PeerId("12D3KooWDs275UdeFaprVeRS4QyB43dJnLfZPrVWigryKi6Zzrp7") role=Authority
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.076 DEBUG tokio-runtime-worker parachain::network-bridge-rx: [Relaychain] Informing collation peer of our view action="PeerConnected" peer=PeerId("12D3KooWHScCvPM5MeaF14t4DmP2RWhGoC6M1fmiinkZcVeTh8JG") local_view=View { heads: [0x28bb60d46950f54bc37edaeed644b785955b8988dd3d5aa2d6066b0966fbcfa6, 0x3362519ec9ae3ec65bc6f0b0cd7ee6676fc5cf828c32e9ad2928692f13be0e53], finalized_number: 66472 }
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.076 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Peer view change peer_id=PeerId("12D3KooWKHDhC7HiNndfaZxU7atamfUorsfeFJiw9tVQSE4qveSu") view=View { heads: [], finalized_number: 0 }
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.076 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Peer connected peer_id=PeerId("12D3KooWKHDhC7HiNndfaZxU7atamfUorsfeFJiw9tVQSE4qveSu") observed_role=Authority maybe_authority=Some({Public(80cdef345604b0ed161800af8fdc1bde9248da3d4aeb498ad3beee00d826197d (5EybALCL...))})
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.076 DEBUG tokio-runtime-worker parachain::network-bridge-rx: [Relaychain] action="PeerConnected" peer_set=Collation version=2 peer=PeerId("12D3KooWHScCvPM5MeaF14t4DmP2RWhGoC6M1fmiinkZcVeTh8JG") role=Authority
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.076 DEBUG tokio-runtime-worker parachain::network-bridge-rx: [Relaychain] Informing collation peer of our view action="PeerConnected" peer=PeerId("12D3KooWKHDhC7HiNndfaZxU7atamfUorsfeFJiw9tVQSE4qveSu") local_view=View { heads: [0x28bb60d46950f54bc37edaeed644b785955b8988dd3d5aa2d6066b0966fbcfa6, 0x3362519ec9ae3ec65bc6f0b0cd7ee6676fc5cf828c32e9ad2928692f13be0e53], finalized_number: 66472 }
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.076 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Peer view change peer_id=PeerId("12D3KooWAx6E45vmY2ucom9Bd7A2rCPvcfFDLyvZa4xxNAZbJg8F") view=View { heads: [], finalized_number: 0 }
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.076 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Peer connected peer_id=PeerId("12D3KooWAx6E45vmY2ucom9Bd7A2rCPvcfFDLyvZa4xxNAZbJg8F") observed_role=Authority maybe_authority=Some({Public(261f8cd2fe601c22a2792e5385ad2fb72d920954d0775007038b445d8e49121d (5Cvh3oUZ...))})
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.076 DEBUG tokio-runtime-worker parachain::network-bridge-rx: [Relaychain] action="PeerConnected" peer_set=Collation version=2 peer=PeerId("12D3KooWKHDhC7HiNndfaZxU7atamfUorsfeFJiw9tVQSE4qveSu") role=Authority
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.076 DEBUG tokio-runtime-worker parachain::network-bridge-rx: [Relaychain] Informing collation peer of our view action="PeerConnected" peer=PeerId("12D3KooWAx6E45vmY2ucom9Bd7A2rCPvcfFDLyvZa4xxNAZbJg8F") local_view=View { heads: [0x28bb60d46950f54bc37edaeed644b785955b8988dd3d5aa2d6066b0966fbcfa6, 0x3362519ec9ae3ec65bc6f0b0cd7ee6676fc5cf828c32e9ad2928692f13be0e53], finalized_number: 66472 }
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.076 DEBUG tokio-runtime-worker parachain::network-bridge-rx: [Relaychain] action="PeerConnected" peer_set=Collation version=2 peer=PeerId("12D3KooWAx6E45vmY2ucom9Bd7A2rCPvcfFDLyvZa4xxNAZbJg8F") role=Authority
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.075 DEBUG tokio-runtime-worker parachain::validator-discovery: [Relaychain] New ConnectToValidators resolved request peer_set=Collation num_peers=6 removed=0
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.075 DEBUG tokio-runtime-worker parachain::validator-discovery: [Relaychain] New ConnectToValidators request peer_set=Collation requested=6 failed_to_resolve=0
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.074 DEBUG tokio-runtime-worker aura::cumulus: [Parachain] Slot claimed. Building relay_parent=0x3362519ec9ae3ec65bc6f0b0cd7ee6676fc5cf828c32e9ad2928692f13be0e53 unincluded_segment_len=2
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.074 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Peer disconnected peer_id=PeerId("12D3KooWDs275UdeFaprVeRS4QyB43dJnLfZPrVWigryKi6Zzrp7") is_validator=true
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.074 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Peer disconnected peer_id=PeerId("12D3KooWAx6E45vmY2ucom9Bd7A2rCPvcfFDLyvZa4xxNAZbJg8F") is_validator=true
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.074 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Peer disconnected peer_id=PeerId("12D3KooWHScCvPM5MeaF14t4DmP2RWhGoC6M1fmiinkZcVeTh8JG") is_validator=true
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.074 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Peer disconnected peer_id=PeerId("12D3KooWLQNS8ULhha5LLTWnSV3DHeXBfUFqr8vjNPGM9SAzBdgu") is_validator=true
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.074 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Peer disconnected peer_id=PeerId("12D3KooWKHDhC7HiNndfaZxU7atamfUorsfeFJiw9tVQSE4qveSu") is_validator=true
2023-09-11T19:48:00-05:00	2023-09-12 00:48:00.074 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Peer disconnected peer_id=PeerId("12D3KooWSj4FWbJSdtAQR1NhE8S7V5792Z6rxddvAgUiwZJ4bZcu") is_validator=true

For an example of how it should look, with logs on both sides:

expand

2023-09-11T20:00:00-05:00	2023-09-12 01:00:00.196 DEBUG tokio-runtime-worker parachain::collator-protocol: Received advertise collation peer_id=PeerId("12D3KooWPL1JNeXKWFh8FNnhexqgPeC4kjKTwHP4EZ5vETXrt3WD") para_id=501 relay_parent=0x6b81b6f29bd8a3a65a1c3eb85ffc7a3c1a3e5064304f26e18018170ab7c679a9
2023-09-11T20:00:00-05:00	2023-09-12 01:00:00.196 DEBUG tokio-runtime-worker parachain::collator-protocol: Seconding is not allowed by backing, queueing advertisement relay_parent=0x6e358bbb5d766472550a791a4c9ae59f3e3bedec980b8d350916ee12bb0fcf6e para_id=Id(501) candidate_hash=0x952c476acf9f6be90ef8fb3b3203afce3d747b7875bac55dd37c08d13657900d traceID=198284880947251209089663558824344399822
2023-09-11T20:00:00-05:00	2023-09-12 01:00:00.195 DEBUG tokio-runtime-worker parachain::collator-protocol: Declared as collator for current para peer_id=PeerId("12D3KooWPL1JNeXKWFh8FNnhexqgPeC4kjKTwHP4EZ5vETXrt3WD") collator_id=Public(7480aee452f1a733e0bb31951e4f52ffeacc1dc88c4cd33eccf029c5c5380c1f (13dknL1S...)) para_id=Id(501)
2023-09-11T20:00:00-05:00	2023-09-12 01:00:00.195 DEBUG tokio-runtime-worker parachain::network-bridge-rx: Informing collation peer of our view action="PeerConnected" peer=PeerId("12D3KooWPL1JNeXKWFh8FNnhexqgPeC4kjKTwHP4EZ5vETXrt3WD") local_view=View { heads: [0x6e358bbb5d766472550a791a4c9ae59f3e3bedec980b8d350916ee12bb0fcf6e], finalized_number: 66592 }
2023-09-11T20:00:00-05:00	2023-09-12 01:00:00.195 DEBUG tokio-runtime-worker parachain::network-bridge-rx: action="PeerConnected" peer_set=Collation version=2 peer=PeerId("12D3KooWPL1JNeXKWFh8FNnhexqgPeC4kjKTwHP4EZ5vETXrt3WD") role=Full
2023-09-11T20:00:00-05:00	2023-09-12 01:00:00.196 DEBUG tokio-runtime-worker parachain::network-bridge-rx: [Relaychain] peer=PeerId("12D3KooWM26dTEt9hgY6PJB8hFCeFa11iUTaPbnUXbzTRZL2Pyma") old_view=View { heads: [], finalized_number: 0 } new_view=View { heads: [0x6e358bbb5d766472550a791a4c9ae59f3e3bedec980b8d350916ee12bb0fcf6e], finalized_number: 66592 } action="NewViewForDebug"
2023-09-11T20:00:00-05:00	2023-09-12 01:00:00.196 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Advertising collation. relay_parent=0x6b81b6f29bd8a3a65a1c3eb85ffc7a3c1a3e5064304f26e18018170ab7c679a9 candidate_hash=0x7ee2e7e06010a62d3abf8c6851ba6b5a665bed23907cc83e522d803b1c188469 peer_id=12D3KooWKHDhC7HiNndfaZxU7atamfUorsfeFJiw9tVQSE4qveSu traceID=168660889572385806264142991431455894362
2023-09-11T20:00:00-05:00	2023-09-12 01:00:00.196 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Advertising collation. relay_parent=0x6e358bbb5d766472550a791a4c9ae59f3e3bedec980b8d350916ee12bb0fcf6e candidate_hash=0x952c476acf9f6be90ef8fb3b3203afce3d747b7875bac55dd37c08d13657900d peer_id=12D3KooWKHDhC7HiNndfaZxU7atamfUorsfeFJiw9tVQSE4qveSu traceID=198284880947251209089663558824344399822
2023-09-11T20:00:00-05:00	2023-09-12 01:00:00.196 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Peer view change: new leaf, advertising for given relay parents leaf=0x6e358bbb5d766472550a791a4c9ae59f3e3bedec980b8d350916ee12bb0fcf6e relay_parents=[0x6e358bbb5d766472550a791a4c9ae59f3e3bedec980b8d350916ee12bb0fcf6e, 0x701e161a8745f4edb8fc2420d36f652c5bcc63acff60793279c99605d250a462, 0x6b81b6f29bd8a3a65a1c3eb85ffc7a3c1a3e5064304f26e18018170ab7c679a9]
2023-09-11T20:00:00-05:00	2023-09-12 01:00:00.196 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Peer view change peer_id=PeerId("12D3KooWKHDhC7HiNndfaZxU7atamfUorsfeFJiw9tVQSE4qveSu") view=View { heads: [0x6e358bbb5d766472550a791a4c9ae59f3e3bedec980b8d350916ee12bb0fcf6e], finalized_number: 66592 }
2023-09-11T20:00:00-05:00	2023-09-12 01:00:00.195 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Peer view change peer_id=PeerId("12D3KooWKHDhC7HiNndfaZxU7atamfUorsfeFJiw9tVQSE4qveSu") view=View { heads: [], finalized_number: 0 }
2023-09-11T20:00:00-05:00	2023-09-12 01:00:00.195 DEBUG tokio-runtime-worker parachain::network-bridge-rx: [Relaychain] Informing collation peer of our view action="PeerConnected" peer=PeerId("12D3KooWM26dTEt9hgY6PJB8hFCeFa11iUTaPbnUXbzTRZL2Pyma") local_view=View { heads: [0x6e358bbb5d766472550a791a4c9ae59f3e3bedec980b8d350916ee12bb0fcf6e], finalized_number: 66592 }
2023-09-11T20:00:00-05:00	2023-09-12 01:00:00.195 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Peer connected peer_id=PeerId("12D3KooWKHDhC7HiNndfaZxU7atamfUorsfeFJiw9tVQSE4qveSu") observed_role=Authority maybe_authority=Some({Public(80cdef345604b0ed161800af8fdc1bde9248da3d4aeb498ad3beee00d826197d (5EybALCL...))})

The expected behavior is that the NotificationStreamOpened event should not land on one side unless it is clear that it will land on both sides, and that no messages will be dropped.

[bkchr]

@paritytech/networking can you look into this with high priority? Afair you have done some changes in substream handling recently?

[altonen]

@bkchr last change to anything related to substreams was the Peerset refactoring in June. Since then we haven't merged anything.

This sounds a little like the finality lagging issue we were seeing earlier this year where the substream was one-sided but the node was not able to detect it because it didn't have anything to send.

[altonen]

@rphmeier @sandreim

I have couple of questions:

• is it possible to get sub-libp2p=trace log target enabled?
• are the collators and validators only connected over the collation protocol or do they have some other protocols open as well, e.g., syncing or GRANDPA? Should they have some other protocol open in addition to collation?
• is it only the collator that opens substream to a validator over the collation protocol and never vice versa?

This immediate reconnection after disconnection is suspicious because there should be back-off mechanism for closed substreams. The back-off is not working if the whole connection is closed which would indicate that the validator/collator pair had only one protocol open and that the validator/collator was redialed immediately after the connection was closed.

[altonen]

What I find weird is that authority discovery is doing something which to me doesn't make sense:

00:48:00.076 parachain::network-bridge-rx: [Relaychain] action="PeerConnected" peer_set=Collation version=2 peer=PeerId("12D3KooWAx6E45vmY2ucom9Bd7A2rCPvcfFDLyvZa4xxNAZbJg8F") role=Authority
00:48:00.075 parachain::validator-discovery: [Relaychain] New ConnectToValidators resolved request peer_set=Collation num_peers=6 removed=0
00:48:00.075 parachain::validator-discovery: [Relaychain] New ConnectToValidators request peer_set=Collation requested=6 failed_to_resolve=0
00:48:00.074 parachain::collator-protocol: [Relaychain] Peer disconnected peer_id=PeerId("12D3KooWAx6E45vmY2ucom9Bd7A2rCPvcfFDLyvZa4xxNAZbJg8F") is_validator=true
00:48:00.072 parachain::collator-protocol: [Relaychain] Advertising collation. relay_parent=0x28bb60d46950f54bc37edaeed644b785955b8988dd3d5aa2d6066b0966fbcfa6 candidate_hash=0x93056876796f64dd62aac272ea69d89f23b0e0d6dfbe349536990898a753b3ad peer_id=12D3KooWAx6E45vmY2ucom9Bd7A2rCPvcfFDLyvZa4xxNAZbJg8F traceID=195424595621779617186766630064172423327
00:48:00.072 parachain::network-bridge-rx: [Relaychain] action="PeerDisconnected" peer_set=Collation peer=PeerId("12D3KooWAx6E45vmY2ucom9Bd7A2rCPvcfFDLyvZa4xxNAZbJg8F")
00:48:00.072 parachain::validator-discovery: [Relaychain] New ConnectToValidators resolved request peer_set=Collation num_peers=0 removed=6
00:48:00.072 parachain::validator-discovery: [Relaychain] New ConnectToValidators request peer_set=Collation requested=0 failed_to_resolve=0

It keeps disconnecting and then reconnecting to the same nodes. I'm not sure why it disconnects the peer in the first place but then reconnecting to it in a few milliseconds doesn't sound correct. Any comment on this?

Grafana for validator
Grafana for collator

One issue in the current implementation of Notifications is that it doesn't inform the protocol that the inbound substream is closed (which is why we have the peer eviction hack in SyncingEngine) and the connection is detected to be closed only if node attempts to send data to remote peer.

What I think can happen is that if local node closes a connection to remote and opens it again before remote node can send any data, the new inbound substream (from remote's PoV) is discarded and this is noticed by the local node only when it tries to send data. Since the Notifications allows half-open connections, the inbound substream towards the local node is never opened because ProtocolController is blissfully unaware that there is a new connection attempt since the connection is already open. This can then result in a pair of substreams, neither which is writable and the closed connection is detected by both nodes only when they attempt to send something.

I need to check if any of that is actually true but I think this ping-pong in the connection state caused by the authority discovery is playing a role here.

[vstakhov]

is it possible to get sub-libp2p=trace log target enabled?

I have enabled that, what particular log lines should I check?

[altonen]

PSM <= Dropped or OpenDesiredByRemote. I'll go check them as well

[dmitry-markin]

Just a guess: is it possible that a collator removes validators for some reason from the reserved peers and this causes the disconnect?

EDIT. May be it's expected behavior, and if not — we'll need to also enable peerset=trace and look for messages like "Disconnecting previously reserved node ..."

[rphmeier]

are the collators and validators only connected over the collation protocol or do they have some other protocols open as well, e.g., syncing or GRANDPA? Should they have some other protocol open in addition to collation?

They are likely connected on sync and Validation (this one, they aren't really supposed to be, but they are and it's not a problem per se) for the periods they are connected.

is it only the collator that opens substream to a validator over the collation protocol and never vice versa?

That's correct. Validators do not add collators to reserved peers on any protocol, and collators add validators to their reserved peers on the Collation protocol only.

[ordian]

There's one potential issue with gossip-support subsystem running on collators and potentially removing all validators from the reserved Validation set

polkadot-sdk/polkadot/node/network/gossip-support/src/lib.rs

Line 256 in ee6eeb7

Vec::new()

I think that might also trigger a disconnect. We should probably not even run gossip-support on collators.

[altonen]

Just a guess: is it possible that a collator removes validators for some reason from the reserved peers and this causes the disconnect?

EDIT. May be it's expected behavior, and if not — we'll need to also enable peerset=trace and look for messages like "Disconnecting previously reserved node ..."

I found this one from the logs

15:06:24.062  WARN tokio-runtime-worker peerset: [Relaychain] Trying to remove unknown reserved node 12D3KooWRJpmAB6diptmuYe3JEEu3vqcm9psZVXFjZLM45pFACJV from SetId(3).    
15:06:24.062 DEBUG tokio-runtime-worker parachain::validator-discovery: [Relaychain] New ConnectToValidators resolved request peer_set=Collation num_peers=3 removed=3
15:06:24.062 DEBUG tokio-runtime-worker parachain::validator-discovery: [Relaychain] New ConnectToValidators request peer_set=Collation requested=3 failed_to_resolve=0

@ordian would that affect the collation set though?

[ordian]

I don't know if the current code affects collation peerset, I expect that this doesn't

polkadot-sdk/polkadot/node/network/bridge/src/validator_discovery.rs

Lines 95 to 100 in ee6eeb7

	let _ = network_service
	.remove_from_peers_set(
	self.peerset_protocol_names.get_main_name(peer_set),
	peers_to_remove,
	)
	.await;

But yeah, the issue might be in collator side issuing disconnecting requests

polkadot-sdk/polkadot/node/network/collator-protocol/src/collator_side/validators_buffer.rs

Line 95 in ee6eeb7

pub fn validators_to_connect(&self) -> Vec<AuthorityDiscoveryId> {

[altonen]

I think we should try disabling those disconnection requests, at least if they're targeting a node that will be added a few moments later again. I don't see the purpose of those but I could be misunderstanding something.

If those are disabled and the issue still persists, it would give us some new information.

[rphmeier]

I can see how the underlying validators_buffer logic could trigger this issue, and we can add a patch to work around it.

But this does not fix the underlying issue, that the connection is being falsely "opened" just because it was closed just before. Is there any good fix for that?