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.5k stars 822 forks source link

Blocked threads after more than a month of uninterrupted uptime #4904

Closed ibhagwan closed 1 year ago

ibhagwan commented 1 year ago

Description

After more than a month or so of uninterrupted uptime, besu ran into a myriad of blocked threads causing sync to fall behind greatly and never catch up.

After a manual service restart (which took a long time to initialize the exisiting DB), everything is back to normal.

LOG OUTPUT

(the same message loops forever) ``` 2023-01-10 12:39:11.958-05:00 | vertx-blocked-thread-checker | WARN | BlockedThreadChecker | Thread Thread[vert.x-worker-thread-14,5,main] has been blocked for 977068 ms, time limit is 60000 ms io.vertx.core.VertxException: Thread blocked at java.base@17.0.5/jdk.internal.misc.Unsafe.park(Native Method) at java.base@17.0.5/java.util.concurrent.locks.LockSupport.park(LockSupport.java:211) at java.base@17.0.5/java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1864) at java.base@17.0.5/java.util.concurrent.ForkJoinPool.unmanagedBlock(ForkJoinPool.java:3463) at java.base@17.0.5/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3434) at java.base@17.0.5/java.util.concurrent.CompletableFuture.waitingGet(CompletableFuture.java:1898) at java.base@17.0.5/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2072) at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.response(ExecutionEngineJsonRpcMethod.java:89) at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.BaseJsonRpcProcessor.process(BaseJsonRpcProcessor.java:42) at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.TracedJsonRpcProcessor.process(TracedJsonRpcProcessor.java:41) at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.TimedJsonRpcProcessor.process(TimedJsonRpcProcessor.java:45) at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.AuthenticatedJsonRpcProcessor.process(AuthenticatedJsonRpcProcessor.java:51) at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.JsonRpcExecutor.execute(JsonRpcExecutor.java:92) at app//org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler.lambda$handler$8(JsonRpcExecutorHandler.java:79) at app//org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler$$Lambda$1152/0x000000080118f5c8.handle(Unknown Source) at app//io.vertx.ext.web.impl.BlockingHandlerDecorator.lambda$handle$0(BlockingHandlerDecorator.java:48) at app//io.vertx.ext.web.impl.BlockingHandlerDecorator$$Lambda$1532/0x00000008012b5258.handle(Unknown Source) at app//io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159) at app//io.vertx.core.impl.ContextImpl$$Lambda$1380/0x0000000801235e60.handle(Unknown Source) at app//io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100) at app//io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157) at app//io.vertx.core.impl.ContextImpl$$Lambda$1373/0x0000000801234190.run(Unknown Source) at java.base@17.0.5/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) at java.base@17.0.5/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) at app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.base@17.0.5/java.lang.Thread.run(Thread.java:833) 2023-01-10 12:39:11.958-05:00 | vertx-blocked-thread-checker | WARN | BlockedThreadChecker | Thread Thread[vert.x-worker-thread-18,5,main] has been blocked for 922700 ms, time limit is 60000 ms io.vertx.core.VertxException: Thread blocked at java.base@17.0.5/jdk.internal.misc.Unsafe.park(Native Method) at java.base@17.0.5/java.util.concurrent.locks.LockSupport.park(LockSupport.java:211) at java.base@17.0.5/java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1864) at java.base@17.0.5/java.util.concurrent.ForkJoinPool.unmanagedBlock(ForkJoinPool.java:3463) at java.base@17.0.5/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3434) at java.base@17.0.5/java.util.concurrent.CompletableFuture.waitingGet(CompletableFuture.java:1898) at java.base@17.0.5/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2072) at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.response(ExecutionEngineJsonRpcMethod.java:89) at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.BaseJsonRpcProcessor.process(BaseJsonRpcProcessor.java:42) at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.TracedJsonRpcProcessor.process(TracedJsonRpcProcessor.java:41) at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.TimedJsonRpcProcessor.process(TimedJsonRpcProcessor.java:45) at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.AuthenticatedJsonRpcProcessor.process(AuthenticatedJsonRpcProcessor.java:51) at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.JsonRpcExecutor.execute(JsonRpcExecutor.java:92) at app//org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler.lambda$handler$8(JsonRpcExecutorHandler.java:79) at app//org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler$$Lambda$1152/0x000000080118f5c8.handle(Unknown Source) at app//io.vertx.ext.web.impl.BlockingHandlerDecorator.lambda$handle$0(BlockingHandlerDecorator.java:48) at app//io.vertx.ext.web.impl.BlockingHandlerDecorator$$Lambda$1532/0x00000008012b5258.handle(Unknown Source) at app//io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159) at app//io.vertx.core.impl.ContextImpl$$Lambda$1380/0x0000000801235e60.handle(Unknown Source) at app//io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100) at app//io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157) at app//io.vertx.core.impl.ContextImpl$$Lambda$1373/0x0000000801234190.run(Unknown Source) at java.base@17.0.5/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) at java.base@17.0.5/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) at app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.base@17.0.5/java.lang.Thread.run(Thread.java:833) 2023-01-10 12:39:11.959-05:00 | vertx-blocked-thread-checker | WARN | BlockedThreadChecker | Thread Thread[vert.x-worker-thread-7,5,main] has been blocked for 723035 ms, time limit is 60000 ms io.vertx.core.VertxException: Thread blocked at java.base@17.0.5/jdk.internal.misc.Unsafe.park(Native Method) at java.base@17.0.5/java.util.concurrent.locks.LockSupport.park(LockSupport.java:211) at java.base@17.0.5/java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1864) at java.base@17.0.5/java.util.concurrent.ForkJoinPool.unmanagedBlock(ForkJoinPool.java:3463) at java.base@17.0.5/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3434) at java.base@17.0.5/java.util.concurrent.CompletableFuture.waitingGet(CompletableFuture.java:1898) at java.base@17.0.5/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2072) at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.response(ExecutionEngineJsonRpcMethod.java:89) at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.BaseJsonRpcProcessor.process(BaseJsonRpcProcessor.java:42) at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.TracedJsonRpcProcessor.process(TracedJsonRpcProcessor.java:41) at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.TimedJsonRpcProcessor.process(TimedJsonRpcProcessor.java:45) at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.AuthenticatedJsonRpcProcessor.process(AuthenticatedJsonRpcProcessor.java:51) at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.JsonRpcExecutor.execute(JsonRpcExecutor.java:92) at app//org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler.lambda$handler$8(JsonRpcExecutorHandler.java:79) at app//org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler$$Lambda$1152/0x000000080118f5c8.handle(Unknown Source) at app//io.vertx.ext.web.impl.BlockingHandlerDecorator.lambda$handle$0(BlockingHandlerDecorator.java:48) at app//io.vertx.ext.web.impl.BlockingHandlerDecorator$$Lambda$1532/0x00000008012b5258.handle(Unknown Source) at app//io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159) at app//io.vertx.core.impl.ContextImpl$$Lambda$1380/0x0000000801235e60.handle(Unknown Source) at app//io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100) at app//io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157) at app//io.vertx.core.impl.ContextImpl$$Lambda$1373/0x0000000801234190.run(Unknown Source) at java.base@17.0.5/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) at java.base@17.0.5/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) at app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.base@17.0.5/java.lang.Thread.run(Thread.java:833) 2023-01-10 12:39:11.959-05:00 | vertx-blocked-thread-checker | WARN | BlockedThreadChecker | Thread Thread[vert.x-worker-thread-0,5,main] has been blocked for 1070237 ms, time limit is 60000 ms io.vertx.core.VertxException: Thread blocked ```

Versions (Add all that apply)

DISTRIB_ID="void"

* Kernel Version: [`uname -a`]

Linux istake 5.19.17_1 #1 SMP PREEMPT_DYNAMIC Mon Oct 31 14:24:17 UTC 2022 x86_64 GNU/Linux

* Virtual Machine software & version: [`vmware -v`]
**N/A**
* Docker Version: [`docker version`]
**N/A**
* Cloud VM, type, size: [Amazon Web Services I3-large]
**N/A**

### Additional Information (Add any of the following or anything else that may be relevant)
* System info - memory, CPU

####################################################################################################

Besu 22.10.3

Configuration:

Network: Mainnet

Data storage: Bonsai

Sync mode: Checkpoint

RPC HTTP APIs: ADMIN,ETH,NET,DEBUG,TXPOOL,WEB3

RPC HTTP port: 8545

Engine APIs: ENGINE,ETH

Engine port: 8551

Host:

Java: openjdk-java-17

Maximum heap size: 3.91 GB

OS: linux-x86_64

glibc: 2.32

