gossamer icon indicating copy to clipboard operation
gossamer copied to clipboard
verified publisher icon ChainSafe

Gossamer Doesn't Retry Dropped Connections

Open danforbes opened this issue 3 years ago • 0 comments

Describe the bug

  • In a cross-client devnet, it was observed that the initial connection between a Substrate and Gossamer node fails. Although the Substrate node is able to retry and establish the connection, the Gossamer node does not reestablish the connection with the Substrate node (the Substrate node sends messages to the Gossamer node, which are received, but the Gossamer node never sends any messages to the Substrate node).

Expected Behavior

  • When a Substrate node is able to peer with a Gossamer node, the Gossamer node should also be able to peer with the Substrate node.

Current Behavior

  • It appears as though the connection between the Substrate and Gossamer node is "asymmetrical" and the Gossamer node is only ever able to receive message from the Substrate node, but does not send any messages to the Substrate node.

Log output

Note the following messages from Substrate (12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN) and Gossamer (12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos) - the full logs are below:

  • Substrate
    • IncomingConnectionError(/ip4/127.0.0.1/tcp/30333,/ip4/127.0.0.1/tcp/7002): Connection error: Connection limit: 2/2.
    • Adding self-reported address /ip4/127.0.0.1/tcp/7002 from 12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos to Kademlia DHT /gssmr_test/kad.
  • Gossamer
    • Host 12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos disconnected from peer 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN
    • host 12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos received message from peer 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN

Note that the Gossamer logs refer to an incorrectly calculated peer ID (CovLVG4fQcqQZzrHMfSycNoF2zJbadwFfuiDpcyfaSdxjE9B4uUFvMYtg1a7GvtRUMzZ3UR) - this is believed to be a separate, unrelated problem at this time.

Substrate Logs

