Substrate: Called on_block_announce with a bad PeerId

[tomaka]

I'm trying to debug this error log being printed at the moment.

For example, here is a selection of logs concerning a faulty peer:

2020-04-09 05:28:04.113 main-tokio- DEBUG sub-libp2p Libp2p => Connection (ConnectionId(TaskId(48824)),Listener { local_addr: "/ip4/10.128.0.9/tcp/30333", send_back_addr: "/ip4/35.198.126.58/tcp/46740" }) to Qmar25qYxcoLzPuzHDZ9nM7o38mNPqnKrZaksf3aY8rdM8 closed.
2020-04-09 05:28:04.113 main-tokio- DEBUG sub-libp2p Libp2p => Disconnected(Qmar25qYxcoLzPuzHDZ9nM7o38mNPqnKrZaksf3aY8rdM8): Was disabled.
2020-04-09 05:29:16.519 main-tokio- DEBUG sub-libp2p Libp2p => Connection (ConnectionId(TaskId(48992)),Listener { local_addr: "/ip4/10.128.0.9/tcp/30333", send_back_addr: "/ip4/35.198.126.58/tcp/47480" }) to Qmar25qYxcoLzPuzHDZ9nM7o38mNPqnKrZaksf3aY8rdM8 established.
2020-04-09 05:29:16.520 main-tokio- DEBUG sub-libp2p Libp2p => Connected(Qmar25qYxcoLzPuzHDZ9nM7o38mNPqnKrZaksf3aY8rdM8, Listener { local_addr: "/ip4/10.128.0.9/tcp/30333", send_back_addr: "/ip4/35.198.126.58/tcp/47480" }): Incoming connection
2020-04-09 05:29:16.520 main-tokio- DEBUG sub-libp2p PSM <= Incoming(Qmar25qYxcoLzPuzHDZ9nM7o38mNPqnKrZaksf3aY8rdM8, IncomingIndex(24268)).
2020-04-09 05:29:16.520 main-tokio- DEBUG sub-libp2p PSM => Accept(IncomingIndex(24268), PeerId("Qmar25qYxcoLzPuzHDZ9nM7o38mNPqnKrZaksf3aY8rdM8")): Enabling connections.
2020-04-09 05:29:16.520 main-tokio- DEBUG sub-libp2p Handler(PeerId("Qmar25qYxcoLzPuzHDZ9nM7o38mNPqnKrZaksf3aY8rdM8")) <= Enable
2020-04-09 05:29:17.146 main-tokio- DEBUG sub-libp2p Handler(PeerId("Qmar25qYxcoLzPuzHDZ9nM7o38mNPqnKrZaksf3aY8rdM8")) => Endpoint Listener { local_addr: "/ip4/10.128.0.9/tcp/30333", send_back_addr: "/ip4/35.198.126.58/tcp/47480" } open for custom protocols.
2020-04-09 05:29:17.146 main-tokio- DEBUG sub-libp2p External API <= Open(PeerId("Qmar25qYxcoLzPuzHDZ9nM7o38mNPqnKrZaksf3aY8rdM8"))
2020-04-09 05:29:17.146 main-tokio- TRACE sync Connecting Qmar25qYxcoLzPuzHDZ9nM7o38mNPqnKrZaksf3aY8rdM8
2020-04-09 05:29:17.146 main-tokio- TRACE sync New peer Qmar25qYxcoLzPuzHDZ9nM7o38mNPqnKrZaksf3aY8rdM8 Status { version: 6, min_supported_version: 3, roles: AUTHORITY, best_number: 1807687, best_hash: 0x0b5673dee66fa81b6c6d81bc9259865deda933b4c11d297e252bb160bf07c1c5, genesis_hash: 0xb0a8d493285c2df73290dfb7e61f870f17b41801197a149ca93654499ea3dafe, chain_status: [] }
2020-04-09 05:29:17.146 main-tokio- DEBUG sync Connected Qmar25qYxcoLzPuzHDZ9nM7o38mNPqnKrZaksf3aY8rdM8
2020-04-09 06:03:42.423 main-tokio- DEBUG sub-libp2p Libp2p => Connection (ConnectionId(TaskId(51883)),Listener { local_addr: "/ip4/10.128.0.9/tcp/30333", send_back_addr: "/ip4/35.198.126.58/tcp/49894" }) to Qmar25qYxcoLzPuzHDZ9nM7o38mNPqnKrZaksf3aY8rdM8 established.
2020-04-09 06:03:42.423 main-tokio- DEBUG sub-libp2p Handler(Qmar25qYxcoLzPuzHDZ9nM7o38mNPqnKrZaksf3aY8rdM8,ConnectionId(TaskId(51883))) <= Enable secondary connection
2020-04-09 06:03:42.677 main-tokio- DEBUG sub-libp2p Libp2p => Connection (ConnectionId(TaskId(51883)),Listener { local_addr: "/ip4/10.128.0.9/tcp/30333", send_back_addr: "/ip4/35.198.126.58/tcp/49894" }) to Qmar25qYxcoLzPuzHDZ9nM7o38mNPqnKrZaksf3aY8rdM8 closed.
2020-04-09 06:03:42.678 main-tokio- DEBUG sub-libp2p External API <= Closed(Qmar25qYxcoLzPuzHDZ9nM7o38mNPqnKrZaksf3aY8rdM8)
2020-04-09 06:03:42.678 main-tokio- TRACE sync Qmar25qYxcoLzPuzHDZ9nM7o38mNPqnKrZaksf3aY8rdM8 disconnected
2020-04-09 06:03:49.304 main-tokio- DEBUG sync Received block announcement 0x3e521bdd4f3b6bdb16e3c545b0bd7acb79a4686e8acf0d5305c301f8f7038462 with number 1808030 from Qmar25qYxcoLzPuzHDZ9nM7o38mNPqnKrZaksf3aY8rdM8
2020-04-09 06:03:49.305 main-tokio- ERROR sync 💔 Called on_block_announce with a bad peer ID

