WARN - AbstractRouter internal error on message control / Outbound gossip stream not initialized or protocol is missing

[benjaminion]

Very occasionally seeing these. They seem to be harmless, if noisy.

07:07:02.678 WARN  - AbstractRouter internal error on message control {
  graft {
    topicID: "/eth2/e7a75d5a/voluntary_exit/ssz_snappy"
  }
}
 from peer PeerHandler(peerId=16Uiu2HAm8LjxjopMfuFTjSdiz8owatVvN3gqzRaZPrayM2fdv1Qc, stream=P2PChannelOverNetty(nettyChannel=[id: 0x687190af/1540/false, L:Mux[/192.168.1.203:9000-687190af/1540/false] - R:Mu>
io.libp2p.core.InternalErrorException: Outbound gossip stream not initialized or protocol is missing
        at io.libp2p.pubsub.gossip.GossipRouterKt.getOutboundProtocol(GossipRouter.kt:38) ~[jvm-libp2p-minimal-0.5.7-RELEASE.jar:?]
        at io.libp2p.pubsub.gossip.GossipRouterKt.getOutboundGossipProtocol(GossipRouter.kt:40) ~[jvm-libp2p-minimal-0.5.7-RELEASE.jar:?]
        at io.libp2p.pubsub.gossip.GossipRouter.enqueuePrune(GossipRouter.kt:444) ~[jvm-libp2p-minimal-0.5.7-RELEASE.jar:?]
        at io.libp2p.pubsub.gossip.GossipRouter.prune(GossipRouter.kt:429) ~[jvm-libp2p-minimal-0.5.7-RELEASE.jar:?]
        at io.libp2p.pubsub.gossip.GossipRouter.handleGraft(GossipRouter.kt:172) ~[jvm-libp2p-minimal-0.5.7-RELEASE.jar:?]
        at io.libp2p.pubsub.gossip.GossipRouter.processControlMessage(GossipRouter.kt:148) ~[jvm-libp2p-minimal-0.5.7-RELEASE.jar:?]
        at io.libp2p.pubsub.gossip.GossipRouter.processControl(GossipRouter.kt:239) ~[jvm-libp2p-minimal-0.5.7-RELEASE.jar:?]
        at io.libp2p.pubsub.AbstractRouter.onInbound(AbstractRouter.kt:177) [jvm-libp2p-minimal-0.5.7-RELEASE.jar:?]
        at io.libp2p.etc.util.P2PService.streamInbound(P2PService.kt:171) ~[jvm-libp2p-minimal-0.5.7-RELEASE.jar:?]
        at io.libp2p.etc.util.P2PService$StreamHandler$channelRead$1.invoke(P2PService.kt:51) ~[jvm-libp2p-minimal-0.5.7-RELEASE.jar:?]
        at io.libp2p.etc.util.P2PService$StreamHandler$channelRead$1.invoke(P2PService.kt:36) ~[jvm-libp2p-minimal-0.5.7-RELEASE.jar:?]
        at io.libp2p.etc.util.P2PService$runOnEventThread$1.run(P2PService.kt:231) [jvm-libp2p-minimal-0.5.7-RELEASE.jar:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:830) [?:?]

Version: teku/v0.12.7-dev-9b0402d7/linux-x86_64/-privatebuild-openjdk64bitservervm-java-13

[Nashatyrev]

Hm, looks the same as #2620 which is already fixed and merged 🤔

[benjaminion]

User reported occurence of this issue today:

Version: teku/v0.12.14+9-gc90a489/linux-x86_64/-ubuntu-openjdk64bitservervm-java-11

WARN  - AbstractRouter internal error on message control {
  graft {
    topicID: "/eth2/e7a75d5a/proposer_slashing/ssz_snappy"
  }
}
 from peer PeerHandler(peerId=16Uiu2HAmSgmoXGRHWcqdcxxa7d76T49R9mTh2pGh7veUzf5kcGdc, stream=P2PChannelOverNetty(nettyChannel=[id: 0xef2a147a/19/false, L:Mux[/192.168.0.44:9001-ef2a147a/19/false] - R:Mux[/104.248.56.138:54078-ef2a147a/19/false]], isInitiator=false))
io.libp2p.core.InternalErrorException: Outbound gossip stream not initialized or protocol is missing

[Nashatyrev]

Ouch, right today was thinking if I need to close this

[Nashatyrev]

Found why this WARN still appears in rare cases.

[benjaminion]

Cool - I've started getting a lot of these myself today after not seeing any for ages.

Also this which seems new but likely related:

20:55:47.258 WARN  - Exception in gossipsub heartbeat
io.libp2p.core.InternalErrorException: Outbound gossip stream not initialized or protocol is missing
        at io.libp2p.pubsub.gossip.GossipRouterKt.getOutboundProtocol(GossipRouter.kt:40) ~[jvm-libp2p-minimal-0.5.8-RELEASE.jar:?]
        at io.libp2p.pubsub.gossip.GossipRouterKt.getOutboundGossipProtocol(GossipRouter.kt:42) ~[jvm-libp2p-minimal-0.5.8-RELEASE.jar:?]
        at io.libp2p.pubsub.gossip.GossipRouter.enqueuePrune(GossipRouter.kt:457) ~[jvm-libp2p-minimal-0.5.8-RELEASE.jar:?]
        at io.libp2p.pubsub.gossip.GossipRouter.prune(GossipRouter.kt:442) ~[jvm-libp2p-minimal-0.5.8-RELEASE.jar:?]
        at io.libp2p.pubsub.gossip.GossipRouter.heartbeat(GossipRouter.kt:371) [jvm-libp2p-minimal-0.5.8-RELEASE.jar:?]
        at io.libp2p.pubsub.gossip.GossipRouter.catchingHeartbeat(GossipRouter.kt:325) [jvm-libp2p-minimal-0.5.8-RELEASE.jar:?]
        at io.libp2p.pubsub.gossip.GossipRouter.access$catchingHeartbeat(GossipRouter.kt:47) [jvm-libp2p-minimal-0.5.8-RELEASE.jar:?]
        at io.libp2p.pubsub.gossip.GossipRouter$heartbeatTask$2$1.invoke(GossipRouter.kt:66) [jvm-libp2p-minimal-0.5.8-RELEASE.jar:?]
        at io.libp2p.pubsub.gossip.GossipRouter$heartbeatTask$2$1.invoke(GossipRouter.kt:47) [jvm-libp2p-minimal-0.5.8-RELEASE.jar:?]
        at io.libp2p.pubsub.gossip.GossipRouterKt$sam$java_lang_Runnable$0.run(GossipRouter.kt) [jvm-libp2p-minimal-0.5.8-RELEASE.jar:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:830) [?:?]

Version: teku/v0.12.15-dev-b792cddc/linux-x86_64/-privatebuild-openjdk64bitservervm-java-13

[Nashatyrev]

Created the fix PR.
The latter WARN should disappear as well
However the latter trace is strange: I supposed that outbound stream can be missing just in case when the inbound stream is just created. Here the outbound stream is missing when we are doing heartbeat, so its highly likely that outbound stream is missing for a longer period

[Nashatyrev]

@benjaminion what network are you now seeing those WARNs?

[benjaminion]

This is Medalla.

[Nashatyrev]

The log WARN was already fixed in Libp2p 0.6.0 and merged to Teku.
Opened a separate Libp2p issue on the suspicious later stacktrace: libp2p/jvm-libp2p#163
So closing this.