Internal error, backward sync completed but failed to import finalized block #5053

i-am-logger · 2023-02-04T20:04:31Z

execution_1 | Setting logging level to INFO
execution_1 | 2023-02-04 19:54:23.830+00:00 | main | INFO | Besu | Starting Besu
execution_1 | 2023-02-04 19:54:24.516+00:00 | main | WARN | Besu | --graphql-http-host has been ignored because --graphql-http-enabled was not defined on the command line.
execution_1 | 2023-02-04 19:54:24.693+00:00 | main | INFO | Besu |
execution_1 | ####################################################################################################
execution_1 | # #
execution_1 | # Besu 23.1.0-dev-e7150102 #
execution_1 | # #
execution_1 | # Configuration: #
execution_1 | # Network: Mainnet #
execution_1 | # Network Id: 1 #
execution_1 | # Data storage: Bonsai #
execution_1 | # Sync mode: Snap #
execution_1 | # RPC HTTP APIs: WEB3,ETH,NET #
execution_1 | # RPC HTTP port: 8545 #
execution_1 | # Engine APIs: ENGINE,ETH #
execution_1 | # Engine port: 8551 #
execution_1 | # #
execution_1 | # Host: #
execution_1 | # Java: openjdk-java-17 #
execution_1 | # Maximum heap size: 64.00 GB #
execution_1 | # OS: linux-x86_64 #
execution_1 | # glibc: 2.31 #
execution_1 | # Total memory: 503.87 GB #
execution_1 | # CPU cores: 80 #
execution_1 | # #
execution_1 | ####################################################################################################
execution_1 | 2023-02-04 19:54:24.694+00:00 | main | INFO | Besu | Connecting to 0 static nodes.
execution_1 | 2023-02-04 19:54:24.694+00:00 | main | INFO | Besu | Security Module: localfile
execution_1 | 2023-02-04 19:54:24.756+00:00 | main | INFO | Besu | Using the native implementation of alt bn128
execution_1 | 2023-02-04 19:54:24.808+00:00 | main | INFO | Besu | Using the native implementation of modexp
execution_1 | 2023-02-04 19:54:24.808+00:00 | main | INFO | Besu | Using the native implementation of the signature algorithm
execution_1 | 2023-02-04 19:54:24.814+00:00 | main | INFO | Besu | Using the native implementation of the blake2bf algorithm
execution_1 | 2023-02-04 19:54:24.840+00:00 | main | INFO | DatabaseMetadata | Lookup database metadata file in data directory: /var/lib/besu
execution_1 | 2023-02-04 19:54:24.910+00:00 | main | INFO | RocksDBKeyValueStorageFactory | Existing database detected at /var/lib/besu. Version 2
execution_1 | 2023-02-04 19:54:30.154+00:00 | main | INFO | KeyPairUtil | Loaded public key 0xba5cb5928621f5ef140f8182dde0c6f0c0447562b2b4d7763b72da5c9ce3df41fd872a26687466e7b711ef53d74526bf724b12fe6217504a76268d815c951cd0 from /var/lib/besu/key
execution_1 | 2023-02-04 19:54:30.353+00: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]
execution_1 | 2023-02-04 19:54:30.392+00: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]
execution_1 | 2023-02-04 19:54:30.401+00:00 | main | INFO | AbstractProtocolScheduleBuilder | Protocol schedule created with milestones: []
execution_1 | 2023-02-04 19:54:31.232+00:00 | main | INFO | TransactionPoolFactory | Enabling transaction pool
execution_1 | 2023-02-04 19:54:31.233+00:00 | main | INFO | TransactionPoolFactory | Disabling transaction handling during initial sync
execution_1 | 2023-02-04 19:54:31.236+00:00 | main | INFO | EthPeers | Updating the default best peer comparator
execution_1 | 2023-02-04 19:54:31.260+00:00 | main | INFO | BesuControllerBuilder | TTD difficulty is present, creating initial sync for PoS
execution_1 | 2023-02-04 19:54:31.276+00:00 | main | INFO | SnapDownloaderFactory | Snap sync was requested, but cannot be enabled because the local blockchain is not empty.
execution_1 | 2023-02-04 19:54:31.278+00:00 | main | INFO | TransitionBesuControllerBuilder | TTD present, creating DefaultSynchronizer that stops propagating after finalization
execution_1 | 2023-02-04 19:54:31.308+00:00 | main | INFO | RunnerBuilder | Detecting NAT service.
execution_1 | 2023-02-04 19:54:31.474+00:00 | main | INFO | AbstractProtocolScheduleBuilder | Protocol schedule created with milestones: []
execution_1 | 2023-02-04 19:54:31.537+00:00 | main | INFO | AbstractProtocolScheduleBuilder | Protocol schedule created with milestones: []
execution_1 | 2023-02-04 19:54:31.768+00:00 | main | INFO | AbstractProtocolScheduleBuilder | Protocol schedule created with milestones: []
execution_1 | 2023-02-04 19:54:31.785+00:00 | main | INFO | Runner | Starting external services ...
execution_1 | 2023-02-04 19:54:31.786+00:00 | main | INFO | MetricsHttpService | Starting metrics http service on 0.0.0.0:6060
execution_1 | 2023-02-04 19:54:31.889+00:00 | vert.x-eventloop-thread-1 | INFO | MetricsHttpService | Metrics service started and listening on 0.0.0.0:6060
execution_1 | 2023-02-04 19:54:31.889+00:00 | main | INFO | JsonRpcHttpService | Starting JSON-RPC service on 0.0.0.0:8545
execution_1 | 2023-02-04 19:54:31.905+00:00 | vert.x-eventloop-thread-1 | INFO | JsonRpcHttpService | JSON-RPC service started and listening on 0.0.0.0:8545
execution_1 | 2023-02-04 19:54:31.905+00:00 | main | INFO | EngineJsonRpcService | Starting JSON-RPC service on 0.0.0.0:8551
execution_1 | 2023-02-04 19:54:31.911+00:00 | vert.x-eventloop-thread-1 | INFO | EngineJsonRpcService | JSON-RPC service started and listening on 0.0.0.0:8551
execution_1 | 2023-02-04 19:54:31.912+00:00 | main | INFO | WebSocketService | Starting Websocket service on 0.0.0.0:8546
execution_1 | 2023-02-04 19:54:31.915+00:00 | vert.x-eventloop-thread-1 | INFO | WebSocketService | Websocket service started and listening on 0.0.0.0:8546
execution_1 | 2023-02-04 19:54:31.918+00:00 | main | INFO | AutoTransactionLogBloomCachingService | Starting auto transaction log bloom caching service.
execution_1 | 2023-02-04 19:54:31.919+00:00 | main | INFO | LogBloomCacheMetadata | Lookup cache metadata file in data directory: /var/lib/besu/caches
execution_1 | 2023-02-04 19:54:31.928+00:00 | main | INFO | Runner | Starting Ethereum main loop ...
execution_1 | 2023-02-04 19:54:31.928+00:00 | main | INFO | DockerNatManager | Starting docker NAT manager.
execution_1 | 2023-02-04 19:54:31.937+00:00 | main | INFO | NetworkRunner | Starting Network.
execution_1 | 2023-02-04 19:54:31.940+00:00 | main | INFO | DefaultP2PNetwork | Starting DNS discovery with URL enrtree://AKA3AM6LPBYEUDMVNU3BSVQJ5AD45Y7YPOHJLEF6W26QOE4VTUDPE@all.mainnet.ethdisco.net
execution_1 | 2023-02-04 19:54:32.010+00:00 | nioEventLoopGroup-2-1 | INFO | RlpxAgent | P2P RLPx agent started and listening on /0.0.0.0:30303.
execution_1 | 2023-02-04 19:54:32.011+00:00 | main | INFO | PeerDiscoveryAgent | Starting peer discovery agent on host=0.0.0.0, port=30303
execution_1 | 2023-02-04 19:54:32.054+00:00 | vert.x-eventloop-thread-1 | INFO | VertxPeerDiscoveryAgent | Started peer discovery agent successfully, on effective host=0.0.0.0 and port=30303
execution_1 | 2023-02-04 19:54:32.055+00:00 | vert.x-eventloop-thread-1 | INFO | PeerDiscoveryAgent | P2P peer discovery agent started and listening on /0.0.0.0:30303
execution_1 | 2023-02-04 19:54:32.108+00:00 | vert.x-eventloop-thread-1 | INFO | PeerDiscoveryAgent | Writing node record to disk. NodeRecord{seq=83, publicKey=0x02ba5cb5928621f5ef140f8182dde0c6f0c0447562b2b4d7763b72da5c9ce3df41, udpAddress=Optional[/127.0.0.1:30303], tcpAddress=Optional[/127.0.0.1:30303], asBase64=-Je4QFFXzeqiZb2EpXqAagdzEjnpXxq90PzI95N7LoRAxSRWULLBJzCv-OzLzUZWApHzyrurQLxpqvSHPyh4a_b9s0hTg2V0aMfGhPCv0OOAgmlkgnY0gmlwhH8AAAGJc2VjcDI1NmsxoQK6XLWShiH17xQPgYLd4MbwwER1YrK013Y7ctpcnOPfQYN0Y3CCdl-DdWRwgnZf, nodeId=0x191631e5043602531ea9c04190dd41bbc6f07a2a368438865f39dea4bdce1e33, customFields={tcp=30303, udp=30303, ip=0x7f000001, eth=[[0xf0afd0e3, 0x]], id=V4, secp256k1=0x02ba5cb5928621f5ef140f8182dde0c6f0c0447562b2b4d7763b72da5c9ce3df41}}
execution_1 | 2023-02-04 19:54:32.181+00:00 | main | INFO | DefaultP2PNetwork | Enode URL enode://ba5cb5928621f5ef140f8182dde0c6f0c0447562b2b4d7763b72da5c9ce3df41fd872a26687466e7b711ef53d74526bf724b12fe6217504a76268d815c951cd0@127.0.0.1:30303
execution_1 | 2023-02-04 19:54:32.183+00:00 | main | INFO | DefaultP2PNetwork | Node address 0x90dd41bbc6f07a2a368438865f39dea4bdce1e33
execution_1 | 2023-02-04 19:54:32.189+00:00 | main | INFO | NetworkRunner | Supported capabilities: [eth/63, eth/64, eth/65, eth/66, eth/67, eth/68], [snap/1]
execution_1 | 2023-02-04 19:54:32.189+00:00 | main | INFO | DefaultSynchronizer | Starting synchronizer.
execution_1 | 2023-02-04 19:54:32.192+00:00 | main | INFO | TransactionPoolFactory | Enabling transaction handling following initial sync
execution_1 | 2023-02-04 19:54:32.196+00:00 | main | INFO | DefaultSynchronizer | Stopping block propagation.
execution_1 | 2023-02-04 19:54:32.197+00:00 | main | INFO | DefaultSynchronizer | Stopping the pruner.
execution_1 | 2023-02-04 19:54:32.198+00:00 | main | INFO | Runner | Ethereum main loop is up.
execution_1 | 2023-02-04 19:54:54.203+00:00 | Timer-0 | INFO | DNSResolver | Resolved 2409 nodes
execution_1 | 2023-02-04 19:56:06.947+00:00 | vert.x-worker-thread-0 | INFO | BackwardSyncContext | Starting a new backward sync session
execution_1 | 2023-02-04 19:56:06.955+00:00 | vert.x-worker-thread-0 | INFO | BackwardsSyncAlgorithm | Current backward sync session is done
execution_1 | 2023-02-04 19:56:08.179+00:00 | vert.x-worker-thread-0 | WARN | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xe8f33c4587ca5e19d441139e1d45ba19bb58450b89e1e4e5e21d179b858ab964
execution_1 | 2023-02-04 19:56:08.196+00:00 | vert.x-worker-thread-0 | WARN | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xe8f33c4587ca5e19d441139e1d45ba19bb58450b89e1e4e5e21d179b858ab964

