Consensys / discovery

Java implementation of Discovery v5
Apache License 2.0
10 stars 22 forks source link

`NPE` during handshake #173

Closed tbenr closed 1 year ago

tbenr commented 1 year ago
[  101390] [  1501.844034] [service_teku-besu-0--teku]                      [I] 2023-08-25 01:35:24.257 DEBUG - Failed to read message [HandshakeMessagePacketImpl{header=Header{header={protocolId=discv5, version=0x0001, flag=HANDSHAKE, nonce=0xcd9d74c536ab3c6a75c26773, authDataSize=131}, authData=HandshakeAuthData{srcNodeId=0x91cee533c2d769ed9d975db8818b429c165caa62b4a0e1138d4ad5e87c2e0675, idSignature=0x6df7fa17d06442612f4440e0de394bdb96c98da79ac9b978debfdc1a7a46da8d4a58ccb789dc51b7ff04236b1b6f0e41f1c5749b4deccffe8af9ec1b8b16cefd, ephemeralPubKey=0x03dc1529c9919ab052d0ea5083bb4c746d537f59b708fcfc16ad022d0000b6b267, enrBytes=0x}}, cipherMsgSize=35}] from node Optional[NodeRecord{seq=3, publicKey=0x0351e208b8ac6f80b4571514262dcf5267e4bfafcfa6aacc04f50feb3c8909c93e, udpAddress=Optional[/10.0.20.100:4000], tcpAddress=Optional[/10.0.20.100:4000], asBase64=-Ly4QIXaXc24eRykr61igZRUBcpd-j6APdwf1XgnKKBYwSIJGEr8JF0pP5oJQiI6tlSJWnsuRcSIonkftH8h7Z--jUMDh2F0dG5ldHOI__________-EZXRoMpBpQ4ceBAAGZv__________gmlkgnY0gmlwhAoAFGSJc2VjcDI1NmsxoQNR4gi4rG-AtFcVFCYtz1Jn5L-vz6aqzAT1D-s8iQnJPohzeW5jbmV0cw-DdGNwgg-gg3VkcIIPoA, nodeId=0x91cee533c2d769ed9d975db8818b429c165caa62b4a0e1138d4ad5e87c2e0675, customFields={tcp=4000, udp=4000, attnets=0xffffffffffffffff, syncnets=0x0f, eth2=0x6943871e04000666ffffffffffffffff, ip=0x0a001464, id=V4, secp256k1=0x0351e208b8ac6f80b4571514262dcf5267e4bfafcfa6aacc04f50feb3c8909c93e}}] in status INITIAL
[  101390] [  1501.844034] [service_teku-besu-0--teku]                      [I] java.lang.NullPointerException: Cannot invoke "org.ethereum.beacon.discovery.pipeline.info.RequestInfo.getRequest()" because "requestInfo" is null
[  101390] [  1501.844034] [service_teku-besu-0--teku]                      [I] at org.ethereum.beacon.discovery.schema.NodeSession.lambda$cancelAllRequests$8(NodeSession.java:214) ~[discovery-22.12.0.jar:22.12.0]
[  101390] [  1501.844034] [service_teku-besu-0--teku]                      [I] at java.lang.Iterable.forEach(Iterable.java:75) ~[?:?]
[  101390] [  1501.844034] [service_teku-besu-0--teku]                      [I] at org.ethereum.beacon.discovery.schema.NodeSession.cancelAllRequests(NodeSession.java:210) ~[discovery-22.12.0.jar:22.12.0]
[  101390] [  1501.844034] [service_teku-besu-0--teku]                      [I] at org.ethereum.beacon.discovery.pipeline.handler.HandshakeMessagePacketHandler.markHandshakeAsFailed(HandshakeMessagePacketHandler.java:159) ~[discovery-22.12.0.jar:22.12.0]
[  101390] [  1501.844034] [service_teku-besu-0--teku]                      [I] at org.ethereum.beacon.discovery.pipeline.handler.HandshakeMessagePacketHandler.handle(HandshakeMessagePacketHandler.java:134) ~[discovery-22.12.0.jar:22.12.0]
[  101390] [  1501.844034] [service_teku-besu-0--teku]                      [I] at reactor.core.publisher.FluxPeekFuseable$PeekFuseableConditionalSubscriber.onNext(FluxPeekFuseable.java:489) ~[reactor-core-3.5.8.jar:3.5.8]
[  101390] [  1501.844034] [service_teku-besu-0--teku]                      [I] at reactor.core.publisher.FluxPeekFuseable$PeekFuseableConditionalSubscriber.onNext(FluxPeekFuseable.java:503) ~[reactor-core-3.5.8.jar:3.5.8]
[  101390] [  1501.844034] [service_teku-besu-0--teku]                      [I] at reactor.core.publisher.FluxPeekFuseable$PeekFuseableConditionalSubscriber.onNext(FluxPeekFuseable.java:503) ~[reactor-core-3.5.8.jar:3.5.8]
[  101390] [  1501.844034] [service_teku-besu-0--teku]                      [I] at reactor.core.publisher.FluxPeekFuseable$PeekFuseableConditionalSubscriber.onNext(FluxPeekFuseable.java:503) ~[reactor-core-3.5.8.jar:3.5.8]
[  101390] [  1501.844034] [service_teku-besu-0--teku]                      [I] at reactor.core.publisher.FluxPeekFuseable$PeekFuseableConditionalSubscriber.onNext(FluxPeekFuseable.java:503) ~[reactor-core-3.5.8.jar:3.5.8]
[  101390] [  1501.844034] [service_teku-besu-0--teku]                      [I] at reactor.core.publisher.FluxPeekFuseable$PeekFuseableConditionalSubscriber.onNext(FluxPeekFuseable.java:503) ~[reactor-core-3.5.8.jar:3.5.8]
[  101390] [  1501.844034] [service_teku-besu-0--teku]                      [I] at reactor.core.publisher.FluxPeekFuseable$PeekFuseableConditionalSubscriber.onNext(FluxPeekFuseable.java:503) ~[reactor-core-3.5.8.jar:3.5.8]
[  101390] [  1501.844034] [service_teku-besu-0--teku]                      [I] at reactor.core.publisher.FluxPeekFuseable$PeekFuseableConditionalSubscriber.onNext(FluxPeekFuseable.java:503) ~[reactor-core-3.5.8.jar:3.5.8]
[  101390] [  1501.844034] [service_teku-besu-0--teku]                      [I] at reactor.core.publisher.FluxReplay$SizeBoundReplayBuffer.replayNormal(FluxReplay.java:877) ~[reactor-core-3.5.8.jar:3.5.8]
[  101390] [  1501.844034] [service_teku-besu-0--teku]                      [I] at reactor.core.publisher.FluxReplay$SizeBoundReplayBuffer.replay(FluxReplay.java:965) ~[reactor-core-3.5.8.jar:3.5.8]
[  101390] [  1501.844034] [service_teku-besu-0--teku]                      [I] at reactor.core.publisher.ReplayProcessor.tryEmitNext(ReplayProcessor.java:508) ~[reactor-core-3.5.8.jar:3.5.8]
[  101390] [  1501.844034] [service_teku-besu-0--teku]                      [I] at reactor.core.publisher.InternalManySink.emitNext(InternalManySink.java:27) ~[reactor-core-3.5.8.jar:3.5.8]
[  101390] [  1501.844034] [service_teku-besu-0--teku]                      [I] at reactor.core.publisher.ReplayProcessor.onNext(ReplayProcessor.java:495) ~[reactor-core-3.5.8.jar:3.5.8]
[  101390] [  1501.844034] [service_teku-besu-0--teku]                      [I] at reactor.core.publisher.FluxCreate$IgnoreSink.next(FluxCreate.java:639) ~[reactor-core-3.5.8.jar:3.5.8]
[  101390] [  1501.844034] [service_teku-besu-0--teku]                      [I] at reactor.core.publisher.FluxCreate$SerializedFluxSink.next(FluxCreate.java:161) ~[reactor-core-3.5.8.jar:3.5.8]
[  101390] [  1501.844034] [service_teku-besu-0--teku]                      [I] at org.ethereum.beacon.discovery.pipeline.PipelineImpl.push(PipelineImpl.java:52) ~[discovery-22.12.0.jar:22.12.0]
[  101390] [  1501.844034] [service_teku-besu-0--teku]                      [I] at reactor.core.publisher.FluxPeekFuseable$PeekFuseableConditionalSubscriber.onNext(FluxPeekFuseable.java:489) [reactor-core-3.5.8.jar:3.5.8]
[  101390] [  1501.844034] [service_teku-besu-0--teku]                      [I] at reactor.core.publisher.FluxReplay$SizeBoundReplayBuffer.replayNormal(FluxReplay.java:877) [reactor-core-3.5.8.jar:3.5.8]
[  101390] [  1501.844040] [service_teku-besu-0--teku]                      [I] at reactor.core.publisher.FluxReplay$SizeBoundReplayBuffer.replay(FluxReplay.java:965) [reactor-core-3.5.8.jar:3.5.8]
[  101390] [  1501.844040] [service_teku-besu-0--teku]                      [I] at reactor.core.publisher.ReplayProcessor.tryEmitNext(ReplayProcessor.java:508) [reactor-core-3.5.8.jar:3.5.8]
[  101390] [  1501.844040] [service_teku-besu-0--teku]                      [I] at reactor.core.publisher.InternalManySink.emitNext(InternalManySink.java:27) [reactor-core-3.5.8.jar:3.5.8]
[  101390] [  1501.844040] [service_teku-besu-0--teku]                      [I] at reactor.core.publisher.ReplayProcessor.onNext(ReplayProcessor.java:495) [reactor-core-3.5.8.jar:3.5.8]
[  101390] [  1501.844040] [service_teku-besu-0--teku]                      [I] at reactor.core.publisher.FluxCreate$IgnoreSink.next(FluxCreate.java:639) [reactor-core-3.5.8.jar:3.5.8]
[  101390] [  1501.844040] [service_teku-besu-0--teku]                      [I] at reactor.core.publisher.FluxCreate$SerializedFluxSink.next(FluxCreate.java:161) [reactor-core-3.5.8.jar:3.5.8]
[  101390] [  1501.844040] [service_teku-besu-0--teku]                      [I] at org.ethereum.beacon.discovery.network.IncomingMessageSink.channelRead0(IncomingMessageSink.java:31) [discovery-22.12.0.jar:22.12.0]
[  101390] [  1501.844040] [service_teku-besu-0--teku]                      [I] at org.ethereum.beacon.discovery.network.IncomingMessageSink.channelRead0(IncomingMessageSink.java:20) [discovery-22.12.0.jar:22.12.0]
[  101390] [  1501.844040] [service_teku-besu-0--teku]                      [I] at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:99) [netty-transport-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844040] [service_teku-besu-0--teku]                      [I] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) [netty-transport-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844040] [service_teku-besu-0--teku]                      [I] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) [netty-transport-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844040] [service_teku-besu-0--teku]                      [I] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) [netty-transport-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844040] [service_teku-besu-0--teku]                      [I] at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103) [netty-codec-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844040] [service_teku-besu-0--teku]                      [I] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) [netty-transport-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844040] [service_teku-besu-0--teku]                      [I] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) [netty-transport-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844040] [service_teku-besu-0--teku]                      [I] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) [netty-transport-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844040] [service_teku-besu-0--teku]                      [I] at io.netty.handler.logging.LoggingHandler.channelRead(LoggingHandler.java:280) [netty-handler-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844040] [service_teku-besu-0--teku]                      [I] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442) [netty-transport-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844040] [service_teku-besu-0--teku]                      [I] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) [netty-transport-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844040] [service_teku-besu-0--teku]                      [I] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) [netty-transport-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844040] [service_teku-besu-0--teku]                      [I] at io.netty.handler.traffic.AbstractTrafficShapingHandler.channelRead(AbstractTrafficShapingHandler.java:506) [netty-handler-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844040] [service_teku-besu-0--teku]                      [I] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442) [netty-transport-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844040] [service_teku-besu-0--teku]                      [I] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) [netty-transport-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844040] [service_teku-besu-0--teku]                      [I] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) [netty-transport-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844040] [service_teku-besu-0--teku]                      [I] at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) [netty-transport-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844040] [service_teku-besu-0--teku]                      [I] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440) [netty-transport-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844045] [service_teku-besu-0--teku]                      [I] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) [netty-transport-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844045] [service_teku-besu-0--teku]                      [I] at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) [netty-transport-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844045] [service_teku-besu-0--teku]                      [I] at io.netty.channel.nio.AbstractNioMessageChannel$NioMessageUnsafe.read(AbstractNioMessageChannel.java:97) [netty-transport-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844517] [service_teku-besu-0--teku]                      [I] at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788) [netty-transport-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844517] [service_teku-besu-0--teku]                      [I] at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724) [netty-transport-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844517] [service_teku-besu-0--teku]                      [I] at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650) [netty-transport-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844517] [service_teku-besu-0--teku]                      [I] at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562) [netty-transport-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844517] [service_teku-besu-0--teku]                      [I] at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) [netty-common-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844517] [service_teku-besu-0--teku]                      [I] at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [netty-common-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844517] [service_teku-besu-0--teku]                      [I] at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [netty-common-4.1.96.Final.jar:4.1.96.Final]
[  101390] [  1501.844517] [service_teku-besu-0--teku]                      [I] at java.lang.Thread.run(Thread.java:833) [?:?]
[  101390] [  1501.865032] [service_teku-besu-0--teku]                      [I] 2023-08-25 01:35:24.299 DEBUG - Cancelling all requests in session NodeSession{0x91cee533c2d769ed9d975db8818b429c165caa62b4a0e1138d4ad5e87c2e0675 (INITIAL)}
[  101390] [  1501.865053] [service_teku-besu-0--teku]                      [I] 2023-08-25 01:35:24.299 DEBUG - Acct schedule not ok: 2645 > 2*1000 from ChannelTC901969167

full trace here: https://ethereum.antithesis.com/report/eL6y6R864ppt1SUzoKzXGu5pubdUU9t1/1yGq_5zY8JIxqoRE8q4syRZv8CHoyAQY1Y-_X4dvBS8.html?auth=v2.public.eyJzY29wZSI6eyJSZXBvcnRTY29wZVYxIjp7ImFzc2V0IjoiMXlHcV81elk4Skl4cW9SRThxNHN5Ulp2OENIb3lBUVkxWS1fWDRkdkJTOC5odG1sIiwicmVwb3J0X2lkIjoiZUw2eTZSODY0cHB0MVNVem9LelhHdTVwdWJkVVU5dDEifX0sIm5iZiI6IjIwMjMtMDgtMzBUMDc6NTQ6NTRaIn0bWJGgX4B6hXPiBi0zIdZZYvCKM-JXmKBBzawc7kMTjfimv2r-fgYGXi3_Pd-lFayXg8HwWMpkjvLXt6YZcTMK