search

hyperledger / besu

An enterprise-grade Java-based, Apache 2.0 licensed Ethereum client https://wiki.hyperledger.org/display/besu
https://www.hyperledger.org/projects/besu
Apache License 2.0
1.52k stars 840 forks source link

Post-Merge some blocks contain 0 transactions #4401

Closed non-fungible-nelson closed 2 years ago

non-fungible-nelson commented 2 years ago

Description

Issue stub - more details to come. Post-Merge we are seeing some blocks with 0 included transactions.

Acceptance Criteria

Steps to Reproduce (Bug)

  1. Observe logs post-merge for included transactions
macfarla commented 2 years ago

Pre-merge prater empty blocks (old discord thread but same user reporting this with post-merge mainnet) https://discord.com/channels/905194001349627914/938504958909747250/1009795829625786418 Hello! I have vouch + teku + besu in prater, and I see that sometimes there are no txs in my proposed blocks. Example: https://prater.beaconcha.in/block/3689038 and https://prater.beaconcha.in/block/3649149 Besu logs show nothing interesting about that: https://pastebin.com/ZcTqHatn Teku logs also nothing related (as I can understand it): https://pastebin.com/vRCGM6uz (about fee address logs - we set in vouch and it works, we can see it in a new block, dunno why teku complains about that constantly) How to research this problem?

macfarla commented 2 years ago

^ empty blocks on prater do happen normally.

From discord thread https://discord.com/channels/697535391594446898/1009446584611774535 there are a couple cases where besu might produce empty blocks.

When asked to produce a block, Besu starts with an empty block proposal candidate, just so it has something to respond to the CL with if it is not done building a block by the time the CL requests it. This historically has happened with nimbus because nimbus was not waiting the prescribed 500 milliseconds between asking for a block to be built and requesting the block. I don't think prysm has had this issue.

The other case is that it is possible non of the transactions in besu's pool are eligible for inclusion, either because of basefee or because of nonce. in 22.7.2 besu is changing its transaction eviction policy to ensure that we prioritize future nonce transactions for eviction ahead of lower value but executable transactions.

If you query the pending transactions endpoint, you can spot check some of the transactions in the pool to check whether they are executable or not

macfarla commented 2 years ago

https://discord.com/channels/905194001349627914/1009795829625786418/1019880263049822208 The same as above, but in mainnet after the merge at least 2 empty blocks https://beaconcha.in/slot/4700074 https://beaconcha.in/slot/4700312 the second one after restart teku/besu

macfarla commented 2 years ago

we are investigating this - working theory is that this is related to resource constraints - suggestion is to try increasing JVM memory as per https://besu.hyperledger.org/en/latest/public-networks/how-to/configure-jvm/manage-memory/

EvilJordan commented 2 years ago

It is not resource constraints. I, and many others, have powerful machines and never experienced this pre-merge. I'm running an Intel NUC i7 with 32gigs and 2TB, with Environment="JAVA_OPTS=-Xmx5g" in my Teku config.

CPU and memory are totally not-pressed.

macfarla commented 2 years ago

@EvilJordan can you add any logs from besu and/or teku and any other related info to this issue - this will help us a lot! Thanks

macfarla commented 2 years ago

from @ricardolyn hey. we have multiple blocks being produced by Besu with no transactions on Mainnet: 2022-09-15 10:49:11.144+00:00 | vert.x-worker-thread-0 | INFO | EngineGetPayload | Fetch block proposal by identifier: 0x0000000039a4e70a, hash: 0x10cc8dc3e64b3dd96f308bdaf30a50415bad9ebd0d0a1321c35cc07715383410, number: 15538609, coinbase: 0x..., transaction count: 0

Bonsai db allowed 1TB

Node size Standard_D8s_v4 8 vCPU 32GiB mem premium ssd 1024 GiB 5000 IOPS 200MBps throughput Pod specs: resources: requests: cpu: 6 memory: 12Gi limits: memory: 16Gi

we are giving 16gb of ram and we have set JVM max memory percentage to 75%. geth and Besu run on the same spec

macfarla commented 2 years ago

Reports on discord - asked for logs - https://besu.hyperledger.org/en/latest/public-networks/how-to/configure-jvm/manage-memory/

yorickdowne commented 2 years ago

I don't have debug logs on so this isn't terribly instructive. Teku CL and Besu EL, here are the consensus and execution logs for an empty proposal

consensus_1  | 2022-09-16 07:44:23.728 INFO  - ESC[32mEpoch Event *** Epoch: 147110, Justified checkpoint: 147109, Finalized checkpoint: 147108, Finalized root: fab70b7be3ac88eae00ed32cb66b66640bf2965f796d932da096cb7555d0554dESC[0m
consensus_1  | 2022-09-16 07:44:23.735 INFO  - Attestation performance: epoch 147108, expected 201, produced 209, included 209 (100%), distance 1 / 1.17 / 6, correct target 209 (100%), correct head 209 (100%)
consensus_1  | 2022-09-16 07:44:27.235 INFO  - ESC[37mSlot Event  *** Slot: 4707520, Block: 6524387954a53979174ef2595f93ee661ae6d0769cbe95a59a1365ba9e61ebe2, Justified: 147109, Finalized: 147108, Peers: 100ESC[0m
consensus_1  | 2022-09-16 07:50:47.625 INFO  - Block performance: epoch 147110, expected 1, produced 1, included 1 (100%)

execution_1  | 2022-09-16 07:44:13.499+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | VALID for fork-choice-update: head: 0xe347f499bef2d890429ff6c7427df40dc1172aa008ea2ff954fd40bc6542ba5f, finalized: 0xbb531f22d6bc946350982301d10cc31e239b3125bbaae470bfae39bd1d015d35, safeBlockHash: 0x43f5629141c0e350196bf7a64ba68eeadfde3f106a4bc8af45e6a44af453ae40
execution_1  | 2022-09-16 07:44:23.761+00:00 | vert.x-worker-thread-0 | INFO  | EngineGetPayload | Fetch block proposal by identifier: 0x000000006b424e56, hash: 0x12da62305308ab734b360a70170315436b70f03df6942d37f9ec8b23172b2b53, number: 15544780, coinbase: 0x388c818ca8b9251b393131c08a736a67ccb19297, transaction count: 0
execution_1  | 2022-09-16 07:44:24.720+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,544,780 / 0 tx / base fee 4.67 gwei / 0 (0.0%) gas / (0x12da62305308ab734b360a70170315436b70f03df6942d37f9ec8b23172b2b53) in 0.760s. Peers: 27
Tachyonica commented 2 years ago

I am running a NUC8i5BEH, 1TB NVME SSD + 4TB SSD, 32 GB RAM, with a Teku-Besu pair that had run flawlessly until the merge. Post merge it began to see missing blocks in the Teku logs that were not missed onchain, with increasing missed attestations over time, decreasing attestation performance, and the publication of one transaction-free empty block at slot 4701480: https://beaconcha.in/slot/4701480

Here are the Besu logs:

besu[285850]: 2022-09-15 13:35:37.739+02:00 | vert.x-worker-thread-0 | INFO | EngineForkchoiceUpdated | VALID for fork-choice-update: head:0x7ac48e0cc8f5bebd1e545661329afe205507acbf9e17604cba9f1ac2b9888e44, finalized: xfbb4d3f6d58ba3f248d2a471887a223289a16995288f02c83bdf8b2af51d5c1f, safeBlockHash:0x7acdadec6a2c887ae01ca76b20a67a613c2bda4461a4f36c89a5d9660aefc222

besu[285850]: 2022-09-15 13:36:23.229+02:00 | vert.x-worker-thread-0 | INFO | EngineGetPayload | Fetch block proposal by identifier: 0x000000000e2e9537, hash: 0xbc12bb44a42f5bcc9e00eec4b3c24370111f6740b775d96160b4f16993a958e0, number: 15538842, coinbase:x9c93698ee475f6a62c6f930c410270972ff10019, transaction count: 0

Here are the Teku logs:

2022-09-15 13:36:24.246+02:00 | CompletableFutureDelayScheduler | ERROR | ExecutionLayerManagerImpl | Unable to obtain a valid bid from builder. Falling back to local execution engine. java.util.concurrent.CompletionException: java.util.concurrent.TimeoutException at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:331) ~[?:?] at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:346) ~[?:?] at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:632) ~[?:?] at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?] at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2088) ~[?:?] at tech.pegasys.teku.infrastructure.async.SafeFuture.lambda$propagateResult$3(SafeFuture.java:145) ~[teku-infrastructure-async-22.9.0.jar:22.9.0] at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859) ~[?:?] at java.util.concurrent.CompletableFuture.uniWhenCompleteStage(CompletableFuture.java:883) ~[?:?] at java.util.concurrent.CompletableFuture.whenComplete(CompletableFuture.java:2251) ~[?:?] at tech.pegasys.teku.infrastructure.async.SafeFuture.whenComplete(SafeFuture.java:580) ~[teku-infrastructure-async-22.9.0.jar:22.9.0] at tech.pegasys.teku.infrastructure.async.SafeFuture.whenComplete(SafeFuture.java:32) ~[teku-infrastructure-async-22.9.0.jar:22.9.0] at tech.pegasys.teku.infrastructure.async.SafeFuture.propagateResult(SafeFuture.java:142) ~[teku-infrastructure-async-22.9.0.jar:22.9.0] at tech.pegasys.teku.infrastructure.async.SafeFuture.lambda$exceptionallyCompose$30(SafeFuture.java:399) ~[teku-infrastructure-async-22.9.0.jar:22.9.0] at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859) ~[?:?] at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:837) ~[?:?] at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?] at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2088) ~[?:?] at java.util.concurrent.CompletableFuture$Timeout.run(CompletableFuture.java:2792) ~[?:?] 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:829) ~[?:?] Caused by: java.util.concurrent.TimeoutException ... 7 more 2022-09-15 13:36:24.334+02:00 | ExecutionLayerChannel-0 | INFO | ExecutionLayerManagerImpl | Falling back to locally produced execution payload (Block Number 15538842, Block Hash = 0xbc12bb44a42f5bcc9e00eec4b3c24370111f6740b775d96160b4f16993a958e0, Fallback Reason = builder_error) 2022-09-15 13:36:24.450+02:00 | validator-async-77 | INFO | teku-validator-log | Validator *** Published block Count: 1, Slot: 4701480, Root: a48360ae141fab8743c121597b21b58735a05cd5d45943ba5ad1ac607d71d4bd, 0 (0%) gas, EL block: bc12bb44a42f5bcc9e00eec4b3c24370111f6740b775d96160b4f16993a958e0 (15538842)