execution_1 | 2023-02-04 19:56:36.760+00:00 | vert.x-worker-thread-0 | WARN | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xe8f33c4587ca5e19d441139e1d45ba19bb58450b89e1e4e5e21d179b858ab964
execution_1 | 2023-02-04 19:56:38.094+00:00 | vert.x-worker-thread-0 | WARN | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xe8f33c4587ca5e19d441139e1d45ba19bb58450b89e1e4e5e21d179b858ab964
execution_1 | 2023-02-04 19:56:38.320+00:00 | vert.x-worker-thread-0 | WARN | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xe8f33c4587ca5e19d441139e1d45ba19bb58450b89e1e4e5e21d179b858ab964
execution_1 | 2023-02-04 19:56:43.985+00:00 | vert.x-worker-thread-0 | WARN | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xe8f33c4587ca5e19d441139e1d45ba19bb58450b89e1e4e5e21d179b858ab964
execution_1 | 2023-02-04 19:56:49.107+00:00 | vert.x-worker-thread-0 | WARN | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xe8f33c4587ca5e19d441139e1d45ba19bb58450b89e1e4e5e21d179b858ab964
execution_1 | 2023-02-04 19:57:00.682+00:00 | vert.x-worker-thread-0 | WARN | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xe8f33c4587ca5e19d441139e1d45ba19bb58450b89e1e4e5e21d179b858ab964

smasher816 · 2023-02-07T14:01:36Z

I am seeing the same with besu+nimbus

