JsonRpcExecutorHandler | Error streaming JSON-RPC response

[i-am-logger]

I started receiving the below error after the merge

execution_1 | 2022-09-15 14:03:47.422+00:00 | vert.x-worker-thread-1 | ERROR | JsonRpcExecutorHandler | Error streaming JSON-RPC response
execution_1 | io.netty.channel.StacklessClosedChannelException
execution_1 | at io.netty.channel.AbstractChannel$AbstractUnsafe.write(Object, ChannelPromise)(Unknown Source)

Frequency: every few minutes

besu besu/v22.7.2/linux-x86_64/openjdk-java-11 via eth-docker
ubuntu 22.04
docker : 20.10.12

[i-am-logger]

also seeing this

execution_1 | 2022-09-15 14:10:39.575+00:00 | vert.x-worker-thread-0 | INFO | EngineForkchoiceUpdated | VALID for fork-choice-update: head: 0x3033e6cdbafa6907b10fc704d38b4a2177b34926b15a79af4ced9165ff799b8b, finalized: 0x9aa91ed7cbb4327905efde1f89d8b86e77f1db3a4ac99236748dd28abf1cf25d, safeBlockHash: 0xcdf9ed89b0c43cda17398dc4da9cfc505e5ccd19f7c39e3b43474180f1051e01

[JanKalin]

The distribution is not even:

jank@rp:~$ besu-log | grep "Error streaming JSON-RPC response" | awk '{print $6,$7}'
2022-09-15 09:35:01.728+02:00
2022-09-15 09:59:49.370+02:00
2022-09-15 10:04:49.155+02:00
2022-09-15 10:23:25.363+02:00
2022-09-15 10:23:25.395+02:00
2022-09-15 10:23:25.417+02:00
2022-09-15 10:23:25.463+02:00
2022-09-15 10:35:26.097+02:00
2022-09-15 10:37:25.836+02:00
2022-09-15 10:37:25.870+02:00
2022-09-15 10:43:01.326+02:00
2022-09-15 10:43:01.353+02:00
2022-09-15 10:43:01.392+02:00
2022-09-15 10:43:01.415+02:00
2022-09-15 11:13:13.835+02:00
2022-09-15 11:15:37.339+02:00
2022-09-15 11:15:37.385+02:00
2022-09-15 11:51:25.617+02:00
2022-09-15 11:51:25.656+02:00
2022-09-15 12:05:51.125+02:00
2022-09-15 12:09:26.868+02:00
2022-09-15 12:10:37.443+02:00
2022-09-15 12:46:36.924+02:00
2022-09-15 12:46:36.966+02:00
2022-09-15 12:46:36.989+02:00
2022-09-15 12:46:37.003+02:00
2022-09-15 12:46:37.019+02:00
2022-09-15 12:46:37.046+02:00
2022-09-15 12:46:37.070+02:00
2022-09-15 12:50:25.287+02:00
2022-09-15 12:50:25.290+02:00
2022-09-15 12:50:25.316+02:00
2022-09-15 12:50:48.927+02:00
2022-09-15 12:50:48.946+02:00
2022-09-15 12:50:48.981+02:00
2022-09-15 12:50:48.999+02:00
2022-09-15 12:58:13.577+02:00
2022-09-15 13:42:49.320+02:00
2022-09-15 13:42:49.341+02:00
2022-09-15 14:00:49.709+02:00
2022-09-15 14:02:01.363+02:00
2022-09-15 14:29:25.113+02:00
2022-09-15 15:10:49.711+02:00
2022-09-15 15:17:01.790+02:00
2022-09-15 15:17:01.819+02:00
2022-09-15 15:28:49.284+02:00
2022-09-15 15:28:49.302+02:00
2022-09-15 15:28:49.321+02:00
2022-09-15 15:28:49.356+02:00
2022-09-15 15:28:49.371+02:00
2022-09-15 15:28:49.382+02:00
2022-09-15 15:28:49.395+02:00
2022-09-15 15:42:54.749+02:00
2022-09-15 15:51:14.097+02:00
2022-09-15 16:01:02.239+02:00
2022-09-15 16:06:14.089+02:00
2022-09-15 16:10:37.245+02:00

At the same time the BC (Lighthouse) complains:

Sep 15 16:01:01 rp lighthouse[2584988]: Sep 15 14:01:01.872 ERRO Execution engine call failed            error: Reqwest(reqwest::Error { kind: Request, url: Url { scheme: "http", cannot_be_a_base: false, username: "", password: None, host: Some(Domain("localhost")), port: Some(8551), path: "/", query: None, fragment: None }, source: TimedOut }), service: exec
Sep 15 16:01:01 rp lighthouse[2584988]: Sep 15 14:01:01.872 ERRO Error fetching block for peer           error: ExecutionLayerErrorPayloadReconstruction(0xe26b2e770de1d171459c80035de4fcb73fc6151fe40c01d1c7920bf2e13692c0, EngineError(Api { error: Reqwest(reqwest::Error { kind: Request, url: Url { scheme: "http", cannot_be_a_base: false, username: "", password: None, host: Some(Domain("localhost")), port: Some(8551), path: "/", query: None, fragment: None }, source: TimedOut }) })), block_root: 0xe96120879d21bf45ed82918fee444678fbf38ae7af5ae34856bff18ce1ad9a7d

[ronaldjmaas]

Experience exact same issue with Besu + Lighthouse combo running on a server (Debian 11, no VM, no docker).

[SomerEsat]

+1 Besu + Lighthouse
Results in missed attestations periodically.

[lfinbob]

Seeing this a lot on Rocket Pool nodes. Affects all CLs. Powerful servers and small machines alike.

[risasoft]

+1 Besu/Lighthouse on RocketPool. Seems to happen every few hours.

[gamell]

Same with Besu + Lighthouse in a RP node using latest opensdk Docker image

[arbora]

+1 Besu/Lighthouse - been experiencing this since Merge, with occasional missed attestations, potentially when they happen at the same time as the issue.

[kinther]

Besu/Nimbus seeing this as well. I was synchronizing fine this morning and then suddenly it began spitting out the fork-choice-update logs. The variables within that log change with each iteration. I have restarted Besu multiple times without any change in behavior.

After restarting both Besu and Nimbus, I'm now seeing the following on start