0xcd2c6 commented 2 years ago

Since the merge I've proposed two blocks, the first one with just 2 transactions, the second one with only 1 transaction. I also experience frequent missed attestations.

I'm running besu/teku (solo), my specs are:

I'm getting the following errors in besu and teku at irregular intervals:


Sep 16 11:19:15 w2265 besu[235619]: org.hyperledger.besu.ethereum.trie.MerkleTrieException: Unable to load trie node value for hash 0xad4714107cdc07b22a8323d379fe4bd357f4f84667fec1bcd240c95ab9d725f9 location 0x
Sep 16 11:19:15 w2265 besu[235619]:         at org.hyperledger.besu.ethereum.trie.StoredNode.lambda$load$0(StoredNode.java:133)
Sep 16 11:19:15 w2265 besu[235619]:         at java.base/java.util.Optional.orElseThrow(Optional.java:408)
Sep 16 11:19:15 w2265 besu[235619]:         at org.hyperledger.besu.ethereum.trie.StoredNode.load(StoredNode.java:131)
Sep 16 11:19:15 w2265 besu[235619]:         at org.hyperledger.besu.ethereum.trie.StoredNode.accept(StoredNode.java:63)
Sep 16 11:19:15 w2265 besu[235619]:         at org.hyperledger.besu.ethereum.trie.StoredMerklePatriciaTrie.get(StoredMerklePatriciaTrie.java:119)
Sep 16 11:19:15 w2265 besu[235619]:         at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateKeyValueStorage.getAccount(BonsaiWorldStateKeyValueStorage.java:110)
Sep 16 11:19:15 w2265 besu[235619]:         at org.hyperledger.besu.ethereum.bonsai.BonsaiPersistedWorldState.get(BonsaiPersistedWorldState.java:340)
Sep 16 11:19:15 w2265 besu[235619]:         at org.hyperledger.besu.ethereum.bonsai.BonsaiLayeredWorldState.get(BonsaiLayeredWorldState.java:232)
Sep 16 11:19:15 w2265 besu[235619]:         at org.hyperledger.besu.ethereum.eth.transactions.TransactionPool.lambda$validateTransaction$2(TransactionPool.java:282)
Sep 16 11:19:15 w2265 besu[235619]:         at java.base/java.util.Optional.map(Optional.java:265)
Sep 16 11:19:15 w2265 besu[235619]:         at org.hyperledger.besu.ethereum.eth.transactions.TransactionPool.validateTransaction(TransactionPool.java:280)
Sep 16 11:19:15 w2265 besu[235619]:         at org.hyperledger.besu.ethereum.eth.transactions.TransactionPool.validateRemoteTransaction(TransactionPool.java:213)
Sep 16 11:19:15 w2265 besu[235619]:         at org.hyperledger.besu.ethereum.eth.transactions.TransactionPool.addRemoteTransactions(TransactionPool.java:153)
Sep 16 11:19:15 w2265 besu[235619]:         at org.hyperledger.besu.ethereum.eth.transactions.TransactionsMessageProcessor.processTransactionsMessage(TransactionsMessageProcessor.java:111)
Sep 16 11:19:15 w2265 besu[235619]:         at org.hyperledger.besu.ethereum.eth.transactions.TransactionsMessageProcessor.processTransactionsMessage(TransactionsMessageProcessor.java:85)
Sep 16 11:19:15 w2265 besu[235619]:         at org.hyperledger.besu.ethereum.eth.transactions.TransactionsMessageHandler.lambda$exec$0(TransactionsMessageHandler.java:48)
Sep 16 11:19:15 w2265 besu[235619]:         at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
Sep 16 11:19:15 w2265 besu[235619]:         at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
Sep 16 11:19:15 w2265 besu[235619]:         at java.base/java.lang.Thread.run(Thread.java:829)

