Missing attestations

[fiiiu]

Describe the bug

Ever since moving from geth to reth a few months ago, my validator is occasionally missing attestations, averaging around one a day. I saw this behavior with alpha.8, alpha.10, alpha.12, and alpha.13. I'm running the latest version of prysm for consensus client. I'm using time.nist.gov as NTP server.

I cannot state for sure that this is reth's fault, but I didn't see this behavior with my same setup when running geth. I'm including INFO level logs around the time when I missed an attestation, for slot 8027743, corresponding to block 18833845. Please let me know if there's any other info I can share.

Thanks!

Steps to reproduce

Run a validator with reth + prysm and wait for missed attestations.

Node logs

2023-12-21T09:27:25.242484Z  INFO reth::node::events: Canonical chain committed number=18833343 hash=0x051c252e133ae86f455829cacfbad6bdedaba5518422e0019b32300763c0ea51 elapsed=421.326179ms
2023-12-21T09:27:25.242550Z  INFO reth::node::events: Forkchoice updated head_block_hash=0x051c252e133ae86f455829cacfbad6bdedaba5518422e0019b32300763c0ea51 safe_block_hash=0x97aea22345cedc9e31cfd51b7d3e490e82da0ed8f2a137683afa739dbfb51a46 finalized_block_hash=0xb9b4d10ef06af762a237c2d467e7f6fecc67de002a551b34096f362b26ad519e status=Valid
2023-12-21T09:27:34.345443Z  INFO reth::cli: Status connected_peers=108 freelist=25452 latest_block=18833343
2023-12-21T09:27:37.325558Z  INFO reth::node::events: Block added to canonical chain number=18833344 hash=0xc3cb99cf0713fe96a5f497c80fc9472e2f2d669392a4a35e374bed066e3dd79a
2023-12-21T09:27:38.068749Z  INFO reth::node::events: Canonical chain committed number=18833344 hash=0xc3cb99cf0713fe96a5f497c80fc9472e2f2d669392a4a35e374bed066e3dd79a elapsed=516.024465ms
2023-12-21T09:27:38.068795Z  INFO reth::node::events: Forkchoice updated head_block_hash=0xc3cb99cf0713fe96a5f497c80fc9472e2f2d669392a4a35e374bed066e3dd79a safe_block_hash=0x97aea22345cedc9e31cfd51b7d3e490e82da0ed8f2a137683afa739dbfb51a46 finalized_block_hash=0xb9b4d10ef06af762a237c2d467e7f6fecc67de002a551b34096f362b26ad519e status=Valid
2023-12-21T09:27:38.101226Z  INFO reth::node::events: Pruner finished tip_block_number=18833344 elapsed=32.416934ms stats={SenderRecovery: (HasMoreData, 17500), Receipts: (Finished, 0)}
2023-12-21T09:27:48.801228Z  INFO reth::node::events: Block added to canonical chain number=18833345 hash=0xa00586e8849c4d089d4cbf11ee95790552ed02a73272036d54c10816386f8ee5
2023-12-21T09:27:49.377986Z  INFO reth::node::events: Canonical chain committed number=18833345 hash=0xa00586e8849c4d089d4cbf11ee95790552ed02a73272036d54c10816386f8ee5 elapsed=335.306759ms
2023-12-21T09:27:49.378031Z  INFO reth::node::events: Forkchoice updated head_block_hash=0xa00586e8849c4d089d4cbf11ee95790552ed02a73272036d54c10816386f8ee5 safe_block_hash=0x97aea22345cedc9e31cfd51b7d3e490e82da0ed8f2a137683afa739dbfb51a46 finalized_block_hash=0xb9b4d10ef06af762a237c2d467e7f6fecc67de002a551b34096f362b26ad519e status=Valid
2023-12-21T09:27:59.345801Z  INFO reth::cli: Status connected_peers=108 freelist=25470 latest_block=18833345
2023-12-21T09:28:01.132339Z  INFO reth::node::events: Block added to canonical chain number=18833346 hash=0x3e72d2157be6a501a2370dc16a7410b97a8e45dc1798cb0cd9d026c6f1f7aad0
2023-12-21T09:28:01.818468Z  INFO reth::node::events: Canonical chain committed number=18833346 hash=0x3e72d2157be6a501a2370dc16a7410b97a8e45dc1798cb0cd9d026c6f1f7aad0 elapsed=462.233358ms
2023-12-21T09:28:01.818517Z  INFO reth::node::events: Forkchoice updated head_block_hash=0x3e72d2157be6a501a2370dc16a7410b97a8e45dc1798cb0cd9d026c6f1f7aad0 safe_block_hash=0x97aea22345cedc9e31cfd51b7d3e490e82da0ed8f2a137683afa739dbfb51a46 finalized_block_hash=0xb9b4d10ef06af762a237c2d467e7f6fecc67de002a551b34096f362b26ad519e status=Valid
2023-12-21T09:28:12.328221Z  INFO reth::node::events: Block added to canonical chain number=18833347 hash=0x03975b86bd9ef8385b50f9b590dd4501c71d3aa05994ec52615105a6b775d419
2023-12-21T09:28:13.090463Z  INFO reth::node::events: Canonical chain committed number=18833347 hash=0x03975b86bd9ef8385b50f9b590dd4501c71d3aa05994ec52615105a6b775d419 elapsed=489.449827ms
2023-12-21T09:28:13.090511Z  INFO reth::node::events: Forkchoice updated head_block_hash=0x03975b86bd9ef8385b50f9b590dd4501c71d3aa05994ec52615105a6b775d419 safe_block_hash=0x97aea22345cedc9e31cfd51b7d3e490e82da0ed8f2a137683afa739dbfb51a46 finalized_block_hash=0xb9b4d10ef06af762a237c2d467e7f6fecc67de002a551b34096f362b26ad519e status=Valid
2023-12-21T09:28:24.345364Z  INFO reth::cli: Status connected_peers=108 freelist=25346 latest_block=18833347

