network/libp2p: Occasional Unexpected incoming data in NotificationsOutSubstream on kusama validators

[alexggh]

On our kusama validators I've noticed a bunch of errors like this appearing: https://grafana.teleport.parity.io/goto/_HJl5ZtNg?orgId=1

ERROR tokio-runtime-worker sub-libp2p: Unexpected incoming data in `NotificationsOutSubstream`

The good news is that the metrics seems to be alright, so maybe the warning is harmless, but this seems to be a new error log, so we need to look into it to make sure there is nothing nefarious going on.

Wild idea, maybe it is somehow related to litep2p enablement on Kusama #7076 and the fact that we just had a new release, which prompted some of the nodes to upgrade.

cc: @paritytech/networking

[MrishoLukamba]

@skunert , I will look into it

[lexnv]

@MrishoLukamba I've created a small PR to handle more edge-cases and logging! Would still be good if you can have a look into this issue 🙏

I suspect the issue is linked to the latest release. While the network backends remain compatible, there may have been a change in the internal error propagation mechanism. For example, litep2p switched to the latest yamux upstream crate which aims to fix several missing io::errors.

The PR handles #7724:

• error cases on the poll_next and enter the termination state.
• distinguish between unexpected received data and io errors (I expect the log to hide an io error and not unexpected data)
• enrich the logs with the remote peer ID (this helps us identify if the remote is litep2p or libp2p etc)

[tdimitrov]

Got the same issue today. There is an additional logline with bytes field (on node kusama-validator-bhs5-1):

2025-02-27 22:42:26.503 ERROR tokio-runtime-worker sub-libp2p: Unexpected incoming data in `NotificationsOutSubstream` peer=PeerId("12D3KooWMVastr6oeLeLnF5dUt1xjc4vFAHeXbMRF2uA7AoJWwuF") bytes=b"\x02\x01\x01\0\0\0\0\0\0\0\xba)\0\0\0\0\0\0P4\xa0\x01"

The error is repeated multiple times.

The error also occured on bootnodes 0 and 1 but without the bytes field. I assume they run an older version. 12D3KooWMVastr6oeLeLnF5dUt1xjc4vFAHeXbMRF2uA7AoJWwuF is the only logged PeerId.

[lexnv]

One more datapoint with a different peerId and message:

2025-02-27 23:41:53.407 ERROR tokio-runtime-worker sub-libp2p: Unexpected incoming data in `NotificationsOutSubstream` peer=PeerId("12D3KooWEmQhe3wE9Xya4AfyNQMupFMZYMfebQiatZ9hprLBSJkH") bytes=b"\x02\x01\x01\0\0\0\0\0\0\0\xba)\0\0\0\0\0\0\xea6\xa0\x01"

Inspecting the authorities of the chain, I could not find these peerIDs (discovered 934/1001), probably they are running as a normal node. Scanning every node as next steps, will post more info soon