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

ERROR Failed to send event: Ok(PayloadStatus #10625

Closed cheddiefender closed 1 month ago

cheddiefender commented 1 month ago

Describe the bug

Just updated from 1.0.0 to 1.0.6 to try out the --engine.experimental flag. I get this error recurringly every 5 mins or so, and it even causes lighthouse to exit (using docker-compose). I have provided the relevant logs for the 2 times that this has happened so far.

Steps to reproduce

  1. Was using reth 1.0.0 docker image with docker-compose
  2. Set --engine.experimental flag in docker-compose.yml
  3. Pulled the new reth image and removed the old one
  4. "docker compose up"

Node logs

first occurrence:
lighthouse-1        | Aug 30 09:59:48.528 INFO New block received                      root: 0xc1466ac16c33984b9c7e3db66207072d1daed8888920dee2fca9ec5423d03529, slot: 9848997
reth-1              | 2024-08-30T09:59:49.823175Z  INFO Block added to canonical chain number=20640653 hash=0x23124eb368fbe8e2da9123239c11994dfc466b71cf3372d7ed869eb579d10eb2 peers=7 txs=75 gas=4.60 Mgas gas_throughput=3.83 Mgas/second full=15.3% base_fee=0.91gwei blobs=0 excess_blobs=0 elapsed=1.199213249s
reth-1              | 2024-08-30T09:59:49.935384Z  INFO Canonical chain committed number=20640653 hash=0x23124eb368fbe8e2da9123239c11994dfc466b71cf3372d7ed869eb579d10eb2 elapsed=265.226µs
lighthouse-1        | Aug 30 09:59:53.002 INFO Synced                                  slot: 9848997, block: 0xc146…3529, epoch: 307781, finalized_epoch: 307779, finalized_root: 0x6c08…ddfb, exec_hash: 0x2312…0eb2 (verified), peers: 95, service: slot_notifier
lighthouse-1        | Aug 30 10:00:00.942 INFO New block received                      root: 0x19adde6054ce7d038880e4178cd1e3659fd782aac917358ea0549c247b67bf92, slot: 9848998
lighthouse-1        | Aug 30 10:00:05.001 INFO Synced                                  slot: 9848998, block:    …  empty, epoch: 307781, finalized_epoch: 307779, finalized_root: 0x6c08…ddfb, exec_hash: 0x2312…0eb2 (verified), peers: 96, service: slot_notifier
reth-1              | 2024-08-30T10:00:08.882980Z  INFO Block added to canonical chain number=20640654 hash=0x332b38f1d034e3acc5894d0645894d1a6a15a53074b85ed44f5f1b78e30010f9 peers=7 txs=306 gas=26.84 Mgas gas_throughput=3.43 Mgas/second full=89.5% base_fee=0.83gwei blobs=0 excess_blobs=0 elapsed=7.818423268s
reth-1              | 2024-08-30T10:00:09.014662Z  INFO Canonical chain committed number=20640654 hash=0x332b38f1d034e3acc5894d0645894d1a6a15a53074b85ed44f5f1b78e30010f9 elapsed=876.096µs
lighthouse-1        | Aug 30 10:00:12.994 INFO New block received                      root: 0xd53648227f0fb79fab5b5fc9b39ab92d15cb8aeff16233f3f5ab19b76c008360, slot: 9848999
reth-1              | 2024-08-30T10:00:16.779245Z  INFO Block added to canonical chain number=20640655 hash=0x4d3423c79cbbfc0d9cd0041d6c7e2fa0dd13a83098378228209b69e925cca9c6 peers=7 txs=146 gas=6.55 Mgas gas_throughput=1.80 Mgas/second full=21.8% base_fee=0.91gwei blobs=6 excess_blobs=0 elapsed=3.648203142s
reth-1              | 2024-08-30T10:00:16.899826Z  INFO Canonical chain committed number=20640655 hash=0x4d3423c79cbbfc0d9cd0041d6c7e2fa0dd13a83098378228209b69e925cca9c6 elapsed=382.104µs
lighthouse-1        | Aug 30 10:00:17.002 INFO Synced                                  slot: 9848999, block: 0xd536…8360, epoch: 307781, finalized_epoch: 307779, finalized_root: 0x6c08…ddfb, exec_hash: 0x4d34…a9c6 (verified), peers: 98, service: slot_notifier
lighthouse-1        | Aug 30 10:00:24.470 INFO New block received                      root: 0xe4b9c3f97caa5972d5ade4996a25fbe3005a522440c9b1e7b9856e024c83071e, slot: 9849000
lighthouse-1        | Aug 30 10:00:29.002 INFO Synced                                  slot: 9849000, block:    …  empty, epoch: 307781, finalized_epoch: 307779, finalized_root: 0x6c08…ddfb, exec_hash: 0x4d34…a9c6 (verified), peers: 99, service: slot_notifier
reth-1              | 2024-08-30T10:00:31.737830Z  INFO Block added to canonical chain number=20640656 hash=0xf03e0d4be7e5b7acc8e7c6868e66bd1c5182392f3b6eaa9ce63cb4ca2263fda0 peers=7 txs=227 gas=30.00 Mgas gas_throughput=4.25 Mgas/second full=100.0% base_fee=0.85gwei blobs=4 excess_blobs=3 elapsed=7.058953348s
reth-1              | 2024-08-30T10:00:31.882799Z  INFO Canonical chain committed number=20640656 hash=0xf03e0d4be7e5b7acc8e7c6868e66bd1c5182392f3b6eaa9ce63cb4ca2263fda0 elapsed=1.225289ms
lighthouse-1        | Aug 30 10:00:36.594 INFO New block received                      root: 0xbf0876482abe59cdbe44a1f5ba3be0afab9a1ae7648f0667d13fdcae8cd79315, slot: 9849001
lighthouse-1        | Aug 30 10:00:41.008 INFO Synced                                  slot: 9849001, block:    …  empty, epoch: 307781, finalized_epoch: 307779, finalized_root: 0x6c08…ddfb, exec_hash: 0xf03e…fda0 (verified), peers: 103, service: slot_notifier
lighthouse-1        | Aug 30 10:00:45.091 WARN Execution engine call failed            error: HttpClient(url: http://reth:8551/, kind: timeout, detail: operation timed out), service: exec
lighthouse-1        | Aug 30 10:00:45.602 WARN Error whilst processing payload status  error: Api { error: HttpClient(url: http://reth:8551/, kind: timeout, detail: operation timed out) }, service: exec
lighthouse-1        | Aug 30 10:00:47.120 ERRO Error during execution engine upcheck   error: HttpClient(url: http://reth:8551/, kind: timeout, detail: operation timed out), service: exec
lighthouse-1        | Aug 30 10:00:50.514 ERRO Error during execution engine upcheck   error: HttpClient(url: http://reth:8551/, kind: timeout, detail: operation timed out), service: exec
lighthouse-1        | Aug 30 10:00:53.505 INFO Synced                                  slot: 9849002, block:    …  empty, epoch: 307781, finalized_epoch: 307779, finalized_root: 0x6c08…ddfb, exec_hash: 0xf03e…fda0 (verified), peers: 100, service: slot_notifier
lighthouse-1        | Aug 30 10:01:02.441 ERRO Error during execution engine upcheck   error: HttpClient(url: http://reth:8551/, kind: timeout, detail: operation timed out), service: exec
lighthouse-1        | Aug 30 10:01:05.054 INFO Synced                                  slot: 9849003, block:    …  empty, epoch: 307781, finalized_epoch: 307779, finalized_root: 0x6c08…ddfb, exec_hash: 0xf03e…fda0 (verified), peers: 94, service: slot_notifier
reth-1              | 2024-08-30T10:01:54.381350Z  INFO Status connected_peers=5 latest_block=20640656
reth-1              | 2024-08-30T10:01:54.666740Z  INFO Block added to canonical chain number=20640657 hash=0x3190b130fae03108a5c46aa407e87812ac02fde000d4171cb35493a0a7d30bb8 peers=0 txs=229 gas=17.88 Mgas gas_throughput=229.48 Kgas/second full=59.6% base_fee=0.95gwei blobs=0 excess_blobs=4 elapsed=77.903249385s
reth-1              | 2024-08-30T10:01:54.666460Z  WARN The database read transaction has been open for too long. Backtrace:
reth-1              |    0: <unknown>
reth-1              |    1: <unknown>
reth-1              |    2: <unknown>
reth-1              |    3: <unknown>
reth-1              |    4: <unknown>
reth-1              |    5: <unknown>
reth-1              |    6: <unknown>
reth-1              |    7: <unknown>
reth-1              |    8: <unknown>
reth-1              |    9: <unknown>
reth-1              |   10: <unknown>
reth-1              |   11: __clone
reth-1              |  open_duration=77.901268005s self.txn_id=5942306
reth-1              | 2024-08-30T10:01:54.670625Z ERROR Failed to send event: Ok(PayloadStatus { status: Valid, latest_valid_hash: Some(0x3190b130fae03108a5c46aa407e87812ac02fde000d4171cb35493a0a7d30bb8) })
lighthouse-1 exited with code 0

second occurrence:
lighthouse-1        | Aug 30 10:07:48.838 INFO New block received                      root: 0x794354003daa97b4c7e62469bdae574482851dd2364b47eec685b578e102fa3a, slot: 9849037
reth-1              | 2024-08-30T10:07:52.731378Z  INFO Block added to canonical chain number=20640693 hash=0x21b45e0fe6c35c6bf7273d509dfc67c565d7edbf1bbc440faaef1a8501dee81c peers=20 txs=201 gas=21.40 Mgas gas_throughput=5.66 Mgas/second full=71.3% base_fee=0.91gwei blobs=2 excess_blobs=3 elapsed=3.784953652s
reth-1              | 2024-08-30T10:07:52.857567Z  INFO Canonical chain committed number=20640693 hash=0x21b45e0fe6c35c6bf7273d509dfc67c565d7edbf1bbc440faaef1a8501dee81c elapsed=605.8µs
lighthouse-1        | Aug 30 10:07:53.001 INFO Synced                                  slot: 9849037, block: 0x7943…fa3a, epoch: 307782, finalized_epoch: 307780, finalized_root: 0x1174…d89a, exec_hash: 0x21b4…e81c (verified), peers: 89, service: slot_notifier
lighthouse-1        | Aug 30 10:08:01.248 INFO New block received                      root: 0xf13fbd5f03c787dc3009645eed1fa3bd1f4be4baab13611b97a56c35e4fffa1a, slot: 9849038
reth-1              | 2024-08-30T10:08:04.023386Z  INFO Block added to canonical chain number=20640694 hash=0xe7efaf35c37de82f8543b8194e23213af578beb91dea828fc86bb27fb8e19f46 peers=21 txs=126 gas=11.27 Mgas gas_throughput=4.20 Mgas/second full=37.6% base_fee=0.96gwei blobs=0 excess_blobs=2 elapsed=2.682755972s
reth-1              | 2024-08-30T10:08:04.153476Z  INFO Canonical chain committed number=20640694 hash=0xe7efaf35c37de82f8543b8194e23213af578beb91dea828fc86bb27fb8e19f46 elapsed=946.55µs
lighthouse-1        | Aug 30 10:08:05.000 INFO Synced                                  slot: 9849038, block: 0xf13f…fa1a, epoch: 307782, finalized_epoch: 307780, finalized_root: 0x1174…d89a, exec_hash: 0xe7ef…9f46 (verified), peers: 88, service: slot_notifier
lighthouse-1        | Aug 30 10:08:12.282 INFO New block received                      root: 0x7ad9e5f6da821d17f8ca4783a921a5158c631324a7ead071a3c01f71c934474f, slot: 9849039
reth-1              | 2024-08-30T10:08:15.898448Z  INFO Block added to canonical chain number=20640695 hash=0x5ce6205063220107faea3bb011abf11dd507e40c5470682bd1b6706a6fae617f peers=18 txs=157 gas=13.18 Mgas gas_throughput=3.75 Mgas/second full=43.9% base_fee=0.93gwei blobs=0 excess_blobs=0 elapsed=3.514309977s
reth-1              | 2024-08-30T10:08:16.014154Z  INFO Canonical chain committed number=20640695 hash=0x5ce6205063220107faea3bb011abf11dd507e40c5470682bd1b6706a6fae617f elapsed=967.39µs
lighthouse-1        | Aug 30 10:08:17.001 INFO Synced                                  slot: 9849039, block: 0x7ad9…474f, epoch: 307782, finalized_epoch: 307780, finalized_root: 0x1174…d89a, exec_hash: 0x5ce6…617f (verified), peers: 89, service: slot_notifier
lighthouse-1        | Aug 30 10:08:25.146 INFO New block received                      root: 0x8c9bc0c0c85eb18c76aaf1795b8b53655dc118f1c336354cfb188be5586f6c93, slot: 9849040
lighthouse-1        | Aug 30 10:08:29.003 INFO Synced                                  slot: 9849040, block:    …  empty, epoch: 307782, finalized_epoch: 307780, finalized_root: 0x1174…d89a, exec_hash: 0x5ce6…617f (verified), peers: 94, service: slot_notifier
reth-1              | 2024-08-30T10:08:30.299202Z  INFO Block added to canonical chain number=20640696 hash=0x9176e957529b800bedc2d7519de50f3319f9cf87b64accfa6bf28616abd80272 peers=20 txs=214 gas=15.09 Mgas gas_throughput=3.00 Mgas/second full=50.3% base_fee=0.92gwei blobs=3 excess_blobs=0 elapsed=5.028224607s
reth-1              | 2024-08-30T10:08:30.440998Z  INFO Canonical chain committed number=20640696 hash=0x9176e957529b800bedc2d7519de50f3319f9cf87b64accfa6bf28616abd80272 elapsed=1.185904ms
lighthouse-1        | Aug 30 10:08:36.667 INFO New block received                      root: 0x88ddbaeb12e7f65dd7a7e093567bfee5e875a88608b577a845bfdff51e7c8084, slot: 9849041
lighthouse-1        | Aug 30 10:08:41.004 INFO Synced                                  slot: 9849041, block:    …  empty, epoch: 307782, finalized_epoch: 307780, finalized_root: 0x1174…d89a, exec_hash: 0x9176…0272 (verified), peers: 95, service: slot_notifier
reth-1              | 2024-08-30T10:08:41.463718Z  INFO Block added to canonical chain number=20640697 hash=0x697e3cfabc5fa3ff91fa6490ea40947701eeb7b4fbd321a5c799e1ce1200bd4d peers=21 txs=192 gas=12.75 Mgas gas_throughput=2.73 Mgas/second full=42.5% base_fee=0.92gwei blobs=0 excess_blobs=0 elapsed=4.670564379s
reth-1              | 2024-08-30T10:08:41.601667Z  INFO Canonical chain committed number=20640697 hash=0x697e3cfabc5fa3ff91fa6490ea40947701eeb7b4fbd321a5c799e1ce1200bd4d elapsed=484.046µs
lighthouse-1        | Aug 30 10:08:48.960 INFO New block received                      root: 0xe0899465c3d23b7e1eb73f7cc806c26e73644f8f4be9b3a4cba00619d78913d6, slot: 9849042
lighthouse-1        | Aug 30 10:08:53.114 INFO Synced                                  slot: 9849042, block:    …  empty, epoch: 307782, finalized_epoch: 307780, finalized_root: 0x1174…d89a, exec_hash: 0x697e…bd4d (verified), peers: 101, service: slot_notifier
lighthouse-1        | Aug 30 10:08:57.680 WARN Execution engine call failed            error: HttpClient(url: http://reth:8551/, kind: timeout, detail: operation timed out), service: exec
lighthouse-1        | Aug 30 10:08:58.776 WARN Error whilst processing payload status  error: Api { error: HttpClient(url: http://reth:8551/, kind: timeout, detail: operation timed out) }, service: exec
lighthouse-1        | Aug 30 10:08:58.902 ERRO Error during execution engine upcheck   error: HttpClient(url: http://reth:8551/, kind: timeout, detail: operation timed out), service: exec
lighthouse-1        | Aug 30 10:08:59.656 INFO Execution engine online                 service: exec
lighthouse-1        | Aug 30 10:08:59.660 INFO Issuing forkchoiceUpdated               forkchoice_state: ForkchoiceState { head_block_hash: 0x697e3cfabc5fa3ff91fa6490ea40947701eeb7b4fbd321a5c799e1ce1200bd4d, safe_block_hash: 0x31add21b3875ac41cf095a6be956ae45986adb442afbd00df7f0e175b5c63ae8, finalized_block_hash: 0x61364bc83ec4c37f01367be9304103438c20ec46b62bdfa54447043e8a921a44 }, service: exec
reth-1              | 2024-08-30T10:09:09.071974Z ERROR Failed to send event: Ok(PayloadStatus { status: Valid, latest_valid_hash: Some(0xfb277403e2369b937eacd1d7e4c8463d66171795361a553d6c724361d18aed93) })
reth-1              | 2024-08-30T10:09:09.075156Z  INFO Block added to canonical chain number=20640698 hash=0xfb277403e2369b937eacd1d7e4c8463d66171795361a553d6c724361d18aed93 peers=21 txs=284 gas=19.45 Mgas gas_throughput=974.39 Kgas/second full=64.8% base_fee=0.90gwei blobs=6 excess_blobs=0 elapsed=19.95989521s
lighthouse-1        | Aug 30 10:09:11.413 INFO Logging to file                         path: "/root/.lighthouse/mainnet/beacon/logs/beacon.log"
lighthouse-1        | Aug 30 10:09:11.418 INFO Lighthouse started                      version: Lighthouse/v5.3.0-d6ba8c3

Platform(s)

Linux (x86)

What version/commit are you on?

1.0.6

What database version are you on?

-

Which chain / network are you on?

mainnet

What type of node are you running?

Archive (default)

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

cheddiefender commented 1 month ago

The issue seems to persist even without the --engine.experimental flag.

cheddiefender commented 1 month ago

Noticed that during these errors the cpu usage of both reth and lighthouse spike drastically.

cheddiefender commented 1 month ago

Issue seems to have stemmed from using lighthouse v5.3.0 instead of v5.1.3-modern