Total memory: 15.63 GB

CPU cores: 4

####################################################################################################

non-fungible-nelson commented 1 year ago

Thank you for this report! We are getting some reports on this, adding to the backlog. @ahamlat @matkt - could be an edge case of #4737 ? Requires more testing.

ahamlat commented 1 year ago

It's hard to say if it is related to #4737 but I don't see any indication in the shared logs. What I understand from the logs is that Besu takes too long to process a block. @ibhagwan could you share Besu Full logs ? And if you have Node exporter dashboard, please share "Storage Disk" panels

ibhagwan commented 1 year ago

After upgrading to 23.1.0 this seems to happen now once in 24 hours, sample log (will continue with the blocked threads in a loop):

2023-02-19 20:26:30.652-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineForkchoiceUpdated | VALID for fork-choice-update: head: 0x40bfad2bbeeca71711f6581429d745aa5b535785cb14aee7856e7542955f5826, finalized: 0x1ee4d65b5c57c2f9ecf2072af9498d83bd420b183a37d26c7145540b0503198d, safeBlockHash: 0xa503b5a3c8bd76f3aea106cf89e32edaa0e6e9e658617609261496e7dd3d22ad
2023-02-19 20:26:37.604-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,666,479 / 109 tx / base fee 22.32 gwei / 15,669,610 (52.2%) gas / (0x68c3425742d7a443cb80691252ca661c131d1daf0b52baecc1eeea1a54a6b070) in 6.938s. Peers: 70
2023-02-19 20:26:39.247-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,666,480 / 143 tx / base fee 22.45 gwei / 13,784,359 (45.9%) gas / (0x5d5029df7e99f4aa9d9a6dc3a79bdd07977418767afffa03ae6b2b0d0a53d87b) in 1.158s. Peers: 69
2023-02-19 20:26:41.876-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,666,481 / 111 tx / base fee 22.22 gwei / 19,478,263 (64.9%) gas / (0xfcd63f492157d1e9efb7f13a7260d70f7cc460e239ec260f6cbe7c11eb506cdc) in 2.104s. Peers: 70
2023-02-19 20:26:48.640-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,666,482 / 117 tx / base fee 23.05 gwei / 14,583,972 (48.6%) gas / (0x53fdd76aa7fa7869cf70d0e2f25b6eafb9d7bb58870789d7ed1ac627584b8eaf) in 6.223s. Peers: 70
2023-02-19 20:26:49.173-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,666,483 / 15 tx / base fee 22.97 gwei / 1,253,948 (4.2%) gas / (0x6c796cc4992eb863b80f482ac5b1b32590028e42cdf76f6a4717262e76322db0) in 0.075s. Peers: 70
2023-02-19 20:26:52.043-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,666,484 / 234 tx / base fee 20.34 gwei / 29,972,872 (99.9%) gas / (0xf2936c64d080d11f475004623925d15ba8607b146d42e826d17d16f32558475d) in 2.548s. Peers: 70
2023-02-19 20:26:53.079-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,666,485 / 140 tx / base fee 22.88 gwei / 15,325,559 (51.1%) gas / (0xc8de19a0d7d43e72696ab5a57101dc58e3c7ff68b8f6ba02ab075b4d4de92f8e) in 0.551s. Peers: 70
2023-02-19 20:27:06.921-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,666,486 / 106 tx / base fee 22.94 gwei / 14,611,383 (48.7%) gas / (0x8230f6aedaaf968792501bf976a904d4e1fe1f6959cdb4805250c304440287a9) in 6.464s. Peers: 70
2023-02-19 20:28:13.657-05:00 | vertx-blocked-thread-checker | WARN  | BlockedThreadChecker | Thread Thread[vert.x-worker-thread-0,5,main] has been blocked for 60277 ms, time limit is 60000 ms
io.vertx.core.VertxException: Thread blocked
        at app//org.rocksdb.Transaction.get(Native Method)
        at app//org.rocksdb.Transaction.get(Transaction.java:278)
        at app//org.hyperledger.besu.plugin.services.storage.rocksdb.segmented.RocksDBSnapshotTransaction.get(RocksDBSnapshotTransaction.java:103)
        at app//org.hyperledger.besu.plugin.services.storage.rocksdb.segmented.RocksDBColumnarKeyValueSnapshot.get(RocksDBColumnarKeyValueSnapshot.java:65)
        at app//org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateKeyValueStorage.getAccountStorageTrieNode(BonsaiWorldStateKeyValueStorage.java:129)
        at app//org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateKeyValueStorage.lambda$getStorageValueBySlotHash$5(BonsaiWorldStateKeyValueStorage.java:179)
        at app//org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateKeyValueStorage$$Lambda$1983/0x0000000801350000.getNode(Unknown Source)
        at app//org.hyperledger.besu.ethereum.trie.StoredNodeFactory.retrieve(StoredNodeFactory.java:96)
        at app//org.hyperledger.besu.ethereum.trie.StoredNode.load(StoredNode.java:132)
        at app//org.hyperledger.besu.ethereum.trie.StoredNode.accept(StoredNode.java:65)
        at app//org.hyperledger.besu.ethereum.trie.GetVisitor.visit(GetVisitor.java:46)
        at app//org.hyperledger.besu.ethereum.trie.BranchNode.accept(BranchNode.java:80)
        at app//org.hyperledger.besu.ethereum.trie.StoredNode.accept(StoredNode.java:66)
        at app//org.hyperledger.besu.ethereum.trie.GetVisitor.visit(GetVisitor.java:46)
        at app//org.hyperledger.besu.ethereum.trie.BranchNode.accept(BranchNode.java:80)
        at app//org.hyperledger.besu.ethereum.trie.StoredNode.accept(StoredNode.java:66)
        at app//org.hyperledger.besu.ethereum.trie.StoredMerklePatriciaTrie.get(StoredMerklePatriciaTrie.java:119)
        at app//org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateKeyValueStorage.getStorageValueBySlotHash(BonsaiWorldStateKeyValueStorage.java:183)
        at app//org.hyperledger.besu.ethereum.bonsai.BonsaiPersistedWorldState.getStorageValueBySlotHash(BonsaiPersistedWorldState.java:457)
        at app//org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.getStorageValueBySlotHash(BonsaiWorldStateUpdater.java:395)
        at app//org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.getStorageValue(BonsaiWorldStateUpdater.java:375)
        at app//org.hyperledger.besu.ethereum.bonsai.BonsaiAccount.getStorageValue(BonsaiAccount.java:208)
        at app//org.hyperledger.besu.evm.worldstate.UpdateTrackingAccount.getStorageValue(UpdateTrackingAccount.java:231)
        at app//org.hyperledger.besu.evm.worldstate.UpdateTrackingAccount.getStorageValue(UpdateTrackingAccount.java:231)
        at app//org.hyperledger.besu.evm.worldstate.UpdateTrackingAccount.getStorageValue(UpdateTrackingAccount.java:231)
        at app//org.hyperledger.besu.evm.operation.SLoadOperation.execute(SLoadOperation.java:64)
        at app//org.hyperledger.besu.evm.EVM.runToHalt(EVM.java:307)
        at app//org.hyperledger.besu.evm.processor.AbstractMessageProcessor.codeExecute(AbstractMessageProcessor.java:174)
        at app//org.hyperledger.besu.evm.processor.AbstractMessageProcessor.process(AbstractMessageProcessor.java:192)
        at app//org.hyperledger.besu.ethereum.mainnet.MainnetTransactionProcessor.process(MainnetTransactionProcessor.java:495)
        at app//org.hyperledger.besu.ethereum.mainnet.MainnetTransactionProcessor.processTransaction(MainnetTransactionProcessor.java:405)
        at app//org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:110)
        at app//org.hyperledger.besu.ethereum.mainnet.BlockProcessor.processBlock(BlockProcessor.java:78)
        at app//org.hyperledger.besu.ethereum.MainnetBlockValidator.processBlock(MainnetBlockValidator.java:218)
        at app//org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:135)
        at app//org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.validateBlock(MergeCoordinator.java:477)
        at app//org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.rememberBlock(MergeCoordinator.java:491)
        at app//org.hyperledger.besu.consensus.merge.blockcreation.TransitionCoordinator.rememberBlock(TransitionCoordinator.java:157)
        at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.engine.AbstractEngineNewPayload.syncResponse(AbstractEngineNewPayload.java:235)
        at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.lambda$response$0(ExecutionEngineJsonRpcMethod.java:73)
        at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod$$Lambda$1623/0x00000008012e2160.handle(Unknown Source)
        at app//io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)
        at app//io.vertx.core.impl.ContextImpl$$Lambda$1405/0x00000008012438d0.handle(Unknown Source)
        at app//io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)
        at app//io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157)
        at app//io.vertx.core.impl.ContextImpl$$Lambda$1402/0x0000000801242e18.run(Unknown Source)
        at app//io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)
        at app//io.vertx.core.impl.TaskQueue$$Lambda$763/0x0000000801089ee8.run(Unknown Source)
        at java.base@17.0.5/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
        at java.base@17.0.5/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
        at app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base@17.0.5/java.lang.Thread.run(Thread.java:833)