$ journalctl -fu nimbus
Feb 07 05:55:16 hoenir nimbus_beacon_node[63425]: WRN 2023-02-07 05:55:16.191-08:00 Eth1 chain monitoring failure, restarting  topics="eth1" err="No eth1 chain progress for too long"
Feb 07 05:55:21 hoenir nimbus_beacon_node[63425]: INF 2023-02-07 05:55:21.202-08:00 Established connection to execution layer  topics="eth1" url=ws://127.0.0.1:8551
Feb 07 05:55:21 hoenir nimbus_beacon_node[63425]: INF 2023-02-07 05:55:21.210-08:00 Starting Eth1 deposit contract monitoring  topics="eth1" contract=0x00000000219ab540356cbb839cbe05303d7705fa
Feb 07 05:55:21 hoenir nimbus_beacon_node[63425]: INF 2023-02-07 05:55:21.211-08:00 Waiting for new Eth1 block headers         topics="eth1"
Feb 07 05:55:23 hoenir nimbus_beacon_node[63425]: INF 2023-02-07 05:55:23.000-08:00 Slot start                                 topics="beacnde" slot=5746175 epoch=179567 sync=synced/opt peers=3 head=63d1a9ad:5746174 finalized=179565:e24b650c delay=569us275ns
Feb 07 05:55:23 hoenir nimbus_beacon_node[63425]: INF 2023-02-07 05:55:23.028-08:00 Slot end                                   topics="beacnde" slot=5746175 nextActionWait=n/a nextAttestationSlot=-1 nextProposalSlot=-1 syncCommitteeDuties=none head=63d1a9ad:5746174
Feb 07 05:55:35 hoenir nimbus_beacon_node[63425]: INF 2023-02-07 05:55:35.001-08:00 Slot start                                 topics="beacnde" slot=5746176 epoch=179568 sync=synced/opt peers=1 head=9a03ff29:5746175 finalized=179565:e24b650c delay=1ms180us537ns
Feb 07 05:55:35 hoenir nimbus_beacon_node[63425]: INF 2023-02-07 05:55:35.059-08:00 Slot end                                   topics="beacnde" slot=5746176 nextActionWait=n/a nextAttestationSlot=-1 nextProposalSlot=-1 syncCommitteeDuties=none head=9a03ff29:5746175
Feb 07 05:55:47 hoenir nimbus_beacon_node[63425]: INF 2023-02-07 05:55:47.001-08:00 Slot start                                 topics="beacnde" slot=5746177 epoch=179568 sync=synced/opt peers=1 head=9a03ff29:5746175 finalized=179565:e24b650c delay=1ms986ns
Feb 07 05:55:47 hoenir nimbus_beacon_node[63425]: INF 2023-02-07 05:55:47.012-08:00 Slot end                                   topics="beacnde" slot=5746177 nextActionWait=n/a nextAttestationSlot=-1 nextProposalSlot=-1 syncCommitteeDuties=none head=9a03ff29:5746175
Feb 07 05:55:59 hoenir nimbus_beacon_node[63425]: INF 2023-02-07 05:55:59.000-08:00 Slot start                                 topics="beacnde" slot=5746178 epoch=179568 sync=synced/opt peers=1 head=9a03ff29:5746175 finalized=179565:e24b650c delay=369us4ns
Feb 07 05:55:59 hoenir nimbus_beacon_node[63425]: INF 2023-02-07 05:55:59.011-08:00 Slot end                                   topics="beacnde" slot=5746178 nextActionWait=n/a nextAttestationSlot=-1 nextProposalSlot=-1 syncCommitteeDuties=none head=9a03ff29:5746175

$ journalctl -fu besu
Feb 07 05:57:11 hoenir besu[63177]: 2023-02-07 05:57:11.864-08:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xcc22eb80224a603e6be9fa49757f353fccf4f3ccfb5951c2643e07412f42474c
Feb 07 05:57:12 hoenir besu[63177]: 2023-02-07 05:57:12.797-08:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xcc22eb80224a603e6be9fa49757f353fccf4f3ccfb5951c2643e07412f42474c
Feb 07 05:57:24 hoenir besu[63177]: 2023-02-07 05:57:24.460-08:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xcc22eb80224a603e6be9fa49757f353fccf4f3ccfb5951c2643e07412f42474c
Feb 07 05:57:36 hoenir besu[63177]: 2023-02-07 05:57:36.382-08:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xcc22eb80224a603e6be9fa49757f353fccf4f3ccfb5951c2643e07412f42474c
Feb 07 05:57:48 hoenir besu[63177]: 2023-02-07 05:57:48.481-08:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xcc22eb80224a603e6be9fa49757f353fccf4f3ccfb5951c2643e07412f42474c
Feb 07 05:58:00 hoenir besu[63177]: 2023-02-07 05:58:00.512-08:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xcc22eb80224a603e6be9fa49757f353fccf4f3ccfb5951c2643e07412f42474c
Feb 07 05:58:12 hoenir besu[63177]: 2023-02-07 05:58:12.506-08:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xcc22eb80224a603e6be9fa49757f353fccf4f3ccfb5951c2643e07412f42474c
Feb 07 05:58:24 hoenir besu[63177]: 2023-02-07 05:58:24.691-08:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xcc22eb80224a603e6be9fa49757f353fccf4f3ccfb5951c2643e07412f42474c
Feb 07 05:58:36 hoenir besu[63177]: 2023-02-07 05:58:36.540-08:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xcc22eb80224a603e6be9fa49757f353fccf4f3ccfb5951c2643e07412f42474c
Feb 07 05:58:48 hoenir besu[63177]: 2023-02-07 05:58:48.534-08:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xcc22eb80224a603e6be9fa49757f353fccf4f3ccfb5951c2643e07412f42474c
Feb 07 05:59:00 hoenir besu[63177]: 2023-02-07 05:59:00.963-08:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xcc22eb80224a603e6be9fa49757f353fccf4f3ccfb5951c2643e07412f42474c
Feb 07 05:59:12 hoenir besu[63177]: 2023-02-07 05:59:12.792-08:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xcc22eb80224a603e6be9fa49757f353fccf4f3ccfb5951c2643e07412f42474c
Feb 07 05:57:11 hoenir besu[63177]: 2023-02-07 05:57:11.864-08:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xcc22eb80224a603e6be9fa49757f353fccf4f3ccfb5951c2643e07412f42474c
Feb 07 05:57:12 hoenir besu[63177]: 2023-02-07 05:57:12.797-08:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xcc22eb80224a603e6be9fa49757f353fccf4f3ccfb5951c2643e07412f42474c
Feb 07 05:57:24 hoenir besu[63177]: 2023-02-07 05:57:24.460-08:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xcc22eb80224a603e6be9fa49757f353fccf4f3ccfb5951c2643e07412f42474c
Feb 07 05:57:36 hoenir besu[63177]: 2023-02-07 05:57:36.382-08:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xcc22eb80224a603e6be9fa49757f353fccf4f3ccfb5951c2643e07412f42474c
Feb 07 05:57:48 hoenir besu[63177]: 2023-02-07 05:57:48.481-08:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xcc22eb80224a603e6be9fa49757f353fccf4f3ccfb5951c2643e07412f42474c
...