Platform(s)

Linux (x86)

What version/commit are you on?

alpha.13

What database version are you on?

1

What type of node are you running?

Full via --full flag

What prune config do you use, if any?

no reth.toml file, running the out-of-the-box precompile as is.

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

No response

Code of Conduct

• I agree to follow the Code of Conduct

[mattsse]

to block 18833845.

could you please share the logs for this block?

[fiiiu]

oh those are the logs I shared, from 18833843 to 47, including the one I missed. or what kind of logs do you need?

[mattsse]

hmm the last entry is for 18833347 which is 500 blocks off

[fiiiu]

omg sorry those 3s and 8s ://

here they go, I see now some back and forth going on there..

2023-12-21T11:08:37.614424Z INFO reth::node::events: Block added to canonical chain number=18833844 hash=0x6ae891980fd1f715e4119e2f5848648913f96433616d445fef8b5210230faa30 2023-12-21T11:08:38.245599Z INFO reth::node::events: Canonical chain committed number=18833844 hash=0x6ae891980fd1f715e4119e2f5848648913f96433616d445fef8b5210230faa30 elapsed=396.949737ms 2023-12-21T11:08:38.245650Z INFO reth::node::events: Forkchoice updated head_block_hash=0x6ae891980fd1f715e4119e2f5848648913f96433616d445fef8b5210230faa30 safe_block_hash=0x8b89e5131d35ff862536e00b2882c16295d1b559a0e15a4dce9ae79a61b400d5 finalized_block_hash=0x3f3eba1e8e80c9d5a1c9bd68ca1a544963d3203302463bafdad37e5d4dc4d4bc status=Valid 2023-12-21T11:08:38.280688Z INFO reth::node::events: Pruner finished tip_block_number=18833844 elapsed=34.904164ms stats={SenderRecovery: (HasMoreData, 17500), Receipts: (Finished, 0)} 2023-12-21T11:08:49.497233Z INFO reth::cli: Status connected_peers=114 freelist=26985 latest_block=18833844 2023-12-21T11:08:52.484539Z INFO reth::node::events: Block added to canonical chain number=18833845 hash=0xb6654136ab96a8706f83374b2b52f30cdf85adf0b2717c433d5ddaff747321e3 2023-12-21T11:08:52.871376Z INFO reth::node::events: Canonical chain committed number=18833845 hash=0xb6654136ab96a8706f83374b2b52f30cdf85adf0b2717c433d5ddaff747321e3 elapsed=11.743621ms 2023-12-21T11:08:52.871423Z INFO reth::node::events: Forkchoice updated head_block_hash=0xb6654136ab96a8706f83374b2b52f30cdf85adf0b2717c433d5ddaff747321e3 safe_block_hash=0x8b89e5131d35ff862536e00b2882c16295d1b559a0e15a4dce9ae79a61b400d5 finalized_block_hash=0x3f3eba1e8e80c9d5a1c9bd68ca1a544963d3203302463bafdad37e5d4dc4d4bc status=Valid 2023-12-21T11:09:01.913537Z INFO reth::node::events: Block added to fork chain number=18833845 hash=0xadf844b79c2cfc5004f9fb39d068bb3ec90772403b9a625413b9f97bbb603e12 2023-12-21T11:09:02.454590Z INFO blockchain_tree: Unwinding canonical chain blocks: 18833845..=18833845 2023-12-21T11:09:03.631705Z INFO reth::node::events: Canonical chain committed number=18833845 hash=0xadf844b79c2cfc5004f9fb39d068bb3ec90772403b9a625413b9f97bbb603e12 elapsed=1.177264197s 2023-12-21T11:09:03.631752Z INFO reth::node::events: Forkchoice updated head_block_hash=0xadf844b79c2cfc5004f9fb39d068bb3ec90772403b9a625413b9f97bbb603e12 safe_block_hash=0x8b89e5131d35ff862536e00b2882c16295d1b559a0e15a4dce9ae79a61b400d5 finalized_block_hash=0x3f3eba1e8e80c9d5a1c9bd68ca1a544963d3203302463bafdad37e5d4dc4d4bc status=Valid 2023-12-21T11:09:13.684360Z INFO reth::node::events: Block added to canonical chain number=18833846 hash=0x1b84b2239f3efe8ef2c893cd4ff81a388926a066bed3a4b6f6044c0e667f73ce 2023-12-21T11:09:14.496343Z INFO reth::cli: Status connected_peers=114 freelist=26883 latest_block=18833845 2023-12-21T11:09:14.591046Z INFO reth::node::events: Canonical chain committed number=18833846 hash=0x1b84b2239f3efe8ef2c893cd4ff81a388926a066bed3a4b6f6044c0e667f73ce elapsed=661.621852ms 2023-12-21T11:09:14.593215Z INFO reth::node::events: Forkchoice updated head_block_hash=0x1b84b2239f3efe8ef2c893cd4ff81a388926a066bed3a4b6f6044c0e667f73ce safe_block_hash=0x8b89e5131d35ff862536e00b2882c16295d1b559a0e15a4dce9ae79a61b400d5 finalized_block_hash=0xe1929ad111a019df93d6cc026aff3e7e0027bf3be8c609a146c99a8305176f1f status=Valid 2023-12-21T11:09:24.799240Z INFO reth::node::events: Block added to canonical chain number=18833847 hash=0xcff19e3ea5a59e503592a3607b3e171c8a9c87a0a9fe0f0a55313122ed731987

