Blocks have automatically rolled back and are now stuck

[suxnju]

I just started using Reth for data synchronization, and currently, the blocks have automatically rolled back and are now stuck.

• A possible reason for the rollback is that I did not run Lighthouse.
• I have since restarted lighthouse, but no changes.

Should I continue to wait, or should I try some other actions?

Here are

• Status displayed by Grafana
• Latest logs from Reth

$ tail -n 10 ./logs/ex_v1.log
ts=2024-06-29T05:07:01.212065564Z level=debug target=net::session message="failed to receive message" err=disconnected remote_peer_id=0xf155651d96aecded880ea55b12ebb28eb00d6a9d919fed492ecec06fe07e355bbbc74666d4c68699b96c0917ef531a66b35dc62032e45dc8b85ccf2551d9db4e
ts=2024-06-29T05:07:05.643054116Z level=debug target=storage::db::mdbx message=Commit total_duration=5.524µs commit_latency="Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 0, audit: 0, write: 0, sync: 0, ending: 0, whole: 1, gc_cputime: 0, gc_prof: MDBX_commit_latency__bindgen_ty_1 { wloops: 0, coalescences: 0, wipes: 0, flushes: 0, kicks: 0, work_counter: 0, work_rtime_monotonic: 0, work_xtime_cpu: 0, work_rsteps: 0, work_xpages: 0, work_majflt: 0, self_counter: 0, self_rtime_monotonic: 0, self_xtime_cpu: 0, self_rsteps: 0, self_xpages: 0, self_majflt: 0 } }))" is_read_only=true
ts=2024-06-29T05:07:09.600998639Z level=info target=reth::cli message=Status connected_peers=100 freelist=17057413 stage=Headers checkpoint=10419848 target=None stage_progress=100.00%
ts=2024-06-29T05:07:09.601053059Z level=info target=reth::cli message=Status connected_peers=100 freelist=17057413 stage=Headers checkpoint=10419848 target=None stage_progress=100.00%
ts=2024-06-29T05:07:10.642865596Z level=debug target=storage::db::mdbx message=Commit total_duration=6.922µs commit_latency="Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 0, audit: 0, write: 0, sync: 0, ending: 0, whole: 1, gc_cputime: 0, gc_prof: MDBX_commit_latency__bindgen_ty_1 { wloops: 0, coalescences: 0, wipes: 0, flushes: 0, kicks: 0, work_counter: 0, work_rtime_monotonic: 0, work_xtime_cpu: 0, work_rsteps: 0, work_xpages: 0, work_majflt: 0, self_counter: 0, self_rtime_monotonic: 0, self_xtime_cpu: 0, self_rsteps: 0, self_xpages: 0, self_majflt: 0 } }))" is_read_only=true
ts=2024-06-29T05:07:13.596291057Z level=debug target=net::session message="failed to receive message" err=disconnected remote_peer_id=0x3fb243d163fbe6b80b5570b8079105fa9f13323494c005f1506dd50290e5c80085e265ef6e1bd83ec2d558f5b3e477e87da61057081d1f2e9b7e30e7bbe25ffa
ts=2024-06-29T05:07:14.265723273Z level=debug target=net::session message="failed to receive message" err=disconnected remote_peer_id=0xa7ddeecd72efd7d050d5ce90e58d8cb70ef2720c1b1d4983200e2e11a9378fb7e079e933f787506e1a4ae95fd9d0ec160f421b9868c1dfc9058f9193d61e76c6
ts=2024-06-29T05:07:14.91226258Z level=debug target=net message="Session established" remote_addr=155.4.114.211:30303 client_version=Nethermind/v1.27.0+220b5b85/linux-x64/dotnet8.0.6 peer_id=0xfae3f775762e0a1bae19827f9d80e1a3776dbdc1f3836253c984dfb7f1295238734e2f86a3bf5da7a455fe7388499fed4ada78dbb5cd6408fd4b3efcecd1424c total_active=99 kind=outgoing peer_enode=enode://fae3f775762e0a1bae19827f9d80e1a3776dbdc1f3836253c984dfb7f1295238734e2f86a3bf5da7a455fe7388499fed4ada78dbb5cd6408fd4b3efcecd1424c@155.4.114.211:30303
ts=2024-06-29T05:07:14.937883365Z level=debug target=net message="Session established" remote_addr=95.216.0.223:30303 client_version=Nethermind/v1.26.0+0068729c/linux-x64/dotnet8.0.4 peer_id=0x4e39dd99ba4012a3f2bf25edd7c8c87a717ca187fbd5a5bd039f290c642a5f2e57abf29c5afc3674f37f94af4c661f23f082e009f35f76f0e0e95dcdeb5bf385 total_active=100 kind=outgoing peer_enode=enode://4e39dd99ba4012a3f2bf25edd7c8c87a717ca187fbd5a5bd039f290c642a5f2e57abf29c5afc3674f37f94af4c661f23f082e009f35f76f0e0e95dcdeb5bf385@95.216.0.223:30303
ts=2024-06-29T05:07:15.642775245Z level=debug target=storage::db::mdbx message=Commit total_duration=2.408µs commit_latency="Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 0, audit: 0, write: 0, sync: 0, ending: 0, whole: 1, gc_cputime: 0, gc_prof: MDBX_commit_latency__bindgen_ty_1 { wloops: 0, coalescences: 0, wipes: 0, flushes: 0, kicks: 0, work_counter: 0, work_rtime_monotonic: 0, work_xtime_cpu: 0, work_rsteps: 0, work_xpages: 0, work_majflt: 0, self_counter: 0, self_rtime_monotonic: 0, self_xtime_cpu: 0, self_rsteps: 0, self_xpages: 0, self_majflt: 0 } }))" is_read_only=true

