search

paradigmxyz / reth

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

TransactionLookup stage hanging #7272

Closed Scott-Sanderson closed 4 months ago

Scott-Sanderson commented 5 months ago

Describe the bug

Database sync is stalled at progress=none on TransactionLookup. ForkChoice messages are stopped and the validator reports the EL is offline (reth is paired with my backup beacon node).

Steps to reproduce

This node performed sync to stage 4 on the beta1 and hung. I upgraded to beta3, the sync started progressing again, with ForkChoice messages, until it hung here on TransactionLookup. The message "local database is uninitialized" is there when I run reth db version smaller_truncated_reth_upload.log

Running: Fedora Server 38 Lighthouse v5.1.0 reth 0.2.0-beta.3 mev-boost 1.7

Node logs

I am attaching my log

Platform(s)

Linux (x86)

What version/commit are you on?

0.2.0-beta.3

What database version are you on?

Current database version: 2 Local database is uninitialized

What type of node are you running?

Full via --full flag

What prune config do you use, if any?

No response

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

No response

Code of Conduct

victorelec14 commented 5 months ago

I have the same problem, I also updated from v0.2.0-beta.1 to Beta.2 and Beta.3.

It takes just over an hour and does not increase progress, it show "stage_progress=None"

execution-1  | 2024-03-23T12:54:20.634938Z  INFO Stage committed progress pipeline_stages=8/12 stage=MerkleExecute checkpoint=0 target=19420672 stage_progress=99.97% stage_eta=1s
execution-1  | 2024-03-23T12:54:20.649068Z  INFO Preparing stage pipeline_stages=8/12 stage=MerkleExecute checkpoint=0 target=19420672
execution-1  | 2024-03-23T12:54:20.649148Z  INFO Executing stage pipeline_stages=8/12 stage=MerkleExecute checkpoint=0 target=19420672 stage_eta=1s
execution-1  | 2024-03-23T12:54:21.886772Z  INFO Status connected_peers=100 freelist=16 stage=MerkleExecute checkpoint=0 target=19420672 stage_progress=99.97% stage_eta=unknown
execution-1  | 2024-03-23T12:54:22.141560Z  INFO Stage finished executing pipeline_stages=8/12 stage=MerkleExecute checkpoint=19420672 target=19420672 stage_progress=100.00% stage_eta=unknown
execution-1  | 2024-03-23T12:54:22.147073Z  INFO Preparing stage pipeline_stages=9/12 stage=TransactionLookup checkpoint=0 target=19420672
execution-1  | 2024-03-23T12:54:22.147098Z  INFO Executing stage pipeline_stages=9/12 stage=TransactionLookup checkpoint=0 target=19420672
execution-1  | 2024-03-23T12:54:46.894244Z  INFO Status connected_peers=100 freelist=20 stage=TransactionLookup checkpoint=0 target=19420672 stage_progress=None
execution-1  | 2024-03-23T12:55:11.886978Z  INFO Status connected_peers=100 freelist=20 stage=TransactionLookup checkpoint=0 target=19420672 stage_progress=None
execution-1  | 2024-03-23T12:55:36.887023Z  INFO Status connected_peers=100 freelist=20 stage=TransactionLookup checkpoint=0 target=19420672 stage_progress=None
execution-1  | 2024-03-23T12:56:01.887459Z  INFO Status connected_peers=100 freelist=20 stage=TransactionLookup checkpoint=0 target=19420672 stage_progress=None
execution-1  | 2024-03-23T12:56:26.890707Z  INFO Status connected_peers=100 freelist=20 stage=TransactionLookup checkpoint=0 target=19420672 stage_progress=None
execution-1  | 2024-03-23T12:56:51.893334Z  INFO Status connected_peers=100 freelist=20 stage=TransactionLookup checkpoint=0 target=19420672 stage_progress=None
execution-1  | 2024-03-23T12:57:16.893971Z  INFO Status connected_peers=100 freelist=20 stage=TransactionLookup checkpoint=0 target=19420672 stage_progress=None
execution-1  | 2024-03-23T12:57:41.894015Z  INFO Status connected_peers=100 freelist=20 stage=TransactionLookup checkpoint=0 target=19420672 stage_progress=None
execution-1  | 2024-03-23T12:58:06.897571Z  INFO Status connected_peers=100 freelist=20 stage=TransactionLookup checkpoint=0 target=19420672 stage_progress=None
execution-1  | 2024-03-23T12:58:31.894197Z  INFO Status connected_peers=100 freelist=20 stage=TransactionLookup checkpoint=0 target=19420672 stage_progress=None
execution-1  | 2024-03-23T12:58:56.894396Z  INFO Status connected_peers=100 freelist=20 stage=TransactionLookup checkpoint=0 target=19420672 stage_progress=None
execution-1  | 2024-03-23T12:59:21.894734Z  INFO Status connected_peers=100 freelist=20 stage=TransactionLookup checkpoint=0 target=19420672 stage_progress=None
execution-1  | 2024-03-23T12:59:46.893849Z  INFO Status connected_peers=100 freelist=20 stage=TransactionLookup checkpoint=0 target=19420672 stage_progress=None
execution-1  | 2024-03-23T13:00:11.894551Z  INFO Status connected_peers=100 freelist=20 stage=TransactionLookup checkpoint=0 target=19420672 stage_progress=None
execution-1  | 2024-03-23T13:00:36.893888Z  INFO Status connected_peers=100 freelist=20 stage=TransactionLookup checkpoint=0 target=19420672 stage_progress=None
execution-1  | 2024-03-23T13:01:01.895248Z  INFO Status connected_peers=100 freelist=20 stage=TransactionLookup checkpoint=0 target=19420672 stage_progress=None
execution-1  | 2024-03-23T13:01:26.893887Z  INFO Status connected_peers=100 freelist=20 stage=TransactionLookup checkpoint=0 target=19420672 stage_progress=None
execution-1  | 2024-03-23T13:01:51.896120Z  INFO Status connected_peers=100 freelist=20 stage=TransactionLookup checkpoint=0 target=19420672 stage_progress=None
execution-1  | 2024-03-23T13:02:16.893682Z  INFO Status connected_peers=100 freelist=20 stage=TransactionLookup checkpoint=0 target=19420672 stage_progress=None
execution-1  | 2024-03-23T13:02:41.894532Z  INFO Status connected_peers=100 freelist=20 stage=TransactionLookup checkpoint=0 target=19420672 stage_progress=None

