Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
ibhagwan opened this issue Jan 10, 2023 · 7 comments
Closed

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

ibhagwan opened this issue Jan 10, 2023 · 7 comments
Labels
bug Something isn't working mainnet syncing

Comments

@ibhagwan
Copy link

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)

  • Software version: [besu --version]
besu/v22.10.3/linux-x86_64/openjdk-java-17
2023-01-10 13:31:11.273-05:00 | main | INFO  | Besu | Using jemalloc
  • Java version: [java -version]
openjdk 17.0.5 2022-10-18
OpenJDK Runtime Environment (build 17.0.5+7-void-r1)
OpenJDK 64-Bit Server VM (build 17.0.5+7-void-r1, mixed mode, sharing)
  • OS Name & Version: [cat /etc/*release]
NAME="Void"
ID="void"
PRETTY_NAME="Void Linux"
HOME_URL="https://voidlinux.org/"
DOCUMENTATION_URL="https://docs.voidlinux.org/"
LOGO="void-logo"
ANSI_COLOR="0;38;2;71;128;97"

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 non-fungible-nelson added bug Something isn't working syncing mainnet labels Jan 26, 2023
@non-fungible-nelson
Copy link
Contributor

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
Copy link
Contributor

ahamlat commented Jan 26, 2023 •
edited
Loading

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
Copy link
Author

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
Copy link
Author

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
Copy link
Author

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)

@ibhagwan ibhagwan mentioned this issue Feb 21, 2023
Closed
@ahamlat
Copy link
Contributor

ahamlat commented Feb 22, 2023

Thanks @ibhagwan, we're tracking this issue in #5121

@ibhagwan
Copy link
Author

ibhagwan commented Feb 23, 2023 •
edited
Loading

@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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working mainnet syncing
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@ahamlat @ibhagwan @non-fungible-nelson