Sep 16 11:08:03 w2265 teku[235819]: 2022-09-16 11:08:03.367 INFO  - Slot Event  *** Slot: 4707938, Block: 8b5f6900c7b1cc533614b3c11b8630533d70201dd80a74d31258bd69e9b4bfa4, Justified: 147122, Finalized: 147121, Peers: 128
Sep 16 11:08:14 w2265 teku[235819]: 2022-09-16 11:08:14.292 ERROR - Execution Client is offline
Sep 16 11:08:14 w2265 teku[235819]: java.util.concurrent.TimeoutException: null
Sep 16 11:08:14 w2265 teku[235819]: at java.util.concurrent.CompletableFuture$Timeout.run(CompletableFuture.java:2792) ~[?:?]
Sep 16 11:08:14 w2265 teku[235819]: at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
Sep 16 11:08:14 w2265 teku[235819]: at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
Sep 16 11:08:14 w2265 teku[235819]: at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
Sep 16 11:08:14 w2265 teku[235819]: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
Sep 16 11:08:14 w2265 teku[235819]: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
Sep 16 11:08:14 w2265 teku[235819]: at java.lang.Thread.run(Thread.java:829) ~[?:?]
Sep 16 11:08:14 w2265 teku[235819]: 2022-09-16 11:08:14.292 ERROR - An error occurred while querying remote transition configuration
Sep 16 11:08:14 w2265 teku[235819]: java.util.concurrent.CompletionException: java.lang.IllegalArgumentException: Invalid remote response: TimeoutException
Sep 16 11:08:14 w2265 teku[235819]: at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:314) ~[?:?]
Sep 16 11:08:14 w2265 teku[235819]: at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:319) ~[?:?]
Sep 16 11:08:14 w2265 teku[235819]: at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:645) ~[?:?]
Sep 16 11:08:14 w2265 teku[235819]: at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?]
Sep 16 11:08:14 w2265 teku[235819]: at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2073) ~[?:?]
Sep 16 11:08:14 w2265 teku[235819]: at tech.pegasys.teku.infrastructure.async.SafeFuture.lambda$propagateResult$3(SafeFuture.java:147) ~[teku-infrastructure-async-22.9.0.jar:22.9.0]
Sep 16 11:08:14 w2265 teku[235819]: at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859) ~[?:?]
Sep 16 11:08:14 w2265 teku[235819]: at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:837) ~[?:?]
Sep 16 11:08:14 w2265 teku[235819]: at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?]
Sep 16 11:08:14 w2265 teku[235819]: at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2088) ~[?:?]
Sep 16 11:08:14 w2265 teku[235819]: at java.util.concurrent.CompletableFuture$Timeout.run(CompletableFuture.java:2792) ~[?:?]
Sep 16 11:08:14 w2265 teku[235819]: at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
Sep 16 11:08:14 w2265 teku[235819]: at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
Sep 16 11:08:14 w2265 teku[235819]: at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
Sep 16 11:08:14 w2265 teku[235819]: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
Sep 16 11:08:14 w2265 teku[235819]: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
Sep 16 11:08:14 w2265 teku[235819]: at java.lang.Thread.run(Thread.java:829) ~[?:?]
Sep 16 11:08:14 w2265 teku[235819]: Caused by: java.lang.IllegalArgumentException: Invalid remote response: TimeoutException
Sep 16 11:08:14 w2265 teku[235819]: at com.google.common.base.Preconditions.checkArgument(Preconditions.java:220) ~[guava-31.1-jre.jar:?]
Sep 16 11:08:14 w2265 teku[235819]: at tech.pegasys.teku.ethereum.executionlayer.ExecutionLayerManagerImpl.unwrapResponseOrThrow(ExecutionLayerManagerImpl.java:504) ~[teku-ethereum-executionlayer-22.9.0.jar:22.9.0]
Sep 16 11:08:14 w2265 teku[235819]: at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:642) ~[?:?]
Sep 16 11:08:14 w2265 teku[235819]: ... 14 more
Sep 16 11:08:14 w2265 teku[235819]: 2022-09-16 11:08:14.524 INFO  - Execution Client is online
ghost commented 2 years ago

we are investigating this - working theory is that this is related to resource constraints - suggestion is to try increasing JVM memory as per https://besu.hyperledger.org/en/latest/public-networks/how-to/configure-jvm/manage-memory/

Our current setup is: Besu: for reference in GCP: e2-standard-4, 16GB, 4vCPU, 1TB Disk "-Xmx8g -Xms8g" Teku: for reference in GCP: e2-standard-4, 16GB, 4vCPU, 1TB Disk "-Xmx8g -Xms8g" (the same) Current Consumption: Besu: 40% CPU, 65% RAM Teku: 20% CPU, 60% RAM In pre-merge we didn't faced any problem with this setup

Restart doesn't help us to stop producing empty blocks :(

ghost commented 2 years ago

Logs from Besu/Teku which produced empty block logs.tar.gz

AugPeach commented 2 years ago

Using geth/teku, I proposed an empty block: https://etherscan.io/block/15545143. Maybe it's just a teku issue instead of a besu issue? Logs are completely uninteresting.

Teku:

2022-09-16 04:56:51.281-04:00 | TimeTick-1 | INFO  | teku-event-log | Slot Event  *** Slot: 4707882, Block: fd7ea87f4249004f517294a8fd06850809619ed1dee561c6bcad50a9f334a9bc, Justified: 147120, Finalized: 147119, Peers: 10
2022-09-16 04:57:03.274-04:00 | TimeTick-1 | INFO  | teku-event-log | Slot Event  *** Slot: 4707883, Block: 053fdd009f7329a1fb3f255827138056cf50bada1ee5030f2b208e93e33aea36, Justified: 147120, Finalized: 147119, Peers: 10
2022-09-16 04:57:12.108-04:00 | validator-async-104 | INFO  | teku-validator-log | Validator   *** Published attestation        Count: 1, Slot: 4707884, Root: c069be0068f8acd6562f11d9f2648437a6cbc2dd7307d24fce1b9c0beb4d0856
2022-09-16 04:57:15.221-04:00 | TimeTick-1 | INFO  | teku-event-log | Slot Event  *** Slot: 4707884, Block: c069be0068f8acd6562f11d9f2648437a6cbc2dd7307d24fce1b9c0beb4d0856, Justified: 147120, Finalized: 147119, Peers: 10
2022-09-16 04:57:27.273-04:00 | TimeTick-1 | INFO  | teku-event-log | Slot Event  *** Slot: 4707885, Block: e4d3337c68c9d13dd9fa2daa6c1fcd1eb01ec2937da0129f37dc54f014137032, Justified: 147120, Finalized: 147119, Peers: 10
2022-09-16 04:57:39.270-04:00 | TimeTick-1 | INFO  | teku-event-log | Slot Event  *** Slot: 4707886, Block: 1ee35111c18333e3bb131a7840f793767b37bd1beb50d9b8e4f1b9954a0f60a9, Justified: 147120, Finalized: 147119, Peers: 10
2022-09-16 04:57:51.272-04:00 | TimeTick-1 | INFO  | teku-event-log | Slot Event  *** Slot: 4707887, Block: 0158c23cf0ce06647497b93a27f322f8186d30d5eab640c55326110e125ba01b, Justified: 147120, Finalized: 147119, Peers: 10
2022-09-16 04:58:03.271-04:00 | TimeTick-1 | INFO  | teku-event-log | Slot Event  *** Slot: 4707888, Block: 51413fef6fde0ed9817110e40c792d894e817f9aae47b2909e84db0ff2c40caa, Justified: 147120, Finalized: 147119, Peers: 10
2022-09-16 04:58:11.607-04:00 | validator-async-109 | INFO  | teku-validator-log | Validator   *** Published block              Count: 1, Slot: 4707889, Root: 5a58132ace7c7e85e01d9501532b8d73798d788ca3d0a285024f025ad0444d8e, 0 (0%) gas, EL block:  acb097c4bf007e9d22733baddc937fed10b284ef785ef3625e9576ac6f07c71b (15545143)
2022-09-16 04:58:15.254-04:00 | TimeTick-1 | INFO  | teku-event-log | Slot Event  *** Slot: 4707889, Block: 5a58132ace7c7e85e01d9501532b8d73798d788ca3d0a285024f025ad0444d8e, Justified: 147120, Finalized: 147119, Peers: 10
2022-09-16 04:58:24.844-04:00 | validator-async-105 | INFO  | teku-validator-log | Validator   *** Published attestation        Count: 1, Slot: 4707890, Root: 46a72dc71a8fd0bad240b75bf2c4099ba910a6c30cff50f2db0286186e533267
2022-09-16 04:58:27.220-04:00 | TimeTick-1 | INFO  | teku-event-log | Slot Event  *** Slot: 4707890, Block: 46a72dc71a8fd0bad240b75bf2c4099ba910a6c30cff50f2db0286186e533267, Justified: 147120, Finalized: 147119, Peers: 10
2022-09-16 04:58:39.272-04:00 | TimeTick-1 | INFO  | teku-event-log | Slot Event  *** Slot: 4707891, Block: cebd8997263f5beb7caf9b49f3940a39420c8b3b3635b53b57cf2de94a46f05f, Justified: 147120, Finalized: 147119, Peers: 10
2022-09-16 04:58:47.264-04:00 | SlotEventsChannel-11 | INFO  | ValidatorBasedStableSubnetSubscriber | Updating number of persistent subnet subscriptions from 11 to 12
2022-09-16 04:58:47.950-04:00 | validator-async-87 | INFO  | teku-validator-log | Validator   *** Published attestation        Count: 1, Slot: 4707892, Root: d53892354a71f9f2427eb50f83a0f4aae1da21c215ff7e9b6d21e1d4cdd1c734
2022-09-16 04:58:51.221-04:00 | TimeTick-1 | INFO  | teku-event-log | Slot Event  *** Slot: 4707892, Block: d53892354a71f9f2427eb50f83a0f4aae1da21c215ff7e9b6d21e1d4cdd1c734, Justified: 147120, Finalized: 147119, Peers: 10
2022-09-16 04:59:03.291-04:00 | TimeTick-1 | INFO  | teku-event-log | Slot Event  *** Slot: 4707893, Block: 62bfc521207f5aedc994efe8d89e2725ba89d61d5d5e051493f6e753697a8d64, Justified: 147120, Finalized: 147119, Peers: 10
2022-09-16 04:59:12.247-04:00 | validator-async-109 | INFO  | teku-validator-log | Validator   *** Published attestation        Count: 1, Slot: 4707894, Root: 7521c1fd32809ea96a7bb61c80d0a3cb084c104847bec306106b6ffb528c2652
2022-09-16 04:59:15.220-04:00 | TimeTick-1 | INFO  | teku-event-log | Slot Event  *** Slot: 4707894, Block: 7521c1fd32809ea96a7bb61c80d0a3cb084c104847bec306106b6ffb528c2652, Justified: 147120, Finalized: 147119, Peers: 10
2022-09-16 04:59:24.644-04:00 | validator-async-105 | INFO  | teku-validator-log | Validator   *** Published attestation        Count: 1, Slot: 4707895, Root: 44dc12469db1062b74b756e64c739f4e8534a180d73a3fb7205724deafa98e0a
2022-09-16 04:59:27.221-04:00 | TimeTick-1 | INFO  | teku-event-log | Slot Event  *** Slot: 4707895, Block: 44dc12469db1062b74b756e64c739f4e8534a180d73a3fb7205724deafa98e0a, Justified: 147120, Finalized: 147119, Peers: 10
2022-09-16 04:59:39.278-04:00 | TimeTick-1 | INFO  | teku-event-log | Slot Event  *** Slot: 4707896, Block: e8b79e02bf3a5b821b3db9203b1a148f5e0d8791a334a2487a22f3aa4144eabf, Justified: 147120, Finalized: 147119, Peers: 10
2022-09-16 04:59:51.273-04:00 | TimeTick-1 | INFO  | teku-event-log | Slot Event  *** Slot: 4707897, Block: 43483c8da327b772f6a9479589e24d5b8f3e855f67f773adad9b8b16093b4b59, Justified: 147120, Finalized: 147119, Peers: 10
2022-09-16 05:00:03.270-04:00 | TimeTick-1 | INFO  | teku-event-log | Slot Event  *** Slot: 4707898, Block: f84643efd2dd662e91b72a181453da7b2cc8b3cf57d5d1894dda1a4c99998aeb, Justified: 147120, Finalized: 147119, Peers: 10
2022-09-16 05:00:13.268-04:00 | validator-async-104 | INFO  | teku-validator-log | Validator   *** Published attestation        Count: 1, Slot: 4707899, Root: 62574725c9ec1f3a8221937433b1a46c5112fb414e27c9199575652baa106ffb
2022-09-16 05:00:15.220-04:00 | TimeTick-1 | INFO  | teku-event-log | Slot Event  *** Slot: 4707899, Block: 62574725c9ec1f3a8221937433b1a46c5112fb414e27c9199575652baa106ffb, Justified: 147120, Finalized: 147119, Peers: 10
2022-09-16 05:00:27.277-04:00 | TimeTick-1 | INFO  | teku-event-log | Slot Event  *** Slot: 4707900, Block:                                                        ... empty, Justified: 147120, Finalized: 147119, Peers: 10
2022-09-16 05:00:39.296-04:00 | TimeTick-1 | INFO  | teku-event-log | Slot Event  *** Slot: 4707901, Block: d18ed3053c5c860bbb47a5ae0c8621771b333d4d9e4183d0581678aa5f29e0d6, Justified: 147120, Finalized: 147119, Peers: 10
2022-09-16 05:00:50.009-04:00 | validator-async-99 | INFO  | teku-validator-log | Validator   *** Published attestation        Count: 1, Slot: 4707902, Root: 6d7fd34d5724777528bbbc821ea61d4d5e4ca1f63e7d436137e123ba14fac9bf
2022-09-16 05:00:51.220-04:00 | TimeTick-1 | INFO  | teku-event-log | Slot Event  *** Slot: 4707902, Block: 6d7fd34d5724777528bbbc821ea61d4d5e4ca1f63e7d436137e123ba14fac9bf, Justified: 147120, Finalized: 147119, Peers: 10
2022-09-16 05:01:03.269-04:00 | TimeTick-1 | INFO  | teku-event-log | Slot Event  *** Slot: 4707903, Block: 15788bd580fee5474b885e023eb9159e9f3fec751e4b4c46d014523a2119f16c, Justified: 147120, Finalized: 147119, Peers: 10
2022-09-16 05:01:12.135-04:00 | TimeTick-1 | INFO  | teku-event-log | Epoch Event *** Epoch: 147122, Justified checkpoint: 147121, Finalized checkpoint: 147120, Finalized root: 868a5d2549447860c825c3a7311c18ceac37a6fff35e123dcf0b32caa09d57e0
2022-09-16 05:01:12.141-04:00 | SlotEventsChannel-10 | INFO  | teku-status-log | Attestation performance: epoch 147120, expected 12, produced 12, included 12 (100%), distance 1 / 1.00 / 1, correct target 12 (100%), correct head 12 (100%)
2022-09-16 05:01:12.142-04:00 | SlotEventsChannel-10 | INFO  | teku-status-log | Block performance: epoch 147121, expected 1, produced 1, included 1 (100%)
2022-09-16 05:01:15.287-04:00 | TimeTick-1 | INFO  | teku-event-log | Slot Event  *** Slot: 4707904, Block: c7cf27e8f514536e4ee2c148eada7d3d81c5527d57d0936b5040d8372169545b, Justified: 147121, Finalized: 147120, Peers: 10
2022-09-16 05:01:27.273-04:00 | TimeTick-1 | INFO  | teku-event-log | Slot Event  *** Slot: 4707905, Block: 03ca1250f840d058c2f45bf03755a3749256a9747b395ac42fabba4549e64bba, Justified: 147121, Finalized: 147120, Peers: 10
2022-09-16 05:01:39.273-04:00 | TimeTick-1 | INFO  | teku-event-log | Slot Event  *** Slot: 4707906, Block: 1cc30d0f945386b1173178b04887ea26518551db5cdaebf2108afb34b53cd12d, Justified: 147121, Finalized: 147120, Peers: 10
2022-09-16 05:01:48.951-04:00 | validator-async-106 | INFO  | teku-validator-log | Validator   *** Published attestation        Count: 1, Slot: 4707907, Root: 99edede82e7cab783092c182e73eec01226fe4f26e796bf8efbaf3f6dfc807b3
2022-09-16 05:01:51.220-04:00 | TimeTick-1 | INFO  | teku-event-log | Slot Event  *** Slot: 4707907, Block: 99edede82e7cab783092c182e73eec01226fe4f26e796bf8efbaf3f6dfc807b3, Justified: 147121, Finalized: 147120, Peers: 10
2022-09-16 05:02:03.271-04:00 | TimeTick-1 | INFO  | teku-event-log | Slot Event  *** Slot: 4707908, Block: 503c20afac8b2bcaca78a8bf5636d65405aed3783a2ef2fdf6bc062138d05c8a, Justified: 147121, Finalized: 147120, Peers: 10