estensen · 2023-02-07T16:36:09Z

Same on Besu 22.10.3 + Lighthouse 3.4.0

i-am-logger · 2023-02-07T16:41:36Z

i had to wipe out the database and resync... now i get this error:

16:39:41.505+00:00 | nioEventLoopGroup-3-5 | INFO | MainnetBlockValidator | Invalid block 16574659 (0x1705627c83ba63c2f36eebc4a9b6f528fdb8da170da86b05f2d88b1b28222998): Optional[Unable to process block because parent world state 0xaafc4f9ce660df414b92bba48eae0129545714962267a5a383c3aac7342f8137 is not available]
execution_1 | 2023-02-07 16:39:41.712+00:00 | nioEventLoopGroup-3-5 | INFO | MainnetBlockValidator | Invalid block 16574659 (0x1705627c83ba63c2f36eebc4a9b6f528fdb8da170da86b05f2d88b1b28222998): Optional[Unable to process block because parent world state 0xaafc4f9ce660df414b92bba48eae0129545714962267a5a383c3aac7342f8137 is not available]
execution_1 | 2023-02-07 16:39:41.917+00:00 | nioEventLoopGroup-3-5 | INFO | MainnetBlockValidator | Invalid block 16574659 (0x1705627c83ba63c2f36eebc4a9b6f528fdb8da170da86b05f2d88b1b28222998): Optional[Unable to process block because parent world state 0xaafc4f9ce660df414b92bba48eae0129545714962267a5a383c3aac7342f8137 is not available]
execution_1 | 2023-02-07 16:39:42.135+00:00 | nioEventLoopGroup-3-5 | INFO | MainnetBlockValidator | Invalid block 16574659 (0x1705627c83ba63c2f36eebc4a9b6f528fdb8da170da86b05f2d88b1b28222998): Optional[Unable to process block because parent world state 0xaafc4f9ce660df414b92bba48eae0129545714962267a5a383c3aac7342f8137 is not available]
execution_1 | 2023-02-07 16:39:42.339+00:00 | nioEventLoopGroup-3-5 | INFO | MainnetBlockValidator | Invalid block 16574659 (0x1705627c83ba63c2f36eebc4a9b6f528fdb8da170da86b05f2d88b1b28222998): Optional[Unable to process block because parent world state 0xaafc4f9ce660df414b92bba48eae0129545714962267a5a383c3aac7342f8137 is not available]
execution_1 | 2023-02-07 16:39:42.545+00:00 | nioEventLoopGroup-3-5 | INFO | MainnetBlockValidator | Invalid block 16574659 (0x1705627c83ba63c2f36eebc4a9b6f528fdb8da170da86b05f2d88b1b28222998): Optional[Unable to process block because parent world state 0xaafc4f9ce660df414b92bba48eae0129545714962267a5a383c3aac7342f8137 is not available]
^CERROR: Aborting.

quickchase · 2023-02-07T17:30:38Z

I also received this error, but I'm trying to sync an archive node so I can't just wipe the DB and start over...

The error appears to have happened after the node crashed from OOM

After importing all the PoW blocks, it started on the PoS blocks, I got this far:

| INFO  | BackwardSyncContext | Backward sync phase 2 of 2, 69.52% completed, imported 2171734 blocks

Then the node OOM. After startup I got this:

vert.x-worker-thread-0 | INFO  | BackwardSyncContext | Starting a new backward sync session
vert.x-worker-thread-0 | INFO  | BackwardsSyncAlgorithm | Current backward sync session is done
vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized

The version is 22.10.3

quickchase · 2023-02-07T21:33:56Z

hardware specs:

Oracle VM
VM.Standard.E4.Flex
OCPU count: 12
Memory: 32GB

Config:

--network=MAINNET \
--data-storage-format=BONSAI \
--Xbonsai-use-snapshots=false \
--sync-mode=FULL \
--Xplugin-rocksdb-high-spec-enabled=true

How long were you syncing for before this happened?

2.5 months

I haven't set anything related to Java other than to install openjdk-17-jre-headless and run Besu off release binary on an Ubuntu 20.04.5 VM

No metrics

quickchase · 2023-02-07T21:40:50Z

Logs
6daylogs.txt.zip

quickchase · 2023-02-08T21:11:47Z

DEBUG Logs:
today.trimmed.log.zip

quickchase · 2023-02-09T00:11:28Z

More logs as requested. Set logging back to info, then sent this:

curl --retry-delay 50 --retry-connrefused --location \
     --request POST 'http://127.0.0.1:8545' \
     --header 'Content-Type: application/json' \
     --data-raw '{
    "jsonrpc": "2.0",
    "method": "admin_changeLogLevel",
    "params": [
        "TRACE", [
          "org.hyperledger.besu.ethereum.eth.sync.backwardsync",
          "org.hyperledger.besu.consensus.merge"
        ]
    ],
    "id": 1
}'

This is the resulting logs:
morelogs.txt.zip

Doesn't look super helpful but 🤷‍♂️

quickchase · 2023-02-09T01:14:57Z

Last 1 hour of logs from Besu, Lighthouse, and Teku. Switching to Teku and rebooting seems to have "fixed it"
3ClientLogs.zip

siladu · 2023-02-09T01:22:10Z

@realsnick @smasher816 @estensen if you're still having this issue, based on quickchase's experience above, you could try switching to teku, letting it sync, then restarting EL.

Can always switch back to another CL once it's in sync :)

siladu · 2023-02-09T01:23:25Z

@realsnick which CL were you using when you got this error?

estensen · 2023-02-15T13:34:40Z

Resynced from scratch like @realsnick

Lost internet today and changed Wi-Fi while backward syncing was in progress, making it halt.
Restarted and I'm now seeing this error again 😢

Having to sync another CL seems like a big hacky workaround.
I don't think I have the hardware to run Teku and Besu on the same machine.
Will there be a real fix to this soon?

estensen · 2023-02-15T13:42:38Z

Is the only option then to do a full resync again? @siladu

siladu · 2023-02-15T20:32:16Z

Having to sync another CL seems like a big hacky workaround.

It is indeed a workaround as we investigate this issue. We are treating this as a besu bug, but it could be a bug that is unique to certain combinations of execution + consensus clients.

Will there be a real fix to this soon?

We are actively looking at this. It's hard to recreate this situation, so any information users can provide is really valuable.

Is the only option then to do a full resync again? @siladu

If you can't try another CL then yes, resync will fix it.
We are also working on ways to repair the state and have some experimental code you could try, but resync would be the easier option if you want to get up and running ASAP

estensen · 2023-02-15T20:56:51Z