.
.
.
.
.
execution-1  | 2024-03-23T14:13:07.866548Z  INFO Status connected_peers=100 freelist=20 stage=TransactionLookup checkpoint=0 target=19420672 stage_progress=None
execution-1  | 2024-03-23T14:13:32.867939Z  INFO Status connected_peers=100 freelist=20 stage=TransactionLookup checkpoint=0 target=19420672 stage_progress=None
execution-1  | 2024-03-23T14:13:57.870988Z  INFO Status connected_peers=100 freelist=20 stage=TransactionLookup checkpoint=0 target=19420672 stage_progress=None
execution-1  | 2024-03-23T14:14:22.871637Z  INFO Status connected_peers=100 freelist=20 stage=TransactionLookup checkpoint=0 target=19420672 stage_progress=None

Thanks

ghost commented 5 months ago

@Scott-Sanderson Can you truncate the content of the log files and modify your post with the log content. Since people will be skeptical to open attached files, and it's just text, so let's post it here or to gist.github.com

Scott-Sanderson commented 5 months ago

I would be happy to provide truncated logs but I do not know what part of the log to snip. The client has been stalled out since I opened this issue last week. The logs now just looks like this repeating, does that help?

Mar 26 08:14:19 high reth[57442]: 2024-03-26T14:14:19.931792Z INFO Status connected_peers=45 freelist=20 stage=TransactionLookup checkpoint=0 target=19463820 stage_progress=None Mar 26 08:14:19 high reth[57442]: Status Mar 26 08:14:44 high reth[57442]: 2024-03-26T14:14:44.932335Z INFO Status connected_peers=45 freelist=20 stage=TransactionLookup checkpoint=0 target=19463820 stage_progress=None Mar 26 08:14:44 high reth[57442]: Status Mar 26 08:15:09 high reth[57442]: 2024-03-26T14:15:09.931679Z INFO Status connected_peers=45 freelist=20 stage=TransactionLookup checkpoint=0 target=19463820 stage_progress=None Mar 26 08:15:09 high reth[57442]: Status Mar 26 08:15:34 high reth[57442]: 2024-03-26T14:15:34.932432Z INFO Status connected_peers=45 freelist=20 stage=TransactionLookup checkpoint=0 target=19463820 stage_progress=None Mar 26 08:15:34 high reth[57442]: Status Mar 26 08:15:59 high reth[57442]: 2024-03-26T14:15:59.932582Z INFO Status connected_peers=45 freelist=20 stage=TransactionLookup checkpoint=0 target=19463820 stage_progress=None Mar 26 08:15:59 high reth[57442]: Status Mar 26 08:16:24 high reth[57442]: 2024-03-26T14:16:24.931952Z INFO Status connected_peers=45 freelist=20 stage=TransactionLookup checkpoint=0 target=19463820 stage_progress=None Mar 26 08:16:24 high reth[57442]: Status Mar 26 08:16:49 high reth[57442]: 2024-03-26T14:16:49.932119Z INFO Status connected_peers=45 freelist=20 stage=TransactionLookup checkpoint=0 target=19463820 stage_progress=None Mar 26 08:16:49 high reth[57442]: Status Mar 26 08:17:14 high reth[57442]: 2024-03-26T14:17:14.932251Z INFO Status connected_peers=45 freelist=20 stage=TransactionLookup checkpoint=0 target=19463820 stage_progress=None Mar 26 08:17:14 high reth[57442]: Status Mar 26 08:17:39 high reth[57442]: 2024-03-26T14:17:39.932333Z INFO Status connected_peers=45 freelist=20 stage=TransactionLookup checkpoint=0 target=19463820 stage_progress=None Mar 26 08:17:39 high reth[57442]: Status Mar 26 08:18:04 high reth[57442]: 2024-03-26T14:18:04.932577Z INFO Status connected_peers=45 freelist=20 stage=TransactionLookup checkpoint=0 target=19463820 stage_progress=None Mar 26 08:18:04 high reth[57442]: Status Mar 26 08:18:29 high reth[57442]: 2024-03-26T14:18:29.931854Z INFO Status connected_peers=45 freelist=20 stage=TransactionLookup checkpoint=0 target=19463820 stage_progress=None Mar 26 08:18:29 high reth[57442]: Status Mar 26 08:18:54 high reth[57442]: 2024-03-26T14:18:54.931761Z INFO Status connected_peers=45 freelist=20 stage=TransactionLookup checkpoint=0 target=19463820 stage_progress=None Mar 26 08:18:54 high reth[57442]: Status Mar 26 08:19:19 high reth[57442]: 2024-03-26T14:19:19.932507Z INFO Status connected_peers=45 freelist=20 stage=TransactionLookup checkpoint=0 target=19463820 stage_progress=None Mar 26 08:19:19 high reth[57442]: Status Mar 26 08:19:44 high reth[57442]: 2024-03-26T14:19:44.932286Z INFO Status connected_peers=45 freelist=20 stage=TransactionLookup checkpoint=0 target=19463820 stage_progress=None Mar 26 08:19:44 high reth[57442]: Status M