2022-08-08 15:52:36.572 TRACE tokio-runtime-worker sub-libp2p: Libp2p => IncomingConnection(/ip6/::1/tcp/30333,/ip6/::1/tcp/64049))
2022-08-08 15:52:36.572 TRACE tokio-runtime-worker sub-libp2p: Libp2p => IncomingConnection(/ip4/127.0.0.1/tcp/30333,/ip4/127.0.0.1/tcp/7002))
2022-08-08 15:52:36.572 TRACE tokio-runtime-worker sub-libp2p: Libp2p => IncomingConnection(/ip4/192.168.88.3/tcp/30333,/ip4/192.168.88.3/tcp/7002))
2022-08-08 15:52:36.581 TRACE tokio-runtime-worker sub-libp2p: Libp2p => Connected(12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos, SetId(0), Listener { local_addr: "/ip4/192.168.88.3/tcp/30333", send_back_addr: "/ip4/192.168.88.3/tcp/7002" }, ConnectionId(2)): Not requested by PSM, disabling.
2022-08-08 15:52:36.582 TRACE tokio-runtime-worker sub-libp2p: Libp2p => Connected(12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos, SetId(1), Listener { local_addr: "/ip4/192.168.88.3/tcp/30333", send_back_addr: "/ip4/192.168.88.3/tcp/7002" }, ConnectionId(2)): Not requested by PSM, disabling.
2022-08-08 15:52:36.582 TRACE tokio-runtime-worker sub-libp2p: Libp2p => Connected(12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos, SetId(2), Listener { local_addr: "/ip4/192.168.88.3/tcp/30333", send_back_addr: "/ip4/192.168.88.3/tcp/7002" }, ConnectionId(2)): Not requested by PSM, disabling.
2022-08-08 15:52:36.582 DEBUG tokio-runtime-worker sub-libp2p: Libp2p => Connected(PeerId("12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos"))
2022-08-08 15:52:36.582 TRACE tokio-runtime-worker sub-libp2p: Libp2p => Connected(12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos, SetId(0), Listener { local_addr: "/ip6/::1/tcp/30333", send_back_addr: "/ip6/::1/tcp/64049" }, ConnectionId(0)): Secondary connection. Leaving closed.
2022-08-08 15:52:36.582 TRACE tokio-runtime-worker sub-libp2p: Libp2p => Connected(12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos, SetId(1), Listener { local_addr: "/ip6/::1/tcp/30333", send_back_addr: "/ip6/::1/tcp/64049" }, ConnectionId(0)): Secondary connection. Leaving closed.
2022-08-08 15:52:36.582 TRACE tokio-runtime-worker sub-libp2p: Libp2p => Connected(12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos, SetId(2), Listener { local_addr: "/ip6/::1/tcp/30333", send_back_addr: "/ip6/::1/tcp/64049" }, ConnectionId(0)): Secondary connection. Leaving closed.
2022-08-08 15:52:36.582 DEBUG tokio-runtime-worker sub-libp2p: Libp2p => Connected(PeerId("12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos"))
2022-08-08 15:52:36.582 DEBUG tokio-runtime-worker sub-libp2p: Libp2p => IncomingConnectionError(/ip4/127.0.0.1/tcp/30333,/ip4/127.0.0.1/tcp/7002): Connection error: Connection limit: 2/2.
2022-08-08 15:52:36.589 TRACE tokio-runtime-worker sub-libp2p: Ping time with PeerId("12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos"): 7.082541ms
2022-08-08 15:52:36.589 TRACE tokio-runtime-worker sub-libp2p: Ping time with PeerId("12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos"): 7.13725ms
2022-08-08 15:52:36.923 TRACE tokio-runtime-worker afg: Polling round 1, state = State { prevote_ghost: None, finalized: None, estimate: None, completable: false }, step = Some(Prevoted)
2022-08-08 15:52:36.923 TRACE tokio-runtime-worker gossip: Cleaned up 0 stale messages, 1 left (1 known) protocol=/2d42e1c0b9e689cdf2b51a09621be564171bdde521fdb169fe538f69c0adb97a/grandpa/1
2022-08-08 15:52:37.095 TRACE tokio-runtime-worker sub-libp2p: Identified PeerId("12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos") => IdentifyInfo { public_key: Ed25519(PublicKey(compressed): 99c0a2cddaf3e7ca06ada16564db9f3bd1972432cadcb4f3a6101b6a8da2b6), protocol_version: "ipfs/0.1.0", agent_version: "github.com/ChainSafe/gossamer@a48f7a604-dirty", listen_addrs: ["/ip4/177.93.69.190/tcp/7002"], protocols: ["/p2p/id/delta/1.0.0", "/ipfs/id/1.0.0", "/ipfs/id/push/1.0.0", "/ipfs/ping/1.0.0", "/2d42e1c0b9e689cdf2b51a09621be564171bdde521fdb169fe538f69c0adb97a/grandpa/1", "/gssmr_test/sync/2", "/gssmr_test/light/2", "/gssmr_test/block-announces/1", "/gssmr_test/transactions/1", "/gssmr_test/kad"], observed_addr: "/ip4/192.168.88.3/tcp/30333" }
2022-08-08 15:52:37.096 TRACE tokio-runtime-worker sub-libp2p: Adding self-reported address /ip4/177.93.69.190/tcp/7002 from 12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos to Kademlia DHT /gssmr_test/kad.
2022-08-08 15:52:37.096 TRACE tokio-runtime-worker sub-libp2p: PSM => Connect(12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos, SetId(0)): Enabling connections.
2022-08-08 15:52:37.096 TRACE tokio-runtime-worker sub-libp2p: Handler(PeerId("12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos"), ConnectionId(2)) <= Open(SetId(0))
2022-08-08 15:52:37.096 TRACE tokio-runtime-worker sub-libp2p: Identified PeerId("12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos") => IdentifyInfo { public_key: Ed25519(PublicKey(compressed): 99c0a2cddaf3e7ca06ada16564db9f3bd1972432cadcb4f3a6101b6a8da2b6), protocol_version: "ipfs/0.1.0", agent_version: "github.com/ChainSafe/gossamer@a48f7a604-dirty", listen_addrs: ["/ip4/127.0.0.1/tcp/7002", "/ip4/177.93.69.190/tcp/7002"], protocols: ["/p2p/id/delta/1.0.0", "/ipfs/id/1.0.0", "/ipfs/id/push/1.0.0", "/ipfs/ping/1.0.0", "/2d42e1c0b9e689cdf2b51a09621be564171bdde521fdb169fe538f69c0adb97a/grandpa/1", "/gssmr_test/sync/2", "/gssmr_test/light/2", "/gssmr_test/block-announces/1", "/gssmr_test/transactions/1", "/gssmr_test/kad"], observed_addr: "/ip6/::1/tcp/30333" }
2022-08-08 15:52:37.096 TRACE tokio-runtime-worker sub-libp2p: Adding self-reported address /ip4/127.0.0.1/tcp/7002 from 12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos to Kademlia DHT /gssmr_test/kad.
2022-08-08 15:52:37.096 TRACE tokio-runtime-worker sub-libp2p: Adding self-reported address /ip4/177.93.69.190/tcp/7002 from 12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos to Kademlia DHT /gssmr_test/kad.
2022-08-08 15:52:37.098 TRACE tokio-runtime-worker sub-libp2p: Handler(12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos, ConnectionId(2)) => OpenResultOk(SetId(0))

Gossamer Logs