Thanks for looking at it @siladu. I'm just a bit stressed that the db gets corrupted two weeks in a row. I do appreciate the hard work you guys are putting in.

These are the logs from when it happened

2023-02-15 14:17:17.636+01:00 | Timer-0 | WARN  | DNSResolver | I/O exception contacting remote DNS server when resolving all.mainnet.ethdisco.net
java.io.IOException: Timed out while trying to resolve all.mainnet.ethdisco.net./TXT, id=47998
	at org.xbill.DNS.Resolver.send(Resolver.java:170)
	at org.apache.tuweni.discovery.DNSResolver.resolveRecordRaw(DNSResolver.kt:155)
	at org.apache.tuweni.discovery.DNSResolver.resolveRecord(DNSResolver.kt:73)
	at org.apache.tuweni.discovery.DNSResolver.visitTree(DNSResolver.kt:120)
	at org.apache.tuweni.discovery.DNSResolver.visitTree(DNSResolver.kt:111)
	at org.apache.tuweni.discovery.DNSResolver.collectAll(DNSResolver.kt:95)
	at org.apache.tuweni.discovery.DNSTimerTask.run(DNSDaemon.kt:89)
	at java.base/java.util.TimerThread.mainLoop(Timer.java:566)
	at java.base/java.util.TimerThread.run(Timer.java:516)
2023-02-15 14:20:14.518+01:00 | jupnp-114286 | WARN  | SpecificationViolationReporter | UPnP specification violation: Unsupported UDA minor version, ignoring: 1
2023-02-15 14:20:14.584+01:00 | jupnp-114286 | WARN  | UpnpNatManager | Detected multiple WANIPConnection services on network. This may interfere with NAT circumvention.
2023-02-15 14:20:54.344+01:00 | vert.x-worker-thread-0 | INFO  | BackwardSyncContext | Starting a new backward sync session
2023-02-15 14:20:55.419+01:00 | nioEventLoopGroup-3-4 | INFO  | BackwardsSyncAlgorithm | Backward sync target block is 16633306 (0xce7ad592dfd48ab2e37703f522540c7a788c5e7f0c5c40d4c9b0068dbaba2df7)
2023-02-15 14:20:55.927+01:00 | nioEventLoopGroup-3-4 | INFO  | BackwardSyncStep | Backward sync phase 1 of 2 completed, downloaded a total of 200 headers. Peers: 2
2023-02-15 14:20:58.023+01:00 | nioEventLoopGroup-3-4 | INFO  | BackwardSyncContext | Backward sync phase 2 of 2, 33.33% completed, imported 1 blocks of at least 3 (current head 16633304, target head 16633306). Peers: 2
2023-02-15 14:21:00.826+01:00 | nioEventLoopGroup-3-4 | INFO  | BackwardSyncContext | Backward sync phase 2 of 2 completed, imported a total of 3 blocks. Peers: 2
2023-02-15 14:21:01.514+01:00 | nioEventLoopGroup-3-4 | INFO  | BackwardsSyncAlgorithm | Backward sync target block is 16633369 (0x4709f52b3dad595047689d055c68091e954c8bb2286b384e24769bd8f1628d84)
2023-02-15 14:21:02.343+01:00 | nioEventLoopGroup-3-4 | INFO  | BackwardSyncStep | Backward sync phase 1 of 2 completed, downloaded a total of 200 headers. Peers: 2
2023-02-15 14:21:08.706+01:00 | nioEventLoopGroup-3-4 | INFO  | BackwardSyncContext | Backward sync phase 2 of 2, 7.58% completed, imported 5 blocks of at least 66 (current head 16633308, target head 16633369). Peers: 2
2023-02-15 14:21:19.779+01:00 | nioEventLoopGroup-3-4 | INFO  | BackwardSyncContext | Backward sync phase 2 of 2, 22.73% completed, imported 15 blocks of at least 66 (current head 16633318, target head 16633369). Peers: 4
2023-02-15 14:21:30.262+01:00 | nioEventLoopGroup-3-4 | INFO  | BackwardSyncContext | Backward sync phase 2 of 2, 34.85% completed, imported 23 blocks of at least 66 (current head 16633326, target head 16633369). Peers: 2

I switched to my 5 GHz and then it stopped logging for 5 minutes. I then aborted and then I started getting Internal error, backward sync completed but failed to import finalized block

I deleted the log files in the database dir and it managed to resolve the issue without resyncing

siladu · 2023-02-15T23:44:59Z

@estensen

I'm just a bit stressed that the db gets corrupted two weeks in a row.

It is unfortunate to happen twice in a row and I'm sure annoying. Be assured we will continue to work on stability issues like this as a top priority :)

In addition, we have dramatically improved overall block processing performance and made syncing more robust, the effect being that resyncing from scratch is much less painful when it does have to happen.

There is an upcoming release which is looking like it will be announced this week (I'm a bit reticent to say this as it's been delayed in the past!) so please bear with us and look out for announcements 🙏

Armaver · 2023-02-20T10:43:00Z

Same problem here. After upgrade to Besu 22.10.3 it spams this on restart:

| vertx-blocked-thread-checker | WARN  | BlockedThreadChecker | Thread Thread[vert.x-eventloop-thread-3,5,main] has been blocked for 19520 ms, time limit is 2000 ms
io.vertx.core.VertxException: Thread blocked
	at app//com.google.common.net.InetAddresses.textToNumericFormatV4(InetAddresses.java:226)
[...]

And after another restart repeating:

| vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0x04d25e230dfbf9cc0138f38c53c34b3359eafa4e5dd075a1c4ba16cd79e41316

After another restart it seems to be back to normal.

Not good for my heart health ;P

siladu · 2023-02-21T02:57:43Z

22.10.3

@Armaver can I just confirm whether you mean upgrade to 22.10.3, or do you mean the recent release: 23.1.0?

Also which CL are you using?

SgtDinosaur · 2023-03-01T20:10:54Z

Same problem here, twice in one week.

siladu · 2023-03-01T22:35:05Z

Same problem here, twice in one week.

Hi @SgtDinosaur which Besu version, sync-mode and CL are you using?

SeaMonkey82 · 2023-03-02T02:28:22Z

CL client is Lighthouse.

~/Downloads/besu/build/install/besu/bin/besu --data-path ~/.eth2/besu --p2p-port 23426 --p2p-host "1.2.3.4" --rpc-http-enabled --host-allowlist "192.168.0.3" --rpc-http-port 8547 --data-storage-format=BONSAI --engine-jwt-enabled=true --engine-rpc-port 8551 --engine-host-allowlist "127.0.0.1" --engine-jwt-secret ~/.eth2/jwtsecret --Xplugin-rocksdb-high-spec-enabled --sync-mode=X_CHECKPOINT