jonathanykh commented 5 months ago

Hey, I have the same issue at 0.2.0-beta 3, it seems that the stage is stuck and nothing gets done after calculating transaction hashes is completed (I do not know how many transactions in total in Ethereum mainnet, therefore actually not sure if all transaction hashes have been calculated).

Here are my logs captured at the end of calculating transaction hashes:

2024-03-27T03:46:28.448535Z DEBUG sync::stages::transaction_lookup: Calculating transaction hashes tx_range=1765037468..1770037571
2024-03-27T03:46:39.257282Z DEBUG net::session: failed to receive message err=disconnected remote_peer_id=0xcfbb1b82c46ea98a6fd96b33bdf1038ba72b8e891fc2a2ce818110805925130db13471b0f3207a8ec36a4b853bec98ac77eac0baa955f030934fb2a45e76f853
2024-03-27T03:46:43.821987Z DEBUG net::session: failed to receive message err=disconnected remote_peer_id=0xdf7ac5ee488b74924bdb861350f174764014ded895332e61d7d8f7672d5b8421e73549bb9b71f0ec2509d179eceac9f5673cb3f69bc5ae2008da3633b17b22bd
2024-03-27T03:46:45.351189Z DEBUG sync::stages::transaction_lookup: Calculating transaction hashes tx_range=1770037571..1775037633
2024-03-27T03:46:48.324056Z DEBUG net::session: failed to receive message err=disconnected remote_peer_id=0x25b663f4199eee2490ff82110fce5fc2051d3808a18bb79e7ee410bdddca18e67bfb5710ddebb8469a36fa6867d374c0c0f89aa40ba2ff311a3e87ee9fe6b827
2024-03-27T03:46:50.755818Z  INFO reth::cli: Status connected_peers=30 freelist=6202 stage=TransactionLookup checkpoint=0 target=19426523 stage_progress=None
2024-03-27T03:46:54.325325Z DEBUG net::session: failed to receive message err=disconnected remote_peer_id=0xc77217ce8abd85ae54e778835cf68cd0289bbeee30cdb32d516be5fd7571adbc72503eec06fc7e555e0929ddf0d0d06772bf9ff0abc326cafdc1e6a0945e900c
2024-03-27T03:46:54.813906Z DEBUG sync::stages::transaction_lookup: Calculating transaction hashes tx_range=1775037633..1780037648
2024-03-27T03:47:04.108371Z DEBUG sync::stages::transaction_lookup: Calculating transaction hashes tx_range=1780037648..1785037666
2024-03-27T03:47:09.149491Z DEBUG net::session: failed to receive message err=disconnected remote_peer_id=0x1cf7db662897dcd2af946fdd47e5b6d8273846e6a6bef4f1f3ec1f2b38c77c6a2382fb9409e43681c15cc043298d9476f2faa14c1adb805c15559e616ff4c361
2024-03-27T03:47:15.756289Z  INFO reth::cli: Status connected_peers=29 freelist=6202 stage=TransactionLookup checkpoint=0 target=19426523 stage_progress=None
2024-03-27T03:47:16.839189Z DEBUG net::session: failed to receive message err=disconnected remote_peer_id=0xfea359e2843059d4f99bb09da45400a6b3f145e80218a1769b86c31362269795cccb1981e87733e45ce4300af01ec524ba28344df293823a262f6add3cfa7af7
2024-03-27T03:47:22.414535Z DEBUG net::session: failed to receive message err=disconnected remote_peer_id=0x02f7dc8b8b5b49fd56e6100eeb10391d58e405639e38194d199b77a5f70b7bf5c3ddfd76af6dfa4dc7dfce3fa21d96f631199ee70795aa3113d5c349de68335d
2024-03-27T03:47:31.688840Z DEBUG net::session: failed to receive message err=disconnected remote_peer_id=0xdf7ac5ee488b74924bdb861350f174764014ded895332e61d7d8f7672d5b8421e73549bb9b71f0ec2509d179eceac9f5673cb3f69bc5ae2008da3633b17b22bd
2024-03-27T03:47:40.762456Z  INFO reth::cli: Status connected_peers=28 freelist=6202 stage=TransactionLookup checkpoint=0 target=19426523 stage_progress=None
2024-03-27T03:47:58.556377Z DEBUG net::session: failed to receive message err=disconnected remote_peer_id=0x1cf7db662897dcd2af946fdd47e5b6d8273846e6a6bef4f1f3ec1f2b38c77c6a2382fb9409e43681c15cc043298d9476f2faa14c1adb805c15559e616ff4c361
2024-03-27T03:48:02.424149Z DEBUG igd_next::aio::tokio: sending broadcast request to: 239.255.255.250:1900 on interface: Ok(0.0.0.0:35081)    
2024-03-27T03:48:05.762904Z  INFO reth::cli: Status connected_peers=29 freelist=6202 stage=TransactionLookup checkpoint=0 target=19426523 stage_progress=None
2024-03-27T03:48:12.426832Z DEBUG net::nat: Failed to resolve external IP via UPnP: failed to find gateway err=IO error: search timed out
2024-03-27T03:48:30.329529Z DEBUG net::session: failed to receive message err=disconnected remote_peer_id=0xdf7ac5ee488b74924bdb861350f174764014ded895332e61d7d8f7672d5b8421e73549bb9b71f0ec2509d179eceac9f5673cb3f69bc5ae2008da3633b17b22bd
2024-03-27T03:48:30.762964Z  INFO reth::cli: Status connected_peers=29 freelist=6202 stage=TransactionLookup checkpoint=0 target=19426523 stage_progress=None
2024-03-27T03:48:44.389554Z DEBUG net::session: failed to receive message err=disconnected remote_peer_id=0x1cf7db662897dcd2af946fdd47e5b6d8273846e6a6bef4f1f3ec1f2b38c77c6a2382fb9409e43681c15cc043298d9476f2faa14c1adb805c15559e616ff4c361
2024-03-27T03:48:46.092315Z DEBUG net::session: eth stream completed remote_peer_id=0x48f462dab313723e05fee35df8172a7d369c42a42d1113a31f880c478884e8ce3f3173818868cdd9398c6e5bbf2c1d0ccb969a6946275905372c18caf6db0599
2024-03-27T03:48:55.762794Z  INFO reth::cli: Status connected_peers=29 freelist=6202 stage=TransactionLookup checkpoint=0 target=19426523 stage_progress=None
2024-03-27T03:49:13.058189Z DEBUG net::session: failed to receive message err=disconnected remote_peer_id=0x91286039f8810f34cabacad863fdd978b8e71adfc4de98a255246b05ef4584495d39541bc83d62296bd355970145596b38927657a9e3b1ce2b1d17e0b8e6ccd9
2024-03-27T03:49:13.542091Z DEBUG net::session: failed to receive message err=disconnected remote_peer_id=0xdf7ac5ee488b74924bdb861350f174764014ded895332e61d7d8f7672d5b8421e73549bb9b71f0ec2509d179eceac9f5673cb3f69bc5ae2008da3633b17b22bd
2024-03-27T03:49:16.096160Z DEBUG net::session: eth stream completed remote_peer_id=0x48f462dab313723e05fee35df8172a7d369c42a42d1113a31f880c478884e8ce3f3173818868cdd9398c6e5bbf2c1d0ccb969a6946275905372c18caf6db0599
2024-03-27T03:49:20.762776Z  INFO reth::cli: Status connected_peers=29 freelist=6202 stage=TransactionLookup checkpoint=0 target=19426523 stage_progress=None
2024-03-27T03:49:23.156096Z DEBUG net::session: failed to receive message err=disconnected remote_peer_id=0x1cf7db662897dcd2af946fdd47e5b6d8273846e6a6bef4f1f3ec1f2b38c77c6a2382fb9409e43681c15cc043298d9476f2faa14c1adb805c15559e616ff4c361
2024-03-27T03:49:39.511660Z DEBUG net::session: eth stream completed remote_peer_id=0x812fc1180f5532fb0550ef307a1a902dd24b3674f00bd8d06bfa2ec8c4348da220ab3b44f6432ffa7b08d16888672cdabce70a835df67b5bf04715ea3c2b4089
2024-03-27T03:49:45.048798Z DEBUG net::session: failed to receive message err=disconnected remote_peer_id=0xfea359e2843059d4f99bb09da45400a6b3f145e80218a1769b86c31362269795cccb1981e87733e45ce4300af01ec524ba28344df293823a262f6add3cfa7af7
2024-03-27T03:49:45.763656Z  INFO reth::cli: Status connected_peers=29 freelist=6202 stage=TransactionLookup checkpoint=0 target=19426523 stage_progress=None

