besu icon indicating copy to clipboard operation
besu copied to clipboard
verified publisher icon hyperledger

besu-nimbus Thread Starvation and GraphQL Errors

Open siladu opened this issue 3 years ago • 0 comments

Nimbus still syncing, so besu hasn't started syncing yet. Config below.

Logs full of ERROR "RoutingContext","message":"Unhandled exception in router" and WARN "JsonRpcService","message":"Rejecting new connection from <redacted>. Max 80 active connections limit reached"

DEBUG logs suggest this might be GraphQL request, but hard to tell if they are correlated

{"@timestamp":"2022-09-26T01:04:26,262","level":"DEBUG","thread":"vert.x-eventloop-thread-1","class":"RoutingContext","message":"RoutingContext failure (500)","throwable":" io.vertx.core.http.HttpClosedException: Connection was closed\n"}
{"@timestamp":"2022-09-26T01:04:26,263","level":"ERROR","thread":"vert.x-eventloop-thread-1","class":"RoutingContext","message":"Unhandled exception in router","throwable":" io.vertx.core.http.HttpClosedException: Connection was closed\n"}
{"@timestamp":"2022-09-26T01:04:26,263","level":"DEBUG","thread":"vert.x-eventloop-thread-1","class":"JsonRpcService","message":"Connection closed from <redacted>:33476. Total of active connections: 80/80","throwable":""}
{"@timestamp":"2022-09-26T01:04:26,265","level":"DEBUG","thread":"vert.x-eventloop-thread-1","class":"GraphQLHttpService","message":"Error handling GraphQL request","throwable":" io.vertx.core.json.DecodeException: Failed to decode:Unrecognized field \"id\" (class org.hyperledger.besu.ethereum.api.graphql.internal.response.GraphQLJsonRequest), not marked as ignorable (3 known properties: \"query\", \"operationName\", \"variables\"])\n at [Source: (String)\"{\"id\":1,\"jsonrpc\":\"2.0\",\"method\":\"web3_clientVersion\",\"params\":null}\"; line: 1, column: 8] (through reference chain: org.hyperledger.besu.ethereum.api.graphql.internal.response.GraphQLJsonRequest[\"id\"])\n\tat io.vertx.core.json.jackson.DatabindCodec.fromParser(DatabindCodec.java:129)\n\tat io.vertx.core.json.jackson.DatabindCodec.fromString(DatabindCodec.java:90)\n\tat io.vertx.core.json.Json.decodeValue(Json.java:83)\n\tat org.hyperledger.besu.ethereum.api.graphql.GraphQLHttpService.handleGraphQLRequest(GraphQLHttpService.java:315)\n\tat io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1212)\n\tat io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:126)\n\tat io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)\n\tat io.vertx.ext.web.handler.impl.TimeoutHandlerImpl.handle(TimeoutHandlerImpl.java:45)\n\tat io.vertx.ext.web.handler.impl.TimeoutHandlerImpl.handle(TimeoutHandlerImpl.java:27)\n\tat io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1212)\n\tat io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:163)\n\tat io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)\n\tat io.vertx.ext.web.handler.impl.BodyHandlerImpl$BHandler.doEnd(BodyHandlerImpl.java:313)\n\tat io.vertx.ext.web.handler.impl.BodyHandlerImpl$BHandler.end(BodyHandlerImpl.java:290)\n\tat io.vertx.ext.web.handler.impl.BodyHandlerImpl.lambda$handle$0(BodyHandlerImpl.java:86)\n\tat io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)\n\tat io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:63)\n\tat io.vertx.core.http.impl.HttpEventHandler.handleEnd(HttpEventHandler.java:76)\n\tat io.vertx.core.http.impl.Http1xServerRequest.onEnd(Http1xServerRequest.java:561)\n\tat io.vertx.core.http.impl.Http1xServerRequest.handleEnd(Http1xServerRequest.java:544)\n\tat io.vertx.core.impl.EventLoopContext.execute(EventLoopContext.java:71)\n\tat io.vertx.core.impl.DuplicatedContext.execute(DuplicatedContext.java:163)\n\tat io.vertx.core.http.impl.Http1xServerConnection.onEnd(Http1xServerConnection.java:191)\n\tat io.vertx.core.http.impl.Http1xServerConnection.onContent(Http1xServerConnection.java:181)\n\tat io.vertx.core.http.impl.Http1xServerConnection.handleOther(Http1xServerConnection.java:161)\n\tat io.vertx.core.http.impl.Http1xServerConnection.handleMessage(Http1xServerConnection.java:149)\n\tat io.vertx.core.net.impl.ConnectionBase.read(ConnectionBase.java:155)\n\tat io.vertx.core.net.impl.VertxHandler.channelRead(VertxHandler.java:153)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)\n\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)\n\tat io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:93)\n\tat io.netty.handler.codec.http.websocketx.extensions.WebSocketServerExtensionHandler.channelRead(WebSocketServerExtensionHandler.java:99)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)\n\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)\n\tat io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)\n\tat io.netty.handler.codec.MessageToMessageCodec.channelRead(MessageToMessageCodec.java:111)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)\n\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)\n\tat io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:327)\n\tat io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:299)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)\n\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)\n\tat io.vertx.core.http.impl.Http1xOrH2CHandler.end(Http1xOrH2CHandler.java:61)\n\tat io.vertx.core.http.impl.Http1xOrH2CHandler.channelRead(Http1xOrH2CHandler.java:38)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)\n\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)\n\tat io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)\n\tat io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)\n\tat io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:800)\n\tat io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:487)\n\tat io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:385)\n\tat io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)\n\tat io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)\n\tat io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n\tat java.base/java.lang.Thread.run(Thread.java:829)\nCaused by: com.fasterxml.jackson.databind.exc.UnrecognizedPropertyException: Unrecognized field \"id\" (class org.hyperledger.besu.ethereum.api.graphql.internal.response.GraphQLJsonRequest), not marked as ignorable (3 known properties: \"query\", \"operationName\", \"variables\"])\n at [Source: (String)\"{\"id\":1,\"jsonrpc\":\"2.0\",\"method\":\"web3_clientVersion\",\"params\":null}\"; line: 1, column: 8] (through reference chain: org.hyperledger.besu.ethereum.api.graphql.internal.response.GraphQLJsonRequest[\"id\"])\n\tat com.fasterxml.jackson.databind.exc.UnrecognizedPropertyException.from(UnrecognizedPropertyException.java:61)\n\tat com.fasterxml.jackson.databind.DeserializationContext.handleUnknownProperty(DeserializationContext.java:1127)\n\tat com.fasterxml.jackson.databind.deser.std.StdDeserializer.handleUnknownProperty(StdDeserializer.java:2023)\n\tat com.fasterxml.jackson.databind.deser.BeanDeserializerBase.handleUnknownProperty(BeanDeserializerBase.java:1700)\n\tat com.fasterxml.jackson.databind.deser.BeanDeserializerBase.handleUnknownVanilla(BeanDeserializerBase.java:1678)\n\tat com.fasterxml.jackson.databind.deser.BeanDeserializer.vanillaDeserialize(BeanDeserializer.java:319)\n\tat com.fasterxml.jackson.databind.deser.BeanDeserializer.deserialize(BeanDeserializer.java:176)\n\tat com.fasterxml.jackson.databind.deser.DefaultDeserializationContext.readRootValue(DefaultDeserializationContext.java:323)\n\tat com.fasterxml.jackson.databind.ObjectMapper._readValue(ObjectMapper.java:4650)\n\tat com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:2831)\n\tat io.vertx.core.json.jackson.DatabindCodec.fromParser(DatabindCodec.java:126)\n\t... 61 more\n"}