2023-03-01 21:16:35.445-05:00 | main | INFO  | Besu | Starting Besu
2023-03-01 21:16:35.719-05:00 | main | INFO  | Besu |
####################################################################################################
#                                                                                                  #
# Besu 23.1.0                                                                                      #
#                                                                                                  #
# Configuration:                                                                                   #
# Network: Mainnet                                                                                 #
# Network Id: 1                                                                                    #
# Data storage: Bonsai                                                                             #
# Sync mode: Checkpoint                                                                            #
# RPC HTTP APIs: ETH,NET,WEB3                                                                      #
# RPC HTTP port: 8547                                                                              #
# Engine APIs: ENGINE,ETH                                                                          #
# Engine port: 8551                                                                                #
# High spec configuration enabled                                                                  #
#                                                                                                  #
# Host:                                                                                            #
# Java: openjdk-java-17                                                                            #
# Maximum heap size: 15.66 GB                                                                      #
# OS: linux-x86_64                                                                                 #
# glibc: 2.35                                                                                      #
# Total memory: 62.65 GB                                                                           #
# CPU cores: 16                                                                                    #
#                                                                                                  #
####################################################################################################
2023-03-01 21:16:35.721-05:00 | main | INFO  | Besu | Connecting to 0 static nodes.
2023-03-01 21:16:35.721-05:00 | main | INFO  | Besu | Security Module: localfile
2023-03-01 21:16:35.751-05:00 | main | INFO  | Besu | Using the native implementation of alt bn128
2023-03-01 21:16:35.776-05:00 | main | INFO  | Besu | Using the native implementation of modexp
2023-03-01 21:16:35.776-05:00 | main | INFO  | Besu | Using the native implementation of the signature algorithm
2023-03-01 21:16:35.784-05:00 | main | INFO  | Besu | Using the native implementation of the blake2bf algorithm
2023-03-01 21:16:35.792-05:00 | main | INFO  | DatabaseMetadata | Lookup database metadata file in data directory: /home/seamonkey/.eth2/besu
2023-03-01 21:16:35.817-05:00 | main | INFO  | RocksDBKeyValueStorageFactory | Existing database detected at /home/seamonkey/.eth2/besu. Version 2
2023-03-01 21:16:47.689-05:00 | main | INFO  | KeyPairUtil | Loaded public key 0x47544ac69f628a82f1058891dc7abdf5aab5e0876381d839b7d5ea0b86bef50003a6df5abd2bc3063298b9ceddc1b64b18a399b4053ada1148b99b249a2bd465 from /home/seamonkey/.eth2/besu/key
2023-03-01 21:16:47.771-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-03-01 21:16:47.785-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-03-01 21:16:47.788-05:00 | main | INFO  | AbstractProtocolScheduleBuilder | Protocol schedule created with milestones: []
2023-03-01 21:16:48.059-05:00 | main | INFO  | TransactionPoolFactory | Enabling transaction pool
2023-03-01 21:16:48.059-05:00 | main | INFO  | TransactionPoolFactory | Disabling transaction handling during initial sync
2023-03-01 21:16:48.061-05:00 | main | INFO  | EthPeers | Updating the default best peer comparator
2023-03-01 21:16:48.075-05:00 | main | INFO  | BesuControllerBuilder | TTD difficulty is present, creating initial sync for PoS
2023-03-01 21:16:48.084-05:00 | main | INFO  | CheckpointDownloaderFactory | Checkpoint sync was requested, but cannot be enabled because the local blockchain is not empty.
2023-03-01 21:16:48.084-05:00 | main | INFO  | TransitionBesuControllerBuilder | TTD present, creating DefaultSynchronizer that stops propagating after finalization
2023-03-01 21:16:48.096-05:00 | main | INFO  | RunnerBuilder | Detecting NAT service.
2023-03-01 21:16:48.137-05:00 | main | INFO  | AbstractProtocolScheduleBuilder | Protocol schedule created with milestones: []
2023-03-01 21:16:48.195-05:00 | main | INFO  | AbstractProtocolScheduleBuilder | Protocol schedule created with milestones: []
2023-03-01 21:16:48.238-05:00 | main | INFO  | Runner | Starting external services ...
2023-03-01 21:16:48.239-05:00 | main | INFO  | JsonRpcHttpService | Starting JSON-RPC service on 127.0.0.1:8547
2023-03-01 21:16:48.301-05:00 | vert.x-eventloop-thread-3 | INFO  | JsonRpcHttpService | JSON-RPC service started and listening on 127.0.0.1:8547
2023-03-01 21:16:48.301-05:00 | main | INFO  | EngineJsonRpcService | Starting JSON-RPC service on 127.0.0.1:8551
2023-03-01 21:16:48.304-05:00 | vert.x-eventloop-thread-3 | INFO  | EngineJsonRpcService | JSON-RPC service started and listening on 127.0.0.1:8551
2023-03-01 21:16:48.306-05:00 | main | INFO  | AutoTransactionLogBloomCachingService | Starting auto transaction log bloom caching service.
2023-03-01 21:16:48.306-05:00 | main | INFO  | LogBloomCacheMetadata | Lookup cache metadata file in data directory: /home/seamonkey/.eth2/besu/caches
2023-03-01 21:16:48.310-05:00 | main | INFO  | Runner | Starting Ethereum main loop ...
2023-03-01 21:16:48.310-05:00 | main | INFO  | NatService | No NAT environment detected so no service could be started
2023-03-01 21:16:48.310-05:00 | main | INFO  | NetworkRunner | Starting Network.
2023-03-01 21:16:48.311-05:00 | main | INFO  | DefaultP2PNetwork | Starting DNS discovery with URL enrtree://AKA3AM6LPBYEUDMVNU3BSVQJ5AD45Y7YPOHJLEF6W26QOE4VTUDPE@all.mainnet.ethdisco.net
2023-03-01 21:16:48.344-05:00 | nioEventLoopGroup-2-1 | INFO  | RlpxAgent | P2P RLPx agent started and listening on /[0:0:0:0:0:0:0:0]:23426.
2023-03-01 21:16:48.344-05:00 | main | INFO  | PeerDiscoveryAgent | Starting peer discovery agent on host=0.0.0.0, port=23426
2023-03-01 21:16:48.368-05:00 | vert.x-eventloop-thread-3 | INFO  | VertxPeerDiscoveryAgent | Started peer discovery agent successfully, on effective host=0.0.0.0 and port=23426
2023-03-01 21:16:48.369-05:00 | vert.x-eventloop-thread-3 | INFO  | PeerDiscoveryAgent | P2P peer discovery agent started and listening on /0.0.0.0:23426
2023-03-01 21:16:48.396-05:00 | vert.x-eventloop-thread-3 | INFO  | PeerDiscoveryAgent | Writing node record to disk. NodeRecord{seq=6, publicKey=0x0347544ac69f628a82f1058891dc7abdf5aab5e0876381d839b7d5ea0b86bef500, udpAddress=Optional[/1.2.3.4:23426], tcpAddress=Optional[/1.2.3.4:23426], asBase64=-Je4QD14_gcgQKKJPYSEQahrUDQn7nXh4oYJloGQPd__qfPhe6VKE7QpZtZOfuhSAif0GCMN3IUqVDKWkZYp5KeZmVgGg2V0aMfGhPCv0OOAgmlkgnY0gmlwhBd8VMWJc2VjcDI1NmsxoQNHVErGn2KKgvEFiJHcer31qrXgh2OB2Dm31eoLhr71AIN0Y3CCW4KDdWRwgluC, nodeId=0x34ae44ec424fb35e9de56488e175f5c6ba3e4105109c60d777265eed508f509f, customFields={tcp=23426, udp=23426, ip=0x177c54c5, eth=[[0xf0afd0e3, 0x]], id=V4, secp256k1=0x0347544ac69f628a82f1058891dc7abdf5aab5e0876381d839b7d5ea0b86bef500}}
2023-03-01 21:16:48.426-05:00 | main | INFO  | DefaultP2PNetwork | Enode URL enode://47544ac69f628a82f1058891dc7abdf5aab5e0876381d839b7d5ea0b86bef50003a6df5abd2bc3063298b9ceddc1b64b18a399b4053ada1148b99b249a2bd465@1.2.3.4:23426
2023-03-01 21:16:48.427-05:00 | main | INFO  | DefaultP2PNetwork | Node address 0xe175f5c6ba3e4105109c60d777265eed508f509f
2023-03-01 21:16:48.443-05:00 | main | INFO  | NetworkRunner | Supported capabilities: [eth/63, eth/64, eth/65, eth/66, eth/67, eth/68], [snap/1]
2023-03-01 21:16:48.444-05:00 | main | INFO  | DefaultSynchronizer | Starting synchronizer.
2023-03-01 21:16:48.445-05:00 | main | INFO  | TransactionPoolFactory | Enabling transaction handling following initial sync
2023-03-01 21:16:48.446-05:00 | main | INFO  | DefaultSynchronizer | Stopping block propagation.
2023-03-01 21:16:48.447-05:00 | main | INFO  | DefaultSynchronizer | Stopping the pruner.
2023-03-01 21:16:48.447-05:00 | main | INFO  | Runner | Ethereum main loop is up.
2023-03-01 21:16:52.271-05:00 | vert.x-worker-thread-0 | INFO  | BackwardSyncContext | Starting a new backward sync session
2023-03-01 21:16:52.272-05:00 | vert.x-worker-thread-0 | INFO  | BackwardsSyncAlgorithm | Current backward sync session is done
2023-03-01 21:16:52.364-05:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xcece3c3436ed52276abdebe0ca6e45e45ee6c0a37039594c74410a399ff68481
2023-03-01 21:17:08.752-05:00 | Timer-0 | WARN  | DNSResolver | I/O exception contacting remote DNS server when resolving 3NL66VB5IUQZMGNON777AT.all.mainnet.ethdisco.net
java.io.IOException: Timed out while trying to resolve 3NL66VB5IUQZMGNON777AT.all.mainnet.ethdisco.net./TXT, id=21881
        at org.xbill.DNS.Resolver.send(Resolver.java:170)
        at org.apache.tuweni.discovery.DNSResolver.resolveRecordRaw(DNSResolver.kt:155)
        at org.apache.tuweni.discovery.DNSResolver.resolveRecord(DNSResolver.kt:73)
        at org.apache.tuweni.discovery.DNSResolver.internalVisit(DNSResolver.kt:175)
        at org.apache.tuweni.discovery.DNSResolver.internalVisit(DNSResolver.kt:184)
        at org.apache.tuweni.discovery.DNSResolver.internalVisit(DNSResolver.kt:184)
        at org.apache.tuweni.discovery.DNSResolver.internalVisit(DNSResolver.kt:184)
        at org.apache.tuweni.discovery.DNSResolver.internalVisit(DNSResolver.kt:184)
        at org.apache.tuweni.discovery.DNSResolver.visitTree(DNSResolver.kt:135)
        at org.apache.tuweni.discovery.DNSResolver.visitTree(DNSResolver.kt:111)
        at org.apache.tuweni.discovery.DNSResolver.collectAll(DNSResolver.kt:95)
        at org.apache.tuweni.discovery.DNSTimerTask.run(DNSDaemon.kt:89)
        at java.base/java.util.TimerThread.mainLoop(Timer.java:566)
        at java.base/java.util.TimerThread.run(Timer.java:516)