• Latest logs from Lighthouse

$ tail -n 10 ./logs/cl_v2.log
Jun 29 05:07:17.001 INFO Syncing                                 est_time: --, distance: 6511 slots (21 hrs 42 mins), peers: 99, service: slot_notifier
Jun 29 05:07:17.002 WARN Syncing deposit contract block cache    est_blocks_remaining: initializing deposits, service: slot_notifier
Jun 29 05:07:22.640 WARN Execution endpoint is not synced        last_seen_block_unix_timestamp: 0, endpoint: http://localhost:8551/, auth=true, service: deposit_contract_rpc
Jun 29 05:07:22.641 ERRO Error updating deposit contract cache   error: Failed to get remote head and new block ranges: EndpointError(FarBehind), retry_millis: 60000, service: deposit_contract_rpc
Jun 29 05:07:29.001 INFO Syncing                                 est_time: --, distance: 6512 slots (21 hrs 42 mins), peers: 96, service: slot_notifier
Jun 29 05:07:29.001 WARN Syncing deposit contract block cache    est_blocks_remaining: initializing deposits, service: slot_notifier
Jun 29 05:07:41.002 INFO Syncing                                 est_time: --, distance: 6513 slots (21 hrs 42 mins), peers: 100, service: slot_notifier
Jun 29 05:07:41.002 WARN Syncing deposit contract block cache    est_blocks_remaining: initializing deposits, service: slot_notifier
Jun 29 05:07:53.001 INFO Syncing                                 est_time: --, distance: 6514 slots (21 hrs 42 mins), peers: 99, service: slot_notifier
Jun 29 05:07:53.001 WARN Syncing deposit contract block cache    est_blocks_remaining: initializing deposits, service: slot_notifier

[mattsse]

could you perhaps share more logs?

[suxnju]

@mattsse @Rjected @joshieDo
Update: I tried re-syncing, but the same issue occurred. However, this time it stopped at block 14461313.

Running script:

reth node \
    --authrpc.jwtsecret "XXX" \
    --authrpc.addr 127.0.0.1 \
    --authrpc.port 8551 \
    --metrics 0.0.0.0:9001 \
    --http --http.corsdomain "*" --http.api all --http.port 8545 \
    --log.file.format log-fmt --log.stdout.format log-fmt \
    --datadir "XXX" --datadir.static_files "XXX" \
    -vvv \
    --debug.tip "0xf9d0d7e9c7a7d452a2377128f44a557880300d149ca393f7b78f5250bd988a5a"

Key error log information is as follows:

ts=2024-07-02T16:13:41.811482155Z level=info target=reth::cli message=Status connected_peers=100 freelist=951724 stage=Execution checkpoint=14461313 target=20188612 stage_progress=53.84%
ts=2024-07-02T16:13:41.811501963Z level=info target=reth::cli message=Status connected_peers=100 freelist=951724 stage=Execution checkpoint=14461313 target=20188612 stage_progress=53.84%
ts=2024-07-02T16:13:45.64256088Z level=debug target=storage::db::mdbx message=Commit total_duration=2.054µs commit_latency="Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 0, audit: 0, write: 0, sync: 0, ending: 0, whole: 1, gc_cputime: 0, gc_prof: MDBX_commit_latency__bindgen_ty_1 { wloops: 0, coalescences: 0, wipes: 0, flushes: 0, kicks: 0, work_counter: 0, work_rtime_monotonic: 0, work_xtime_cpu: 0, work_rsteps: 0, work_xpages: 0, work_majflt: 0, self_counter: 0, self_rtime_monotonic: 0, self_xtime_cpu: 0, self_rsteps: 0, self_xpages: 0, self_majflt: 0 } }))" is_read_only=true
ts=2024-07-02T16:13:47.240621302Z level=debug target=reth_ethereum_consensus::validation message="receipts verification failed" error="receipt root mismatch: got 0x44c837487451b57e674de677df8e7edf237b3a1dad33730b0cdd33f833fca75e, expected 0x62d9b59b3de0e3017643c4ce86fda98ea1e4f93e68c1c70f2b912ab4580950c5" receipts="XXX"
ts=2024-07-02T16:13:47.385366422Z level=error target=sync::pipeline message="Stage encountered an execution error: receipt root mismatch: got 0x44c837487451b57e674de677df8e7edf237b3a1dad33730b0cdd33f833fca75e, expected 0x62d9b59b3de0e3017643c4ce86fda98ea1e4f93e68c1c70f2b912ab4580950c5" stage=Execution bad_block=14465384
ts=2024-07-02T16:13:47.385456999Z level=error target=sync::pipeline message="Stage encountered an execution error: receipt root mismatch: got 0x44c837487451b57e674de677df8e7edf237b3a1dad33730b0cdd33f833fca75e, expected 0x62d9b59b3de0e3017643c4ce86fda98ea1e4f93e68c1c70f2b912ab4580950c5" stage=Execution bad_block=14465384
ts=2024-07-02T16:13:47.38607385Z level=debug target=sync::pipeline span=Unwinding span_path=Unwinding message="Unwind point too far for stage" from=0 to=14461313 stage=Finish
ts=2024-07-02T16:13:47.386724908Z level=debug target=sync::pipeline span=Unwinding span_path=Unwinding message="Unwind point too far for stage" from=0 to=14461313 stage=IndexAccountHistory

More logs:
reth_log.log

Some possibly related issues include:

• Sender Recovery cleanup pipeline stage #9221

[mattsse]

hmm, sorry about this.
I wasn't able to reproduce the first issue, and I'm struggling to understand where it might got the wrong block from...

by resyncing do you mean, nuking the db and starting over?

[suxnju]

@mattsse Yes, I tried re-syncing again (setting a new empty data_dir and datadir.static_files).

I am now certain that the issue lies with encountering a Stage encountered an execution error: receipt root mismatch which causes the "Executing stage" to fail, triggering Unwinding and deleting the downloaded Headers, Bodies, and SenderRecovery.

I also tried to unwind 20,000 blocks, but the issue persisted, and I still encountered bad_block=Some(14465384).

reth stage unwind \
    --log.file.format log-fmt --log.stdout.format log-fmt \
    --datadir "/mnt/data/reth_sync/data/eth_archive/" --datadir.static_files "/mnt/data/reth_sync/data/statics/" \
    num-blocks 20000 \

Regarding the bad_block, could this be related to not running Lighthouse? I am using --debug.tip.

[emhane]

did this issue resolve for you @suxnju ?

[suxnju]

did this issue resolve for you @suxnju ?

Sorry for the late response, in fact, I found issues on my RAM, and now it has been fixed, I will try to re-sync again to see the same problem