geth:

Sep 16 04:55:35 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:55:35.571] Unindexed transactions                   blocks=1   txs=380   tail=13,195,131 elapsed=3.678ms
Sep 16 04:55:49 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:55:49.637] Imported new potential chain segment     blocks=1   txs=405   mgas=29.277  elapsed=662.869ms   mgasps=44.167   number=15,545,131 hash=d66dca..be86a5 dirty=127.90MiB
Sep 16 04:55:49 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:55:49.661] Chain head was updated                   number=15,545,131 hash=d66dca..be86a5 root=fc947b..cad3f8 elapsed=12.895784ms
Sep 16 04:55:49 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:55:49.664] Unindexed transactions                   blocks=1   txs=240   tail=13,195,132 elapsed=2.522ms
Sep 16 04:56:00 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:56:00.839] Imported new potential chain segment     blocks=1   txs=182   mgas=8.725   elapsed=407.331ms   mgasps=21.419   number=15,545,132 hash=ab8bfd..30b011 dirty=127.90MiB
Sep 16 04:56:00 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:56:00.853] Chain head was updated                   number=15,545,132 hash=ab8bfd..30b011 root=ffee1a..01a73b elapsed=3.192012ms
Sep 16 04:56:00 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:56:00.863] Unindexed transactions                   blocks=1   txs=3     tail=13,195,133 elapsed="179.635µs"
Sep 16 04:56:12 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:56:12.655] Imported new potential chain segment     blocks=1   txs=303   mgas=25.931  elapsed=660.070ms   mgasps=39.285   number=15,545,133 hash=c53edd..dc0665 dirty=127.90MiB
Sep 16 04:56:12 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:56:12.672] Chain head was updated                   number=15,545,133 hash=c53edd..dc0665 root=a123ce..f1d162 elapsed=6.240099ms
Sep 16 04:56:12 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:56:12.676] Unindexed transactions                   blocks=1   txs=275   tail=13,195,134 elapsed=3.742ms
Sep 16 04:56:23 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:56:23.568] Imported new potential chain segment     blocks=1   txs=72    mgas=6.988   elapsed=135.005ms   mgasps=51.757   number=15,545,134 hash=5607c9..bcff64 dirty=127.90MiB
Sep 16 04:56:23 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:56:23.576] Chain head was updated                   number=15,545,134 hash=5607c9..bcff64 root=6c3047..b524fa elapsed=1.537633ms
Sep 16 04:56:23 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:56:23.577] Unindexed transactions                   blocks=1   txs=19    tail=13,195,135 elapsed="522.805µs"
Sep 16 04:56:36 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:56:36.946] Imported new potential chain segment     blocks=1   txs=445   mgas=28.503  elapsed=1.002s      mgasps=28.435   number=15,545,135 hash=6a3db3..7281ff dirty=127.90MiB
Sep 16 04:56:36 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:56:36.968] Chain head was updated                   number=15,545,135 hash=6a3db3..7281ff root=5b387d..98e4bd elapsed=9.313861ms
Sep 16 04:56:36 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:56:36.969] Unindexed transactions                   blocks=1   txs=88    tail=13,195,136 elapsed=1.159ms
Sep 16 04:56:49 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:56:49.306] Imported new potential chain segment     blocks=1   txs=135   mgas=20.853  elapsed=984.290ms   mgasps=21.186   number=15,545,136 hash=007a29..7bfab6 dirty=127.90MiB
Sep 16 04:56:49 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:56:49.321] Chain head was updated                   number=15,545,136 hash=007a29..7bfab6 root=e0db84..7b9cf2 elapsed=7.193995ms
Sep 16 04:56:49 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:56:49.325] Unindexed transactions                   blocks=1   txs=344   tail=13,195,137 elapsed=4.446ms
Sep 16 04:57:00 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:57:00.312] Imported new potential chain segment     blocks=1   txs=260   mgas=24.489  elapsed=365.697ms   mgasps=66.965   number=15,545,137 hash=ad78b3..a9840e dirty=127.90MiB
Sep 16 04:57:00 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:57:00.333] Chain head was updated                   number=15,545,137 hash=ad78b3..a9840e root=8ae490..eb458c elapsed=8.034944ms
Sep 16 04:57:00 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:57:00.334] Unindexed transactions                   blocks=1   txs=144   tail=13,195,138 elapsed=1.609ms
Sep 16 04:57:11 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:57:11.990] Imported new potential chain segment     blocks=1   txs=196   mgas=14.826  elapsed=339.526ms   mgasps=43.666   number=15,545,138 hash=95b91a..8c14e6 dirty=127.90MiB
Sep 16 04:57:12 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:57:12.003] Chain head was updated                   number=15,545,138 hash=95b91a..8c14e6 root=992c29..3b20e5 elapsed=4.890803ms
Sep 16 04:57:12 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:57:12.005] Unindexed transactions                   blocks=1   txs=207   tail=13,195,139 elapsed=2.163ms
Sep 16 04:57:24 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:57:24.807] Imported new potential chain segment     blocks=1   txs=300   mgas=19.120  elapsed=418.420ms   mgasps=45.695   number=15,545,139 hash=92d170..f73065 dirty=127.90MiB
Sep 16 04:57:24 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:57:24.828] Chain head was updated                   number=15,545,139 hash=92d170..f73065 root=42027e..7b0993 elapsed=9.008129ms
Sep 16 04:57:24 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:57:24.828] Unindexed transactions                   blocks=1   txs=43    tail=13,195,140 elapsed="551.599µs"
Sep 16 04:57:35 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:57:35.921] Imported new potential chain segment     blocks=1   txs=93    mgas=7.155   elapsed=151.320ms   mgasps=47.283   number=15,545,140 hash=f37b5e..03dbdd dirty=127.90MiB
Sep 16 04:57:35 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:57:35.932] Chain head was updated                   number=15,545,140 hash=f37b5e..03dbdd root=04e73a..261267 elapsed=3.024927ms
Sep 16 04:57:35 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:57:35.933] Unindexed transactions                   blocks=1   txs=123   tail=13,195,141 elapsed=1.420ms
Sep 16 04:57:48 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:57:48.375] Imported new potential chain segment     blocks=1   txs=231   mgas=18.311  elapsed=405.607ms   mgasps=45.144   number=15,545,141 hash=b24569..5d194f dirty=127.90MiB
Sep 16 04:57:48 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:57:48.392] Chain head was updated                   number=15,545,141 hash=b24569..5d194f root=f00296..2684ad elapsed=6.99892ms
Sep 16 04:57:48 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:57:48.393] Unindexed transactions                   blocks=1   txs=88    tail=13,195,142 elapsed="766.486µs"
Sep 16 04:58:00 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:58:00.695] Imported new potential chain segment     blocks=1   txs=189   mgas=11.819  elapsed=482.309ms   mgasps=24.504   number=15,545,142 hash=89d265..a6b691 dirty=127.90MiB
Sep 16 04:58:00 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:58:00.761] Chain head was updated                   number=15,545,142 hash=89d265..a6b691 root=ff60ce..dd75a5 elapsed=6.263158ms
Sep 16 04:58:00 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:58:00.763] Unindexed transactions                   blocks=1   txs=274   tail=13,195,143 elapsed=1.799ms
Sep 16 04:58:11 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:58:11.475] Imported new potential chain segment     blocks=1   txs=0     mgas=0.000   elapsed="306.678µs" mgasps=0.000    number=15,545,143 hash=acb097..07c71b dirty=127.90MiB
Sep 16 04:58:11 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:58:11.597] Chain head was updated                   number=15,545,143 hash=acb097..07c71b root=ff60ce..dd75a5 elapsed="64.575µs"
Sep 16 04:58:11 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:58:11.602] Unindexed transactions                   blocks=1   txs=533   tail=13,195,144 elapsed=4.957ms
Sep 16 04:58:24 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:58:24.763] Imported new potential chain segment     blocks=1   txs=186   mgas=14.756  elapsed=400.538ms   mgasps=36.840   number=15,545,144 hash=2b5542..6946ef dirty=127.90MiB
Sep 16 04:58:24 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:58:24.776] Chain head was updated                   number=15,545,144 hash=2b5542..6946ef root=86037d..305257 elapsed=5.114828ms
Sep 16 04:58:24 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:58:24.779] Unindexed transactions                   blocks=1   txs=283   tail=13,195,145 elapsed=2.707ms
Sep 16 04:58:37 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:58:37.069] Imported new potential chain segment     blocks=1   txs=339   mgas=26.139  elapsed=662.653ms   mgasps=39.447   number=15,545,145 hash=2e6466..8e17f6 dirty=127.90MiB
Sep 16 04:58:37 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:58:37.088] Chain head was updated                   number=15,545,145 hash=2e6466..8e17f6 root=375d9e..c8d80e elapsed=7.926051ms
Sep 16 04:58:37 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:58:37.090] Unindexed transactions                   blocks=1   txs=99    tail=13,195,146 elapsed=1.182ms
Sep 16 04:58:47 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:58:47.841] Imported new potential chain segment     blocks=1   txs=102   mgas=4.225   elapsed=277.096ms   mgasps=15.246   number=15,545,146 hash=09b849..1ffe06 dirty=127.90MiB
Sep 16 04:58:47 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:58:47.850] Chain head was updated                   number=15,545,146 hash=09b849..1ffe06 root=f86843..1551b0 elapsed=1.274994ms
Sep 16 04:58:47 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:58:47.854] Unindexed transactions                   blocks=1   txs=372   tail=13,195,147 elapsed=4.048ms
Sep 16 04:58:59 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:58:59.924] Imported new potential chain segment     blocks=1   txs=117   mgas=9.923   elapsed=209.945ms   mgasps=47.265   number=15,545,147 hash=a3e8f8..87c114 dirty=127.90MiB
Sep 16 04:58:59 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:58:59.938] Chain head was updated                   number=15,545,147 hash=a3e8f8..87c114 root=571956..fa3af9 elapsed=2.398555ms
Sep 16 04:58:59 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:58:59.939] Unindexed transactions                   blocks=1   txs=34    tail=13,195,148 elapsed="712.936µs"
Sep 16 04:59:12 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:59:12.165] Imported new potential chain segment     blocks=1   txs=161   mgas=10.377  elapsed=325.944ms   mgasps=31.837   number=15,545,148 hash=154b35..9b2275 dirty=127.90MiB
Sep 16 04:59:12 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:59:12.179] Chain head was updated                   number=15,545,148 hash=154b35..9b2275 root=cb0095..e91809 elapsed=4.736858ms
Sep 16 04:59:12 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:59:12.188] Unindexed transactions                   blocks=1   txs=810   tail=13,195,149 elapsed=8.800ms
Sep 16 04:59:24 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:59:24.518] Imported new potential chain segment     blocks=1   txs=229   mgas=19.737  elapsed=429.183ms   mgasps=45.987   number=15,545,149 hash=c97cc8..f26831 dirty=127.90MiB
Sep 16 04:59:24 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:59:24.537] Chain head was updated                   number=15,545,149 hash=c97cc8..f26831 root=6546e5..eee970 elapsed=7.376738ms
Sep 16 04:59:24 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:59:24.539] Unindexed transactions                   blocks=1   txs=164   tail=13,195,150 elapsed=2.295ms
Sep 16 04:59:36 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:59:36.887] Imported new potential chain segment     blocks=1   txs=298   mgas=27.189  elapsed=501.328ms   mgasps=54.234   number=15,545,150 hash=1a3da4..06e950 dirty=127.90MiB
Sep 16 04:59:36 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:59:36.910] Chain head was updated                   number=15,545,150 hash=1a3da4..06e950 root=352ae4..3e5610 elapsed=11.482161ms
Sep 16 04:59:36 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:59:36.911] Unindexed transactions                   blocks=1   txs=142   tail=13,195,151 elapsed=1.496ms
Sep 16 04:59:48 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:59:48.155] Imported new potential chain segment     blocks=1   txs=215   mgas=16.780  elapsed=376.345ms   mgasps=44.585   number=15,545,151 hash=396c61..bd0d42 dirty=127.90MiB
Sep 16 04:59:48 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:59:48.169] Chain head was updated                   number=15,545,151 hash=396c61..bd0d42 root=6a9f3c..486789 elapsed=4.63877ms
Sep 16 04:59:48 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:59:48.172] Unindexed transactions                   blocks=1   txs=169   tail=13,195,152 elapsed=2.270ms
Sep 16 04:59:59 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:59:59.354] Imported new potential chain segment     blocks=1   txs=0     mgas=0.000   elapsed="316.907µs" mgasps=0.000    number=15,545,152 hash=e22521..cb2da9 dirty=127.90MiB
Sep 16 04:59:59 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:59:59.467] Chain head was updated                   number=15,545,152 hash=e22521..cb2da9 root=6a9f3c..486789 elapsed="62.024µs"
Sep 16 04:59:59 ThinkCentre-M90n-1 geth[854]: INFO [09-16|04:59:59.467] Unindexed transactions                   blocks=1   txs=111   tail=13,195,153 elapsed="855.653µs"
Sep 16 05:00:13 ThinkCentre-M90n-1 geth[854]: INFO [09-16|05:00:13.169] Imported new potential chain segment     blocks=1   txs=348   mgas=30.000  elapsed=653.985ms   mgasps=45.872   number=15,545,153 hash=ce2853..22d46e dirty=127.90MiB
Sep 16 05:00:13 ThinkCentre-M90n-1 geth[854]: INFO [09-16|05:00:13.188] Chain head was updated                   number=15,545,153 hash=ce2853..22d46e root=736760..bdbc38 elapsed=7.588255ms
Sep 16 05:00:13 ThinkCentre-M90n-1 geth[854]: INFO [09-16|05:00:13.190] Unindexed transactions                   blocks=1   txs=146   tail=13,195,154 elapsed=1.741ms
fab-10 commented 2 years ago