eth1_1           | 2022-09-15 18:32:05.023+00:00 | main | INFO  | DefaultSynchronizer | Stopping block propagation.
eth1_1           | 2022-09-15 18:32:05.027+00:00 | main | INFO  | DefaultSynchronizer | Stopping the pruner.
eth1_1           | 2022-09-15 18:32:05.036+00:00 | main | INFO  | Runner | Ethereum main loop is up.
eth1_1           | 2022-09-15 18:32:12.793+00:00 | vert.x-worker-thread-9 | ERROR | JsonRpcExecutorHandler | Error streaming JSON-RPC response
eth1_1           | java.io.IOException: io.vertx.core.http.HttpClosedException: Connection was closed
eth1_1           |      at org.hyperledger.besu.ethereum.api.jsonrpc.JsonResponseStreamer.stopOnFailureOrClosed(JsonResponseStreamer.java:85)
eth1_1           |      at org.hyperledger.besu.ethereum.api.jsonrpc.JsonResponseStreamer.write(JsonResponseStreamer.java:57)
eth1_1           |      at com.fasterxml.jackson.core.json.UTF8JsonGenerator._flushBuffer(UTF8JsonGenerator.java:2171)
eth1_1           |      at com.fasterxml.jackson.core.json.UTF8JsonGenerator.close(UTF8JsonGenerator.java:1214)
eth1_1           |      at com.fasterxml.jackson.databind.ObjectWriter._writeValueAndClose(ObjectWriter.java:1224)
eth1_1           |      at com.fasterxml.jackson.databind.ObjectWriter.writeValue(ObjectWriter.java:1044)
eth1_1           |      at org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler.lambda$handler$6(JsonRpcExecutorHandler.java:90)
eth1_1           |      at io.vertx.ext.web.impl.BlockingHandlerDecorator.lambda$handle$0(BlockingHandlerDecorator.java:48)
eth1_1           |      at io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)
eth1_1           |      at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)
eth1_1           |      at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157)
eth1_1           |      at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)
eth1_1           |      at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
eth1_1           |      at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
eth1_1           |      at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
eth1_1           |      at java.base/java.lang.Thread.run(Thread.java:833)
eth1_1           | Caused by: io.vertx.core.http.HttpClosedException: Connection was closed
eth1_1           | 2022-09-15 18:32:22.323+00:00 | nioEventLoopGroup-3-1 | INFO  | BackwardSyncStep | Saved headers 15540889 -> 15540690 (head: 15540195)
eth1_1           | 2022-09-15 18:32:28.430+00:00 | nioEventLoopGroup-3-7 | INFO  | BackwardSyncStep | Saved headers 15540657 -> 15540657 (head: 15540195)
eth1_1           | 2022-09-15 18:32:29.008+00:00 | nioEventLoopGroup-3-7 | INFO  | BackwardSyncStep | Saved headers 15540657 -> 15540657 (head: 15540195)
eth1_1           | 2022-09-15 18:32:50.009+00:00 | nioEventLoopGroup-3-8 | INFO  | BackwardSyncStep | Saved headers 15540657 -> 15540657 (head: 15540195)
eth1_1           | 2022-09-15 18:33:13.843+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | SYNCING for fork-choice-update: head: 0xb79e1c60d5321c4b01ba350c3d13f098d7cb1c2d74132ef2945b458d364146a6, finalized: 0x68b25c0ce9a92e58db89aaa940f225a7f828dc045eda946a94c1bf10eea07360, safeBlockHash: 0x8f91686df892319c53f5ded180b4cce7da588768f0cf10ad3aaf617fbdd49c12
eth1_1           | 2022-09-15 18:34:03.512+00:00 | Timer-0 | INFO  | DNSResolver | Resolved 2409 nodes
eth1_1           | 2022-09-15 18:34:12.784+00:00 | Timer-0 | WARN  | RlpxAgent | Attempt to connect to peer with no listening port: enode://92ae467ca2719a0ca683d103580b78f3d0d0d58be0f8313ebe268da05e94ef0f2d91aa7834b0ec260e4b121a04a4bbf428d31d2b86bd34df3141ee56ccd63b01@34.76.173.33:0?discport=30853
eth1_1           | 2022-09-15 18:34:26.000+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | SYNCING for fork-choice-update: head: 0xbf08c82e662a12793970ad5ad64797d8d99a2be1e37ef5869facd4cce8975c99, finalized: 0x68b25c0ce9a92e58db89aaa940f225a7f828dc045eda946a94c1bf10eea07360, safeBlockHash: 0x8f91686df892319c53f5ded180b4cce7da588768f0cf10ad3aaf617fbdd49c12
eth1_1           | 2022-09-15 18:35:36.483+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | SYNCING for fork-choice-update: head: 0xa324f4e1448f4a3689dab8c2d46ac995f1eb0df48c7b32d3894b3ac5a664869b, finalized: 0x68b25c0ce9a92e58db89aaa940f225a7f828dc045eda946a94c1bf10eea07360, safeBlockHash: 0x8f91686df892319c53f5ded180b4cce7da588768f0cf10ad3aaf617fbdd49c12
eth1_1           | 2022-09-15 18:36:37.420+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | SYNCING for fork-choice-update: head: 0x77c1b3597b07630687657e685b522ddabb3b03af8f2a6de004b982a3439517e4, finalized: 0x68b25c0ce9a92e58db89aaa940f225a7f828dc045eda946a94c1bf10eea07360, safeBlockHash: 0x8f91686df892319c53f5ded180b4cce7da588768f0cf10ad3aaf617fbdd49c12
eth1_1           | 2022-09-15 18:37:30.859+00:00 | vert.x-worker-thread-0 | WARN  | EngineExchangeTransitionConfiguration | Configured terminal block hash 0x0000000000000000000000000000000000000000000000000000000000000000 does not match value of consensus client 0x55b11b918355b1ef9c5db810302ebad0bf2544255b530cdce90674d5887bb286
eth1_1           | 2022-09-15 18:37:49.022+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | SYNCING for fork-choice-update: head: 0x2de06f1a622c5bf011cce893605a266c931ded560ed462f42638e4c5049b6273, finalized: 0x8f91686df892319c53f5ded180b4cce7da588768f0cf10ad3aaf617fbdd49c12, safeBlockHash: 0xcf6306b2d9fefbfa0cd08473cbeb898ffd06b1e2515315d5c52624a3d0601743

...and it cycles through the fork-choice-update logs never making any progress.

[maninthecryptosuit]

Same problem here - Besu with Lighthouse. 1 missed attestation slot so far (slot 4701535 at block 15538896).

But VC and BN dont show any errors, Besu had the JSON error a few mins before the missed attestation.

Didnt have any issue all this while on Besu, until a few hours after the merge when the JSON streaming errors started popping up in Besu.

Restart didn't help preventing more errors. No more missed attestations yet.

CONFIG: NUC11PAHi5 with 32GB RAM, 2TB Samsung 970 Evo Plus nVME, 1 Gbps high quality fibre internet.
Ubuntu Desktop 20.04 LTS. Linux open file limit is 100,000.
Besu 22.7.2, Lighthouse 3.1.0
I have JAVA_OPTS=-Xmx8g to my startup script for besu.

Besu at the time:

Sep 15 14:48:01  besu[196971]: 2022-09-15 14:48:01.726+03:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | VALID for fork-choice-update: head: 0x77c193b59a3e1707699ce>
Sep 15 14:48:01  besu[196971]: 2022-09-15 14:48:01.483+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,899 / 287 tx / base fee 7.60 gwei / 26,658,198 (8>
Sep 15 14:47:47  besu[196971]: 2022-09-15 14:47:47.979+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,898 / 10 tx / base fee 8.50 gwei / 2,307,432 (7.7>
Sep 15 14:47:37  besu[196971]: 2022-09-15 14:47:37.622+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,897 / 556 tx / base fee 7.74 gwei / 26,843,274 (8>
Sep 15 14:47:24  besu[196971]: 2022-09-15 14:47:24.842+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,896 / 217 tx / base fee 7.89 gwei / 12,640,824 (4>
Sep 15 14:47:13  besu[196971]: 2022-09-15 14:47:13.542+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,895 / 352 tx / base fee 7.05 gwei / 29,274,114 (9>
Sep 15 14:47:00  besu[196971]: 2022-09-15 14:47:00.717+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,894 / 146 tx / base fee 7.30 gwei / 10,843,179 (3>
Sep 15 14:46:50  besu[196971]: 2022-09-15 14:46:50.073+03:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | VALID for fork-choice-update: head: 0x84b3cf60531bf7d34a1cc>
Sep 15 14:46:49  besu[196971]: 2022-09-15 14:46:49.896+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,893 / 210 tx / base fee 6.91 gwei / 21,880,436 (7>
Sep 15 14:46:36  besu[196971]: 2022-09-15 14:46:36.824+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,892 / 247 tx / base fee 6.82 gwei / 16,526,871 (5>
Sep 15 14:46:24  besu[196971]: 2022-09-15 14:46:24.489+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,891 / 50 tx / base fee 7.44 gwei / 4,956,434 (16.>
Sep 15 14:46:13  besu[196971]: 2022-09-15 14:46:13.269+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,890 / 257 tx / base fee 6.89 gwei / 24,604,180 (8>
Sep 15 14:46:00  besu[196971]: 2022-09-15 14:46:00.142+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,889 / 184 tx / base fee 6.91 gwei / 14,727,872 (4>
Sep 15 14:45:48  besu[196971]: 2022-09-15 14:45:48.775+03:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | VALID for fork-choice-update: head: 0xce825e51b0948b6f3a760>
Sep 15 14:45:48  besu[196971]: 2022-09-15 14:45:48.616+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,888 / 178 tx / base fee 7.05 gwei / 12,569,765 (4>
Sep 15 14:45:36  besu[196971]: 2022-09-15 14:45:36.360+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,887 / 82 tx / base fee 7.65 gwei / 5,536,379 (18.>
Sep 15 14:45:25  besu[196971]: 2022-09-15 14:45:25.542+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,886 / 172 tx / base fee 7.83 gwei / 12,354,873 (4>
Sep 15 14:45:14  besu[196971]: 2022-09-15 14:45:14.882+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,885 / 731 tx / base fee 7.01 gwei / 28,893,843 (9>
Sep 15 14:44:59  besu[196971]: 2022-09-15 14:44:59.951+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,884 / 17 tx / base fee 7.95 gwei / 934,243 (3.1%)>
Sep 15 14:44:49  besu[196971]: 2022-09-15 14:44:49.850+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,883 / 282 tx / base fee 7.47 gwei / 22,591,346 (7>
Sep 15 14:44:36  besu[196971]: 2022-09-15 14:44:36.529+03:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | VALID for fork-choice-update: head: 0xb1e420adafcdbd073cacd>
Sep 15 14:44:36  besu[196971]: 2022-09-15 14:44:36.361+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,882 / 187 tx / base fee 7.65 gwei / 12,192,184 (4>
Sep 15 14:44:24  besu[196971]: 2022-09-15 14:44:24.830+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,881 / 177 tx / base fee 7.61 gwei / 15,691,148 (5>
Sep 15 14:44:12  besu[196971]: 2022-09-15 14:44:12.590+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,880 / 233 tx / base fee 7.50 gwei / 16,742,846 (5>
Sep 15 14:43:59  besu[196971]: 2022-09-15 14:43:59.917+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,879 / 24 tx / base fee 8.44 gwei / 1,588,971 (5.3>
Sep 15 14:43:49  besu[196971]:         at io.netty.channel.AbstractChannel$AbstractUnsafe.write(Object, ChannelPromise)(Unknown Source)
Sep 15 14:43:49  besu[196971]: io.netty.channel.StacklessClosedChannelException
Sep 15 14:43:49  besu[196971]: 2022-09-15 14:43:49.692+03:00 | vert.x-worker-thread-0 | ERROR | JsonRpcExecutorHandler | Error streaming JSON-RPC response
Sep 15 14:43:49  besu[196971]: 2022-09-15 14:43:49.667+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,878 / 352 tx / base fee 7.50 gwei / 29,996,673 (1>
Sep 15 14:43:36  besu[196971]: 2022-09-15 14:43:36.325+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,877 / 162 tx / base fee 7.66 gwei / 12,608,135 (4>
Sep 15 14:43:27  besu[196971]: 2022-09-15 14:43:27.412+03:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | VALID for fork-choice-update: head: 0x8d323caed70551d29d627>
Sep 15 14:43:26  besu[196971]: 2022-09-15 14:43:26.989+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,876 / 864 tx / base fee 6.81 gwei / 29,980,786 (9>
Sep 15 14:43:12  besu[196971]: 2022-09-15 14:43:12.729+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,875 / 206 tx / base fee 6.78 gwei / 15,450,170 (5>
Sep 15 14:43:00  besu[196971]: 2022-09-15 14:43:00.319+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,874 / 81 tx / base fee 7.34 gwei / 5,850,995 (19.>
Sep 15 14:42:49  besu[196971]: 2022-09-15 14:42:49.746+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,873 / 356 tx / base fee 6.80 gwei / 24,595,519 (8>

BN at the time:

Sep 15 14:48:24  lighthouse[127013]: Sep 15 11:48:24.358 INFO New block received                      root: 0x8ecc7a877afca7c056728e056d58d47e7edb472f68cef43717945f07a0a5843f, slot:>
Sep 15 14:48:17  lighthouse[127013]: Sep 15 11:48:17.000 INFO Synced                                  slot: 4701539, block:    …  empty, epoch: 146923, finalized_epoch: 146921, fina>
Sep 15 14:48:05  lighthouse[127013]: Sep 15 11:48:05.001 INFO Synced                                  slot: 4701538, block: 0x2478…5904, epoch: 146923, finalized_epoch: 146921, fina>
Sep 15 14:48:01  lighthouse[127013]: Sep 15 11:48:01.514 INFO New RPC block received                  hash: 0x2478…5904, slot: 4701538
Sep 15 14:48:00  lighthouse[127013]: Sep 15 11:48:00.458 INFO New block received                      root: 0x24787bf1e466dbc998b3fd67b91bee96ee6c4b3f9a0fdefc50baf8cbcb975904, slot:>
Sep 15 14:47:53  lighthouse[127013]: Sep 15 11:47:53.001 INFO Synced                                  slot: 4701537, block: 0xf43f…4731, epoch: 146923, finalized_epoch: 146921, fina>
Sep 15 14:47:48  lighthouse[127013]: Sep 15 11:47:48.008 INFO New RPC block received                  hash: 0xf43f…4731, slot: 4701537
Sep 15 14:47:48  lighthouse[127013]: Sep 15 11:47:48.001 INFO Attestation included in block           validator: 385774, slot: 4701536, epoch: 146923, inclusion_lag: 0 slot(s), inde>
Sep 15 14:47:47  lighthouse[127013]: Sep 15 11:47:47.830 INFO New block received                      root: 0xf43ff8ddfb00906873e04de9ab94c02b6460e24930358111e6bf604277bd4731, slot:>
Sep 15 14:47:43  lighthouse[127013]: Sep 15 11:47:43.865 INFO Attestation included in aggregate       validator: 385774, src: gossip, slot: 4701536, epoch: 146923, delay_ms: 859, in>
Sep 15 14:47:43  lighthouse[127013]: Sep 15 11:47:43.569 INFO Attestation included in aggregate       validator: 385774, src: gossip, slot: 4701536, epoch: 146923, delay_ms: 546, in>
Sep 15 14:47:43  lighthouse[127013]: Sep 15 11:47:43.402 INFO Attestation included in aggregate       validator: 385774, src: gossip, slot: 4701536, epoch: 146923, delay_ms: 394, in>
Sep 15 14:47:43  lighthouse[127013]: Sep 15 11:47:43.321 INFO Attestation included in aggregate       validator: 385774, src: gossip, slot: 4701536, epoch: 146923, delay_ms: 294, in>
Sep 15 14:47:41  lighthouse[127013]: Sep 15 11:47:41.001 INFO Synced                                  slot: 4701536, block: 0x5e63…6304, epoch: 146923, finalized_epoch: 146921, fina>
Sep 15 14:47:39  lighthouse[127013]: Sep 15 11:47:39.014 INFO Unaggregated attestation                validator: 385774, src: api, slot: 4701536, epoch: 146923, delay_ms: 13, index:>
Sep 15 14:47:36  lighthouse[127013]: Sep 15 11:47:36.320 INFO New block received                      root: 0x5e63b6b06a57425b26be1b7256f3bd5176275ef6cbf7d5fcbf42908bae916304, slot:>
Sep 15 14:47:32  lighthouse[127013]: Sep 15 11:47:32.099 INFO Previous epoch attestation(s) success   validators: ["385773", "385774", "385775"], epoch: 146921, service: val_mon
Sep 15 14:47:32  lighthouse[127013]: Sep 15 11:47:32.036 INFO Attestation included in aggregate       validator: 385774, src: gossip, slot: 4701535, epoch: 146922, delay_ms: 1034, i>
Sep 15 14:47:31  lighthouse[127013]: Sep 15 11:47:31.629 INFO Attestation included in aggregate       validator: 385774, src: gossip, slot: 4701535, epoch: 146922, delay_ms: 599, in>
Sep 15 14:47:31  lighthouse[127013]: Sep 15 11:47:31.161 INFO Attestation included in aggregate       validator: 385774, src: gossip, slot: 4701535, epoch: 146922, delay_ms: 154, in>
Sep 15 14:47:29  lighthouse[127013]: Sep 15 11:47:29.001 INFO Synced                                  slot: 4701535, block: 0x8f6f…3649, epoch: 146922, finalized_epoch: 146920, fina>
Sep 15 14:47:27  lighthouse[127013]: Sep 15 11:47:27.026 INFO Unaggregated attestation                validator: 385774, src: api, slot: 4701535, epoch: 146922, delay_ms: 23, index:>
Sep 15 14:47:24  lighthouse[127013]: Sep 15 11:47:24.855 INFO New RPC block received                  hash: 0x8f6f…3649, slot: 4701535
Sep 15 14:47:24  lighthouse[127013]: Sep 15 11:47:24.234 INFO New block received                      root: 0x8f6f764b4904fed13b35d561db25757567ae878a68cc31332a085d1704533649, slot:>
Sep 15 14:47:17  lighthouse[127013]: Sep 15 11:47:17.001 INFO Synced                                  slot: 4701534, block: 0xd1a4…e83c, epoch: 146922, finalized_epoch: 146920, fina>
Sep 15 14:47:12  lighthouse[127013]: Sep 15 11:47:12.152 INFO New block received                      root: 0xd1a47c725356afbc802a6e05d065926abb9fb7c9297067669f1568e6b842e83c, slot:>
Sep 15 14:47:05  lighthouse[127013]: Sep 15 11:47:05.001 INFO Synced                                  slot: 4701533, block: 0x75af…d309, epoch: 146922, finalized_epoch: 146920, fina>
Sep 15 14:47:00  lighthouse[127013]: Sep 15 11:47:00.730 INFO New RPC block received                  hash: 0x75af…d309, slot: 4701533
Sep 15 14:47:00  lighthouse[127013]: Sep 15 11:47:00.171 INFO New block received                      root: 0x75af89e1aebcec331daa3d8d5de5020dd8e896d9d99dff6641378e757e26d309, slot:>
Sep 15 14:46:53  lighthouse[127013]: Sep 15 11:46:53.001 INFO Synced                                  slot: 4701532, block: 0x033f…6959, epoch: 146922, finalized_epoch: 146920, fina>
Sep 15 14:46:49  lighthouse[127013]: Sep 15 11:46:49.088 INFO New block received                      root: 0x033f5bd03f3ff3fc9b58c65e0e21a145232f8c6139efdac3361078ce13f66959, slot:>
Sep 15 14:46:41  lighthouse[127013]: Sep 15 11:46:41.001 INFO Synced                                  slot: 4701531, block: 0xfe52…6249, epoch: 146922, finalized_epoch: 146920, fina>
Sep 15 14:46:35  lighthouse[127013]: Sep 15 11:46:35.951 INFO New block received                      root: 0xfe5244b36b14d3195ea5a1d479c9fa81257c8bcac6114984796f502b708a6249, slot:>
Sep 15 14:46:29  lighthouse[127013]: Sep 15 11:46:29.000 INFO Synced                                  slot: 4701530, block: 0xd88d…7587, epoch: 146922, finalized_epoch: 146920, fina>
Sep 15 14:46:24  lighthouse[127013]: Sep 15 11:46:24.502 INFO New RPC block received                  hash: 0xd88d…7587, slot: 4701530
Sep 15 14:46:24  lighthouse[127013]: Sep 15 11:46:24.204 INFO New block received                      root: 0xd88d20ee4bca8518e53b86e2b6eb86246617aabf221c333fabc76a54e7567587, slot:>
Sep 15 14:46:17  lighthouse[127013]: Sep 15 11:46:17.001 INFO Synced                                  slot: 4701529, block: 0x655e…6bca, epoch: 146922, finalized_epoch: 146920, fina>
Sep 15 14:46:12  lighthouse[127013]: Sep 15 11:46:12.048 INFO New block received                      root: 0x655e73d76e0e6cc4e056c88c8c8140dac0c8f2733a4b745b31a134f3b4bb6bca, slot:>
Sep 15 14:46:05  lighthouse[127013]: Sep 15 11:46:05.000 INFO Synced                                  slot: 4701528, block: 0xb57c…7701, epoch: 146922, finalized_epoch: 146920, fina>
Sep 15 14:45:59  lighthouse[127013]: Sep 15 11:45:59.583 INFO New block received                      root: 0xb57cc813409bf2d151e2f433bbc21debb814230dfb235cc5897bfb69a8b27701, slot:>
Sep 15 14:45:53  lighthouse[127013]: Sep 15 11:45:53.001 INFO Synced                                  slot: 4701527, block: 0xe5fe…bdfb, epoch: 146922, finalized_epoch: 146920, fina>
Sep 15 14:45:48  lighthouse[127013]: Sep 15 11:45:48.026 INFO New block received                      root: 0xe5fe7fe8ec122a8acdd3aa9861c8ff6c738ab5604a87a09d11113ba5ac0cbdfb, slot:>
Sep 15 14:45:41  lighthouse[127013]: Sep 15 11:45:41.000 INFO Synced                                  slot: 4701526, block: 0xcbb8…adae, epoch: 146922, finalized_epoch: 146920, fina

VC at the time:

Sep 15 14:47:39  lighthouse[127036]: Sep 15 11:47:39.014 INFO Successfully published attestations     type: unaggregated, slot: 4701536, committee_index: 38, head_block: 0x5e63b6b06>
Sep 15 14:47:29  lighthouse[127036]: Sep 15 11:47:29.001 INFO All validators active                   slot: 4701535, epoch: 146922, total_validators: X, active_validators: X, curren>
Sep 15 14:47:29  lighthouse[127036]: Sep 15 11:47:29.000 INFO Connected to beacon node(s)             synced: 1, available: 1, total: 1, service: notifier
Sep 15 14:47:27  lighthouse[127036]: Sep 15 11:47:27.027 INFO Successfully published attestations     type: unaggregated, slot: 4701535, committee_index: 3, head_block: 0x8f6f764b49>
Sep 15 14:47:17  lighthouse[127036]: Sep 15 11:47:17.001 INFO All validators active                   slot: 4701534, epoch: 146922, total_validators: X, active_validators: X, curren>

ADDDITONAL ERRORS:
I also see "uncaught exception in thread" and "Unable to load trie node value for hash" errors:

Sep 15 14:55:38 [196971]: io.netty.channel.StacklessClosedChannelException
Sep 15 14:55:38 [196971]:         at io.netty.channel.AbstractChannel$AbstractUnsafe.write(Object, ChannelPromise)(Unknown Source)
Sep 15 14:55:51 [196971]: 2022-09-15 14:55:51.098+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,936 / 680 tx / base fee 8.05 gwei / 29,990,742 (1>
Sep 15 14:56:01 [196971]: 2022-09-15 14:56:01.370+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,937 / 198 tx / base fee 9.06 gwei / 16,785,997 (5>
Sep 15 14:56:01 [196971]: 2022-09-15 14:56:01.625+03:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | VALID for fork-choice-update: head: 0x2f65339df81189ce28883>
Sep 15 14:56:11 [196971]: 2022-09-15 14:56:11.973+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,938 / 91 tx / base fee 9.19 gwei / 6,845,947 (22.>
Sep 15 14:56:25 [196971]: 2022-09-15 14:56:25.542+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,939 / 316 tx / base fee 8.57 gwei / 24,726,134 (8>
Sep 15 14:56:35 [196971]: 2022-09-15 14:56:35.792+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,940 / 74 tx / base fee 9.26 gwei / 4,610,794 (15.>
Sep 15 14:56:51 [196971]: 2022-09-15 14:56:51.068+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,941 / 294 tx / base fee 8.46 gwei / 29,392,790 (9>
Sep 15 14:56:51 [196971]: 2022-09-15 14:56:51.101+03:00 | vert.x-worker-thread-18 | ERROR | JsonRpcExecutorHandler | Error streaming JSON-RPC response
Sep 15 14:56:51 [196971]: io.netty.channel.StacklessClosedChannelException
Sep 15 14:56:51 [196971]:         at io.netty.channel.AbstractChannel$AbstractUnsafe.write(Object, ChannelPromise)(Unknown Source)
Sep 15 14:56:51 [196971]: 2022-09-15 14:56:51.127+03:00 | vert.x-worker-thread-18 | ERROR | JsonRpcExecutorHandler | Error streaming JSON-RPC response
Sep 15 14:56:51 [196971]: io.netty.channel.StacklessClosedChannelException
Sep 15 14:56:51 [196971]:         at io.netty.channel.AbstractChannel$AbstractUnsafe.write(Object, ChannelPromise)(Unknown Source)
Sep 15 14:57:00 [196971]: 2022-09-15 14:57:00.432+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,942 / 87 tx / base fee 9.48 gwei / 6,022,132 (20.>
Sep 15 14:57:12 [196971]: 2022-09-15 14:57:12.979+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,943 / 181 tx / base fee 8.77 gwei / 16,485,584 (5>
Sep 15 14:57:13 [196971]: 2022-09-15 14:57:13.191+03:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | VALID for fork-choice-update: head: 0xc4242af2d7443f63a0db0>
Sep 15 14:57:26 [196971]: 2022-09-15 14:57:26.347+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,944 / 707 tx / base fee 8.88 gwei / 25,421,922 (8>
Sep 15 14:57:36 [196971]: 2022-09-15 14:57:36.385+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,945 / 141 tx / base fee 9.65 gwei / 8,955,856 (29>
Sep 15 14:57:49 [196971]: 2022-09-15 14:57:49.228+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,946 / 159 tx / base fee 9.16 gwei / 14,309,509 (4>
Sep 15 14:58:01 [196971]: 2022-09-15 14:58:01.329+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,947 / 255 tx / base fee 9.11 gwei / 18,604,610 (6>
Sep 15 14:58:11 [196971]: 2022-09-15 14:58:11.917+03:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,538,948 / 28 tx / base fee 9.38 gwei / 1,787,814 (6.0>
Sep 15 14:58:14 [196971]: 2022-09-15 14:58:14.027+03:00 | EthScheduler-Transactions-4 | ERROR | Besu | Uncaught exception in thread "EthScheduler-Transactions-4"
Sep 15 14:58:14 [196971]: org.hyperledger.besu.ethereum.trie.MerkleTrieException: Unable to load trie node value for hash 0x48890e3357468f90672a3bdd8ec3cd7b61bb6a373251fb3f903c>
Sep 15 14:58:14 [196971]:         at org.hyperledger.besu.ethereum.trie.StoredNode.lambda$load$0(StoredNode.java:133)
Sep 15 14:58:14 [196971]:         at java.base/java.util.Optional.orElseThrow(Optional.java:408)
Sep 15 14:58:14 [196971]:         at org.hyperledger.besu.ethereum.trie.StoredNode.load(StoredNode.java:131)
Sep 15 14:58:14 [196971]:         at org.hyperledger.besu.ethereum.trie.StoredNode.accept(StoredNode.java:63)
Sep 15 14:58:14 [196971]:         at org.hyperledger.besu.ethereum.trie.StoredMerklePatriciaTrie.get(StoredMerklePatriciaTrie.java:119)
Sep 15 14:58:14 [196971]:         at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateKeyValueStorage.getAccount(BonsaiWorldStateKeyValueStorage.java:110)
Sep 15 14:58:14 [196971]:         at org.hyperledger.besu.ethereum.bonsai.BonsaiPersistedWorldState.get(BonsaiPersistedWorldState.java:340)
Sep 15 14:58:14 [196971]:         at org.hyperledger.besu.ethereum.bonsai.BonsaiLayeredWorldState.get(BonsaiLayeredWorldState.java:232)
Sep 15 14:58:14 [196971]:         at org.hyperledger.besu.ethereum.eth.transactions.TransactionPool.lambda$validateTransaction$2(TransactionPool.java:282)
Sep 15 14:58:14 [196971]:         at java.base/java.util.Optional.map(Optional.java:265)
Sep 15 14:58:14 [196971]:         at org.hyperledger.besu.ethereum.eth.transactions.TransactionPool.validateTransaction(TransactionPool.java:280)
Sep 15 14:58:14 [196971]:         at org.hyperledger.besu.ethereum.eth.transactions.TransactionPool.validateRemoteTransaction(TransactionPool.java:213)
Sep 15 14:58:14 [196971]:         at org.hyperledger.besu.ethereum.eth.transactions.TransactionPool.addRemoteTransactions(TransactionPool.java:153)
Sep 15 14:58:14 [196971]:         at org.hyperledger.besu.ethereum.eth.transactions.TransactionsMessageProcessor.processTransactionsMessage(TransactionsMessageProcessor.java:11>
Sep 15 14:58:14 [196971]:         at org.hyperledger.besu.ethereum.eth.transactions.TransactionsMessageProcessor.processTransactionsMessage(TransactionsMessageProcessor.java:85)
Sep 15 14:58:14 [196971]:         at org.hyperledger.besu.ethereum.eth.transactions.TransactionsMessageHandler.lambda$exec$0(TransactionsMessageHandler.java:48)
Sep 15 14:58:14 [196971]:         at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
Sep 15 14:58:14 [196971]:         at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
Sep 15 14:58:14 [196971]:         at java.base/java.lang.Thread.run(Thread.java:829)

Lighthouse sometimes complains about "Error Execution engine call failed" and "Error during execution engine upcheck":

Sep 15 15:18:53  lighthouse[127013]: Sep 15 12:18:53.000 INFO Synced                                  slot: 4701692, block: 0x9f3a…4bde, epoch: 146927, finalized_epoch: 146925, fina>
Sep 15 15:19:00  lighthouse[127013]: Sep 15 12:19:00.808 INFO New block received                      root: 0xdfdc116c6683f54d0b6321f9b58e008bad1ec05961808f76c9070ecf6234b90a, slot:>
Sep 15 15:19:01  lighthouse[127013]: Sep 15 12:19:01.914 ERRO Execution engine call failed            error: Reqwest(reqwest::Error { kind: Request, url: Url { scheme: "http", canno>
Sep 15 15:19:01  lighthouse[127013]: Sep 15 12:19:01.914 ERRO Error fetching block for peer           error: ExecutionLayerErrorPayloadReconstruction(0x56183a657fa1b7498f4ec197ce456>
Sep 15 15:19:01  lighthouse[127013]: Sep 15 12:19:01.924 ERRO Execution engine call failed            error: Reqwest(reqwest::Error { kind: Request, url: Url { scheme: "http", canno>
Sep 15 15:19:01  lighthouse[127013]: Sep 15 12:19:01.924 ERRO Error fetching block for peer           error: ExecutionLayerErrorPayloadReconstruction(0x988600f495a40defc8127eda5b59c>
Sep 15 15:19:05  lighthouse[127013]: Sep 15 12:19:05.000 INFO Synced                                  slot: 4701693, block: 0xdfdc…b90a, epoch: 146927, finalized_epoch: 146925, fina>
Sep 15 15:19:12  lighthouse[127013]: Sep 15 12:19:12.084 INFO New block received                      root: 0xcdbefd7e58594d6cfdd8ed336a7adc63335e1146b92c5b20cd50c2cec597294a, slot:>
Sep 15 15:19:12  lighthouse[127013]: Sep 15 12:19:12.247 INFO New RPC block received                  hash: 0xcdbe…294a, slot: 4701694

[iamhsk]

From a Discord message:
Here are the cleanest Besu logs I can get for one of these instances of ERROR | JsonRpcExecutorHandler | Error streaming JSON-RPC response, with associated Lighthouse logs. Also an inclusion of a graph of rate(execution_layer_get_payload_by_block_hash_time_sum{}[5m])/rate(execution_layer_get_payload_by_block_hash_time_count{}[5m]) which a lighthouse dev thought might be informative, but which doesn't show much at the time of the error.

Note: No attestation was actually missed at this time by validator xxxxxx, but it had a possibly-related invalid head/target vote which resulted in effectively a missed attestation.

As for env details: i7 NUC with 32GB RAM and 2TB Samsung EVO 970 SSD. All metrics were well in the green at the time of the error, with no suspicious bumps of any kind.

besulogs2022-09-15.txt

[siladu]

https://discord.com/channels/905194001349627914/938504958909747250/1019905431054864434

I'm getting this error every few min:
ERROR | JsonRpcExecutorHandler | Error streaming JSON-RPC response
Sep 15 09:20:26 besu[186377]: io.netty.channel.StacklessClosedChannelException
Sep 15 09:20:26 besu[186377]: at io.netty.channel.AbstractChannel$AbstractUnsafe.write(Object, ChannelPromise)(Unknown Source)

No negative impcat on metrics or missed attestations

[siladu]

+1 Besu + Lighthouse
Results in missed attestations periodically.

@SomerEsat please can you explain how you came to the conclusion that Json RPC error leads to missed attestations please? Some users have this but without missed attestations

[siladu]

@ibootstrapper @JanKalin @ronaldjmaas @lfinbob @risasoft @gamell

Please can you confirm if you are getting frequent missed attestations and how your chains are progressing generally?
Are you seeing this error but everything else is fine?

[gamell]

No missed attestations on my side, but switched to a geth/lighthouse fallback node as precaution for now, so I only have ~10h of logs/attesting experience with this issue.

[SomerEsat]

@siladu

I went from 99% to 83% effectiveness pre to post Merge. No changes to setup. Software latest versions. Fully synced prior to the merge. Also, Beaconcha.in confirmed it via alerting.

I'm not sure what actual cause is, but it seems to happen when I see this (Besu):

Sep 16 00:15:48 ETH-STAKER-001 besu[15568]: 2022-09-16 00:15:48.739+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,542,582 / 68 tx / base fee 5.71 gwei / 5,253,353 (17.5%) gas / (0xbc47e7bb19b48e0ccefbabc23732c561950ffb2690ffcd900d4c97057bcee90d) in 0.639s. Peers: 27
Sep 16 00:16:02 ETH-STAKER-001 besu[15568]: 2022-09-16 00:16:02.831+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,542,583 / 172 tx / base fee 5.25 gwei / 25,984,191 (86.6%) gas / (0xc945270ba8b55b9766fa448b9833e96233f2f2bdf123c707f068cecea0b316f3) in 2.857s. Peers: 27
Sep 16 00:16:02 ETH-STAKER-001 besu[15568]: 2022-09-16 00:16:02.851+00:00 | vert.x-worker-thread-4 | ERROR | JsonRpcExecutorHandler | Error streaming JSON-RPC response
Sep 16 00:16:02 ETH-STAKER-001 besu[15568]: io.netty.channel.StacklessClosedChannelException
Sep 16 00:16:02 ETH-STAKER-001 besu[15568]:         at io.netty.channel.AbstractChannel$AbstractUnsafe.write(Object, ChannelPromise)(Unknown Source)
Sep 16 00:16:16 ETH-STAKER-001 besu[15568]: 2022-09-16 00:16:16.481+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,542,584 / 252 tx / base fee 5.73 gwei / 25,152,721 (83.8%) gas / (0x2d35535e8b50744f65cbb1c3954977563ae0f9c2770eb5607051a045703cbec8) in 3.795s. Peers: 27
Sep 16 00:16:17 ETH-STAKER-001 besu[15568]: 2022-09-16 00:16:17.247+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | VALID for fork-choice-update: head: 0x2d35535e8b50744f65cbb1c3954977563ae0f9c2770eb5607051a045703cbec8, finalized: 0x4d44e27519f1de4e0a833e29c9cde1665677376b3612d4e46f9cd8d525ac001f, safeBlockHash: 0xa66da527c8fbefb5d76507c310d08419714fde0598aca0beb5e62ff569a3fcb3
Sep 16 00:16:33 ETH-STAKER-001 besu[15568]: 2022-09-16 00:16:33.331+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,542,585 / 312 tx / base fee 6.21 gwei / 29,989,032 (100.0%) gas / (0xcc7ea7216e0184910630134f8445b2ad1e0ef72f67498c9dd2e9fbef50e86938) in 4.350s. Peers: 27
Sep 16 00:16:33 ETH-STAKER-001 besu[15568]: 2022-09-16 00:16:33.367+00:00 | vert.x-worker-thread-2 | ERROR | JsonRpcExecutorHandler | Error streaming JSON-RPC response
Sep 16 00:16:33 ETH-STAKER-001 besu[15568]: io.netty.channel.StacklessClosedChannelException
Sep 16 00:16:33 ETH-STAKER-001 besu[15568]:         at io.netty.channel.AbstractChannel$AbstractUnsafe.write(Object, ChannelPromise)(Unknown Source)
Sep 16 00:16:40 ETH-STAKER-001 besu[15568]: 2022-09-16 00:16:40.613+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,542,586 / 173 tx / base fee 6.99 gwei / 16,130,211 (53.8%) gas / (0xc0afa3352469c8f02db410b2d0bed4afe7e211c1b06220775fb8e9fd52c1e757) in 4.089s. Peers: 27

And then this (lighthouse beacon):

Sep 16 00:15:53 ETH-STAKER-001 lighthouse[15764]: Sep 16 00:15:53.001 INFO Synced                                  slot: 4705277, block: 0xfc4b…32f3, epoch: 147039, finalized_epoch: 147037, finalized_root: 0xdf10…c092, exec_hash: 0xbc47…e90d (verified), peers: 88, service: slot_notifier
Sep 16 00:15:59 ETH-STAKER-001 lighthouse[15764]: Sep 16 00:15:59.680 INFO New block received                      root: 0xc91101365d2781e4b8371587ca5c6d1336448d426fdaf0b40f69206dd3950d2f, slot: 4705278
Sep 16 00:16:00 ETH-STAKER-001 lighthouse[15764]: Sep 16 00:16:00.999 ERRO Execution engine call failed            error: Reqwest(reqwest::Error { kind: Request, url: Url { scheme: "http", cannot_be_a_base: false, username: "", password: None, host: Some(Ipv4(127.0.0.1)), port: Some(8551), path: "/", query: None, fragment: None }, source: TimedOut }), service: exec
Sep 16 00:16:00 ETH-STAKER-001 lighthouse[15764]: Sep 16 00:16:00.999 ERRO Error fetching block for peer           error: ExecutionLayerErrorPayloadReconstruction(0x137c26ceaba59576cc5808ce40cc7ca05cc8511691d542c53f68ea9567743e7b, EngineError(Api { error: Reqwest(reqwest::Error { kind: Request, url: Url { scheme: "http", cannot_be_a_base: false, username: "", password: None, host: Some(Ipv4(127.0.0.1)), port: Some(8551), path: "/", query: None, fragment: None }, source: TimedOut }) })), block_root: 0xfcbcfb49e1582f0aac1d99a225dcd7dd9c629fcb8497c320032631e7250b2a5a
Sep 16 00:16:02 ETH-STAKER-001 lighthouse[15764]: Sep 16 00:16:02.001 ERRO Error during execution engine upcheck   error: Reqwest(reqwest::Error { kind: Request, url: Url { scheme: "http", cannot_be_a_base: false, username: "", password: None, host: Some(Ipv4(127.0.0.1)), port: Some(8551), path: "/", query: None, fragment: None }, source: TimedOut }), service: exec
Sep 16 00:16:02 ETH-STAKER-001 lighthouse[15764]: Sep 16 00:16:02.856 INFO Execution engine online                 service: exec
Sep 16 00:16:02 ETH-STAKER-001 lighthouse[15764]: Sep 16 00:16:02.856 INFO Issuing forkchoiceUpdated               forkchoice_state: ForkChoiceState { head_block_hash: 0xbc47e7bb19b48e0ccefbabc23732c561950ffb2690ffcd900d4c97057bcee90d, safe_block_hash: 0xa66da527c8fbefb5d76507c310d08419714fde0598aca0beb5e62ff569a3fcb3, finalized_block_hash: 0x4d44e27519f1de4e0a833e29c9cde1665677376b3612d4e46f9cd8d525ac001f }, service: exec
Sep 16 00:16:05 ETH-STAKER-001 lighthouse[15764]: Sep 16 00:16:05.001 INFO Synced     

Note the timing:
-- Lighthouse reports a "Execution engine call failed" & "Error fetching block for peer" at 00:16:00.999
-- Lighthouse reports a "Error during execution engine upcheck" at 00:16:02.001
-- Besu reports a "Error streaming JSON-RPC response" at 00:16:02.851

Around that time, if an attestation is scheduled, it tends to fail. Having said that, the last attestation to fail (across multiple validators) is approx. 1 hour ago from now.

Edit: Just got alerts for 2 missed attestations (1 each from 2 separate validators).

[lfinbob]

@ibootstrapper @JanKalin @ronaldjmaas @lfinbob @risasoft @gamell

Please can you confirm if you are getting frequent missed attestations and how your chains are progressing generally? Are you seeing this error but everything else is fine?

I've personally only missed 1 attestation per validator after the merge, despite 126 JSON-RPC errors:

# docker logs rocketpool_eth1 |& grep "Error streaming JSON-RPC response" | wc -l
126

It's a fast server, Ryzen 5950X, 128GB RAM, 2x4 TB NVMe. Many other Besu users in Rocket Pool discord #support see more missed attestations or no attestations at all, especially on weaker devices.

My rated.network effectiveness seems to be still fine as well:

[terahertz5k]

I am getting missed attestations with this error and lighthouse. was not getting any before the merge. my effectiveness has dropped from 97-100% to 85-89% on two validators.

[JanKalin]

@ibootstrapper @JanKalin @ronaldjmaas @lfinbob @risasoft @gamell

Please can you confirm if you are getting frequent missed attestations and how your chains are progressing generally? Are you seeing this error but everything else is fine?

Just after the merge I had to restart besu as many others. I had one missed attestation today, but that was before the restart.

From the merge to now (3:27 CEST) I've had 257 JSON-RPC errors and 9 errors org.hyperledger.besu.ethereum.trie.MerkleTrieException: Unable to load trie node value for hash. But the trie error occured also before the merge, around once per day, whereas the JSON-RPC didn't.

Except for this error both the execution and consesus layers are following the chain in real time. HW is AMD Ryzen 5 5600G, 32GB RAM 3.2GHz and Samsung SSD 980 Pro 2TB, with load hovering a bit below 1.0, and loads of free RAM. I added JAVA_OPTS=-Xmx8g to my startup script for besu.

EDIT: the consensus layer client is Lighthouse

[i-am-logger]

Yes, missing many today . I'm running in a HP server 512gb ram and 4x10 cores (80 threads)

[risasoft]

@ibootstrapper @JanKalin @ronaldjmaas @lfinbob @risasoft @gamell

Please can you confirm if you are getting frequent missed attestations and how your chains are progressing generally? Are you seeing this error but everything else is fine?

Chain is progressing, but this results in one missed attestation every few hours. Here is an example miss:

Lighthouse
Sep 15 21:35:00.783 INFO New block received                      root: 0x4877fa38a814b534a13b4f4fc6387454517362899269f624909b0f1b8215d03f, slot: 4704473
Sep 15 21:35:02.081 ERRO Execution engine call failed            error: Reqwest(reqwest::Error { kind: Request, url: Url { scheme: "http", cannot_be_a_base: false, username: "", password: None, host: Some(Domain("eth1")), port: Some(8551), path: "/", query: None, fragment: None }, source: TimedOut }), service: exec
Sep 15 21:35:02.081 ERRO Error fetching block for peer           error: ExecutionLayerErrorPayloadReconstruction(0x83eda8c5d447c958100c731fd38c6bca6ddf01e0cd620879050db3c3d5a97cf6, EngineError(Api { error: Reqwest(reqwest::Error { kind: Request, url: Url { scheme: "http", cannot_be_a_base: false, username: "", password: None, host: Some(Domain("eth1")), port: Some(8551), path: "/", query: None, fragment: None }, source: TimedOut }) })), block_root: 0x1ef5478c465d73a6c116b8d11ca8322629ec577f440c1ed36a6636dc16bf6901
Sep 15 21:35:05.000 INFO Synced                                  slot: 4704473, block: 0x4877…d03f, epoch: 147014, finalized_epoch: 147012, finalized_root: 0xa47e…7db3, exec_hash: 0xd52e…7fbd (verified), peers: 88, service: slot_notifier
Sep 15 21:35:12.196 INFO New block received                      root: 0x635cab6529683e845a778725b3bc212ff508034d57ac5c1f257a6efccb8bfb79, slot: 4704474
Sep 15 21:35:17.000 INFO Synced                                  slot: 4704474, block: 0x635c…fb79, epoch: 147014, finalized_epoch: 147012, finalized_root: 0xa47e…7db3, exec_hash: 0x77f4…2917 (verified), peers: 88, service: slot_notifier
Sep 15 21:35:24.469 INFO New block received                      root: 0xd295d95de95210eb4f22f900b0b1736e5caf68635d4001677bddf301389047b8, slot: 4704475
Sep 15 21:35:29.001 INFO Synced                                  slot: 4704475, block: 0xd295…47b8, epoch: 147014, finalized_epoch: 147012, finalized_root: 0xa47e…7db3, exec_hash: 0x2db3…be0c (verified), peers: 88, service: slot_notifier
Sep 15 21:35:36.269 INFO New block received                      root: 0x29fd729042a57ef1274b2399d17ec8880c9e2f98ec3634032f25b5e6cfff6635, slot: 4704476
Sep 15 21:35:41.001 INFO Synced                                  slot: 4704476, block: 0x29fd…6635, epoch: 147014, finalized_epoch: 147012, finalized_root: 0xa47e…7db3, exec_hash: 0xa79a…6fe5 (verified), peers: 88, service: slot_notifier
Sep 15 21:35:48.291 INFO New block received                      root: 0xc3c107468d514bf185df9015ea155acfd799e6da20123901837ebae8cd4b2515, slot: 4704477
Sep 15 21:35:53.001 INFO Synced                                  slot: 4704477, block: 0xc3c1…2515, epoch: 147014, finalized_epoch: 147012, finalized_root: 0xa47e…7db3, exec_hash: 0x6a73…618a (verified), peers: 88, service: slot_notifier
Sep 15 21:35:59.640 INFO New block received                      root: 0x93be335807c55b00d05fc8b18d951f91f01b45e9c4763b2c39e14f6c7cd9a8ef, slot: 4704478

Besu
2022-09-15 21:35:02.557+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,541,793 / 295 tx / base fee 10.15 gwei / 24,501,866 (81.7%) gas / (0xd52ebae0959ff920cb4c134418796d3b0c266853cb76bc3b903b858c4d217fbd) in 1.613s. Peers: 31
2022-09-15 21:35:02.653+00:00 | vert.x-worker-thread-4 | ERROR | JsonRpcExecutorHandler | Error streaming JSON-RPC response
2022-09-15 21:35:02.912+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | VALID for fork-choice-update: head: 0xd52ebae0959ff920cb4c134418796d3b0c266853cb76bc3b903b858c4d217fbd, finalized: 0x1822b4ad60df1b5ff7ba3ef0c5a2b364ad8fa6b10e85aec645a5de608c99331d, safeBlockHash: 0x5360f100463f5583d0f363a69f52bbcabe16c0dea2f2f1aaccb23b635390e4d3
2022-09-15 21:35:13.014+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,541,794 / 123 tx / base fee 10.95 gwei / 13,220,761 (44.1%) gas / (0x77f4b903afd5ad093eeb3ec5281cadf67a23c64f0a2e3222f87195da61f22917) in 0.700s. Peers: 31
2022-09-15 21:35:26.007+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,541,795 / 219 tx / base fee 10.79 gwei / 20,635,640 (68.8%) gas / (0x2db376c30e6da6a4dff5830d3e2190692ca57358e474a7defa1b83029dcdbe0c) in 1.407s. Peers: 31
2022-09-15 21:35:36.913+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,541,796 / 120 tx / base fee 11.30 gwei / 9,326,028 (31.1%) gas / (0xa79a442a9770a68f901a8b0cc3704d645e5a41b40ce93ac608bbfa186a696fe5) in 0.528s. Peers: 31
2022-09-15 21:35:49.201+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,541,797 / 167 tx / base fee 10.76 gwei / 12,233,151 (40.8%) gas / (0x6a73b3b9882561b7e5b34b9b005d1668fbc01cef178379d2531a9633e5c2618a) in 0.792s. Peers: 3100:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,543,062 / 408 tx / base fee 5.72 gwei / 19,633,855 (65.4%) gas / (0x2ff9b26b1f5f9d642820b0cbdf18dedd

[Gabriel-Trintinalia]

mainnet-nightly-fast-sync:
LH:
Sep 13 20:03:21.111 ERRO Error updating deposit contract cache error: "All fallbacks errored: http://10.0.0.32:8551/, auth=true => BlockDownloadFailed(\"eth_getBlockByNumber call failed Reqwest(reqwest::Error { kind: Request, url: Url { scheme: \\\"http\\\", cannot_be_a_base: false, username: \\\"\\\", password: None, host: Some(Ipv4(10.0.0.32)), port: Some(8551), path: \\\"/\\\", query: None, fragment: None }, source: hyper::Error(Connect, ConnectError(\\\"tcp connect error\\\", Os { code: 111, kind: ConnectionRefused, message: \\\"Connection refused\\\" })) })\")", retry_millis: 60000, service: deposit_contract_rpc
Besu:
eth_getBlockByHash - Error streaming JSON-RPC response

[ronaldjmaas]

@silado Since merge I missed 13 attestations. Although I see a lot of RPC JSON related errors in both Besu and Lighthouse BN log, I do not see any errors in the Lighthouse VC. Lighthouse VC log always shows 'Successfully published attestations' regardless if attestations were missed or not.

Besu + Lighthouse clients are successfully synced to chain. No issues there.

Note before merge I only missed 1 or 2 attestations during monthly upgrade / system reboot. Node has been running rock solid for many months until today.

[adv0r]

same

[siladu]

We added logging and see that lighthouse (which I think most users on this issue are using) sending eth_getBlockByHash is responsible for the streaming JSON-RPC response error, at least on our canary node.

#4398 (comment)

[ronaldjmaas]

There is something odd in the Lighthouse VC logs for the published attestations that miss. Not sure if it is relevant or not:

Missed attestations:
Sep 16 01:41:15.022 INFO Successfully published attestations type: unaggregated, slot: 4705704, committee_index: 48, head_block: 0xfe6b1636baa39acc3b4d3b35bb46fc4a8540df4c065b186eaee5092d84b3b5af, validator_indices: [XXXXXX], count: 1, service: attestation
Sep 16 03:58:27.019 INFO Successfully published attestations type: unaggregated, slot: 4706390, committee_index: 21, head_block: 0xc1e1d0cdacea21a3de2c9ea6ea36ccf595e9a81f9440b949b9ad5dafe3996749, validator_indices: [XXXXXX], count: 1, service: attestation
Sep 16 04:17:15.041 INFO Successfully published attestations type: unaggregated, slot: 4706484, committee_index: 21, head_block: 0x0a891eb8da184a2817b098a7d86c9e0dc6c2de8707892ef1db1b847ebc9e97d4, validator_indices: [XXXXXX], count: 1, service: attestation
Sep 16 06:39:39.035 INFO Successfully published attestations type: unaggregated, slot: 4707196, committee_index: 32, head_block: 0x8dbae33da336fadf013121763835c2c44dee95dd371c92823e471840b79254d0, validator_indices: [XXXXXX], count: 1, service: attestation
Sep 16 07:06:15.023 INFO Successfully published attestations type: unaggregated, slot: 4707329, committee_index: 11, head_block: 0x4d64715e4bbf8586f3c26a7f0d53505a80ccca4283ec5dc68a5db302c463f1ed, validator_indices: [XXXXXX], count: 1, service: attestation

There is a mismatch between the slot # and head_block. So if I understand correctly, the head_block values should have been:
Sep 16 01:41:15.022 INFO Successfully published attestations type: unaggregated, slot: 4705704, committee_index: 48, head_block: 0x1b63f6cb9807b7199abeb84dc719e7afc3ada69977df395718737fc81f4cdacd, validator_indices: [XXXXXX], count: 1, service: attestation
Sep 16 03:58:27.019 INFO Successfully published attestations type: unaggregated, slot: 4706390, committee_index: 21, head_block: 0x120f1de35c70dd7efe7492900dbf5b81e05242f37bbda786a4ddcfe6052f48f0, validator_indices: [XXXXXX], count: 1, service: attestation
Sep 16 04:17:15.041 INFO Successfully published attestations type: unaggregated, slot: 4706484, committee_index: 21, head_block: 0x181ae05b4dceecf4445cec54b651ebd6cb3ce4ea053c23de350521396b06b007, validator_indices: [XXXXXX], count: 1, service: attestation
Sep 16 06:39:39.035 INFO Successfully published attestations type: unaggregated, slot: 4707196, committee_index: 32, head_block: 0x977e52ad454edbe5de23f967decbc3861c8ab754d71435216fca38ee7dcca548, validator_indices: [XXXXXX], count: 1, service: attestation
Sep 16 07:06:15.023 INFO Successfully published attestations type: unaggregated, slot: 4707329, committee_index: 11, head_block: 0xef2ad9a4e387468d5a7cfc5921c56e78f3e50140bfbb54d9087b75d46e625ba5, validator_indices: [XXXXXX], count: 1, service: attestation

[ahamlat]

Here some update from the team.
We find a bug in the code where all the calls that come through the engine API port (8551) are sequential. For example, especially for the pair Lighthouse/Besu, all the errors io.netty.channel.StacklessClosedChannelException on eth calls are thrown because they have to wait to some engine_newPayloadV1 call to finish its execution, and this may take more than 1 second, which is the timeout set from the CL side.
We're currently working to make ETH calls parallel to the engine API calls, even if these ETH calls are made on port 8551.

[Primea1]

Still an issue with new update