Regarding reth db version It shows that:

Current database version: 2
Local database version: 2

I also tried reth stage drop tx-lookup and reth stage drop merkle, which it syncs the merkle stage again but still stuck at TransactionsLookup.

I am now upgrading to 0.2.0-beta 4 to see if it still happens, will provide update later.

update: the issue is still here despite upgrading to beta 4

victorelec14 commented 5 months ago

The problem continues in 0.2.0-beta 4 for me.

Should I eliminate the Bodies and headers? or the entire db?

docker compose exec execution reth stage drop tx-lookup


Error: failed to open the database: no matching key/data pair found (-30798)

Location: crates/storage/db/src/lib.rs:160:9

Scott-Sanderson commented 5 months ago

Turns out I wasn't passing my --data-dir on the reth db version command and it was looking in the default dir. With the correct --datadir, I get Current database version: 2 Local database version: 2

Scott-Sanderson commented 5 months ago

I still have the problem in beta4 so dropped the DB and trying a fresh sync now.

RomulusERC commented 5 months ago

I too have this issue. The lovely folk in Telegram asked to post trace logs from net::session, so here they are. Reth Version: 0.2.0-beta.4 Lighthouse version: v5.1.2-5ce1619

reth.log

mattsse commented 5 months ago

it could be that default chunk size is too large resulting in progress reporting being unhelpful.