(I made the effort to find all the entries that are possibly relevant to this peer, but the logs are huge and it's not impossible that I have missed some)
(also, feel free to copy-paste these logs for better readability)

It seems to me that:

• A first connection to Qmar25qYxcoLzPuzHDZ9nM7o38mNPqnKrZaksf3aY8rdM8 is established with task ID 48992.
• The PSM approves it.
• We report to the external API that the substream has been opened.
• A second connection with task ID 51883 gets established to the same peer.
• That second connection (task ID 51883) gets closed shortly after (200ms)
• We report to the external API that the substream has been closed.

The last step seems wrong to me, as the first connection should still be alive. I didn't find anything in the logs about task ID 48992 other than what is above.

cc @romanb is that related to https://github.com/libp2p/rust-libp2p/pull/1546?

[tomaka]

Doesn't seem to happen anymore on my Google Cloud node after #5595 :tada:
I'm going to continue running the node to be sure, but this error was fairly frequent so the chances are high that it's fixed.

[dvc94ch]

This issue is still happening when trying to submit an extrinsic from a light client to a full node.

The logs on the client are:

[2020-04-19T13:30:10Z INFO  substrate_subxt] Creating Extrinsic with genesis hash 0xe42e94e47797345248579ed3a74bedba4edbc129938df79391247e14cc0abd29 and account nonce 8
[2020-04-19T13:30:10Z INFO  substrate_subxt::rpc] Submitting Extrinsic `0xb6c05835dab6fc26bfc7ac535d542b83dedb90a2b4c0b4bc3457f09c48f559c2`
[2020-04-19T13:30:10Z DEBUG substrate_subxt::rpc] Events storage key "26aa394eea5630e07c48ae0c9558cef780d41e5e16056765bc8461851072c9d7"
[2020-04-19T13:30:10Z DEBUG jsonrpc_core::io] Response: {"jsonrpc":"2.0","result":1,"id":4}.
[2020-04-19T13:30:10Z DEBUG yamux::connection] 0b1771be: new outbound (Stream 0b1771be/21) of (Connection 0b1771be Client (streams 6))
[2020-04-19T13:30:10Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /sup/light/2
[2020-04-19T13:30:10Z DEBUG sc_network::protocol::light_client_handler] no peer available to send request to
[2020-04-19T13:30:10Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /sup/light/2
[2020-04-19T13:30:10Z DEBUG libp2p_core::upgrade::apply] Successfully applied negotiated protocol
[2020-04-19T13:30:10Z DEBUG yamux::connection] 0b1771be: new outbound (Stream 0b1771be/23) of (Connection 0b1771be Client (streams 6))
[2020-04-19T13:30:10Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /sup/light/2
[2020-04-19T13:30:10Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /sup/light/2
[2020-04-19T13:30:11Z DEBUG libp2p_core::upgrade::apply] Successfully applied negotiated protocol

and the logs of the full node

2020-04-19 15:30:09.919 main-tokio- DEBUG afg  Round 1978: precommits: 2/2/2 weight, 2/2 actual
2020-04-19 15:30:10.533 main-tokio- DEBUG afg  Finding best chain containing block 0xb7d36c4d7935de15c3a8210ac1b3fc762c9b9502c39ad6de458e41932e9cb841 with number limit None
2020-04-19 15:30:10.533 main-tokio- DEBUG afg  Casting prevote for round 1979
2020-04-19 15:30:10.580 main-tokio- DEBUG afg  Announcing block 0xb7d3…b841 to peers which we voted on in round 1979 in set 0
2020-04-19 15:30:10.581 main-tokio- DEBUG sync  Reannouncing block 0xb7d36c4d7935de15c3a8210ac1b3fc762c9b9502c39ad6de458e41932e9cb841
2020-04-19 15:30:10.622 main-tokio- DEBUG sync  Received block announcement 0x4ad0378dc729c4c152bf14bdc4118c7cfd95f61c03f7f23e61d92db31e1c645a with number 456 from QmPEL7emGs49g6dCVDru7q9AF5h1navMvB8aJZJfcf9LCN
2020-04-19 15:30:10.622 main-tokio- ERROR sync  💔 Called on_block_announce with a bad peer ID
2020-04-19 15:30:10.634 main-tokio- DEBUG multistream_select::listener_select  Listener: confirming protocol: /ipfs/kad/1.0.0
2020-04-19 15:30:10.634 main-tokio- DEBUG multistream_select::listener_select  Listener: sent confirmed protocol: /ipfs/kad/1.0.0
2020-04-19 15:30:10.635 main-tokio- DEBUG libp2p_core::upgrade::apply  Successfully applied negotiated protocol
2020-04-19 15:30:10.652 main-tokio- DEBUG sync  Received block announcement 0xb7d36c4d7935de15c3a8210ac1b3fc762c9b9502c39ad6de458e41932e9cb841 with number 454 from QmV34iyTNb4gAG7bSPUrKXT7KTaWq7QWovMs4DP9cchfaj
2020-04-19 15:30:10.694 main-tokio- DEBUG yamux::connection::stream  cd528beb/17: eof
2020-04-19 15:30:10.734 main-tokio- DEBUG multistream_select::listener_select  Listener: confirming protocol: /sup/light/2
2020-04-19 15:30:10.735 main-tokio- DEBUG multistream_select::listener_select  Listener: sent confirmed protocol: /sup/light/2
2020-04-19 15:30:10.741 main-tokio- DEBUG libp2p_core::upgrade::apply  Successfully applied negotiated protocol
2020-04-19 15:30:10.844 main-tokio- DEBUG multistream_select::listener_select  Listener: confirming protocol: /sup/light/2
2020-04-19 15:30:10.844 main-tokio- DEBUG multistream_select::listener_select  Listener: sent confirmed protocol: /sup/light/2
2020-04-19 15:30:10.856 main-tokio- DEBUG libp2p_core::upgrade::apply  Successfully applied negotiated protocol
2020-04-19 15:30:10.888 main-tokio- DEBUG multistream_select::listener_select  Listener: confirming protocol: /sup/light/2
2020-04-19 15:30:10.888 main-tokio- DEBUG multistream_select::listener_select  Listener: sent confirmed protocol: /sup/light/2
2020-04-19 15:30:10.894 main-tokio- DEBUG afg  Completed round 1978, state = State { prevote_ghost: Some((0xb7d36c4d7935de15c3a8210ac1b3fc762c9b9502c39ad6de458e41932e9cb841, 454)), finalized: Some((0xb7d36c4d7935de15c3a8210ac1b3fc762c9b9502c39ad6de458e41932e9cb841, 454)), estimate: Some((0xb7d36c4d7935de15c3a8210ac1b3fc762c9b9502c39ad6de458e41932e9cb841, 454)), completable: true }, step = Some(Precommitted)
2020-04-19 15:30:10.895 main-tokio- DEBUG afg  Round 1978: prevotes: 2/2/2 weight, 2/2 actual
2020-04-19 15:30:10.895 main-tokio- DEBUG afg  Round 1978: precommits: 2/2/2 weight, 2/2 actual
2020-04-19 15:30:10.895 main-tokio- DEBUG afg  Committing: round_number = 1978, target_number = 454, target_hash = 0xb7d36c4d7935de15c3a8210ac1b3fc762c9b9502c39ad6de458e41932e9cb841
2020-04-19 15:30:10.895 main-tokio- DEBUG afg  Completed round 1978, state = State { prevote_ghost: Some((0xb7d36c4d7935de15c3a8210ac1b3fc762c9b9502c39ad6de458e41932e9cb841, 454)), finalized: Some((0xb7d36c4d7935de15c3a8210ac1b3fc762c9b9502c39ad6de458e41932e9cb841, 454)), estimate: Some((0xb7d36c4d7935de15c3a8210ac1b3fc762c9b9502c39ad6de458e41932e9cb841, 454)), completable: true }, step = Some(Precommitted)
2020-04-19 15:30:10.895 main-tokio- DEBUG afg  Round 1978: prevotes: 2/2/2 weight, 2/2 actual
2020-04-19 15:30:10.895 main-tokio- DEBUG afg  Round 1978: precommits: 2/2/2 weight, 2/2 actual
2020-04-19 15:30:10.895 main-tokio- DEBUG afg  Voter Sunshine Node concluded round 1978 in set 0. Estimate = Some(454), Finalized in round = Some(454)
2020-04-19 15:30:10.934 main-tokio- DEBUG libp2p_core::upgrade::apply  Successfully applied negotiated protocol
2020-04-19 15:30:11.198 main-tokio- DEBUG afg  Casting precommit for round 1979

the code to produce these logs is in https://github.com/paritytech/substrate-subxt/pull/91 and https://github.com/web3garden/sunshine-node/pull/54

and was invoked with the following cli:

./target/release/sunshine-node --base-path /tmp/alice --alice &> /tmp/alice.log
./target/release/sunshine-node --base-path /tmp/bob --bob
cargo run --example reserve_shares_and_watch --features light-client &> /tmp/lightclient.log

cc @4meta5

[tomaka]

Triaging.

To be more precise, the issue is that this remote sends a message on the notifications substream before the main substream is open. In other words, it is the sender that misbehaves.

I don't really know what could cause this from the top of my head, and if it doesn't cause any bug or misbehaviour I'm tempted to finish #5670, which would fix that issue by design.

[Demi-Marie]

Switching IP networks is a good way to cause these warnings. These warnings are not fatal and eventually go away.

[stiiifff]

FYI, getting this error message at every block on every full node when a light client is syncing (so not just when submitting an extrinsic).