We have identified a case when there is timeout in RocksDB org.rocksdb.RocksDBException: TimedOut(LockTimeout), that interrupts the block creation. This lock timeout is triggered when another task is concurrently accessing the same data, and it takes more than a second to complete. Since the this error is transient, it make sense to retry the block creating if there is still time, since the other task may have completed in the meantime.

I am working on a PR for this retry mechanism

2022-09-16T07:51:42+01:00       ... 9 more
2022-09-16T07:51:42+01:00       at org.hyperledger.besu.ethereum.blockcreation.AbstractBlockCreator.createBlock(AbstractBlockCreator.java:193)
2022-09-16T07:51:42+01:00       at org.hyperledger.besu.ethereum.bonsai.BonsaiInMemoryWorldState.rootHash(BonsaiInMemoryWorldState.java:37)
2022-09-16T07:51:42+01:00       at org.hyperledger.besu.ethereum.bonsai.BonsaiInMemoryWorldState.rootHash(BonsaiInMemoryWorldState.java:43)
2022-09-16T07:51:42+01:00       at org.hyperledger.besu.ethereum.bonsai.BonsaiPersistedWorldState.calculateRootHash(BonsaiPersistedWorldState.java:224)
2022-09-16T07:51:42+01:00       at org.hyperledger.besu.ethereum.trie.StoredMerklePatriciaTrie.put(StoredMerklePatriciaTrie.java:142)
2022-09-16T07:51:42+01:00       at org.hyperledger.besu.ethereum.trie.StoredNode.accept(StoredNode.java:63)
2022-09-16T07:51:42+01:00       at org.hyperledger.besu.ethereum.trie.StoredNode.load(StoredNode.java:131)
2022-09-16T07:51:42+01:00       at java.base/java.util.Optional.orElseThrow(Optional.java:408)
2022-09-16T07:51:42+01:00       at org.hyperledger.besu.ethereum.trie.StoredNode.lambda$load$0(StoredNode.java:133)
2022-09-16T07:51:42+01:00   Caused by: org.hyperledger.besu.ethereum.trie.MerkleTrieException: Unable to load trie node value for hash 0x285085468a377839e01b244d1532878d5979d5e11030b3d90f58ceef5f93bba4 location 0x
2022-09-16T07:51:42+01:00       ... 6 more
2022-09-16T07:51:42+01:00       at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1700)
2022-09-16T07:51:42+01:00       at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.lambda$preparePayload$3(MergeCoordinator.java:192)
2022-09-16T07:51:42+01:00       at org.hyperledger.besu.consensus.merge.blockcreation.MergeBlockCreator.createBlock(MergeBlockCreator.java:67)
2022-09-16T07:51:42+01:00       at org.hyperledger.besu.ethereum.blockcreation.AbstractBlockCreator.createBlock(AbstractBlockCreator.java:211)
2022-09-16T07:51:42+01:00   Caused by: java.lang.IllegalStateException: Block creation failed unexpectedly. Will restart on next block added to chain.
2022-09-16T07:51:42+01:00       at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183)
2022-09-16T07:51:42+01:00       at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594)
2022-09-16T07:51:42+01:00       at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656)
2022-09-16T07:51:42+01:00       at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020)
2022-09-16T07:51:42+01:00       at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290)
2022-09-16T07:51:42+01:00       at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.exec(CompletableFuture.java:1692)
2022-09-16T07:51:42+01:00       at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1702)
2022-09-16T07:51:42+01:00       at java.base/java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:319)
2022-09-16T07:51:42+01:00       at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:314)
2022-09-16T07:51:42+01:00   java.util.concurrent.CompletionException: java.lang.IllegalStateException: Block creation failed unexpectedly. Will restart on next block added to chain.
2022-09-16T07:51:42+01:00   2022-09-16 06:51:42.748+00:00 | ForkJoinPool.commonPool-worker-11 | WARN  | MergeCoordinator | something went wrong creating block
2022-09-16T07:51:42+01:00       ... 17 more
2022-09-16T07:51:42+01:00       at org.hyperledger.besu.plugin.services.storage.rocksdb.segmented.RocksDBColumnarKeyValueStorage$RocksDbTransaction.put(RocksDBColumnarKeyValueStorage.java:260)
2022-09-16T07:51:42+01:00       at org.rocksdb.Transaction.put(Transaction.java:705)
2022-09-16T07:51:42+01:00       at org.rocksdb.Transaction.put(Native Method)
2022-09-16T07:51:42+01:00   Caused by: org.rocksdb.RocksDBException: TimedOut(LockTimeout)
2022-09-16T07:51:42+01:00       ... 9 more
2022-09-16T07:51:42+01:00       at org.hyperledger.besu.ethereum.blockcreation.AbstractBlockCreator.createBlock(AbstractBlockCreator.java:193)
2022-09-16T07:51:42+01:00       at org.hyperledger.besu.ethereum.bonsai.BonsaiInMemoryWorldState.rootHash(BonsaiInMemoryWorldState.java:37)
2022-09-16T07:51:42+01:00       at org.hyperledger.besu.ethereum.bonsai.BonsaiInMemoryWorldState.rootHash(BonsaiInMemoryWorldState.java:43)
2022-09-16T07:51:42+01:00       at org.hyperledger.besu.ethereum.bonsai.BonsaiPersistedWorldState.calculateRootHash(BonsaiPersistedWorldState.java:171)
2022-09-16T07:51:42+01:00       at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateKeyValueStorage$Updater.putStorageValueBySlotHash(BonsaiWorldStateKeyValueStorage.java:362)
2022-09-16T07:51:42+01:00       at org.hyperledger.besu.services.kvstore.SegmentedKeyValueStorageAdapter$1.put(SegmentedKeyValueStorageAdapter.java:80)
2022-09-16T07:51:42+01:00       at org.hyperledger.besu.services.kvstore.SegmentedKeyValueStorageTransactionTransitionValidatorDecorator.put(SegmentedKeyValueStorageTransactionTransitionValidatorDecorator.java:36)
2022-09-16T07:51:42+01:00       at org.hyperledger.besu.plugin.services.storage.rocksdb.segmented.RocksDBColumnarKeyValueStorage$RocksDbTransaction.put(RocksDBColumnarKeyValueStorage.java:247)
2022-09-16T07:51:42+01:00       at org.hyperledger.besu.plugin.services.storage.rocksdb.segmented.RocksDBColumnarKeyValueStorage$RocksDbTransaction.put(RocksDBColumnarKeyValueStorage.java:266)
2022-09-16T07:51:42+01:00   Caused by: org.hyperledger.besu.plugin.services.exception.StorageException: org.rocksdb.RocksDBException: TimedOut(LockTimeout)
2022-09-16T07:51:42+01:00       ... 6 more
2022-09-16T07:51:42+01:00       at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1700)
2022-09-16T07:51:42+01:00       at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.lambda$preparePayload$3(MergeCoordinator.java:192)
2022-09-16T07:51:42+01:00       at org.hyperledger.besu.consensus.merge.blockcreation.MergeBlockCreator.createBlock(MergeBlockCreator.java:67)
2022-09-16T07:51:42+01:00       at org.hyperledger.besu.ethereum.blockcreation.AbstractBlockCreator.createBlock(AbstractBlockCreator.java:211)
2022-09-16T07:51:42+01:00   Caused by: java.lang.IllegalStateException: Block creation failed unexpectedly. Will restart on next block added to chain.
2022-09-16T07:51:42+01:00       at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183)
2022-09-16T07:51:42+01:00       at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594)
2022-09-16T07:51:42+01:00       at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656)
2022-09-16T07:51:42+01:00       at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020)
2022-09-16T07:51:42+01:00       at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290)
2022-09-16T07:51:42+01:00       at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.exec(CompletableFuture.java:1692)
2022-09-16T07:51:42+01:00       at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1702)
2022-09-16T07:51:42+01:00       at java.base/java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:319)
2022-09-16T07:51:42+01:00       at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:314)
2022-09-16T07:51:42+01:00   java.util.concurrent.CompletionException: java.lang.IllegalStateException: Block creation failed unexpectedly. Will restart on next block added to chain.
2022-09-16T07:51:42+01:00   2022-09-16 06:51:42.376+00:00 | ForkJoinPool.commonPool-worker-5 | WARN  | MergeCoordinator | something went wrong creating block
matkt commented 2 years ago