2022-08-08T15:52:36-04:00 DBUG bootstrapping to peer 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN	host.go:L283	pkg=network
2022-08-08T15:52:36-04:00 DBUG starting DHT with bootnodes [{12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN: [/ip4/127.0.0.1/tcp/30333]}]...	discovery.go:L103	pkg=network
2022-08-08T15:52:36-04:00 TRCE Host 12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos connected to peer 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN	connmgr.go:L115	pkg=network
2022-08-08T15:52:36-04:00 TRCE Host 12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos connected to peer 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN	connmgr.go:L115	pkg=network
2022-08-08T15:52:36-04:00 TRCE Host 12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos connected to peer 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN	connmgr.go:L115	pkg=network
2022-08-08T15:52:36-04:00 DBUG connection successful with peer 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN	service.go:L723	pkg=network
2022-08-08T15:52:36-04:00 TRCE Host 12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos disconnected from peer 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN	connmgr.go:L125	pkg=network
2022-08-08T15:52:37-04:00 INFO started network service with supported protocols /p2p/id/delta/1.0.0, /ipfs/id/1.0.0, /ipfs/id/push/1.0.0, /ipfs/ping/1.0.0, /2d42e1c0b9e689cdf2b51a09621be564171bdde521fdb169fe538f69c0adb97a/grandpa/1, /gssmr_test/sync/2, /gssmr_test/light/2, /gssmr_test/block-announces/1, /gssmr_test/transactions/1, /gssmr_test/kad	service.go:L322	pkg=network
2022-08-08T15:52:37-04:00 DBUG incrementing grandpa round, next round will be 1	grandpa.go:L348	pkg=grandpa
2022-08-08T15:52:37-04:00 DBUG starting round 1 with set id 0	grandpa.go:L404	pkg=grandpa
2022-08-08T15:52:37-04:00 DBUG preparing to send pre-vote message round=1, setID=0, message=stage=prevote hash=0x2d42e1c0b9e689cdf2b51a09621be564171bdde521fdb169fe538f69c0adb97a number=0 authorityID=0xd17c2d7823ebf260fd138f2d7e27d114c0145d968b5ff5006125f2414fadae69...	grandpa.go:L555	pkg=grandpa
2022-08-08T15:52:37-04:00 DBUG receiving vote messages...	vote_message.go:L30	pkg=grandpa
2022-08-08T15:52:37-04:00 DBUG preparing to send neighbor message: &{1 0 0}...	grandpa.go:L468	pkg=grandpa
2022-08-08T15:52:37-04:00 DBUG before neighbor message: to 1 peers: CovLVG4fQcqQZzrHMfSycNoF2zJbadwFfuiDpcyfaSdxjE9B4uUFvMYtg1a7GvtRUMzZ3UR...	grandpa.go:L481	pkg=grandpa
2022-08-08T15:52:37-04:00 DBUG sending neighbor message to 1 peers: CovLVG4fQcqQZzrHMfSycNoF2zJbadwFfuiDpcyfaSdxjE9B4uUFvMYtg1a7GvtRUMzZ3UR...	grandpa.go:L485	pkg=grandpa
2022-08-08T15:52:37-04:00 WARN send neighbour message: 02010100000000000000000000000000000000000000	network.go:L188	pkg=grandpa
2022-08-08T15:52:37-04:00 DBUG gossiping from host 12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos message of type 5: ConsensusMessage Data=02010100000000000000000000000000000000000000	service.go:L519	pkg=network
2022-08-08T15:52:37-04:00 DBUG sending neighbor message: unsuccesfull peers (1): CovLVG4fQcqQZzrHMfSycNoF2zJbadwFfuiDpcyfaSdxjE9B4uUFvMYtg1a7GvtRUMzZ3UR	grandpa.go:L489	pkg=grandpa
2022-08-08T15:52:37-04:00 EROR failed to do action {call=reportPeer, set-id=0, reputation change value: -2147483648, reason: Unsupported protocol, peers=[CovLVG4fQcqQZzrHMfSycNoF2zJbadwFfuiDpcyfaSdxjE9B4uUFvMYtg1a7GvtRUMzZ3UR] on peerSet: cannot add reputation: peer doesn't exist: for peer id CovLVG4fQcqQZzrHMfSycNoF2zJbadwFfuiDpcyfaSdxjE9B4uUFvMYtg1a7GvtRUMzZ3UR	peerset.go:L769	pkg=peerset
2022-08-08T15:52:37-04:00 TRCE received stream using sub-protocol /gssmr_test/block-announces/1	service.go:L501	pkg=network
2022-08-08T15:52:37-04:00 TRCE host 12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos received message from peer 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN: BlockAnnounceHandshake Roles=4 BestBlockNumber=0 BestBlockHash=0x2d42e1c0b9e689cdf2b51a09621be564171bdde521fdb169fe538f69c0adb97a GenesisHash=0x2d42e1c0b9e689cdf2b51a09621be564171bdde521fdb169fe538f69c0adb97a	inbound.go:L43	pkg=network
2022-08-08T15:52:37-04:00 TRCE received handshake on notifications sub-protocol /gssmr_test/block-announces/1 from peer 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN, message is: BlockAnnounceHandshake Roles=4 BestBlockNumber=0 BestBlockHash=0x2d42e1c0b9e689cdf2b51a09621be564171bdde521fdb169fe538f69c0adb97a GenesisHash=0x2d42e1c0b9e689cdf2b51a09621be564171bdde521fdb169fe538f69c0adb97a	notifications.go:L158	pkg=network
2022-08-08T15:52:37-04:00 TRCE receiver: validating handshake using protocol /gssmr_test/block-announces/1	notifications.go:L172	pkg=network
2022-08-08T15:52:37-04:00 TRCE receiver: sent handshake to peer 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN using protocol /gssmr_test/block-announces/1	notifications.go:L201	pkg=network
2022-08-08T15:52:37-04:00 TRCE received stream using sub-protocol /2d42e1c0b9e689cdf2b51a09621be564171bdde521fdb169fe538f69c0adb97a/grandpa/1	service.go:L501	pkg=network
2022-08-08T15:52:37-04:00 TRCE received stream using sub-protocol /gssmr_test/transactions/1	service.go:L501	pkg=network
2022-08-08T15:52:37-04:00 TRCE host 12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos received message from peer 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN: transactionHandshake	inbound.go:L43	pkg=network
2022-08-08T15:52:37-04:00 TRCE received handshake on notifications sub-protocol /gssmr_test/transactions/1 from peer 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN, message is: transactionHandshake	notifications.go:L158	pkg=network
2022-08-08T15:52:37-04:00 TRCE receiver: validating handshake using protocol /gssmr_test/transactions/1	notifications.go:L172	pkg=network
2022-08-08T15:52:37-04:00 DBUG decoding grandpa handshake: 04	network.go:L107	pkg=grandpa
2022-08-08T15:52:37-04:00 TRCE host 12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos received message from peer 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN: GrandpaHandshake Roles=4	inbound.go:L43	pkg=network
2022-08-08T15:52:37-04:00 TRCE received handshake on notifications sub-protocol /2d42e1c0b9e689cdf2b51a09621be564171bdde521fdb169fe538f69c0adb97a/grandpa/1 from peer 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN, message is: GrandpaHandshake Roles=4	notifications.go:L158	pkg=network
2022-08-08T15:52:37-04:00 TRCE receiver: validating handshake using protocol /2d42e1c0b9e689cdf2b51a09621be564171bdde521fdb169fe538f69c0adb97a/grandpa/1	notifications.go:L172	pkg=network
2022-08-08T15:52:37-04:00 TRCE receiver: sent handshake to peer 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN using protocol /gssmr_test/transactions/1	notifications.go:L201	pkg=network
2022-08-08T15:52:37-04:00 DBUG our grandpa handshake encoded: 04	network.go:L49	pkg=grandpa
2022-08-08T15:52:37-04:00 TRCE receiver: sent handshake to peer 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN using protocol /2d42e1c0b9e689cdf2b51a09621be564171bdde521fdb169fe538f69c0adb97a/grandpa/1	notifications.go:L201	pkg=network
2022-08-08T15:52:37-04:00 WARN decodeMessage from network: [2 1 1 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]	network.go:L118	pkg=grandpa
2022-08-08T15:52:37-04:00 WARN decoded from network: ConsensusMessage Data=02010100000000000000000000000000000000000000 (*network.ConsensusMessage)
	err:<nil>	network.go:L121	pkg=grandpa
2022-08-08T15:52:37-04:00 TRCE host 12D3KooWLAYv1aYsKgVt4ZcJ2ZJJgkjy3vueamXLxvWDPdtB9fos received message from peer 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN: ConsensusMessage Data=02010100000000000000000000000000000000000000	inbound.go:L43	pkg=network
2022-08-08T15:52:37-04:00 TRCE received message on notifications sub-protocol /2d42e1c0b9e689cdf2b51a09621be564171bdde521fdb169fe538f69c0adb97a/grandpa/1 from peer 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN, message is: ConsensusMessage Data=02010100000000000000000000000000000000000000	notifications.go:L211	pkg=network
2022-08-08T15:52:37-04:00 WARN handling network message from 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN: ConsensusMessage Data=02010100000000000000000000000000000000000000 (*network.ConsensusMessage)	network.go:L126	pkg=grandpa
2022-08-08T15:52:37-04:00 WARN grandpa message from 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN: &{1 0 0} (*grandpa.V1NeighbourMessage)
	cm: ConsensusMessage Data=02010100000000000000000000000000000000000000
err:<nil>	network.go:L141	pkg=grandpa
2022-08-08T15:52:37-04:00 TRCE handling grandpa message: &{1 0 0}	message_handler.go:L44	pkg=grandpa

danforbes avatar Aug 09 '22 15:08 danforbes