2023-03-01 21:19:13.957-05:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xcece3c3436ed52276abdebe0ca6e45e45ee6c0a37039594c74410a399ff68481
2023-03-01 21:19:13.957-05:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xcece3c3436ed52276abdebe0ca6e45e45ee6c0a37039594c74410a399ff68481
2023-03-01 21:19:37.082-05:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0x1d3b6ee73952cde028ecc5bc454649c62c3ecebfdfdc07c2da387a940549b1e2
2023-03-01 21:19:56.241-05:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0x56b109f5a2d153f7080d1896281df50e1dd317c9ef0c166582b394470cca17ae
2023-03-01 21:20:03.448-05:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0x495b976cbf1347900238bc18518521a8d495c6715f8d71a60023ec8b253de650
2023-03-01 21:20:10.594-05:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0x39b168ade390645fc468cc3df28a6ff0e8f42885ed4588546673d7847a01cebe
2023-03-01 21:20:17.329-05:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0x087956e866f8d091659310983d08963aa846f5f8e265a6702b7a24e885372b4c
2023-03-01 21:20:23.980-05:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xd9b95a42d1b11f3caef855bd987b1b6f5f7620dd010f9536720c68f4cd3be637
2023-03-01 21:20:30.681-05:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0x988061c6504742fecf488e70c2ef9c82f81a044e3456d3a3dd70976cf9caa465
2023-03-01 21:20:37.464-05:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0x857795d1050a7c047841308a778493bf0a3ee991443d6dbfe804204970edfb31
2023-03-01 21:20:39.664-05:00 | Timer-0 | INFO  | DNSResolver | Resolved 2409 nodes
2023-03-01 21:20:45.318-05:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0x5155e2ca4481da84d0e092aae026628922df747ff8ab9e1765d0d3156dd1a396
2023-03-01 21:20:46.940-05:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0x5155e2ca4481da84d0e092aae026628922df747ff8ab9e1765d0d3156dd1a396
2023-03-01 21:20:47.496-05:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0x5155e2ca4481da84d0e092aae026628922df747ff8ab9e1765d0d3156dd1a396
2023-03-01 21:20:52.665-05:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0x0c29d67fa5587244420ec51f0c9e43b3814a4d3cae03ff0738b90c0fbb0814e1
2023-03-01 21:20:59.591-05:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xa5dd354b7139fc1b27739c2646f7dd9d258cd2d3545cdcc48e3320726d025e12
2023-03-01 21:21:00.021-05:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0xdc7c68f450994b3ecc3b26cf8226d7ca8a0c498cf3325f1e9714442123798889
2023-03-01 21:21:06.781-05:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | Internal error, backward sync completed but failed to import finalized block 0x4d888bc62b40fa4f61af28a6c8402bc3ff18caac9f1f6ea491ff75f61b8ea453