[mattsse]

@shekhirin a few things happening here:

new block 18833844 committed
pruner kicks ins
new block 18833845 arrives https://etherscan.io/block/18833845/f
18833845 block made canonical at 08:52.871423Z
18833845 reorged at 09:02.454590Z

this is 10 secs later.

then only 2s later 18833846 is committed

the pruner was only active for elapsed=34.904164ms

[0xSheller]

i second this, second time it happens to me in ~2 weeks and would hate to resync again. let me know what i can do to help investigate this.

[gakonst]

@0xSheller can you share some more logs? is this still happening on latest alpha? cc @fiiiu

[0xarbitrary]

I also tried to run some of my validators with reth, and this resulted in about 10% of missed attestations. Now they are using geth again, but I have the Lighthouse validator broadcast the attestations to both Lighthouse beacon nodes (one paired with geth, the other one with reth). The one paired with reth very often shows errors like this one:

Feb 08 11:03:14.073 INFO New block received                      root: 0x7a02c9b1b0b2ed4b81598e0b7daf25f08f9e100998aeeccc2642e716cab5dd20, slot: 8380514
Feb 08 11:03:15.011 ERRO Failure verifying attestation for gossip, attestation_slot: 8380514, committee_index: 18, request_index: 0, error: UnknownHeadBlock { beacon_block_root: 0x7a02c9b1b0b2ed4b81598e0b7daf25f08f9e100998aeeccc2642e716cab5dd20 }
Feb 08 11:03:15.011 WARN Error processing HTTP API request       method: POST, path: /eth/v1/beacon/pool/attestations, status: 400 Bad Request, elapsed: 201.38µs
Feb 08 11:03:17.001 INFO Synced                                  slot: 8380514, block: 0x7a02…dd20, epoch: 261891, finalized_epoch: 261889, finalized_root: 0xc3e8…c883, exec_hash: 0xec70…7f37 (verified), peers: 88, service: slot_notifier