Another one involved eth_getBalance which doesn't seem like it should come from the CL...

{"@timestamp":"2022-09-26T01:05:05,367","level":"DEBUG","thread":"vert.x-eventloop-thread-1","class":"GraphQLHttpService","message":"Error handling GraphQL request","throwable":" io.vertx.core.json.DecodeException: Failed to decode:Unrecognized field \"id\" (class org.hyperledger.besu.ethereum.api.graphql.internal.response.GraphQLJsonRequest), not marked as ignorable (3 known properties: \"query\", \"operationName\", \"variables\"])\n at [Source: (String)\"{\"id\":1,\"jsonrpc\":\"2.0\",\"method\":\"eth_getBalance\",\"params\":[\"Failed to decode:Unrecognized field \\\"id\\\" (c\",\"latest\"]}\"; line: 1, column: 8] (through reference chain: org.hyperledger.besu.ethereum.api.graphql.internal.response.GraphQLJsonRequest[\"id\"])\n\tat io.vertx.core.json.jackson.DatabindCodec.fromParser(DatabindCodec.java:129)\n\tat io.vertx.core.json.jackson.DatabindCodec.fromString(DatabindCodec.java:90)\n\tat io.vertx.core.json.Json.decodeValue(Json.java:83)\n\tat org.hyperledger.besu.ethereum.api.graphql.GraphQLHttpService.handleGraphQLRequest(GraphQLHttpService.java:315)\n\tat io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1212)\n\tat io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:126)\n\tat io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)\n\tat io.vertx.ext.web.handler.impl.TimeoutHandlerImpl.handle(TimeoutHandlerImpl.java:45)\n\tat io.vertx.ext.web.handler.impl.TimeoutHandlerImpl.handle(TimeoutHandlerImpl.java:27)\n\tat io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1212)\n\tat io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:163)\n\tat io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:141)\n\tat io.vertx.ext.web.handler.impl.BodyHandlerImpl$BHandler.doEnd(BodyHandlerImpl.java:313)\n\tat io.vertx.ext.web.handler.impl.BodyHandlerImpl$BHandler.end(BodyHandlerImpl.java:290)\n\tat io.vertx.ext.web.handler.impl.BodyHandlerImpl.lambda$handle$0(BodyHandlerImpl.java:86)\n\tat io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)\n\tat io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:63)\n\tat io.vertx.core.http.impl.HttpEventHandler.handleEnd(HttpEventHandler.java:76)\n\tat io.vertx.core.http.impl.Http1xServerRequest.onEnd(Http1xServerRequest.java:561)\n\tat io.vertx.core.http.impl.Http1xServerRequest.handleEnd(Http1xServerRequest.java:544)\n\tat io.vertx.core.impl.EventLoopContext.execute(EventLoopContext.java:71)\n\tat io.vertx.core.impl.DuplicatedContext.execute(DuplicatedContext.java:163)\n\tat io.vertx.core.http.impl.Http1xServerConnection.onEnd(Http1xServerConnection.java:191)\n\tat io.vertx.core.http.impl.Http1xServerConnection.onContent(Http1xServerConnection.java:181)\n\tat io.vertx.core.http.impl.Http1xServerConnection.handleOther(Http1xServerConnection.java:161)\n\tat io.vertx.core.http.impl.Http1xServerConnection.handleMessage(Http1xServerConnection.java:149)\n\tat io.vertx.core.net.impl.ConnectionBase.read(ConnectionBase.java:155)\n\tat io.vertx.core.net.impl.VertxHandler.channelRead(VertxHandler.java:153)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)\n\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)\n\tat io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:93)\n\tat io.netty.handler.codec.http.websocketx.extensions.WebSocketServerExtensionHandler.channelRead(WebSocketServerExtensionHandler.java:99)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)\n\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)\n\tat io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)\n\tat io.netty.handler.codec.MessageToMessageCodec.channelRead(MessageToMessageCodec.java:111)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)\n\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)\n\tat io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:327)\n\tat io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:299)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)\n\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)\n\tat io.vertx.core.http.impl.Http1xOrH2CHandler.end(Http1xOrH2CHandler.java:61)\n\tat io.vertx.core.http.impl.Http1xOrH2CHandler.channelRead(Http1xOrH2CHandler.java:38)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)\n\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)\n\tat io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)\n\tat io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)\n\tat io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:800)\n\tat io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:487)\n\tat io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:385)\n\tat io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)\n\tat io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)\n\tat io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n\tat java.base/java.lang.Thread.run(Thread.java:829)\nCaused by: com.fasterxml.jackson.databind.exc.UnrecognizedPropertyException: Unrecognized field \"id\" (class org.hyperledger.besu.ethereum.api.graphql.internal.response.GraphQLJsonRequest), not marked as ignorable (3 known properties: \"query\", \"operationName\", \"variables\"])\n at [Source: (String)\"{\"id\":1,\"jsonrpc\":\"2.0\",\"method\":\"eth_getBalance\",\"params\":[\"Failed to decode:Unrecognized field \\\"id\\\" (c\",\"latest\"]}\"; line: 1, column: 8] (through reference chain: org.hyperledger.besu.ethereum.api.graphql.internal.response.GraphQLJsonRequest[\"id\"])\n\tat com.fasterxml.jackson.databind.exc.UnrecognizedPropertyException.from(UnrecognizedPropertyException.java:61)\n\tat com.fasterxml.jackson.databind.DeserializationContext.handleUnknownProperty(DeserializationContext.java:1127)\n\tat com.fasterxml.jackson.databind.deser.std.StdDeserializer.handleUnknownProperty(StdDeserializer.java:2023)\n\tat com.fasterxml.jackson.databind.deser.BeanDeserializerBase.handleUnknownProperty(BeanDeserializerBase.java:1700)\n\tat com.fasterxml.jackson.databind.deser.BeanDeserializerBase.handleUnknownVanilla(BeanDeserializerBase.java:1678)\n\tat com.fasterxml.jackson.databind.deser.BeanDeserializer.vanillaDeserialize(BeanDeserializer.java:319)\n\tat com.fasterxml.jackson.databind.deser.BeanDeserializer.deserialize(BeanDeserializer.java:176)\n\tat com.fasterxml.jackson.databind.deser.DefaultDeserializationContext.readRootValue(DefaultDeserializationContext.java:323)\n\tat com.fasterxml.jackson.databind.ObjectMapper._readValue(ObjectMapper.java:4650)\n\tat com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:2831)\n\tat io.vertx.core.json.jackson.DatabindCodec.fromParser(DatabindCodec.java:126)\n\t... 61 more\n"}

Nimbus logs contain: WRN 2022-09-26 01:39:03.126+00:00 Eth1 chain monitoring failure, restarting topics="eth1" err="getBlockByHash(m.dataProvider,\n BlockHash(m.depositsChain.finalizedBlockHash.data)) failed 3 times. Last error: Parameter [result] expected JObject but got JNull"

Screenshot 2022-09-26 at 11 11 34

AWS t3.xlarge, prd-besu-clc-nimbus-ohio-mainnet-nightly-checkpoint-sync

Nimbus command: nimbus_beacon_node --data-dir=/data --network=mainnet --nat=extip:<redacted> --web3-url=http://<redacted>:8551 --web3-force-polling=yes --non-interactive --rest --jwt-secret=/config/jwt-secret.hex --log-level=info

Besu: standard CLC build with X_CHECKPOINT + BONSAI, with -Xmx5g GraphQL config:

# graphql
graphql-http-enabled=true
graphql-http-host="0.0.0.0"
graphql-http-port=8547
graphql-http-cors-origins=["all"]

siladu avatar Sep 26 '22 01:09 siladu