you could try decreasing this value in reth.toml in the datadir directory, and see if updates are more frequent and to rule out other issues

[stages.transaction_lookup]
chunk_size = 5000000

nvm this currently does to solve the issue

jonathanykh commented 5 months ago

hey guys, wanted to report that for my beta 4 syncing reth node, the TransactionLookup stage stopped hanging and I am past this stage now after I realize I haven't upgraded my lighthouse to a 4844 compliant version (pretty dumb i know...)

note that, my backfill sync target block is 19426523, which is a bit before 4844 goes live.

so what i would suggest to people having the same problem is to check if your consensus client is the latest version, if not upgrade it and restart reth to see if it syncs through the tx lookup stage now.

now the question is, does during TransactionLookup stage execution client must need to communicate consensus client in this stage, and if the consensus client is stalled due to it being a pre-4844 version it cause reth sync also hangs?

victorelec14 commented 5 months ago

I tried to do a new sync and now I have a restart loop and frozen at "checkpoint=2371510"

Lighthouse/v5.1.3-3058b96
Reth Version: 0.2.0-beta.4 (c04dbe6)

image

execution-1  | JWT secret was supplied in .env
execution-1  | 2024-03-31T19:53:01.639731Z  INFO Starting reth version="0.2.0-beta.4 (c04dbe6)"
execution-1  | 2024-03-31T19:53:01.640907Z  INFO Opening database path="/var/lib/reth/db"
execution-1  | 2024-03-31T19:53:01.667803Z  INFO Configuration loaded path="/var/lib/reth/reth.toml"
execution-1  | 2024-03-31T19:53:01.690588Z  INFO Database opened
execution-1  | 2024-03-31T19:53:01.690619Z  INFO Starting metrics endpoint addr=0.0.0.0:6060
execution-1  | 2024-03-31T19:53:01.693267Z  INFO 
execution-1  | Pre-merge hard forks (block based):
execution-1  | - Frontier                         @0
execution-1  | - Homestead                        @1150000
execution-1  | - Dao                              @1920000
execution-1  | - Tangerine                        @2463000
execution-1  | - SpuriousDragon                   @2675000
execution-1  | - Byzantium                        @4370000
execution-1  | - Constantinople                   @7280000
execution-1  | - Petersburg                       @7280000
execution-1  | - Istanbul                         @9069000
execution-1  | - MuirGlacier                      @9200000
execution-1  | - Berlin                           @12244000
execution-1  | - London                           @12965000
execution-1  | - ArrowGlacier                     @13773000
execution-1  | - GrayGlacier                      @15050000
execution-1  | Merge hard forks:
execution-1  | - Paris                            @58750000000000000000000 (network is known to be merged)
execution-1  | Post-merge hard forks (timestamp based):
execution-1  | - Shanghai                         @1681338455
execution-1  | - Cancun                           @1710338135
execution-1  | 2024-03-31T19:53:01.788439Z  INFO Transaction pool initialized
execution-1  | 2024-03-31T19:53:01.789186Z  INFO Connecting to P2P network
execution-1  | 2024-03-31T19:53:01.790396Z  INFO Loading saved peers file=/var/lib/reth/known-peers.json
execution-1  | 2024-03-31T19:53:01.803175Z  INFO StaticFileProducer initialized
execution-1  | 2024-03-31T19:53:01.804731Z  INFO Pruner initialized prune_config=PruneConfig { block_interval: 5, segments: PruneModes { sender_recovery: Some(Full), transaction_lookup: None, receipts: Some(Before(11052984)), account_history: Some(Distance(10064)), storage_history: Some(Distance(10064)), receipts_log_filter: ReceiptsLogPruneConfig({0x00000000219ab540356cbb839cbe05303d7705fa: Before(11052984)}) } }
execution-1  | 2024-03-31T19:53:01.804889Z  INFO Consensus engine initialized
execution-1  | 2024-03-31T19:53:01.804935Z  INFO Engine API handler initialized
execution-1  | 2024-03-31T19:53:01.809883Z  INFO RPC auth server started url=0.0.0.0:8551
execution-1  | 2024-03-31T19:53:01.810332Z  INFO RPC IPC server started url=/tmp/reth.ipc
execution-1  | 2024-03-31T19:53:01.810426Z  INFO RPC HTTP server started url=0.0.0.0:8545
execution-1  | 2024-03-31T19:53:01.810466Z  INFO RPC WS server started url=0.0.0.0:8546
execution-1  | 2024-03-31T19:53:01.810521Z  INFO Starting consensus engine
execution-1  | 2024-03-31T19:53:01.811284Z  INFO Static File Producer started targets=StaticFileTargets { headers: None, receipts: None, transactions: None }
execution-1  | 2024-03-31T19:53:01.811707Z  INFO Static File Producer finished targets=StaticFileTargets { headers: None, receipts: None, transactions: None } elapsed=239.622µs
execution-1  | 2024-03-31T19:53:01.811801Z  INFO Target block already reached checkpoint=19538697 target=Hash(0x9bb799784fa413e1ac389a5775f65590ee82952744e20c4d96e72d309ada13e8)
execution-1  | 2024-03-31T19:53:01.812007Z  INFO Preparing stage pipeline_stages=1/12 stage=Headers checkpoint=19538697 target=None
execution-1  | 2024-03-31T19:53:01.812190Z  INFO Executing stage pipeline_stages=1/12 stage=Headers checkpoint=19538697 target=None
execution-1  | 2024-03-31T19:53:01.812612Z  INFO Stage finished executing pipeline_stages=1/12 stage=Headers checkpoint=19538697 target=None stage_progress=100.00%
execution-1  | 2024-03-31T19:53:01.812952Z  INFO Preparing stage pipeline_stages=2/12 stage=Bodies checkpoint=19538697 target=19538697
execution-1  | 2024-03-31T19:53:01.813112Z  INFO Executing stage pipeline_stages=2/12 stage=Bodies checkpoint=19538697 target=19538697
execution-1  | 2024-03-31T19:53:01.813246Z  INFO Stage finished executing pipeline_stages=2/12 stage=Bodies checkpoint=19538697 target=19538697 stage_progress=100.00%
execution-1  | 2024-03-31T19:53:01.813376Z  INFO Preparing stage pipeline_stages=3/12 stage=SenderRecovery checkpoint=19538697 target=19538697
execution-1  | 2024-03-31T19:53:01.813499Z  INFO Executing stage pipeline_stages=3/12 stage=SenderRecovery checkpoint=19538697 target=19538697
execution-1  | 2024-03-31T19:53:01.813635Z  INFO Stage finished executing pipeline_stages=3/12 stage=SenderRecovery checkpoint=19538697 target=19538697 stage_progress=100.00%
execution-1  | 2024-03-31T19:53:01.813758Z  INFO Preparing stage pipeline_stages=4/12 stage=Execution checkpoint=2371510 target=19538697
execution-1  | 2024-03-31T19:53:01.813887Z  INFO Executing stage pipeline_stages=4/12 stage=Execution checkpoint=2371510 target=19538697
execution-1  | 2024-03-31T19:53:04.808249Z  INFO Status connected_peers=0 freelist=24136 stage=Execution checkpoint=2371510 target=19538697
execution-1  | 2024-03-31T19:53:29.806004Z  INFO Status connected_peers=3 freelist=24136 stage=Execution checkpoint=2371510 target=19538697
execution-1  | 2024-03-31T19:53:54.806055Z  INFO Status connected_peers=2 freelist=24136 stage=Execution checkpoint=2371510 target=19538697
execution-1  | 2024-03-31T19:54:17.722436Z  INFO Received forkchoice updated message when syncing head_block_hash=0x7266c01c5baa2a59999ec7a38c353ecff9c3d8c3a92373fed5041770164822c8 safe_block_hash=0x0d2bb4c01682409f976119922f83880f6002d58f05b4504094997974aa73fdab finalized_block_hash=0x4ab44a268814b95bdde2b53152df2e2012dd0c4e1473316f4c1e12bcf5320588
execution-1  | 2024-03-31T19:54:19.810954Z  INFO Status connected_peers=2 freelist=24136 stage=Execution checkpoint=2371510 target=19538697
execution-1  | 2024-03-31T19:54:44.808300Z  INFO Status connected_peers=2 freelist=24136 stage=Execution checkpoint=2371510 target=19538697
execution-1  | 2024-03-31T19:55:09.805777Z  INFO Status connected_peers=2 freelist=24136 stage=Execution checkpoint=2371510 target=19538697
execution-1  | 2024-03-31T19:55:34.806622Z  INFO Status connected_peers=3 freelist=24136 stage=Execution checkpoint=2371510 target=19538697
execution-1  | 2024-03-31T19:55:59.805957Z  INFO Status connected_peers=4 freelist=24136 stage=Execution checkpoint=2371510 target=19538697
execution-1  | 2024-03-31T19:56:24.805924Z  INFO Status connected_peers=4 freelist=24136 stage=Execution checkpoint=2371510 target=19538697
execution-1  | 2024-03-31T19:56:49.805800Z  INFO Status connected_peers=4 freelist=24136 stage=Execution checkpoint=2371510 target=19538697
execution-1  | 2024-03-31T19:57:14.806584Z  INFO Status connected_peers=5 freelist=24136 stage=Execution checkpoint=2371510 target=19538697
execution-1  | 2024-03-31T19:57:39.816961Z  INFO Status connected_peers=5 freelist=24136 stage=Execution checkpoint=2371510 target=19538697
execution-1  | 2024-03-31T19:58:04.810048Z  INFO Status connected_peers=4 freelist=24136 stage=Execution checkpoint=2371510 target=19538697
execution-1  | 2024-03-31T19:58:29.806174Z  INFO Status connected_peers=4 freelist=24136 stage=Execution checkpoint=2371510 target=19538697
execution-1  | 2024-03-31T19:58:54.806293Z  INFO Status connected_peers=6 freelist=24136 stage=Execution checkpoint=2371510 target=19538697
execution-1  | 2024-03-31T19:59:19.806265Z  INFO Status connected_peers=7 freelist=24136 stage=Execution checkpoint=2371510 target=19538697
execution-1  | 2024-03-31T19:59:44.807347Z  INFO Status connected_peers=6 freelist=24136 stage=Execution checkpoint=2371510 target=19538697
execution-1  | 2024-03-31T20:00:09.828218Z  INFO Status connected_peers=7 freelist=24136 stage=Execution checkpoint=2371510 target=19538697
execution-1  | JWT secret was supplied in .env
execution-1  | 2024-03-31T20:00:16.895262Z  INFO Starting reth version="0.2.0-beta.4 (c04dbe6)"
execution-1  | 2024-03-31T20:00:16.896540Z  INFO Opening database path="/var/lib/reth/db"
execution-1  | 2024-03-31T20:00:16.942107Z  INFO Configuration loaded path="/var/lib/reth/reth.toml"
execution-1  | 2024-03-31T20:00:16.974895Z  INFO Database opened
execution-1  | 2024-03-31T20:00:16.975250Z  INFO Starting metrics endpoint addr=0.0.0.0:6060
execution-1  | 2024-03-31T20:00:16.979108Z  INFO 
execution-1  | Pre-merge hard forks (block based):
execution-1  | - Frontier                         @0
execution-1  | - Homestead                        @1150000
execution-1  | - Dao                              @1920000
execution-1  | - Tangerine                        @2463000
execution-1  | - SpuriousDragon                   @2675000
execution-1  | - Byzantium                        @4370000
execution-1  | - Constantinople                   @7280000
execution-1  | - Petersburg                       @7280000
execution-1  | - Istanbul                         @9069000
execution-1  | - MuirGlacier                      @9200000
execution-1  | - Berlin                           @12244000
execution-1  | - London                           @12965000
execution-1  | - ArrowGlacier                     @13773000
execution-1  | - GrayGlacier                      @15050000
execution-1  | Merge hard forks:
execution-1  | - Paris                            @58750000000000000000000 (network is known to be merged)
execution-1  | Post-merge hard forks (timestamp based):
execution-1  | - Shanghai                         @1681338455
execution-1  | - Cancun                           @1710338135
execution-1  | 2024-03-31T20:00:17.172239Z  INFO Transaction pool initialized
execution-1  | 2024-03-31T20:00:17.172807Z  INFO Connecting to P2P network
execution-1  | 2024-03-31T20:00:17.173667Z  INFO Loading saved peers file=/var/lib/reth/known-peers.json
execution-1  | 2024-03-31T20:00:17.183794Z  INFO StaticFileProducer initialized
execution-1  | 2024-03-31T20:00:17.185095Z  INFO Pruner initialized prune_config=PruneConfig { block_interval: 5, segments: PruneModes { sender_recovery: Some(Full), transaction_lookup: None, receipts: Some(Before(11052984)), account_history: Some(Distance(10064)), storage_history: Some(Distance(10064)), receipts_log_filter: ReceiptsLogPruneConfig({0x00000000219ab540356cbb839cbe05303d7705fa: Before(11052984)}) } }
execution-1  | 2024-03-31T20:00:17.185589Z  INFO Consensus engine initialized
execution-1  | 2024-03-31T20:00:17.185769Z  INFO Engine API handler initialized
execution-1  | 2024-03-31T20:00:17.189907Z  INFO RPC auth server started url=0.0.0.0:8551
execution-1  | 2024-03-31T20:00:17.190438Z  INFO RPC IPC server started url=/tmp/reth.ipc
execution-1  | 2024-03-31T20:00:17.190458Z  INFO RPC HTTP server started url=0.0.0.0:8545
execution-1  | 2024-03-31T20:00:17.190468Z  INFO RPC WS server started url=0.0.0.0:8546
execution-1  | 2024-03-31T20:00:17.190500Z  INFO Starting consensus engine
execution-1  | 2024-03-31T20:00:17.191381Z  INFO Static File Producer started targets=StaticFileTargets { headers: None, receipts: None, transactions: None }
execution-1  | 2024-03-31T20:00:17.191791Z  INFO Preparing stage pipeline_stages=1/12 stage=Headers checkpoint=19538697 target=None
execution-1  | 2024-03-31T20:00:17.191816Z  INFO Static File Producer finished targets=StaticFileTargets { headers: None, receipts: None, transactions: None } elapsed=307.523µs
execution-1  | 2024-03-31T20:00:17.191874Z  INFO Target block already reached checkpoint=19538697 target=Hash(0x9bb799784fa413e1ac389a5775f65590ee82952744e20c4d96e72d309ada13e8)
execution-1  | 2024-03-31T20:00:17.192071Z  INFO Executing stage pipeline_stages=1/12 stage=Headers checkpoint=19538697 target=None
execution-1  | 2024-03-31T20:00:17.192786Z  INFO Stage finished executing pipeline_stages=1/12 stage=Headers checkpoint=19538697 target=None stage_progress=100.00%
execution-1  | 2024-03-31T20:00:17.193119Z  INFO Preparing stage pipeline_stages=2/12 stage=Bodies checkpoint=19538697 target=19538697
execution-1  | 2024-03-31T20:00:17.193140Z  INFO Executing stage pipeline_stages=2/12 stage=Bodies checkpoint=19538697 target=19538697
execution-1  | 2024-03-31T20:00:17.193397Z  INFO Stage finished executing pipeline_stages=2/12 stage=Bodies checkpoint=19538697 target=19538697 stage_progress=100.00%
execution-1  | 2024-03-31T20:00:17.193455Z  INFO Preparing stage pipeline_stages=3/12 stage=SenderRecovery checkpoint=19538697 target=19538697
execution-1  | 2024-03-31T20:00:17.193487Z  INFO Executing stage pipeline_stages=3/12 stage=SenderRecovery checkpoint=19538697 target=19538697
execution-1  | 2024-03-31T20:00:17.193497Z  INFO Stage finished executing pipeline_stages=3/12 stage=SenderRecovery checkpoint=19538697 target=19538697 stage_progress=100.00%
execution-1  | 2024-03-31T20:00:17.193996Z  INFO Preparing stage pipeline_stages=4/12 stage=Execution checkpoint=2371510 target=19538697
execution-1  | 2024-03-31T20:00:17.194252Z  INFO Executing stage pipeline_stages=4/12 stage=Execution checkpoint=2371510 target=19538697
execution-1  | 2024-03-31T20:00:20.189462Z  INFO Status connected_peers=0 freelist=24136 stage=Execution checkpoint=2371510 target=19538697
execution-1  | 2024-03-31T20:00:45.186368Z  INFO Status connected_peers=1 freelist=24136 stage=Execution checkpoint=2371510 target=19538697
execution-1  | 2024-03-31T20:01:10.188810Z  INFO Status connected_peers=3 freelist=24136 stage=Execution checkpoint=2371510 target=19538697
execution-1  | 2024-03-31T20:01:21.968094Z  INFO Received forkchoice updated message when syncing head_block_hash=0x7266c01c5baa2a59999ec7a38c353ecff9c3d8c3a92373fed5041770164822c8 safe_block_hash=0x0d2bb4c01682409f976119922f83880f6002d58f05b4504094997974aa73fdab finalized_block_hash=0x4ab44a268814b95bdde2b53152df2e2012dd0c4e1473316f4c1e12bcf5320588
execution-1  | 2024-03-31T20:01:35.186818Z  INFO Status connected_peers=2 freelist=24136 stage=Execution checkpoint=2371510 target=19538697
execution-1  | 2024-03-31T20:02:00.189346Z  INFO Status connected_peers=2 freelist=24136 stage=Execution checkpoint=2371510 target=19538697
Scott-Sanderson commented 5 months ago

