search

paradigmxyz / reth

Modular, contributor-friendly and blazing-fast implementation of the Ethereum protocol, in Rust
https://reth.rs/
Apache License 2.0
4.01k stars 1.23k forks source link

Berachain pruned rethnode panics and fails on rewind #12797

Open Staking7pc opened 5 days ago

Staking7pc commented 5 days ago

Describe the bug

I am running a berachain pruned node which is synched using a snapshot of an archived node. This is the second time I am seeing the node stop synching with the error

WARN storage::db::mdbx: The database read transaction has been open for too long. Backtrace: 0: <unknown> 1: <unknown> 2: <unknown> 3: <unknown> 4: <unknown> 5: <unknown> 6: <unknown> 7: <unknown> 8: <unknown> 9: <unknown> 10: <unknown> 11: <unknown> 12: start_thread 13: clone open_duration=140.424747423s self.txn_id=50010882

2024-11-22T13:45:21.493770Z  INFO reth::cli: Initialized tracing, debug log directory: /root/.cache/reth/logs/80084
2024-11-22T13:45:21.496094Z  INFO reth::cli: Starting reth version="1.1.1 (15c230ba)"
2024-11-22T13:45:21.496252Z  INFO reth::cli: Opening database path="/root/BERA/testnet/.reth/db"
2024-11-22T13:45:21.637380Z DEBUG reth_node_builder::launch::common: Raised file descriptor limit from=65096 to=65096
2024-11-22T13:45:21.643300Z  INFO reth::cli: Configuration loaded path="/root/BERA/testnet/.reth/reth.toml"
2024-11-22T13:45:21.643312Z  INFO reth::cli: Adding trusted nodes
2024-11-22T13:45:21.669933Z  INFO reth::cli: Verifying storage consistency.
2024-11-22T13:45:21.926870Z  INFO reth::providers::static_file: Setting unwind target. db_first_entry=413482445 highest_static_file_entry=413449165 unwind_target=6702297 segment=Receipts
2024-11-22T13:45:21.927050Z  INFO reth::cli: Executing an unwind after a failed storage consistency check. unwind_target=Unwind(6702297)
2024-11-22T13:45:21.931063Z DEBUG pruner: Pruner started tip_block_number=7194871
2024-11-22T13:45:21.931211Z DEBUG pruner: Segment pruning started segment=Headers purpose=StaticFile to_block=7194871 prune_mode=Before(7194872)
2024-11-22T13:45:21.932838Z DEBUG pruner: Segment pruning finished segment=Headers purpose=StaticFile to_block=7194871 prune_mode=Before(7194872) segment_output.pruned=9
2024-11-22T13:45:21.932843Z DEBUG pruner: Segment pruning started segment=Transactions purpose=StaticFile to_block=7194871 prune_mode=Before(7194872)
2024-11-22T13:45:21.934514Z DEBUG pruner: Segment pruning finished segment=Transactions purpose=StaticFile to_block=7194871 prune_mode=Before(7194872) segment_output.pruned=93
2024-11-22T13:45:21.934789Z DEBUG pruner: Segment pruning started segment=Receipts purpose=StaticFile to_block=6702297 prune_mode=Before(6702298)
2024-11-22T13:45:21.934798Z DEBUG pruner: Segment pruning finished segment=Receipts purpose=StaticFile to_block=6702297 prune_mode=Before(6702298) segment_output.pruned=0
2024-11-22T13:45:21.934800Z DEBUG pruner: Pruner finished tip_block_number=7194871 elapsed=3.726834ms deleted_entries=102 limiter=PruneLimiter { deleted_entries_limit: Some(PruneDeletedEntriesLimit { limit: 18446744073709551615, deleted: 102 }), time_limit: None } output=PrunerOutput { progress: Finished, segments: [(Headers, SegmentOutput { progress: Finished, pruned: 9, checkpoint: Some(SegmentOutputCheckpoint { block_number: Some(7194871), tx_number: None }) }), (Transactions, SegmentOutput { progress: Finished, pruned: 93, checkpoint: Some(SegmentOutputCheckpoint { block_number: Some(7194871), tx_number: Some(432700705) }) }), (Receipts, SegmentOutput { progress: Finished, pruned: 0, checkpoint: None })] } stats=[(Headers, 9, Finished), (Transactions, 93, Finished)]
2024-11-22T13:45:21.954130Z DEBUG storage::db::mdbx: Commit total_duration=19.156965ms commit_latency=Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 14, audit: 0, write: 0, sync: 1225, ending: 0, whole: 1240, 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=false
2024-11-22T13:45:21.955594Z  INFO Unwinding{stage=Finish}: sync::pipeline: Starting unwind from=7194871 to=6702297 bad_block=None
2024-11-22T13:45:21.955601Z  INFO Unwinding{stage=Finish}: sync::pipeline: Stage unwound stage=Finish unwind_to=6702297 progress=6702297 done=true
2024-11-22T13:45:21.969018Z DEBUG Unwinding{stage=Finish}: storage::db::mdbx: Commit total_duration=12.442497ms commit_latency=Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 2, audit: 0, write: 0, sync: 811, ending: 0, whole: 814, 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=false
2024-11-22T13:45:21.969090Z  INFO Unwinding{stage=Prune}: sync::pipeline: Starting unwind from=7194871 to=6702297 bad_block=None
2024-11-22T13:45:21.969149Z  INFO Unwinding{stage=Prune}: sync::pipeline: Stage unwound stage=Prune unwind_to=6702297 progress=6702297 done=true
2024-11-22T13:45:21.979764Z DEBUG Unwinding{stage=Prune}: storage::db::mdbx: Commit total_duration=10.584071ms commit_latency=Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 3, audit: 0, write: 0, sync: 689, ending: 0, whole: 692, 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=false
2024-11-22T13:45:21.979829Z  INFO Unwinding{stage=IndexAccountHistory}: sync::pipeline: Starting unwind from=7194871 to=6702297 bad_block=None
2024-11-22T13:46:48.933284Z  INFO Unwinding{stage=IndexAccountHistory}: sync::pipeline: Stage unwound stage=IndexAccountHistory unwind_to=6702297 progress=7094870 done=false
2024-11-22T13:46:49.128339Z DEBUG Unwinding{stage=IndexAccountHistory}: storage::db::mdbx: Commit total_duration=195.031362ms commit_latency=Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 438, audit: 0, write: 0, sync: 12330, ending: 10, whole: 12780, gc_cputime: 112, 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=false
2024-11-22T13:46:49.128405Z  INFO Unwinding{stage=IndexAccountHistory}: sync::pipeline: Stage unwound stage=IndexAccountHistory unwind_to=6702297 progress=6994869 done=false
2024-11-22T13:46:49.134797Z DEBUG Unwinding{stage=IndexAccountHistory}: storage::db::mdbx: Commit total_duration=6.34977ms commit_latency=Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 2, audit: 0, write: 0, sync: 412, ending: 0, whole: 415, 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=false
2024-11-22T13:46:49.134837Z  INFO Unwinding{stage=IndexAccountHistory}: sync::pipeline: Stage unwound stage=IndexAccountHistory unwind_to=6702297 progress=6894868 done=false
2024-11-22T13:46:49.141476Z DEBUG Unwinding{stage=IndexAccountHistory}: storage::db::mdbx: Commit total_duration=6.607386ms commit_latency=Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 1, audit: 0, write: 0, sync: 430, ending: 0, whole: 432, 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=false
2024-11-22T13:46:49.141509Z  INFO Unwinding{stage=IndexAccountHistory}: sync::pipeline: Stage unwound stage=IndexAccountHistory unwind_to=6702297 progress=6794867 done=false
2024-11-22T13:46:49.148233Z DEBUG Unwinding{stage=IndexAccountHistory}: storage::db::mdbx: Commit total_duration=6.696864ms commit_latency=Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 1, audit: 0, write: 0, sync: 436, ending: 0, whole: 438, 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=false
2024-11-22T13:46:49.148261Z  INFO Unwinding{stage=IndexAccountHistory}: sync::pipeline: Stage unwound stage=IndexAccountHistory unwind_to=6702297 progress=6702297 done=true
2024-11-22T13:46:49.154948Z DEBUG Unwinding{stage=IndexAccountHistory}: storage::db::mdbx: Commit total_duration=6.659033ms commit_latency=Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 2, audit: 0, write: 0, sync: 433, ending: 0, whole: 435, 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=false
2024-11-22T13:46:49.154981Z  INFO Unwinding{stage=IndexStorageHistory}: sync::pipeline: Starting unwind from=7194871 to=6702297 bad_block=None
2024-11-22T13:49:36.557142Z  INFO Unwinding{stage=IndexStorageHistory}: sync::pipeline: Stage unwound stage=IndexStorageHistory unwind_to=6702297 progress=7094870 done=false
2024-11-22T13:49:38.136179Z DEBUG Unwinding{stage=IndexStorageHistory}: storage::db::mdbx: Commit total_duration=1.579007031s commit_latency=Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 1273, audit: 0, write: 0, sync: 102173, ending: 32, whole: 103480, gc_cputime: 1012, 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=false
2024-11-22T13:50:21.670222Z  WARN libmdbx: Long-lived read transaction has been timed out open_duration=300.000059797s
2024-11-22T13:51:18.776654Z  INFO Unwinding{stage=IndexStorageHistory}: sync::pipeline: Stage unwound stage=IndexStorageHistory unwind_to=6702297 progress=6994869 done=false
2024-11-22T13:51:20.047900Z DEBUG Unwinding{stage=IndexStorageHistory}: storage::db::mdbx: Commit total_duration=1.27091991s commit_latency=Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 927, audit: 0, write: 0, sync: 82325, ending: 35, whole: 83289, gc_cputime: 768, 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=false
2024-11-22T14:04:47.616599Z  INFO Unwinding{stage=IndexStorageHistory}: sync::pipeline: Stage unwound stage=IndexStorageHistory unwind_to=6702297 progress=6894868 done=false
2024-11-22T14:04:49.718685Z DEBUG Unwinding{stage=IndexStorageHistory}: storage::db::mdbx: Commit total_duration=2.099041446s commit_latency=Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 12390, audit: 0, write: 0, sync: 125025, ending: 107, whole: 137523, gc_cputime: 4022, 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=false
2024-11-22T14:18:48.947654Z  INFO Unwinding{stage=IndexStorageHistory}: sync::pipeline: Stage unwound stage=IndexStorageHistory unwind_to=6702297 progress=6794867 done=false
2024-11-22T14:18:49.326076Z DEBUG Unwinding{stage=IndexStorageHistory}: storage::db::mdbx: Commit total_duration=378.009962ms commit_latency=Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 8425, audit: 0, write: 0, sync: 16224, ending: 120, whole: 24771, gc_cputime: 3879, 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=false
2024-11-22T14:30:12.888373Z  INFO Unwinding{stage=IndexStorageHistory}: sync::pipeline: Stage unwound stage=IndexStorageHistory unwind_to=6702297 progress=6702297 done=true
2024-11-22T14:30:14.640110Z DEBUG Unwinding{stage=IndexStorageHistory}: storage::db::mdbx: Commit total_duration=1.751250013s commit_latency=Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 6920, audit: 0, write: 0, sync: 107739, ending: 107, whole: 114768, gc_cputime: 4495, 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=false
2024-11-22T14:30:14.642771Z  INFO Unwinding{stage=TransactionLookup}: sync::pipeline: Starting unwind from=7194871 to=6702297 bad_block=None
2024-11-22T14:43:47.623182Z  INFO Unwinding{stage=TransactionLookup}: sync::pipeline: Stage unwound stage=TransactionLookup unwind_to=6702297 progress=6702297 done=true
2024-11-22T14:43:52.554259Z DEBUG Unwinding{stage=TransactionLookup}: storage::db::mdbx: Commit total_duration=4.926550348s commit_latency=Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 38898, audit: 0, write: 0, sync: 283809, ending: 123, whole: 322832, gc_cputime: 4720, 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=false
2024-11-22T14:43:52.557025Z  INFO Unwinding{stage=MerkleExecute}: sync::pipeline: Starting unwind from=7194871 to=6702297 bad_block=None
2024-11-22T14:43:52.557230Z  INFO Unwinding{stage=MerkleExecute}: sync::stages::merkle::unwind: Stage is always skipped
2024-11-22T14:43:52.557239Z  INFO Unwinding{stage=MerkleExecute}: sync::pipeline: Stage unwound stage=MerkleExecute unwind_to=6702297 progress=6702297 done=true
2024-11-22T14:43:52.566365Z DEBUG Unwinding{stage=MerkleExecute}: storage::db::mdbx: Commit total_duration=9.092252ms commit_latency=Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 14, audit: 0, write: 0, sync: 580, ending: 0, whole: 595, 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=false
2024-11-22T14:43:52.566555Z  INFO Unwinding{stage=StorageHashing}: sync::pipeline: Starting unwind from=7194871 to=6702297 bad_block=None
2024-11-22T14:46:10.216032Z  INFO Unwinding{stage=StorageHashing}: sync::pipeline: Stage unwound stage=StorageHashing unwind_to=6702297 progress=7094870 done=false
2024-11-22T14:46:12.531565Z DEBUG Unwinding{stage=StorageHashing}: storage::db::mdbx: Commit total_duration=2.315472658s commit_latency=Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 1099, audit: 0, write: 0, sync: 150598, ending: 47, whole: 151745, gc_cputime: 87, 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=false
2024-11-22T14:47:27.966243Z  INFO Unwinding{stage=StorageHashing}: sync::pipeline: Stage unwound stage=StorageHashing unwind_to=6702297 progress=6994869 done=false
2024-11-22T14:47:30.789891Z DEBUG Unwinding{stage=StorageHashing}: storage::db::mdbx: Commit total_duration=2.823601389s commit_latency=Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 875, audit: 0, write: 0, sync: 184143, ending: 26, whole: 185046, gc_cputime: 566, 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=false
2024-11-22T14:55:15.303182Z  INFO Unwinding{stage=StorageHashing}: sync::pipeline: Stage unwound stage=StorageHashing unwind_to=6702297 progress=6894868 done=false
2024-11-22T14:55:17.672076Z DEBUG Unwinding{stage=StorageHashing}: storage::db::mdbx: Commit total_duration=2.368754064s commit_latency=Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 8879, audit: 0, write: 0, sync: 146251, ending: 106, whole: 155237, gc_cputime: 3357, 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=false
2024-11-22T15:01:42.655726Z  INFO Unwinding{stage=StorageHashing}: sync::pipeline: Stage unwound stage=StorageHashing unwind_to=6702297 progress=6794867 done=false
2024-11-22T15:01:43.966919Z DEBUG Unwinding{stage=StorageHashing}: storage::db::mdbx: Commit total_duration=1.311086179s commit_latency=Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 8361, audit: 0, write: 0, sync: 77453, ending: 106, whole: 85922, gc_cputime: 3700, 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=false
2024-11-22T15:07:39.247900Z  INFO Unwinding{stage=StorageHashing}: sync::pipeline: Stage unwound stage=StorageHashing unwind_to=6702297 progress=6702297 done=true
2024-11-22T15:07:40.711869Z DEBUG Unwinding{stage=StorageHashing}: storage::db::mdbx: Commit total_duration=1.463745325s commit_latency=Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 9707, audit: 0, write: 0, sync: 86117, ending: 100, whole: 95926, gc_cputime: 3222, 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=false
2024-11-22T15:07:40.719289Z  INFO Unwinding{stage=AccountHashing}: sync::pipeline: Starting unwind from=7194871 to=6702297 bad_block=None
2024-11-22T15:08:45.556497Z  INFO Unwinding{stage=AccountHashing}: sync::pipeline: Stage unwound stage=AccountHashing unwind_to=6702297 progress=7094870 done=false
2024-11-22T15:08:45.963144Z DEBUG Unwinding{stage=AccountHashing}: storage::db::mdbx: Commit total_duration=406.606604ms commit_latency=Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 585, audit: 0, write: 0, sync: 26045, ending: 14, whole: 26645, gc_cputime: 336, 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=false
2024-11-22T15:08:45.963210Z  INFO Unwinding{stage=AccountHashing}: sync::pipeline: Stage unwound stage=AccountHashing unwind_to=6702297 progress=6994869 done=false
2024-11-22T15:08:45.969212Z DEBUG Unwinding{stage=AccountHashing}: storage::db::mdbx: Commit total_duration=5.957366ms commit_latency=Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 1, audit: 0, write: 0, sync: 387, ending: 0, whole: 389, 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=false
2024-11-22T15:08:45.969241Z  INFO Unwinding{stage=AccountHashing}: sync::pipeline: Stage unwound stage=AccountHashing unwind_to=6702297 progress=6894868 done=false
2024-11-22T15:08:45.975354Z DEBUG Unwinding{stage=AccountHashing}: storage::db::mdbx: Commit total_duration=6.087649ms commit_latency=Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 1, audit: 0, write: 0, sync: 397, ending: 0, whole: 398, 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=false
2024-11-22T15:08:45.975384Z  INFO Unwinding{stage=AccountHashing}: sync::pipeline: Stage unwound stage=AccountHashing unwind_to=6702297 progress=6794867 done=false
2024-11-22T15:08:45.981624Z DEBUG Unwinding{stage=AccountHashing}: storage::db::mdbx: Commit total_duration=6.214179ms commit_latency=Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 0, audit: 0, write: 0, sync: 405, ending: 0, whole: 406, 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=false
2024-11-22T15:08:45.981654Z  INFO Unwinding{stage=AccountHashing}: sync::pipeline: Stage unwound stage=AccountHashing unwind_to=6702297 progress=6702297 done=true
2024-11-22T15:08:45.987606Z DEBUG Unwinding{stage=AccountHashing}: storage::db::mdbx: Commit total_duration=5.921028ms commit_latency=Some(CommitLatency(MDBX_commit_latency { preparation: 0, gc_wallclock: 0, audit: 0, write: 0, sync: 386, ending: 0, whole: 387, 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=false
2024-11-22T15:08:45.987778Z  INFO Unwinding{stage=MerkleUnwind}: sync::pipeline: Starting unwind from=7194871 to=6702297 bad_block=None
2024-11-22T15:08:45.988610Z DEBUG Unwinding{stage=MerkleUnwind}: trie::loader: incremental state root range=6702298..=7194871
2024-11-22T15:26:49.954079Z ERROR Unwinding{stage=MerkleUnwind}: sync::stages::merkle: Failed to verify block state root! 
Invalid state root error on stage verification!
This is an error that likely requires a report to the reth team with additional information.
Please include the following information in your report:
 * This error message
 * The state root of the block that was rejected
 * The output of `reth db stats --checksum` from the database that was being used. This will take a long time to run!
 * 50-100 lines of logs before and after the first occurrence of the log message with the state root of the block that was rejected.
 * The debug logs from __the same time period__. To find the default location for these logs, run:

Since then it restarts and keeps trying to unwind in a loop and fails with

target_block=6702297 got=0xd054a64478e5c953b518e8362193a820951aca16e1ad96ce247cf6eebe6f6ef0 expected=SealedHeader { hash: 0xe000731dd83e0651f5e350897c7645727a3bc4977e2e7a82ea7e8e6f752a7640, header: Header { parent_hash: 0xc7e9cfafbe91c0c8fe5d9e3f105356ffda0f18ee502c019e59e029bf6c7ad194, ommers_hash: 0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347, beneficiary: 0x34d68dffa8cfe02dd9c480b8bfb7c3a9ed3fc24a, state_root: 0xe8c622071d853ea0812fcc221e496e97931c6da63e328b7483f333cafe5fa985, transactions_root: 0x54722b4a2c0b1dcc72c4abe4e7f8a959d5da19b3dbf54d9862cf774d08ad1aba, receipts_root: 0xbd59516505f3bc8c0f352efae24251d89c9d6d9518961d60225d3a4abc962984, withdrawals_root: Some(0x990f81a9f994b6d13a53be8a19d3a7ae05b5274fbf12f26d59d35de1ede7a3b2), logs_bloom: 0xcba26a4238022a000903a2558c4411619fd5883d191422d81ca295d1c88185b81ea9b662b9398c024c4ec3a11879231eb11c101c2e19e05a00102e408a6bb040888c2c40f33ac41be42840fb56042c2a2c4c53dcbbc0399650f93f5ccd89604a693072dd2f6147907a2acb7715307daa14d0981bbd454e4bdad441faa63b91e082f4dd804c5815d1fca3ea742db501448d665411ca40e5b8110752e090fbc281530ede429933c0a5d8568e4c05866a0fe755007325a5f9d808a84749802f58835cc9f64e386e0aa1781596204423ae1b6008e03231d82834472ad09a3082258d045a617682c7ca34b5c7385c893c4090a45e97359b95ede5f4d5790a4eff6c21, difficulty: 0, number: 6702297, gas_limit: 30000000, gas_used: 29947757, timestamp: 1731280580, mix_hash: 0xf964b9d73c807a829c470ae0d2d8cc342efef9673153582149b8ca4b93390029, nonce: 0x0000000000000000, base_fee_per_gas: Some(3608895534), blob_gas_used: Some(0), excess_blob_gas: Some(0), parent_beacon_block_root: Some(0x7f1f26f7d6c46ebcd397ea861d09a3eb9cc06d07e2af013ad89633bb0099716e), requests_hash: None, extra_data: 0x } }

Steps to reproduce

start the chain create a snpshot from archive node restore snapshot chain runs for a few days then erros

Node logs

Platform(s)

Linux (x86)

What version/commit are you on?

reth Version: 1.1.1 Commit SHA: 15c230bac20e2b1b3532c8b0d470e815fbc0cc22

What database version are you on?

reth db --datadir /root/BERA/testnet/.reth version 2024-11-23T00:45:27.788436Z INFO Initialized tracing, debug log directory: /root/.cache/reth/logs/mainnet Current database version: 2 Local database version: 2

Which chain / network are you on?

Berachain Bartio 80084

What type of node are you running?

Full via --full flag

What prune config do you use, if any?

[stages.prune] commit_threshold = 1000000

[stages.account_hashing] clean_threshold = 500000 commit_threshold = 100000

[stages.storage_hashing] clean_threshold = 500000 commit_threshold = 100000

[stages.merkle] clean_threshold = 5000

[stages.transaction_lookup] chunk_size = 5000000

[stages.index_account_history] commit_threshold = 100000

[stages.index_storage_history] commit_threshold = 100000

[stages.etl] file_size = 524288000

[prune] block_interval = 5

[prune.segments.receipts_log_filter]

If you've built Reth from source, provide the full command you used

No response

Code of Conduct

Staking7pc commented 5 days ago

Adding Full Debug logsreth-tr.log