@EvilJordan had a crash of its Besu node and it stopped. I also found a potential problem with the transaction pool but I need to investigate further. I don't believe @EvilJordan had exceptions when it had empty blocks. that's why for my part I look at the pool level

matkt commented 2 years ago

it is a user who uses MEV. So for this user it doesn't seem related to Besu. he just did an MEV update and we'll see if that's better

0xcd2c6 commented 2 years ago

I've since had two more proposals, the first with zero transactions, the second with 341 transactions. I haven't changed or updated anything since the merge. The errors and missed attestations remain.

Edit: and just now another proposal containing 1 transaction.

vanjan commented 2 years ago

I'm using besu/teku via rocket pool and I've had 3 empty proposals out of 5 since the merge (0 0 1 0 1) I thought it might have been b/c of mev-boost but it still happens after turning it off.

2022-09-17 17:30:16.104+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,554,798 / 442 tx / base fee 3.99 gwei / 29,992,840 (100.0%) gas / (0xdf15b8a516e51ae6d9c9f2759d0d87146eacaf5e03d8e502b6d7f2f4c1a7b250) in 4.285s. Peers: 31
2022-09-17 17:30:16.946+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | VALID for fork-choice-update: head: 0xdf15b8a516e51ae6d9c9f2759d0d87146eacaf5e03d8e502b6d7f2f4c1a7b250, finalized: 0x5658e81f6627771c986b3e1dc82dbee41dfbfa9db229734f0e538505c58f13dc, safeBlockHash: 0xbcecc0c803d8a733c582345c069aeb7b743b9a412188f9329d486ba8c71e56eb
2022-09-17 17:30:23.795+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,554,799 / 23 tx / base fee 4.49 gwei / 1,755,361 (5.9%) gas / (0x91220814a1d8acb6295de8f944b4e2b4777172f24275c078876f675ca1b81058) in 0.132s. Peers: 31
2022-09-17 17:30:42.252+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,554,800 / 1018 tx / base fee 3.99 gwei / 29,986,090 (100.0%) gas / (0x3dd87f76b6f7f16c7e6ead64eb095e21a35c654f11bafb6b84911624abd9b71f) in 6.341s. Peers: 31
2022-09-17 17:30:45.532+00:00 | ForkJoinPool.commonPool-worker-15 | WARN  | MergeCoordinator | something went wrong creating block
java.util.concurrent.CompletionException: java.lang.IllegalStateException: Block creation failed unexpectedly. Will restart on next block added to chain.
    at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:315)
    at java.base/java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:320)
    at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1770)
    at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.exec(CompletableFuture.java:1760)
    at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:373)
    at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1182)
    at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1655)
    at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1622)
    at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:165)