The reth logs around that time are these:

2024-02-08T11:03:01.590251Z  INFO reth::cli: Status connected_peers=27 freelist=3881244 latest_block=19183023
2024-02-08T11:03:03.098119Z  INFO reth::commands::node::events: Block added to canonical chain number=19183024 hash=0x5c1c93c0f6fd38f9747c5c67ab8da2645987a1819c7e9644d30d2a97f68942b4
2024-02-08T11:03:04.076707Z  INFO reth::commands::node::events: Canonical chain committed number=19183024 hash=0x5c1c93c0f6fd38f9747c5c67ab8da2645987a1819c7e9644d30d2a97f68942b4 elapsed=800.533038ms
2024-02-08T11:03:04.076875Z  INFO reth::commands::node::events: Forkchoice updated head_block_hash=0x5c1c93c0f6fd38f9747c5c67ab8da2645987a1819c7e9644d30d2a97f68942b4 safe_block_hash=0x092025f5a1ad1a70c20475b66f53376326b1a3b46d1bbe2f1be8551e4e220c8c finalized_block_hash=0xac312a4347315115c1b08d3c7d9902aa48b632168660b1482e83f10308ba86d2 status=Valid
2024-02-08T11:03:15.392145Z  INFO reth::commands::node::events: Block added to canonical chain number=19183025 hash=0xec701b957855adc8f3b1a9bbdeff59d4df126f773e2fb4ca0f26bcb882ac7f37
2024-02-08T11:03:16.343410Z  INFO reth::commands::node::events: Canonical chain committed number=19183025 hash=0xec701b957855adc8f3b1a9bbdeff59d4df126f773e2fb4ca0f26bcb882ac7f37 elapsed=768.077938ms
2024-02-08T11:03:16.343442Z  INFO reth::commands::node::events: Forkchoice updated head_block_hash=0xec701b957855adc8f3b1a9bbdeff59d4df126f773e2fb4ca0f26bcb882ac7f37 safe_block_hash=0x092025f5a1ad1a70c20475b66f53376326b1a3b46d1bbe2f1be8551e4e220c8c finalized_block_hash=0xac312a4347315115c1b08d3c7d9902aa48b632168660b1482e83f10308ba86d2 status=Valid
2024-02-08T11:03:25.808589Z  INFO reth::commands::node::events: Block added to canonical chain number=19183026 hash=0x6499492cdc774fc26ba5eed7d6869b0cfb849b1959d21c15b0362611bf729ecb
2024-02-08T11:03:26.565436Z  INFO reth::commands::node::events: Canonical chain committed number=19183026 hash=0x6499492cdc774fc26ba5eed7d6869b0cfb849b1959d21c15b0362611bf729ecb elapsed=581.473161ms

This happens with both alpha.16 and alpha.17. I haven't tried any older releases.
I use the official docker image, with these options:

  node \
  --metrics 0.0.0.0:9001 \
  --http --http.addr 0.0.0.0 --http.api eth,web3,net --http.corsdomain "*" \
  --ws --ws.api eth,web3,net --ws.origins "*" --ws.addr 0.0.0.0 \
  --authrpc.jwtsecret /var/lib/jwtsecret/jwt.hex \
  --authrpc.addr 0.0.0.0 \
  --full

[emhane]

likely has to do with starvation due to blocking loops #6541