search

paradigmxyz / reth

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

lighthouse - reth stop syncing #10102

Closed allnil closed 2 months ago

allnil commented 2 months ago

Describe the bug

This logs was observed during batch syncing Reth synced with --debug.tip, beacon tries to do batch sync on its side

lighthouse:

beacon-chain-1  | Aug 05 20:28:42.581 DEBG Beacon block rejected                   reason: ExecutionPayloadError(RequestFailed(EngineError(Api { error: ServerMessage { code: -32603, message: "Server error" } }))), service: beacon
beacon-chain-1  | Aug 05 20:28:42.581 DEBG Execution layer verification failed     err: ExecutionPayloadError(RequestFailed(EngineError(Api { error: ServerMessage { code: -32603, message: "Server error" } }))), outcome: pausing sync
beacon-chain-1  | Aug 05 20:28:42.581 DEBG Batch processing failed                 service: sync, error: Execution layer offline. Reason: ExecutionPayloadError(RequestFailed(EngineError(Api { error: ServerMessage { code: -32603, message: "Server error" } }))), imported_blocks: 0, last_block_slot: 2399, chain: 15829411364620742088, first_block_slot: 2368, batch_epoch: 74

also calling eth/v1/node/syncing on lighthouse side

{"data":{"is_syncing":true,"is_optimistic":true,"el_offline":true,"head_slot":"2367","sync_distance":"520"}}%

I use reth v1.0.1 + execution extension I will continue to observe and try something + maybe update with the most recent dev

Steps to reproduce

reth + lighthouse testnet

  1. sync reth with debug.tip
  2. observe lighthouse

Node logs

reth  | 2024-08-05T20:47:46.289466Z  INFO reth::cli: Status connected_peers=1 freelist=147 latest_block=2559
reth  | 2024-08-05T20:47:50.416398Z DEBUG storage::db::mdbx: Commit total_duration=3.954µ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
reth  | 2024-08-05T20:47:55.416368Z DEBUG storage::db::mdbx: Commit total_duration=4.012µ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
reth  | 2024-08-05T20:47:58.278226Z DEBUG net::session: pending session timed out remote_addr=173.234.17.129:30303 direction=Outgoing(0xf3ecf0c3451851a61dc84a3a9963be2bb849589c48c49ba94c2371992616f75cc112b6853681b7a483ef2dd550eadc17aaf469a6c1ea68b9b5f5eb8f8577c4d8)
reth  | 2024-08-05T20:47:58.304432Z DEBUG net::session: pending session timed out remote_addr=103.219.170.93:13304 direction=Outgoing(0x7629aa04bbdae482d227ce72684716631c245baa04d5e0c2f0bd21e1e813e007b06d9a6e7646c69727449313846e79c3ea951119d1c4e1c8b7a111d571e64afc)

Platform(s)

Linux (x86)

What version/commit are you on?

v1.0.1

What database version are you on?

Current database version: 2

Which chain / network are you on?

dev

What type of node are you running?

Archive (default)

What prune config do you use, if any?

default

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

No response

Code of Conduct

Rjected commented 2 months ago

can you add more logs from the reth side?

allnil commented 2 months ago

@Rjected yep:

reth  | 2024-08-05T21:46:56.289107Z  INFO reth::cli: Status connected_peers=1 freelist=147 latest_block=2559
reth  | 2024-08-05T21:46:58.717982Z DEBUG net::session: pending session timed out remote_addr=158.181.80.55:30404 direction=Outgoing(0x3555f7e144d6618036d2b852908e9b757b578a4e9eaf06006138469d7932dc70654105fda4d40c30f63d285d9d484be26894e01df378f01d677cb10e53f4c591)
reth  | 2024-08-05T21:46:59.863551Z DEBUG net::session: pending session timed out remote_addr=54.147.194.99:30312 direction=Outgoing(0xb77271089ac5f3fa205ea40c04e88857e6affac8453e4bcbe861f18fa5733d4dc42eca7bf5f8389218dbdf320663551bf2aebd7c60942a5649faf9b7b57f154b)
reth  | 2024-08-05T21:47:00.416480Z DEBUG storage::db::mdbx: Commit total_duration=4.378µ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
reth  | 2024-08-05T21:47:05.416428Z DEBUG storage::db::mdbx: Commit total_duration=4.587µ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
reth  | 2024-08-05T21:47:10.416385Z DEBUG storage::db::mdbx: Commit total_duration=4.172µ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
reth  | 2024-08-05T21:47:14.397023Z DEBUG net::session: pending session timed out remote_addr=15.206.198.252:20630 direction=Outgoing(0x30dc2b7986e2ec5902498ec26fad6fcecece617aa1652f227f684ede6a0939bb7a205ada1c91420d30b427c86bbdcc31fdfd6d955dd8f5854370f583025a0708)
reth  | 2024-08-05T21:47:14.410320Z DEBUG net::session: pending session timed out remote_addr=65.109.69.183:30303 direction=Outgoing(0xdfa605d08b4a1003be177db6a9d4e0cdf09c32582977a7058d9ddfe4dabd91ddf1ac7dd1873e8ffafc625148b3ddc92760783435eb6a73fd30a1a877ddcffc8b)
reth  | 2024-08-05T21:47:15.416414Z DEBUG storage::db::mdbx: Commit total_duration=3.66µ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
reth  | 2024-08-05T21:47:18.278599Z DEBUG net::session: pending session timed out remote_addr=45.32.131.30:30311 direction=Outgoing(0xda3b08a3990a1f9aa5ee8468bcf0e688f5d4daf5530aa412696d04eec032d34ea243c22a2a5938b760ed5f3790ec9729bce7da200830a4c42c8c0bbcb842c9d1)
reth  | 2024-08-05T21:47:20.416466Z DEBUG storage::db::mdbx: Commit total_duration=3.982µ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
reth  | 2024-08-05T21:47:21.289942Z  INFO reth::cli: Status connected_peers=1 freelist=147 latest_block=2559
reth  | 2024-08-05T21:47:25.416450Z DEBUG storage::db::mdbx: Commit total_duration=4.067µ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
reth  | 2024-08-05T21:47:28.944242Z DEBUG net::session: pending session timed out remote_addr=178.62.114.74:0 direction=Outgoing(0x23cdd878380a598d7e4f68b7e6375399333a119ca3f1f3a649d93d8999e07e537afc44fda972f36ad7c5dd181049f36fa6886a09b2bf4c06589f05301750e818)
reth  | 2024-08-05T21:47:30.416590Z DEBUG storage::db::mdbx: Commit total_duration=3.487µ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
reth  | 2024-08-05T21:47:35.416389Z DEBUG storage::db::mdbx: Commit total_duration=3.868µ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

at the same time beacon:

beacon-chain-1  | Aug 05 21:48:38.499 WARN Execution engine call failed            error: ServerMessage { code: -32603, message: "Server error" }, service: exec
beacon-chain-1  | Aug 05 21:48:38.500 DEBG Execution engine upcheck complete       state: Syncing, service: exec
beacon-chain-1  | Aug 05 21:48:38.501 DEBG Refused to advance head state           current_slot: 5047, head_slot: 2367, service: state_advance
beacon-chain-1  | Aug 05 21:48:38.508 WARN Producing block with no sync contributions, slot: 5024, service: beacon
beacon-chain-1  | Aug 05 21:48:38.541 WARN Execution engine call failed            error: ServerMessage { code: -32603, message: "Server error" }, service: exec
beacon-chain-1  | Aug 05 21:48:38.541 WARN Error whilst processing payload status  error: Api { error: ServerMessage { code: -32603, message: "Server error" } }, service: exec
beacon-chain-1  | Aug 05 21:48:38.541 DEBG Beacon block rejected                   reason: ExecutionPayloadError(RequestFailed(EngineError(Api { error: ServerMessage { code: -32603, message: "Server error" } }))), service: beacon
beacon-chain-1  | Aug 05 21:48:38.542 DEBG Execution layer verification failed     err: ExecutionPayloadError(RequestFailed(EngineError(Api { error: ServerMessage { code: -32603, message: "Server error" } }))), outcome: pausing sync
beacon-chain-1  | Aug 05 21:48:38.542 DEBG Batch processing failed                 service: sync, error: Execution layer offline. Reason: ExecutionPayloadError(RequestFailed(EngineError(Api { error: ServerMessage { code: -32603, message: "Server error" } }))), imported_blocks: 0, last_block_slot: 2399, chain: 3539736379911949609, first_block_slot: 2368, batch_epoch: 74
beacon-chain-1  | Aug 05 21:48:38.542 DEBG Batch processing result                 client: Lighthouse: version: v5.2.1-9e12c21, os_version: x86_64-linux, batch_epoch: 74, start_slot: 2368, end_slot: 2399, downloaded: 0, processed: 0, processed_no_penalty: 255, state: Processing(16Uiu2HAmA9Fd5wtVVeyoke41U9P8fqyT8aUpwzd48tjoydd4Mhdr), batch_ty: blocks_and_blobs, result: NonFaultyFailure, chain: 3539736379911949609, service: range_sync, service: sync
beacon-chain-1  | Aug 05 21:48:38.542 DEBG Sending BlobsByRange requests           peer: 16Uiu2HAmA9Fd5wtVVeyoke41U9P8fqyT8aUpwzd48tjoydd4Mhdr, count: 32, method: BlobsByRange, service: sync
beacon-chain-1  | Aug 05 21:48:38.542 DEBG Requesting batch                        start_slot: 2368, end_slot: 2399, downloaded: 0, processed: 0, processed_no_penalty: 255, state: Downloading(16Uiu2HAmA9Fd5wtVVeyoke41U9P8fqyT8aUpwzd48tjoydd4Mhdr, 0 blocks, 96998), batch_ty: blocks_and_blobs, epoch: 74, chain: 3539736379911949609, service: range_sync, service: syncbeacon-chain-1  | Aug 05 21:48:38.543 DEBG Execution engine upcheck complete       state: Syncing, service: exec
beacon-chain-1  | Aug 05 21:48:38.557 DEBG Completed batch received                awaiting_batches: 0, blocks: 16, epoch: 74, chain: 3539736379911949609, service: range_sync, service: sync
beacon-chain-1  | Aug 05 21:48:38.558 DEBG Parent state is not advanced            state_slot: 2367, block_slot: 2368, service: beacon
beacon-chain-1  | Aug 05 21:48:38.665 WARN Execution engine call failed            error: ServerMessage { code: -32603, message: "Server error" }, service: exec
beacon-chain-1  | Aug 05 21:48:38.666 WARN Error whilst processing payload status  error: Api { error: ServerMessage { code: -32603, message: "Server error" } }, service: exec
beacon-chain-1  | Aug 05 21:48:38.666 DEBG Beacon block rejected                   reason: ExecutionPayloadError(RequestFailed(EngineError(Api { error: ServerMessage { code: -32603, message: "Server error" } }))), service: beacon
beacon-chain-1  | Aug 05 21:48:38.666 DEBG Execution layer verification failed     err: ExecutionPayloadError(RequestFailed(EngineError(Api { error: ServerMessage { code: -32603, message: "Server error" } }))), outcome: pausing sync
beacon-chain-1  | Aug 05 21:48:38.667 DEBG Batch processing failed                 service: sync, error: Execution layer offline. Reason: ExecutionPayloadError(RequestFailed(EngineError(Api { error: ServerMessage { code: -32603, message: "Server error" } }))), imported_blocks: 0, last_block_slot: 2399, chain: 3539736379911949609, first_block_slot: 2368, batch_epoch: 74
beacon-chain-1  | Aug 05 21:48:38.667 DEBG Batch processing result                 client: Lighthouse: version: v5.2.1-9e12c21, os_version: x86_64-linux, batch_epoch: 74, start_slot: 2368, end_slot: 2399, downloaded: 0, processed: 0, processed_no_penalty: 255, state: Processing(16Uiu2HAmA9Fd5wtVVeyoke41U9P8fqyT8aUpwzd48tjoydd4Mhdr), batch_ty: blocks_and_blobs, result: NonFaultyFailure, chain: 3539736379911949609, service: range_sync, service: sync
beacon-chain-1  | Aug 05 21:48:38.667 DEBG Sending BlobsByRange requests           peer: 16Uiu2HAmA9Fd5wtVVeyoke41U9P8fqyT8aUpwzd48tjoydd4Mhdr, count: 32, method: BlobsByRange, service: sync
beacon-chain-1  | Aug 05 21:48:38.667 DEBG Requesting batch                        start_slot: 2368, end_slot: 2399, downloaded: 0, processed: 0, processed_no_penalty: 255, state: Downloading(16Uiu2HAmA9Fd5wtVVeyoke41U9P8fqyT8aUpwzd48tjoydd4Mhdr, 0 blocks, 96999), batch_ty: blocks_and_blobs, epoch: 74, chain: 3539736379911949609, service: range_sync, service: syncbeacon-chain-1  | Aug 05 21:48:38.667 DEBG Execution engine upcheck complete       state: Syncing, service: exec
beacon-chain-1  | Aug 05 21:48:38.682 DEBG Completed batch received                awaiting_batches: 0, blocks: 16, epoch: 74, chain: 3539736379911949609, service: range_sync, service: sync
beacon-chain-1  | Aug 05 21:48:38.683 DEBG Parent state is not advanced            state_slot: 2367, block_slot: 2368, service: beacon
allnil commented 2 months ago

from the reth side these logs just repeating over and over and if I will restart the node with new tip it will progress

allnil commented 2 months ago

I figured it out Guess that the number of validators in testnet was not sufficient for PoS setup adding 128 validators resolved all issues