SgtDinosaur · 2023-03-02T08:06:47Z

Same problem here, twice in one week.

Hi @SgtDinosaur which Besu version, sync-mode and CL are you using?

I was using the second latest and then switched to the latest in the hope of fixing the issue. I now switched to Nethermind, hope to come back quick. My CL was Lighthouse.

Thank you guys for responding and looking into it!

)   ## PR description There is an issue when restarting Besu when a backward sync session is running, since after the restart it is possible that the Consensus client sends a FcU or a NewPayload for a block that is present in the backward sync storage, but not yet imported, so not on the main chain, but still the backward sync thinks it should not do anything with that block, so it returns like it has completed the sync, but since the sync is not done actually then the internal error that the finalize block is not present. The solution is to persist the backward sync status, so in case of a restart, it can resume from where it was interrupted. ## Fixed Issue(s)   fixes #5053 ## Documentation - [x] I thought about documentation and added the `doc-change-required` label to this PR if [updates are required](https://wiki.hyperledger.org/display/BESU/Documentation). ## Acceptance Tests (Non Mainnet) - [x] I have considered running `./gradlew acceptanceTestNonMainnet` locally if my PR affects non-mainnet modules. ## Changelog - [x] I thought about the changelog and included a [changelog update if required](https://wiki.hyperledger.org/display/BESU/Changelog). --------- Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net> Co-authored-by: Sally MacFarlane <macfarla.github@gmail.com>

siladu · 2023-03-23T05:26:40Z

This fix has been released in https://github.com/hyperledger/besu/releases/tag/23.1.2

…perledger#5182)   ## PR description There is an issue when restarting Besu when a backward sync session is running, since after the restart it is possible that the Consensus client sends a FcU or a NewPayload for a block that is present in the backward sync storage, but not yet imported, so not on the main chain, but still the backward sync thinks it should not do anything with that block, so it returns like it has completed the sync, but since the sync is not done actually then the internal error that the finalize block is not present. The solution is to persist the backward sync status, so in case of a restart, it can resume from where it was interrupted. ## Fixed Issue(s)   fixes hyperledger#5053 ## Documentation - [x] I thought about documentation and added the `doc-change-required` label to this PR if [updates are required](https://wiki.hyperledger.org/display/BESU/Documentation). ## Acceptance Tests (Non Mainnet) - [x] I have considered running `./gradlew acceptanceTestNonMainnet` locally if my PR affects non-mainnet modules. ## Changelog - [x] I thought about the changelog and included a [changelog update if required](https://wiki.hyperledger.org/display/BESU/Changelog). --------- Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net> Co-authored-by: Sally MacFarlane <macfarla.github@gmail.com>

estensen mentioned this issue Feb 7, 2023

Best peer has chain height below pivotBlock height hangs #4725

Closed

estensen mentioned this issue Feb 8, 2023

No buffer space available #5072

Open

non-fungible-nelson added bug Something isn't working mainnet syncing labels Feb 15, 2023

siladu mentioned this issue Feb 22, 2023

Out of Order Backwards Sync Logs #5121

Closed

fab-10 self-assigned this Mar 2, 2023

fab-10 mentioned this issue Mar 7, 2023

Fix for backward sync wrongly thinking it is done after a restart #5182

Merged

3 tasks

non-fungible-nelson added the TeamChupa GH issues worked on by Chupacabara Team label Mar 7, 2023

fab-10 closed this as completed in #5182 Mar 15, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Internal error, backward sync completed but failed to import finalized block #5053

Internal error, backward sync completed but failed to import finalized block #5053

i-am-logger commented Feb 4, 2023

smasher816 commented Feb 7, 2023

estensen commented Feb 7, 2023 •

edited

Loading

i-am-logger commented Feb 7, 2023

quickchase commented Feb 7, 2023

quickchase commented Feb 7, 2023

quickchase commented Feb 7, 2023

quickchase commented Feb 8, 2023

quickchase commented Feb 9, 2023

quickchase commented Feb 9, 2023

siladu commented Feb 9, 2023 •

edited

Loading

siladu commented Feb 9, 2023

estensen commented Feb 15, 2023 •

edited

Loading

estensen commented Feb 15, 2023 •

edited

Loading

siladu commented Feb 15, 2023

estensen commented Feb 15, 2023

siladu commented Feb 15, 2023

Armaver commented Feb 20, 2023 •

edited

Loading

siladu commented Feb 21, 2023 •

edited

Loading

SgtDinosaur commented Mar 1, 2023

siladu commented Mar 1, 2023 •

edited

Loading

SeaMonkey82 commented Mar 2, 2023

SgtDinosaur commented Mar 2, 2023

siladu commented Mar 23, 2023

Internal error, backward sync completed but failed to import finalized block #5053

Internal error, backward sync completed but failed to import finalized block #5053

Comments

i-am-logger commented Feb 4, 2023

smasher816 commented Feb 7, 2023

estensen commented Feb 7, 2023 • edited Loading

i-am-logger commented Feb 7, 2023

quickchase commented Feb 7, 2023

quickchase commented Feb 7, 2023

quickchase commented Feb 7, 2023

quickchase commented Feb 8, 2023

quickchase commented Feb 9, 2023

quickchase commented Feb 9, 2023

siladu commented Feb 9, 2023 • edited Loading

siladu commented Feb 9, 2023

estensen commented Feb 15, 2023 • edited Loading

estensen commented Feb 15, 2023 • edited Loading

siladu commented Feb 15, 2023

estensen commented Feb 15, 2023

siladu commented Feb 15, 2023

Armaver commented Feb 20, 2023 • edited Loading

siladu commented Feb 21, 2023 • edited Loading

SgtDinosaur commented Mar 1, 2023

siladu commented Mar 1, 2023 • edited Loading

SeaMonkey82 commented Mar 2, 2023

SgtDinosaur commented Mar 2, 2023

siladu commented Mar 23, 2023

estensen commented Feb 7, 2023 •

edited

Loading

siladu commented Feb 9, 2023 •

edited

Loading

estensen commented Feb 15, 2023 •

edited

Loading

estensen commented Feb 15, 2023 •

edited

Loading

Armaver commented Feb 20, 2023 •

edited

Loading

siladu commented Feb 21, 2023 •

edited

Loading

siladu commented Mar 1, 2023 •

edited

Loading