Caused by: java.lang.IllegalStateException: Block creation failed unexpectedly. Will restart on next block added to chain.
    at org.hyperledger.besu.ethereum.blockcreation.AbstractBlockCreator.createBlock(AbstractBlockCreator.java:211)
    at org.hyperledger.besu.consensus.merge.blockcreation.MergeBlockCreator.createBlock(MergeBlockCreator.java:67)
    at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.lambda$preparePayload$3(MergeCoordinator.java:192)
    at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1768)
    ... 6 more
Caused by: org.hyperledger.besu.plugin.services.exception.StorageException: org.rocksdb.RocksDBException: TimedOut(LockTimeout)
    at org.hyperledger.besu.plugin.services.storage.rocksdb.segmented.RocksDBColumnarKeyValueStorage$RocksDbTransaction.put(RocksDBColumnarKeyValueStorage.java:266)
    at org.hyperledger.besu.plugin.services.storage.rocksdb.segmented.RocksDBColumnarKeyValueStorage$RocksDbTransaction.put(RocksDBColumnarKeyValueStorage.java:247)
    at org.hyperledger.besu.services.kvstore.SegmentedKeyValueStorageTransactionTransitionValidatorDecorator.put(SegmentedKeyValueStorageTransactionTransitionValidatorDecorator.java:36)
    at org.hyperledger.besu.services.kvstore.SegmentedKeyValueStorageAdapter$1.put(SegmentedKeyValueStorageAdapter.java:80)
    at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateKeyValueStorage$Updater.putStorageValueBySlotHash(BonsaiWorldStateKeyValueStorage.java:362)
    at org.hyperledger.besu.ethereum.bonsai.BonsaiPersistedWorldState.calculateRootHash(BonsaiPersistedWorldState.java:171)
    at org.hyperledger.besu.ethereum.bonsai.BonsaiInMemoryWorldState.rootHash(BonsaiInMemoryWorldState.java:43)
    at org.hyperledger.besu.ethereum.bonsai.BonsaiInMemoryWorldState.rootHash(BonsaiInMemoryWorldState.java:37)
    at org.hyperledger.besu.ethereum.blockcreation.AbstractBlockCreator.createBlock(AbstractBlockCreator.java:193)
    ... 9 more
Caused by: org.rocksdb.RocksDBException: TimedOut(LockTimeout)
    at org.rocksdb.Transaction.put(Native Method)
    at org.rocksdb.Transaction.put(Transaction.java:705)
    at org.hyperledger.besu.plugin.services.storage.rocksdb.segmented.RocksDBColumnarKeyValueStorage$RocksDbTransaction.put(RocksDBColumnarKeyValueStorage.java:260)
    ... 17 more
2022-09-17 17:30:47.136+00:00 | vert.x-worker-thread-0 | INFO  | EngineGetPayload | Fetch block proposal by identifier: 0x0000000032d214a7, hash: 0x56e19650ed30f0b3fca282b41a2ffd33bb7fec2626dabdf754dc16252f92be22, number: 15554801, coinbase: 0xf68e2b1fab9469ff2177912ad330c019d62e374e, transaction count: 0
2022-09-17 17:30:47.498+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,554,801 / 0 tx / base fee 4.49 gwei / 0 (0.0%) gas / (0x56e19650ed30f0b3fca282b41a2ffd33bb7fec2626dabdf754dc16252f92be22) in 0.001s. Peers: 31
2022-09-17 17:31:03.968+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,554,802 / 492 tx / base fee 3.93 gwei / 29,984,255 (99.9%) gas / (0xda0e13d1b5089a58d8a40effbe3445f97a5da73b04940bf831be51f8204a6c3d) in 4.415s. Peers: 31
2022-09-17 17:31:13.282+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,554,803 / 172 tx / base fee 4.42 gwei / 15,546,775 (51.8%) gas / (0x759c905f46f35565cd76d79f9795b805ea1770c002b21f9ae8f56a52fa9a1102) in 1.740s. Peers: 31
2022-09-17 17:31:24.875+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,554,804 / 88 tx / base fee 4.44 gwei / 8,288,320 (27.6%) gas / (0x6352584a0fda81830f8daa3d452db4b1068f8e557075727cdb1a6ce2bcc0e436) in 0.895s. Peers: 31
2022-09-17 17:31:25.013+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | VALID for fork-choice-update: head: 0x6352584a0fda81830f8daa3d452db4b1068f8e557075727cdb1a6ce2bcc0e436, finalized: 0x5658e81f6627771c986b3e1dc82dbee41dfbfa9db229734f0e538505c58f13dc, safeBlockHash: 0xbcecc0c803d8a733c582345c069aeb7b743b9a412188f9329d486ba8c71e56eb
non-fungible-nelson commented 2 years ago

This above error is slightly different and should be fixed by #4407 - still investigating empty blocks.