2023-02-19 20:28:14.319-05:00 | vertx-blocked-thread-checker | WARN  | BlockedThreadChecker | Thread Thread[vert.x-worker-thread-13,5,main] has been blocked for 60941 ms, time limit is 60000 ms
io.vertx.core.VertxException: Thread blocked
        at java.base@17.0.5/jdk.internal.misc.Unsafe.park(Native Method)
        at java.base@17.0.5/java.util.concurrent.locks.LockSupport.park(LockSupport.java:211)
        at java.base@17.0.5/java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1864)
        at java.base@17.0.5/java.util.concurrent.ForkJoinPool.unmanagedBlock(ForkJoinPool.java:3463)
        at java.base@17.0.5/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3434)
        at java.base@17.0.5/java.util.concurrent.CompletableFuture.waitingGet(CompletableFuture.java:1898)
        at java.base@17.0.5/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2072)
        at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.response(ExecutionEngineJsonRpcMethod.java:89)
        at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.BaseJsonRpcProcessor.process(BaseJsonRpcProcessor.java:42)
        at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.TracedJsonRpcProcessor.process(TracedJsonRpcProcessor.java:41)
        at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.TimedJsonRpcProcessor.process(TimedJsonRpcProcessor.java:45)
        at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.AuthenticatedJsonRpcProcessor.process(AuthenticatedJsonRpcProcessor.java:51)
        at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.JsonRpcExecutor.execute(JsonRpcExecutor.java:92)
        at app//org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler.executeRequest(JsonRpcExecutorHandler.java:118)
        at app//org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler.executeJsonObjectRequest(JsonRpcExecutorHandler.java:131)
        at app//org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler.lambda$handler$0(JsonRpcExecutorHandler.java:78)
        at app//org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler$$Lambda$1178/0x000000080119fc40.handle(Unknown Source)
        at app//io.vertx.ext.web.impl.BlockingHandlerDecorator.lambda$handle$0(BlockingHandlerDecorator.java:48)
        at app//io.vertx.ext.web.impl.BlockingHandlerDecorator$$Lambda$1561/0x00000008012c3cd8.handle(Unknown Source)
        at app//io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)
        at app//io.vertx.core.impl.ContextImpl$$Lambda$1405/0x00000008012438d0.handle(Unknown Source)
        at app//io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)
        at app//io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157)
        at app//io.vertx.core.impl.ContextImpl$$Lambda$1402/0x0000000801242e18.run(Unknown Source)
        at java.base@17.0.5/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
        at java.base@17.0.5/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
        at app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base@17.0.5/java.lang.Thread.run(Thread.java:833)
ibhagwan commented 1 year ago

It's hard to say if it is related to #4737 but I don't see any indication in the shared logs. What I understand from the logs is that Besu takes too long to process a block. @ibhagwan could you share Besu Full logs ? And if you have Node exporter dashboard, please share "Storage Disk" panels

Sorry I seem to have missed this ping, I don't have any node explorer, I have a minimally installed Linux with nothing aside the essentials to run a besu/nimbus combo, the besu logs are pretty uneventful, literally nothing but the VALID for fork-choice-update and Imported #<nr> logs.

Here's how the restart appears right after the force restart due to blocked thread and subsequent recovery:

2023-02-20 22:53:57.677-05:00 | main | INFO  | Besu | Starting Besu
2023-02-20 22:53:58.010-05:00 | main | INFO  | Besu |
####################################################################################################
#                                                                                                  #
# Besu 23.1.0                                                                                      #
#                                                                                                  #
# Configuration:                                                                                   #
# Network: Mainnet                                                                                 #
# Network Id: 1                                                                                    #
# Data storage: Bonsai                                                                             #
# Sync mode: Checkpoint                                                                            #
# RPC HTTP APIs: ADMIN,ETH,NET,DEBUG,TXPOOL,WEB3                                                   #
# RPC HTTP port: 8545                                                                              #
# Engine APIs: ENGINE,ETH                                                                          #
# Engine port: 8551                                                                                #
#                                                                                                  #
# Host:                                                                                            #
# Java: openjdk-java-17                                                                            #
# Maximum heap size: 3.91 GB                                                                       #
# OS: linux-x86_64                                                                                 #
# glibc: 2.36                                                                                      #
# Total memory: 15.64 GB                                                                           #
# CPU cores: 4                                                                                     #
#                                                                                                  #
####################################################################################################
2023-02-20 22:53:58.012-05:00 | main | INFO  | Besu | Connecting to 0 static nodes.
2023-02-20 22:53:58.012-05:00 | main | INFO  | Besu | Security Module: localfile
2023-02-20 22:53:58.032-05:00 | main | INFO  | Besu | Using the native implementation of alt bn128
2023-02-20 22:53:58.049-05:00 | main | INFO  | Besu | Using the native implementation of modexp
2023-02-20 22:53:58.049-05:00 | main | INFO  | Besu | Using the native implementation of the signature algorithm
2023-02-20 22:53:58.051-05:00 | main | INFO  | Besu | Using the native implementation of the blake2bf algorithm
2023-02-20 22:53:58.061-05:00 | main | INFO  | DatabaseMetadata | Lookup database metadata file in data directory: /var/lib/besu/mainnet
2023-02-20 22:53:58.092-05:00 | main | INFO  | RocksDBKeyValueStorageFactory | Existing database detected at /var/lib/besu/mainnet. Version 2
2023-02-20 22:55:18.583-05:00 | main | INFO  | KeyPairUtil | Loaded public key 0xcee8298a7d6857e3e014b31b77d9e631e7bb017928d2a94dc5d799c683479d1a143503373773ee91eb4023c0bacd3f98a0a9f875bb412a876cfe713ed2073b4c from /var/lib/besu/mainnet/key
2023-02-20 22:55:18.704-05:00 | main | INFO  | AbstractProtocolScheduleBuilder | Protocol schedule created with milestones: [Frontier: 0, Homestead: 1150000, DaoRecoveryInit: 1920000, DaoRecoveryTransition: 1920001, Homestead: 1920010, TangerineWhistle: 2463000, SpuriousDragon: 2675000, Byzantium: 4370000, Petersburg: 7280000, Istanbul: 9069000, MuirGlacier: 9200000, Berlin: 12244000, London: 12965000, ArrowGlacier: 13773000, GrayGlacier: 15050000]
2023-02-20 22:55:18.722-05:00 | main | INFO  | AbstractProtocolScheduleBuilder | Protocol schedule created with milestones: [Frontier: 0, Homestead: 1150000, DaoRecoveryInit: 1920000, DaoRecoveryTransition: 1920001, Homestead: 1920010, TangerineWhistle: 2463000, SpuriousDragon: 2675000, Byzantium: 4370000, Petersburg: 7280000, Istanbul: 9069000, MuirGlacier: 9200000, Berlin: 12244000, London: 12965000, ArrowGlacier: 13773000, GrayGlacier: 15050000]
2023-02-20 22:55:18.728-05:00 | main | INFO  | AbstractProtocolScheduleBuilder | Protocol schedule created with milestones: []
2023-02-20 22:55:19.149-05:00 | main | INFO  | TransactionPoolFactory | Enabling transaction pool
2023-02-20 22:55:19.149-05:00 | main | INFO  | TransactionPoolFactory | Disabling transaction handling during initial sync
2023-02-20 22:55:19.151-05:00 | main | INFO  | EthPeers | Updating the default best peer comparator
2023-02-20 22:55:19.168-05:00 | main | INFO  | BesuControllerBuilder | TTD difficulty is present, creating initial sync for PoS
2023-02-20 22:55:19.189-05:00 | main | INFO  | CheckpointDownloaderFactory | Checkpoint sync was requested, but cannot be enabled because the local blockchain is not empty.
2023-02-20 22:55:19.190-05:00 | main | INFO  | TransitionBesuControllerBuilder | TTD present, creating DefaultSynchronizer that stops propagating after finalization
2023-02-20 22:55:19.211-05:00 | main | INFO  | RunnerBuilder | Detecting NAT service.
2023-02-20 22:55:19.269-05:00 | main | INFO  | AbstractProtocolScheduleBuilder | Protocol schedule created with milestones: []
2023-02-20 22:55:19.314-05:00 | main | INFO  | AbstractProtocolScheduleBuilder | Protocol schedule created with milestones: []
2023-02-20 22:55:19.648-05:00 | main | INFO  | AbstractProtocolScheduleBuilder | Protocol schedule created with milestones: []
2023-02-20 22:55:19.652-05:00 | main | INFO  | Runner | Starting external services ...
2023-02-20 22:55:19.653-05:00 | main | INFO  | JsonRpcHttpService | Starting JSON-RPC service on 0.0.0.0:8545
2023-02-20 22:55:19.784-05:00 | vert.x-eventloop-thread-1 | INFO  | JsonRpcHttpService | JSON-RPC service started and listening on 0.0.0.0:8545
2023-02-20 22:55:19.785-05:00 | main | INFO  | EngineJsonRpcService | Starting JSON-RPC service on 0.0.0.0:8551
2023-02-20 22:55:19.789-05:00 | vert.x-eventloop-thread-1 | INFO  | EngineJsonRpcService | JSON-RPC service started and listening on 0.0.0.0:8551
2023-02-20 22:55:19.790-05:00 | main | INFO  | GraphQLHttpService | Starting GraphQL HTTP service on 0.0.0.0:8547
2023-02-20 22:55:19.791-05:00 | vert.x-eventloop-thread-1 | INFO  | GraphQLHttpService | GraphQL HTTP service started and listening on 0.0.0.0:8547
2023-02-20 22:55:19.792-05:00 | main | INFO  | WebSocketService | Starting Websocket service on 0.0.0.0:8546
2023-02-20 22:55:19.793-05:00 | vert.x-eventloop-thread-1 | INFO  | WebSocketService | Websocket service started and listening on 0.0.0.0:8546
2023-02-20 22:55:19.795-05:00 | main | INFO  | AutoTransactionLogBloomCachingService | Starting auto transaction log bloom caching service.
2023-02-20 22:55:19.795-05:00 | main | INFO  | LogBloomCacheMetadata | Lookup cache metadata file in data directory: /var/lib/besu/mainnet/caches
2023-02-20 22:55:19.817-05:00 | main | INFO  | Runner | Starting Ethereum main loop ...
2023-02-20 22:55:19.817-05:00 | main | INFO  | NatService | No NAT environment detected so no service could be started
2023-02-20 22:55:19.817-05:00 | main | INFO  | NetworkRunner | Starting Network.
2023-02-20 22:55:19.818-05:00 | main | INFO  | DefaultP2PNetwork | Starting DNS discovery with URL enrtree://AKA3AM6LPBYEUDMVNU3BSVQJ5AD45Y7YPOHJLEF6W26QOE4VTUDPE@all.mainnet.ethdisco.net
2023-02-20 22:55:19.863-05:00 | nioEventLoopGroup-2-1 | INFO  | RlpxAgent | P2P RLPx agent started and listening on /[0:0:0:0:0:0:0:0]:30303.
2023-02-20 22:55:19.864-05:00 | main | INFO  | PeerDiscoveryAgent | Starting peer discovery agent on host=0.0.0.0, port=30303
2023-02-20 22:55:19.895-05:00 | vert.x-eventloop-thread-1 | INFO  | VertxPeerDiscoveryAgent | Started peer discovery agent successfully, on effective host=0:0:0:0:0:0:0:0%0 and port=30303
2023-02-20 22:55:19.897-05:00 | main | INFO  | PeerDiscoveryAgent | P2P peer discovery agent started and listening on /[0:0:0:0:0:0:0:0%0]:30303
2023-02-20 22:55:19.940-05:00 | main | INFO  | PeerDiscoveryAgent | Writing node record to disk. NodeRecord{seq=35, publicKey=0x02cee8298a7d6857e3e014b31b77d9e631e7bb017928d2a94dc5d799c683479d1a, udpAddress=Optional[/8.9.8.160:30303], tcpAddress=Optional[/8.9.8.160:30303], asBase64=-Je4QP6uZ-JVM1LKyLnVtzaXNHt-kxeRh_qqbiM7FtgScjdRbV19NFC8pCTapQm25lSHfkrwkBswEjgt8m2uTs6QZjsjg2V0aMfGhPCv0OOAgmlkgnY0gmlwhAgJCKCJc2VjcDI1NmsxoQLO6CmKfWhX4-AUsxt32eYx57sBeSjSqU3F15nGg0edGoN0Y3CCdl-DdWRwgnZf, nodeId=0x3305b5a0d8b9d38a36fc2c73aa1de5eb86f3d889f68e7684cbfc1c0c3643db68, customFields={tcp=30303, udp=30303, ip=0x080908a0, eth=[[0xf0afd0e3, 0x]], id=V4, secp256k1=0x02cee8298a7d6857e3e014b31b77d9e631e7bb017928d2a94dc5d799c683479d1a}}
2023-02-20 22:55:20.022-05:00 | main | INFO  | DefaultP2PNetwork | Enode URL enode://cee8298a7d6857e3e014b31b77d9e631e7bb017928d2a94dc5d799c683479d1a143503373773ee91eb4023c0bacd3f98a0a9f875bb412a876cfe713ed2073b4c@8.9.8.160:30303
2023-02-20 22:55:20.023-05:00 | main | INFO  | DefaultP2PNetwork | Node address 0xaa1de5eb86f3d889f68e7684cbfc1c0c3643db68
2023-02-20 22:55:20.033-05:00 | main | INFO  | NetworkRunner | Supported capabilities: [eth/63, eth/64, eth/65, eth/66, eth/67, eth/68], [snap/1]
2023-02-20 22:55:20.033-05:00 | main | INFO  | DefaultSynchronizer | Starting synchronizer.
2023-02-20 22:55:20.035-05:00 | main | INFO  | TransactionPoolFactory | Enabling transaction handling following initial sync
2023-02-20 22:55:20.036-05:00 | main | INFO  | DefaultSynchronizer | Stopping block propagation.
2023-02-20 22:55:20.037-05:00 | main | INFO  | DefaultSynchronizer | Stopping the pruner.
2023-02-20 22:55:20.038-05:00 | main | INFO  | Runner | Ethereum main loop is up.
2023-02-20 22:55:32.953-05:00 | Timer-0 | INFO  | DNSResolver | Resolved 2409 nodes
:
5
2023-02-20 22:59:37.253-05:00 | vert.x-worker-thread-0 | INFO  | BackwardSyncContext | Starting a new backward sync session
2023-02-20 22:59:40.098-05:00 | nioEventLoopGroup-3-7 | INFO  | BackwardSyncStep | Backward sync phase 1 of 2 completed, downloaded a total of 211 headers. Peers: 18
2023-02-20 22:59:48.535-05:00 | nioEventLoopGroup-3-4 | INFO  | BackwardSyncContext | Backward sync phase 2 of 2, 0.78% completed, imported 1 blocks of at least 129 (current head 16674230, target head 16674358). Peers: 20
2023-02-20 22:59:59.140-05:00 | nioEventLoopGroup-3-4 | INFO  | BackwardSyncContext | Backward sync phase 2 of 2, 11.63% completed, imported 15 blocks of at least 129 (current head 16674244, target head 16674358). Peers: 22
2023-02-20 23:00:09.414-05:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardSyncContext | Backward sync phase 2 of 2, 18.60% completed, imported 24 blocks of at least 129 (current head 16674253, target head 16674358). Peers: 23
2023-02-20 23:00:20.313-05:00 | nioEventLoopGroup-3-7 | INFO  | BackwardSyncContext | Backward sync phase 2 of 2, 27.91% completed, imported 36 blocks of at least 129 (current head 16674265, target head 16674358). Peers: 21
2023-02-20 23:00:30.474-05:00 | nioEventLoopGroup-3-7 | INFO  | BackwardSyncContext | Backward sync phase 2 of 2, 37.98% completed, imported 49 blocks of at least 129 (current head 16674278, target head 16674358). Peers: 21
2023-02-20 23:00:41.060-05:00 | nioEventLoopGroup-3-3 | INFO  | BackwardSyncContext | Backward sync phase 2 of 2, 42.64% completed, imported 55 blocks of at least 129 (current head 16674284, target head 16674358). Peers: 29
2023-02-20 23:00:52.696-05:00 | nioEventLoopGroup-3-3 | INFO  | BackwardSyncContext | Backward sync phase 2 of 2, 52.71% completed, imported 68 blocks of at least 129 (current head 16674297, target head 16674358). Peers: 31
2023-02-20 23:01:03.404-05:00 | nioEventLoopGroup-3-10 | INFO  | BackwardSyncContext | Backward sync phase 2 of 2, 57.36% completed, imported 74 blocks of at least 129 (current head 16674303, target head 16674358). Peers: 32
2023-02-20 23:01:14.023-05:00 | nioEventLoopGroup-3-10 | INFO  | BackwardSyncContext | Backward sync phase 2 of 2, 68.99% completed, imported 89 blocks of at least 129 (current head 16674318, target head 16674358). Peers: 34
2023-02-20 23:01:25.597-05:00 | nioEventLoopGroup-3-7 | INFO  | BackwardSyncContext | Backward sync phase 2 of 2, 72.09% completed, imported 93 blocks of at least 129 (current head 16674322, target head 16674358). Peers: 32
2023-02-20 23:01:35.830-05:00 | nioEventLoopGroup-3-7 | INFO  | BackwardSyncContext | Backward sync phase 2 of 2, 86.82% completed, imported 112 blocks of at least 129 (current head 16674341, target head 16674358). Peers: 32
2023-02-20 23:01:45.929-05:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardSyncContext | Backward sync phase 2 of 2, 97.67% completed, imported 126 blocks of at least 129 (current head 16674355, target head 16674358). Peers: 31
2023-02-20 23:01:47.516-05:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardSyncContext | Backward sync phase 2 of 2 completed, imported a total of 129 blocks. Peers: 31
2023-02-20 23:01:47.517-05:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Current backward sync session is done
^[[A2023-02-20 23:05:13.941-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,674,359 / 103 tx / base fee 22.39 gwei / 9,105,734 (30.4%) gas / (0xb15b8ebe5c3f889f1829e81e1dd51880ce19b5888aa56db0782eecb61a0c51bc) in 0.623s. Peers: 63
2023-02-20 23:05:15.107-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,674,360 / 125 tx / base fee 21.29 gwei / 13,965,219 (46.6%) gas / (0x32f639f9013e30860b5dfe0e930058ee6d8453335dc4614f5224110e474b3012) in 0.686s. Peers: 62
2023-02-20 23:05:15.184-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineForkchoiceUpdated | VALID for fork-choice-update: head: 0xb15b8ebe5c3f889f1829e81e1dd51880ce19b5888aa56db0782eecb61a0c51bc, finalized: 0xd9039e5ad296a5fb0a79e8b9610f93bb9e93b15124bf191a73376227c2a8d11b, safeBlockHash: 0xaaabd5cf9a747b78b415170da8218fdc4d05c6c2e9398edb97c22088e37d80fe
2023-02-20 23:05:16.346-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,674,361 / 137 tx / base fee 21.11 gwei / 15,223,890 (50.7%) gas / (0x36f309983d1a14c3c05ff1b4667223d23df9d596f25e30e063603d574c514da8) in 0.849s. Peers: 62
2023-02-20 23:05:17.315-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,674,362 / 110 tx / base fee 21.15 gwei / 12,973,854 (43.2%) gas / (0xe2d8ee7689d0dd8f28c541b1aec2c50996767159ac7a484e6fb1da4615a46701) in 0.595s. Peers: 63
2023-02-20 23:05:18.406-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,674,363 / 161 tx / base fee 20.79 gwei / 14,672,684 (48.9%) gas / (0xa725c2852ae2de2472864153032efecd186f79381cf37422ea6034c0816a3c08) in 0.713s. Peers: 62
2023-02-20 23:05:19.268-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,674,364 / 106 tx / base fee 20.74 gwei / 12,310,992 (41.0%) gas / (0xb24cd9274cfc2a420f88aa38014656d2d21ce57c36e7d1c8154011611d05439e) in 0.511s. Peers: 63
2023-02-20 23:05:20.346-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,674,365 / 146 tx / base fee 20.27 gwei / 17,773,469 (59.2%) gas / (0x42c0028b5052f6a2b65de6bfdb411fe2d1699b7b510fc21e451c91609dd16e6f) in 0.594s. Peers: 63
2023-02-20 23:05:21.427-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,674,366 / 199 tx / base fee 20.74 gwei / 16,370,270 (54.6%) gas / (0x801f2aca5ed50c293ac2903a97027e41f532d6927626c98f8d4a4021fa5ad37c) in 0.754s. Peers: 64
2023-02-20 23:05:22.317-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,674,367 / 148 tx / base fee 20.98 gwei / 12,511,072 (41.7%) gas / (0x1da1695a6ed08be6c9d175dc21a33aa8c122420cc0001297ca586bb74c65f116) in 0.534s. Peers: 62
2023-02-20 23:05:23.297-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,674,368 / 185 tx / base fee 20.54 gwei / 18,543,001 (61.8%) gas / (0xd3b3e919e2d6699d6b7d032f032cad3957aef0c9a0cf2760b94f67635b7c70be) in 0.663s. Peers: 62
2023-02-20 23:05:24.009-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,674,369 / 110 tx / base fee 21.15 gwei / 12,851,331 (42.8%) gas / (0x24a1d096293b822a02be9c70615b6df0e67e51e3c6036826c1b4bc7dba73c4ae) in 0.503s. Peers: 62
2023-02-20 23:05:26.645-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,674,370 / 122 tx / base fee 20.77 gwei / 29,953,146 (99.8%) gas / (0x2cf92ce5a0c74f27325696e3ad933e5c0481939b89a700dbed7308785cdb730a) in 2.431s. Peers: 62
2023-02-20 23:05:27.325-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,674,371 / 125 tx / base fee 23.36 gwei / 13,844,102 (46.1%) gas / (0xd62e6114022499de2839f7c6d85e52a44ba1254e405eb53767f02f241c0ab96f) in 0.468s. Peers: 62
ibhagwan commented 1 year ago

Hopefully this also helps, after restarting the node can never sync back until both the EL and CL are fully restarted (again):

Note the many WARN | DefaultBlockchain | Chain Reorganization +85 new / -0 old warnings

2023-02-20 23:17:13.517-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,674,435 / 32 tx / base fee 26.72 gwei / 2,747,596 (9.2%) gas / (0xe576cb53e698b30965686693ef37aa691ab9f70a63bd11f4b697c8683630b448) in 0.108s. Peers: 67
2023-02-20 23:17:14.792-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,674,436 / 229 tx / base fee 24.00 gwei / 27,493,223 (91.6%) gas / (0xeb85385f70b2d3fb0f5fd7d74d8dd72b0d88a8f7c9d2e3f1c250f591ffd4fa08) in 0.998s. Peers: 67
2023-02-20 23:17:15.607-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,674,437 / 98 tx / base fee 26.49 gwei / 9,242,783 (30.8%) gas / (0x6ae702ee490af1994fdd06f9648cc705f3a96584f486c81062d713a05e7fe1ba) in 0.356s. Peers: 67
2023-02-20 23:18:59.842-05:00 | vert.x-worker-thread-0 | INFO  | BackwardSyncContext | Starting a new backward sync session
2023-02-20 23:18:59.952-05:00 | nioEventLoopGroup-3-1 | INFO  | BackwardSyncStep | Backward sync phase 1 of 2 completed, downloaded a total of 197 headers. Peers: 69
2023-02-20 23:19:00.874-05:00 | nioEventLoopGroup-3-1 | WARN  | DefaultBlockchain | Chain Reorganization +0 new / -80 old
Old - hash: 0x45303c414b3c72a9559017bd84aee2e1cb74463e4f9b18d0713480b156423633, height: 16674438
New - hash: 0x6493d045ee713f467143621811930a9f4d3a6255ff3ecdd3e7d8f41df169bb1c, height: 16674358
Ancestor - hash: 0x6493d045ee713f467143621811930a9f4d3a6255ff3ecdd3e7d8f41df169bb1c, height: 16674358
2023-02-20 23:19:01.902-05:00 | nioEventLoopGroup-3-1 | INFO  | BackwardSyncContext | Backward sync phase 2 of 2, 7.69% completed, imported 1 blocks of at least 13 (current head 16674438, target head 16674450). Peers: 69
2023-02-20 23:20:03.304-05:00 | nioEventLoopGroup-3-1 | INFO  | BackwardSyncContext | Backward sync phase 2 of 2, 66.67% completed, imported 2 blocks of at least 3 (current head 16674439, target head 16674440). Peers: 69
2023-02-20 23:20:10.644-05:00 | vertx-blocked-thread-checker | WARN  | BlockedThreadChecker | Thread Thread[vert.x-worker-thread-0,5,main] has been blocked for 60196 ms, time limit is 60000 ms
io.vertx.core.VertxException: Thread blocked
at java.base@17.0.5/jdk.internal.misc.Unsafe.park(Native Method)
at java.base@17.0.5/java.util.concurrent.locks.LockSupport.park(LockSupport.java:341)
at java.base@17.0.5/java.util.concurrent.ForkJoinTask.awaitDone(ForkJoinTask.java:468)
at java.base@17.0.5/java.util.concurrent.ForkJoinTask.invoke(ForkJoinTask.java:687)
at java.base@17.0.5/java.util.stream.ForEachOps$ForEachOp.evaluateParallel(ForEachOps.java:159)
at java.base@17.0.5/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateParallel(ForEachOps.java:173)
at java.base@17.0.5/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:233)
at java.base@17.0.5/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:596)
at java.base@17.0.5/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:765)
at app//org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.commit(BonsaiWorldStateUpdater.java:263)
at app//org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:134)
at app//org.hyperledger.besu.ethereum.mainnet.BlockProcessor.processBlock(BlockProcessor.java:78)
at app//org.hyperledger.besu.ethereum.MainnetBlockValidator.processBlock(MainnetBlockValidator.java:218)
at app//org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:135)
at app//org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.validateBlock(MergeCoordinator.java:477)
at app//org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.rememberBlock(MergeCoordinator.java:491)
at app//org.hyperledger.besu.consensus.merge.blockcreation.TransitionCoordinator.rememberBlock(TransitionCoordinator.java:157)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.engine.AbstractEngineNewPayload.syncResponse(AbstractEngineNewPayload.java:235)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.lambda$response$0(ExecutionEngineJsonRpcMethod.java:73)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod$$Lambda$1654/0x0000000801305800.handle(Unknown Source)
at app//io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)
at app//io.vertx.core.impl.ContextImpl$$Lambda$1383/0x0000000801245238.handle(Unknown Source)
at app//io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)
at app//io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157)
at app//io.vertx.core.impl.ContextImpl$$Lambda$1382/0x0000000801246aa0.run(Unknown Source)
at app//io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)
at app//io.vertx.core.impl.TaskQueue$$Lambda$763/0x000000080108a5a8.run(Unknown Source)
at java.base@17.0.5/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base@17.0.5/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base@17.0.5/java.lang.Thread.run(Thread.java:833)
2023-02-20 23:20:11.158-05:00 | vertx-blocked-thread-checker | WARN  | BlockedThreadChecker | Thread Thread[vert.x-worker-thread-14,5,main] has been blocked for 60719 ms, time limit is 60000 ms
io.vertx.core.VertxException: Thread blocked
at java.base@17.0.5/jdk.internal.misc.Unsafe.park(Native Method)
at java.base@17.0.5/java.util.concurrent.locks.LockSupport.park(LockSupport.java:211)
at java.base@17.0.5/java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1864)
at java.base@17.0.5/java.util.concurrent.ForkJoinPool.unmanagedBlock(ForkJoinPool.java:3463)
at java.base@17.0.5/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3434)
at java.base@17.0.5/java.util.concurrent.CompletableFuture.waitingGet(CompletableFuture.java:1898)
at java.base@17.0.5/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2072)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.response(ExecutionEngineJsonRpcMethod.java:89)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.BaseJsonRpcProcessor.process(BaseJsonRpcProcessor.java:42)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.TracedJsonRpcProcessor.process(TracedJsonRpcProcessor.java:41)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.TimedJsonRpcProcessor.process(TimedJsonRpcProcessor.java:45)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.AuthenticatedJsonRpcProcessor.process(AuthenticatedJsonRpcProcessor.java:51)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.JsonRpcExecutor.execute(JsonRpcExecutor.java:92)
at app//org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler.executeRequest(JsonRpcExecutorHandler.java:118)
at app//org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler.executeJsonObjectRequest(JsonRpcExecutorHandler.java:131)
at app//org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler.lambda$handler$0(JsonRpcExecutorHandler.java:78)
at app//org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler$$Lambda$1178/0x000000080119fcd0.handle(Unknown Source)
at app//io.vertx.ext.web.impl.BlockingHandlerDecorator.lambda$handle$0(BlockingHandlerDecorator.java:48)
at app//io.vertx.ext.web.impl.BlockingHandlerDecorator$$Lambda$1613/0x00000008012cf350.handle(Unknown Source)
at app//io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)
at app//io.vertx.core.impl.ContextImpl$$Lambda$1383/0x0000000801245238.handle(Unknown Source)
at app//io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)
at app//io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157)
at app//io.vertx.core.impl.ContextImpl$$Lambda$1382/0x0000000801246aa0.run(Unknown Source)
at java.base@17.0.5/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base@17.0.5/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base@17.0.5/java.lang.Thread.run(Thread.java:833)
2023-02-20 23:20:11.636-05:00 | vertx-blocked-thread-checker | WARN  | BlockedThreadChecker | Thread Thread[vert.x-worker-thread-0,5,main] has been blocked for 61197 ms, time limit is 60000 ms
io.vertx.core.VertxException: Thread blocked
at java.base@17.0.5/jdk.internal.misc.Unsafe.park(Native Method)
at java.base@17.0.5/java.util.concurrent.locks.LockSupport.park(LockSupport.java:341)
at java.base@17.0.5/java.util.concurrent.ForkJoinTask.awaitDone(ForkJoinTask.java:468)
at java.base@17.0.5/java.util.concurrent.ForkJoinTask.invoke(ForkJoinTask.java:687)
at java.base@17.0.5/java.util.stream.ForEachOps$ForEachOp.evaluateParallel(ForEachOps.java:159)
at java.base@17.0.5/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateParallel(ForEachOps.java:173)
at java.base@17.0.5/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:233)
at java.base@17.0.5/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:596)
at java.base@17.0.5/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:765)
at app//org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.commit(BonsaiWorldStateUpdater.java:263)
at app//org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:134)
at app//org.hyperledger.besu.ethereum.mainnet.BlockProcessor.processBlock(BlockProcessor.java:78)
at app//org.hyperledger.besu.ethereum.MainnetBlockValidator.processBlock(MainnetBlockValidator.java:218)
at app//org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:135)
at app//org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.validateBlock(MergeCoordinator.java:477)
at app//org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.rememberBlock(MergeCoordinator.java:491)
at app//org.hyperledger.besu.consensus.merge.blockcreation.TransitionCoordinator.rememberBlock(TransitionCoordinator.java:157)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.engine.AbstractEngineNewPayload.syncResponse(AbstractEngineNewPayload.java:235)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.lambda$response$0(ExecutionEngineJsonRpcMethod.java:73)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod$$Lambda$1654/0x0000000801305800.handle(Unknown Source)
at app//io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)
at app//io.vertx.core.impl.ContextImpl$$Lambda$1383/0x0000000801245238.handle(Unknown Source)
at app//io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)
at app//io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157)
at app//io.vertx.core.impl.ContextImpl$$Lambda$1382/0x0000000801246aa0.run(Unknown Source)
at app//io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)
at app//io.vertx.core.impl.TaskQueue$$Lambda$763/0x000000080108a5a8.run(Unknown Source)
at java.base@17.0.5/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base@17.0.5/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base@17.0.5/java.lang.Thread.run(Thread.java:833)
2023-02-20 23:20:12.158-05:00 | vertx-blocked-thread-checker | WARN  | BlockedThreadChecker | Thread Thread[vert.x-worker-thread-14,5,main] has been blocked for 61719 ms, time limit is 60000 ms
io.vertx.core.VertxException: Thread blocked
at java.base@17.0.5/jdk.internal.misc.Unsafe.park(Native Method)
at java.base@17.0.5/java.util.concurrent.locks.LockSupport.park(LockSupport.java:211)
at java.base@17.0.5/java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1864)
at java.base@17.0.5/java.util.concurrent.ForkJoinPool.unmanagedBlock(ForkJoinPool.java:3463)
at java.base@17.0.5/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3434)
at java.base@17.0.5/java.util.concurrent.CompletableFuture.waitingGet(CompletableFuture.java:1898)
at java.base@17.0.5/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2072)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.response(ExecutionEngineJsonRpcMethod.java:89)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.BaseJsonRpcProcessor.process(BaseJsonRpcProcessor.java:42)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.TracedJsonRpcProcessor.process(TracedJsonRpcProcessor.java:41)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.TimedJsonRpcProcessor.process(TimedJsonRpcProcessor.java:45)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.AuthenticatedJsonRpcProcessor.process(AuthenticatedJsonRpcProcessor.java:51)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.JsonRpcExecutor.execute(JsonRpcExecutor.java:92)
at app//org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler.executeRequest(JsonRpcExecutorHandler.java:118)
at app//org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler.executeJsonObjectRequest(JsonRpcExecutorHandler.java:131)
at app//org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler.lambda$handler$0(JsonRpcExecutorHandler.java:78)
at app//org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler$$Lambda$1178/0x000000080119fcd0.handle(Unknown Source)
at app//io.vertx.ext.web.impl.BlockingHandlerDecorator.lambda$handle$0(BlockingHandlerDecorator.java:48)
at app//io.vertx.ext.web.impl.BlockingHandlerDecorator$$Lambda$1613/0x00000008012cf350.handle(Unknown Source)
at app//io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)
at app//io.vertx.core.impl.ContextImpl$$Lambda$1383/0x0000000801245238.handle(Unknown Source)
at app//io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)
at app//io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157)
at app//io.vertx.core.impl.ContextImpl$$Lambda$1382/0x0000000801246aa0.run(Unknown Source)
at java.base@17.0.5/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base@17.0.5/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base@17.0.5/java.lang.Thread.run(Thread.java:833)
2023-02-20 23:20:12.636-05:00 | vertx-blocked-thread-checker | WARN  | BlockedThreadChecker | Thread Thread[vert.x-worker-thread-0,5,main] has been blocked for 62197 ms, time limit is 60000 ms
io.vertx.core.VertxException: Thread blocked
at java.base@17.0.5/jdk.internal.misc.Unsafe.park(Native Method)
at java.base@17.0.5/java.util.concurrent.locks.LockSupport.park(LockSupport.java:341)
at java.base@17.0.5/java.util.concurrent.ForkJoinTask.awaitDone(ForkJoinTask.java:468)
at java.base@17.0.5/java.util.concurrent.ForkJoinTask.invoke(ForkJoinTask.java:687)
at java.base@17.0.5/java.util.stream.ForEachOps$ForEachOp.evaluateParallel(ForEachOps.java:159)
at java.base@17.0.5/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateParallel(ForEachOps.java:173)
at java.base@17.0.5/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:233)
at java.base@17.0.5/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:596)
at java.base@17.0.5/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:765)
at app//org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.commit(BonsaiWorldStateUpdater.java:263)
at app//org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:134)
at app//org.hyperledger.besu.ethereum.mainnet.BlockProcessor.processBlock(BlockProcessor.java:78)
at app//org.hyperledger.besu.ethereum.MainnetBlockValidator.processBlock(MainnetBlockValidator.java:218)
at app//org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:135)
at app//org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.validateBlock(MergeCoordinator.java:477)
at app//org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.rememberBlock(MergeCoordinator.java:491)
at app//org.hyperledger.besu.consensus.merge.blockcreation.TransitionCoordinator.rememberBlock(TransitionCoordinator.java:157)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.engine.AbstractEngineNewPayload.syncResponse(AbstractEngineNewPayload.java:235)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.lambda$response$0(ExecutionEngineJsonRpcMethod.java:73)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod$$Lambda$1654/0x0000000801305800.handle(Unknown Source)
at app//io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)
at app//io.vertx.core.impl.ContextImpl$$Lambda$1383/0x0000000801245238.handle(Unknown Source)
at app//io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)
at app//io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157)
at app//io.vertx.core.impl.ContextImpl$$Lambda$1382/0x0000000801246aa0.run(Unknown Source)
at app//io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)
at app//io.vertx.core.impl.TaskQueue$$Lambda$763/0x000000080108a5a8.run(Unknown Source)
at java.base@17.0.5/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base@17.0.5/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base@17.0.5/java.lang.Thread.run(Thread.java:833)
2023-02-20 23:20:12.871-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,674,439 / 132 tx / base fee 24.26 gwei / 18,850,142 (62.8%) gas / (0x07aae8ce5cb717e95d2925379fb351ecf47cf4b1d0c02e18f029f8eb3cd8f976) in 62.426s. Peers: 69
2023-02-20 23:20:14.060-05:00 | vert.x-worker-thread-0 | WARN  | DefaultBlockchain | Chain Reorganization +80 new / -0 old
Old - hash: 0x6493d045ee713f467143621811930a9f4d3a6255ff3ecdd3e7d8f41df169bb1c, height: 16674358
New - hash: 0x45303c414b3c72a9559017bd84aee2e1cb74463e4f9b18d0713480b156423633, height: 16674438
Ancestor - hash: 0x6493d045ee713f467143621811930a9f4d3a6255ff3ecdd3e7d8f41df169bb1c, height: 16674358
2023-02-20 23:20:15.026-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineForkchoiceUpdated | VALID for fork-choice-update: head: 0x45303c414b3c72a9559017bd84aee2e1cb74463e4f9b18d0713480b156423633, finalized: 0x1da1695a6ed08be6c9d175dc21a33aa8c122420cc0001297ca586bb74c65f116, safeBlockHash: 0x4e26e46833af448770aa167c014d7c76f287caa5765ce77a6d2d260f897f174f
2023-02-20 23:20:16.622-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,674,440 / 94 tx / base fee 25.04 gwei / 7,769,112 (25.9%) gas / (0x05cd1dc8f465f0157edc56b4b89cc4ea537b031cd9b262abb4d71dc300df056f) in 0.795s. Peers: 60
2023-02-20 23:20:16.887-05:00 | nioEventLoopGroup-3-1 | WARN  | DefaultBlockchain | Chain Reorganization +0 new / -82 old
Old - hash: 0x05cd1dc8f465f0157edc56b4b89cc4ea537b031cd9b262abb4d71dc300df056f, height: 16674440
New - hash: 0x6493d045ee713f467143621811930a9f4d3a6255ff3ecdd3e7d8f41df169bb1c, height: 16674358
Ancestor - hash: 0x6493d045ee713f467143621811930a9f4d3a6255ff3ecdd3e7d8f41df169bb1c, height: 16674358
2023-02-20 23:20:17.937-05:00 | nioEventLoopGroup-3-1 | INFO  | BackwardSyncContext | Backward sync phase 2 of 2, 13.64% completed, imported 3 blocks of at least 22 (current head 16674440, target head 16674459). Peers: 60
2023-02-20 23:20:17.945-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,674,441 / 218 tx / base fee 23.53 gwei / 15,471,237 (51.6%) gas / (0x667db55f40d1342f7063a11329621e318b4a1119f4b5ade8d313c772b5655268) in 0.675s. Peers: 60
2023-02-20 23:20:18.794-05:00 | vert.x-worker-thread-0 | WARN  | DefaultBlockchain | Chain Reorganization +83 new / -0 old
Old - hash: 0x6493d045ee713f467143621811930a9f4d3a6255ff3ecdd3e7d8f41df169bb1c, height: 16674358
New - hash: 0x667db55f40d1342f7063a11329621e318b4a1119f4b5ade8d313c772b5655268, height: 16674441
Ancestor - hash: 0x6493d045ee713f467143621811930a9f4d3a6255ff3ecdd3e7d8f41df169bb1c, height: 16674358
2023-02-20 23:20:28.126-05:00 | nioEventLoopGroup-3-1 | WARN  | DefaultBlockchain | Chain Reorganization +0 new / -83 old
Old - hash: 0x667db55f40d1342f7063a11329621e318b4a1119f4b5ade8d313c772b5655268, height: 16674441
New - hash: 0x6493d045ee713f467143621811930a9f4d3a6255ff3ecdd3e7d8f41df169bb1c, height: 16674358
Ancestor - hash: 0x6493d045ee713f467143621811930a9f4d3a6255ff3ecdd3e7d8f41df169bb1c, height: 16674358
2023-02-20 23:20:28.385-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,674,442 / 122 tx / base fee 23.62 gwei / 13,992,334 (46.6%) gas / (0xb75190beb25f87b1436b38d16a2f7322f1ac9d4aadde70a1f3c0439ada7e333e) in 7.518s. Peers: 60
2023-02-20 23:20:29.235-05:00 | nioEventLoopGroup-3-1 | INFO  | BackwardSyncContext | Backward sync phase 2 of 2, 18.18% completed, imported 4 blocks of at least 22 (current head 16674441, target head 16674459). Peers: 60
2023-02-20 23:20:29.553-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,674,443 / 112 tx / base fee 23.42 gwei / 8,942,650 (29.8%) gas / (0x6ea063014dfb844f811202d6bcdb923b2a45cb7f29d6c3822ebfeadf15d41bd6) in 0.466s. Peers: 61
2023-02-20 23:20:30.287-05:00 | vert.x-worker-thread-0 | WARN  | DefaultBlockchain | Chain Reorganization +85 new / -0 old
Old - hash: 0x6493d045ee713f467143621811930a9f4d3a6255ff3ecdd3e7d8f41df169bb1c, height: 16674358
New - hash: 0x6ea063014dfb844f811202d6bcdb923b2a45cb7f29d6c3822ebfeadf15d41bd6, height: 16674443
Ancestor - hash: 0x6493d045ee713f467143621811930a9f4d3a6255ff3ecdd3e7d8f41df169bb1c, height: 16674358
2023-02-20 23:20:31.310-05:00 | nioEventLoopGroup-3-1 | WARN  | DefaultBlockchain | Chain Reorganization +0 new / -85 old
Old - hash: 0x6ea063014dfb844f811202d6bcdb923b2a45cb7f29d6c3822ebfeadf15d41bd6, height: 16674443
New - hash: 0x6493d045ee713f467143621811930a9f4d3a6255ff3ecdd3e7d8f41df169bb1c, height: 16674358
Ancestor - hash: 0x6493d045ee713f467143621811930a9f4d3a6255ff3ecdd3e7d8f41df169bb1c, height: 16674358
2023-02-20 23:20:32.309-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,674,444 / 148 tx / base fee 22.24 gwei / 13,856,519 (46.2%) gas / (0x0d32090662aa6e77eb145278aaeef57d9eae99fe50d339117f7b6a291999acd9) in 0.597s. Peers: 61
2023-02-20 23:20:33.119-05:00 | vert.x-worker-thread-0 | WARN  | DefaultBlockchain | Chain Reorganization +86 new / -0 old
Old - hash: 0x6493d045ee713f467143621811930a9f4d3a6255ff3ecdd3e7d8f41df169bb1c, height: 16674358
New - hash: 0x0d32090662aa6e77eb145278aaeef57d9eae99fe50d339117f7b6a291999acd9, height: 16674444
Ancestor - hash: 0x6493d045ee713f467143621811930a9f4d3a6255ff3ecdd3e7d8f41df169bb1c, height: 16674358
2023-02-20 23:20:38.309-05:00 | nioEventLoopGroup-3-1 | WARN  | DefaultBlockchain | Chain Reorganization +0 new / -86 old
Old - hash: 0x0d32090662aa6e77eb145278aaeef57d9eae99fe50d339117f7b6a291999acd9, height: 16674444
New - hash: 0x6493d045ee713f467143621811930a9f4d3a6255ff3ecdd3e7d8f41df169bb1c, height: 16674358
Ancestor - hash: 0x6493d045ee713f467143621811930a9f4d3a6255ff3ecdd3e7d8f41df169bb1c, height: 16674358
2023-02-20 23:20:38.408-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,674,445 / 107 tx / base fee 22.03 gwei / 10,430,158 (34.8%) gas / (0x4a166b1170b10f0c3e51bc4b364db3e02664dfaf153801221e8ce3eaaddd865f) in 4.303s. Peers: 60
2023-02-20 23:20:39.149-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,674,446 / 18 tx / base fee 21.19 gwei / 1,433,064 (4.8%) gas / (0xd2a3924aef14367953162223f3248abb45817aeeec9d0f8987270337310ac55c) in 0.154s. Peers: 60
2023-02-20 23:20:39.613-05:00 | nioEventLoopGroup-3-1 | INFO  | BackwardSyncContext | Backward sync phase 2 of 2, 30.43% completed, imported 7 blocks of at least 23 (current head 16674444, target head 16674460). Peers: 60
2023-02-20 23:20:39.811-05:00 | vert.x-worker-thread-0 | WARN  | DefaultBlockchain | Chain Reorganization +88 new / -0 old
Old - hash: 0x6493d045ee713f467143621811930a9f4d3a6255ff3ecdd3e7d8f41df169bb1c, height: 16674358
New - hash: 0xd2a3924aef14367953162223f3248abb45817aeeec9d0f8987270337310ac55c, height: 16674446
Ancestor - hash: 0x6493d045ee713f467143621811930a9f4d3a6255ff3ecdd3e7d8f41df169bb1c, height: 16674358
2023-02-20 23:20:47.050-05:00 | nioEventLoopGroup-3-1 | WARN  | DefaultBlockchain | Chain Reorganization +0 new / -88 old
Old - hash: 0xd2a3924aef14367953162223f3248abb45817aeeec9d0f8987270337310ac55c, height: 16674446
New - hash: 0x6493d045ee713f467143621811930a9f4d3a6255ff3ecdd3e7d8f41df169bb1c, height: 16674358
Ancestor - hash: 0x6493d045ee713f467143621811930a9f4d3a6255ff3ecdd3e7d8f41df169bb1c, height: 16674358
2023-02-20 23:20:49.277-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,674,447 / 192 tx / base fee 18.79 gwei / 29,981,128 (99.9%) gas / (0x273a2fcb4b29de5dcaeff9eb5a5d4b19b82265c84c8694204b3745cab11b0080) in 7.769s. Peers: 67
2023-02-20 23:20:50.634-05:00 | nioEventLoopGroup-3-1 | INFO  | BackwardSyncContext | Backward sync phase 2 of 2, 36.36% completed, imported 8 blocks of at least 22 (current head 16674445, target head 16674459). Peers: 67
2023-02-20 23:21:19.887-05:00 | nioEventLoopGroup-3-1 | INFO  | BackwardSyncContext | Backward sync phase 2 of 2, 40.91% completed, imported 9 blocks of at least 22 (current head 16674446, target head 16674459). Peers: 64
2023-02-20 23:21:45.667-05:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #16,674,448 / 258 tx / base fee 21.14 gwei / 29,898,739 (99.7%) gas / (0x3649559c301e037aea6e7f0f7cdd02f3b0235b2cc6e44914389027c55f893dff) in 55.654s. Peers: 65
2023-02-20 23:22:14.385-05:00 | vertx-blocked-thread-checker | WARN  | BlockedThreadChecker | Thread Thread[vert.x-worker-thread-11,5,main] has been blocked for 60041 ms, time limit is 60000 ms
io.vertx.core.VertxException: Thread blocked
at java.base@17.0.5/jdk.internal.misc.Unsafe.park(Native Method)
at java.base@17.0.5/java.util.concurrent.locks.LockSupport.park(LockSupport.java:211)
at java.base@17.0.5/java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1864)
at java.base@17.0.5/java.util.concurrent.ForkJoinPool.unmanagedBlock(ForkJoinPool.java:3463)
at java.base@17.0.5/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3434)
at java.base@17.0.5/java.util.concurrent.CompletableFuture.waitingGet(CompletableFuture.java:1898)
at java.base@17.0.5/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2072)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.response(ExecutionEngineJsonRpcMethod.java:89)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.BaseJsonRpcProcessor.process(BaseJsonRpcProcessor.java:42)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.TracedJsonRpcProcessor.process(TracedJsonRpcProcessor.java:41)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.TimedJsonRpcProcessor.process(TimedJsonRpcProcessor.java:45)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.AuthenticatedJsonRpcProcessor.process(AuthenticatedJsonRpcProcessor.java:51)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.JsonRpcExecutor.execute(JsonRpcExecutor.java:92)
at app//org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler.executeRequest(JsonRpcExecutorHandler.java:118)
at app//org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler.executeJsonObjectRequest(JsonRpcExecutorHandler.java:131)
at app//org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler.lambda$handler$0(JsonRpcExecutorHandler.java:78)
at app//org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler$$Lambda$1178/0x000000080119fcd0.handle(Unknown Source)
at app//io.vertx.ext.web.impl.BlockingHandlerDecorator.lambda$handle$0(BlockingHandlerDecorator.java:48)
at app//io.vertx.ext.web.impl.BlockingHandlerDecorator$$Lambda$1613/0x00000008012cf350.handle(Unknown Source)
at app//io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)
at app//io.vertx.core.impl.ContextImpl$$Lambda$1383/0x0000000801245238.handle(Unknown Source)
at app//io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)
at app//io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157)
at app//io.vertx.core.impl.ContextImpl$$Lambda$1382/0x0000000801246aa0.run(Unknown Source)
at java.base@17.0.5/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base@17.0.5/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base@17.0.5/java.lang.Thread.run(Thread.java:833)
ahamlat commented 1 year ago

Thanks @ibhagwan, we're tracking this issue in https://github.com/hyperledger/besu/issues/5121

ibhagwan commented 1 year ago

@ahamlat, I’m still unsure about the issue in the OP but the good news is the latest issues turned out the be a result of block storage device issues with the hosting company, as a soon as this was sorted out my node is back to 99% effectiveness, closing.