I started a fresh sync with beta4 and have made it to near the end of stage 4. Will update here if I can make it past TransactionLookup atage.

victorelec14 commented 5 months ago

hey guys, wanted to report that for my beta 4 syncing reth node, the TransactionLookup stage stopped hanging and I am past this stage now after I realize I haven't upgraded my lighthouse to a 4844 compliant version (pretty dumb i know...)

note that, my backfill sync target block is 19426523, which is a bit before 4844 goes live.

so what i would suggest to people having the same problem is to check if your consensus client is the latest version, if not upgrade it and restart reth to see if it syncs through the tx lookup stage now.

now the question is, does during TransactionLookup stage execution client must need to communicate consensus client in this stage, and if the consensus client is stalled due to it being a pre-4844 version it cause reth sync also hangs?

@jonathanykh Does this issue have anything to do with what you say? It will be included in the next release (beta5)

https://github.com/paradigmxyz/reth/pull/7399
https://github.com/paradigmxyz/reth/commit/9de7b4152e79ec635c4db956252d4e7046921e2f

Scott-Sanderson commented 5 months ago

~hung again on TransactionLookup, checkpoint = 0 :(~

edit: Well, it jumped from checkpoint=0 to 100% complete and finished the pipeline!

Screenshot 2024-04-01 at 17 54 13
jonathanykh commented 5 months ago

hey guys, wanted to report that for my beta 4 syncing reth node, the TransactionLookup stage stopped hanging and I am past this stage now after I realize I haven't upgraded my lighthouse to a 4844 compliant version (pretty dumb i know...) note that, my backfill sync target block is 19426523, which is a bit before 4844 goes live. so what i would suggest to people having the same problem is to check if your consensus client is the latest version, if not upgrade it and restart reth to see if it syncs through the tx lookup stage now. now the question is, does during TransactionLookup stage execution client must need to communicate consensus client in this stage, and if the consensus client is stalled due to it being a pre-4844 version it cause reth sync also hangs?

@jonathanykh Does this issue have anything to do with what you say? It will be included in the next release (beta5)

7399 9de7b41

georgios mentioned execution does not interact with consensus during pipeline sync, and my target block is before cancun, so I guess no? other thing I would like to mention is aside from updating the CL I also rebooted my PC that hosts reth, not sure by any means if this would be relevant.

onbjerg commented 5 months ago

now the question is, does during TransactionLookup stage execution client must need to communicate consensus client in this stage, and if the consensus client is stalled due to it being a pre-4844 version it cause reth sync also hangs?

This should not have an effect, no. The only EL <-> CL communication for historical sync is the CL telling the EL what the latest block is, and we sync to that. All data is then downloaded over P2P from other execution clients.

Would you guys mind posting what kind of disk and CPU you are using? My hunch is that most likely this is an I/O bottleneck, i.e. it is actually doing work, it just does it so slowly that it doesn't commit (and thus reports 0 progress). Reth only reports progress being made once the data is committed to disk, which may take some time, especially on this stage.

Most likely it got solved for some of you because of changes in Reth since the last version you ran

victorelec14 commented 5 months ago

Confirmed that with the v0.2.0-beta.4 , the synchronization completes correctly. There was no need to update to beta5.

Thanks!

image

onbjerg commented 4 months ago

I will close this for the time being; feel free to ping here or open a new issue if this persists for any of you.