Failed to validate header: TimestampIsInFuture

[mattstam]

Describe the bug

While running the node for a prolonged period of time, this error may occur:

ERROR reth_blockchain_tree::blockchain_tree: Failed to validate header 0xb2e6…49ce: TimestampIsInFuture { timestamp: 1691152067, present_timestamp: 1691152066 } block=SealedBlockWithSenders { block: SealedBlock { header: SealedHeader { header: Header { parent_hash: 0xcae2aa00f3870084168f9125913b95aa35c5eb641b73a822bd556770fd9cad8c, ommers_hash: 0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347, beneficiary: 0x997834315bbdc3d958bb9689d1c34f03c68e6c90, state_root: 0xd8587e1a4e7a1f0fbcab5ea99de324c5859f8282a06c007f36338bc0fadced2a, transactions_root: 0xdd97a2fe62c0d6df5b81a4a3c96171c7b2a02c455245f3a830c0eaab9842c9d4, receipts_root: 0x24e06d6d3510e7b010bd78fdd43862b68b7927d748f70ea7676c8c0613eb1e01, withdrawals_root: Some(0x35c0017fc2cbd7f6b3af8863ab9832a05309e97127bfc253e3f5f344feb46fd1), logs_bloom: 0x856105c0c64914b13c381038ab0c1221113012888cad2238332901c030a02c14440501622013a642c010190032ba11040a31d03288aceb000200105e812c02500603811c0c9c0a2f38cbc2aa500024ac88a47448246618a0b251567ce860004092438045960a0025271678421c11284b188200e18100242c220820980138c2420f428a5422842501106d7c0b28800e7848002001892449bc5e352c4c0294e4708a800122414d6045c22254e01296bc004c813882c147250221403c6a1890304501920cc64146480248004653874810d24a84d272e11d3cbd0280e50a24186756c8be644a002e2388281ee5a07e02004e01a196354f082078802bf81740053699, difficulty: 0x0000000000000000000000000000000000000000000000000000000000000000_U256, number: 17841617, gas_limit: 30000000, gas_used: 9066945, timestamp: 1691152067, mix_hash: 0x62314daf4126dbf7421dda71d79bc06af88f08f3f8042528e0127d7a4d84c767, nonce: 0, base_fee_per_gas: Some(15796076737), extra_data: Bytes(0xda83010c01846765746888676f312e32302e378777696e646f7773) }, hash: 0xb2e63da8e5dce7910a664f106e816e6be07b3be8884b38da79fe8428388949ce }, body: ...

which puts the execution client in a bad state. From the logs, it isn't obvious that reth is in a bad state except for the occasional:

WARN reth::node::events: Post-merge network, but no beacon client seen for a while. Please launch one to follow the chain! period=53358.549665153s

What really gives away that there is a problem is missed attestations dues to the consensus client (prysm) having issues:

time="2023-08-04 12:27:46" level=error msg="Could not handle p2p pubsub" error="could not notify the engine of the new payload: received an INVALID payload from execution engine" prefix=sync 
...
time="2023-08-04 12:32:35" level=warning msg="Execution client is not syncing" prefix=powchain

Steps to reproduce

Has occured twice, once after running for 2 days, another time after running for 9 hours. Seems to occur after a while when running with Prysm.

Consensus client will be in a continously bad state. Rebooting both clients fixed the issue.

Node logs

execution:

2023-08-04T12:27:13.311506Z  INFO reth::node::events: Forkchoice updated head_block_hash=0x076674f27eb860f2ea37957a799927cf14e5d8b54842f6b994469a27b94ca440 safe_block_hash=0x451822cccf8525836443b6bd12da8dca80880e26c3ed1d0144ce3ef586ecf46c finalized_block_hash=0x7634b76ded2815e95c6d19a00ae658c9c34c230a21df71609e2ecf5e4d378fce status=Valid
2023-08-04T12:27:24.734286Z  INFO try_insert_validated_block{block=(17841615, 0xbc9ea4f4a6a6801e8cb498083c5b6b2b8151941f414fd269b6f98a7e0067c042)}: blockchain_tree: return=Ok(Valid)
2023-08-04T12:27:24.734354Z  INFO reth::node::events: Block added to canonical chain number=17841615 hash=0xbc9ea4f4a6a6801e8cb498083c5b6b2b8151941f414fd269b6f98a7e0067c042
2023-08-04T12:27:24.784528Z  INFO make_canonical{block_hash=0xbc9ea4f4a6a6801e8cb498083c5b6b2b8151941f414fd269b6f98a7e0067c042}: blockchain_tree: Committing new canonical chain: [(17841615, 0xbc9ea4f4a6a6801e8cb498083c5b6b2b8151941f414fd269b6f98a7e0067c042)]
2023-08-04T12:27:25.311459Z  INFO reth::node::events: Forkchoice updated head_block_hash=0xbc9ea4f4a6a6801e8cb498083c5b6b2b8151941f414fd269b6f98a7e0067c042 safe_block_hash=0x451822cccf8525836443b6bd12da8dca80880e26c3ed1d0144ce3ef586ecf46c finalized_block_hash=0x7634b76ded2815e95c6d19a00ae658c9c34c230a21df71609e2ecf5e4d378fce status=Valid
2023-08-04T12:27:34.041000Z  INFO reth::cli: Status connected_peers=83 latest_block=17841615
2023-08-04T12:27:36.588983Z  INFO try_insert_validated_block{block=(17841616, 0xcae2aa00f3870084168f9125913b95aa35c5eb641b73a822bd556770fd9cad8c)}: blockchain_tree: return=Ok(Valid)
2023-08-04T12:27:36.589050Z  INFO reth::node::events: Block added to canonical chain number=17841616 hash=0xcae2aa00f3870084168f9125913b95aa35c5eb641b73a822bd556770fd9cad8c
2023-08-04T12:27:36.641815Z  INFO make_canonical{block_hash=0xcae2aa00f3870084168f9125913b95aa35c5eb641b73a822bd556770fd9cad8c}: blockchain_tree: Committing new canonical chain: [(17841616, 0xcae2aa00f3870084168f9125913b95aa35c5eb641b73a822bd556770fd9cad8c)]
2023-08-04T12:27:37.796697Z  INFO reth::node::events: Forkchoice updated head_block_hash=0xcae2aa00f3870084168f9125913b95aa35c5eb641b73a822bd556770fd9cad8c safe_block_hash=0x451822cccf8525836443b6bd12da8dca80880e26c3ed1d0144ce3ef586ecf46c finalized_block_hash=0x7634b76ded2815e95c6d19a00ae658c9c34c230a21df71609e2ecf5e4d378fce status=Valid
2023-08-04T12:27:46.962687Z ERROR reth_blockchain_tree::blockchain_tree: Failed to validate header 0xb2e6…49ce: TimestampIsInFuture { timestamp: 1691152067, present_timestamp: 1691152066 } block=SealedBlockWithSenders { block: SealedBlock { header: SealedHeader { header: Header { parent_hash: 0xcae2aa00f3870084168f9125913b95aa35c5eb641b73a822bd556770fd9cad8c, ommers_hash: 0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347, beneficiary: 0x997834315bbdc3d958bb9689d1c34f03c68e6c90, state_root: 0xd8587e1a4e7a1f0fbcab5ea99de324c5859f8282a06c007f36338bc0fadced2a, transactions_root: 0xdd97a2fe62c0d6df5b81a4a3c96171c7b2a02c455245f3a830c0eaab9842c9d4, receipts_root: 0x24e06d6d3510e7b010bd78fdd43862b68b7927d748f70ea7676c8c0613eb1e01, withdrawals_root: Some(0x35c0017fc2cbd7f6b3af8863ab9832a05309e97127bfc253e3f5f344feb46fd1), logs_bloom: 0x856105c0c64914b13c381038ab0c1221113012888cad2238332901c030a02c14440501622013a642c010190032ba11040a31d03288aceb000200105e812c02500603811c0c9c0a2f38cbc2aa500024ac88a47448246618a0b251567ce860004092438045960a0025271678421c11284b188200e18100242c220820980138c2420f428a5422842501106d7c0b28800e7848002001892449bc5e352c4c0294e4708a800122414d6045c22254e01296bc004c813882c147250221403c6a1890304501920cc64146480248004653874810d24a84d272e11d3cbd0280e50a24186756c8be644a002e2388281ee5a07e02004e01a196354f082078802bf81740053699, difficulty: 0x0000000000000000000000000000000000000000000000000000000000000000_U256, number: 17841617, gas_limit: 30000000, gas_used: 9066945, timestamp: 1691152067, mix_hash: 0x62314daf4126dbf7421dda71d79bc06af88f08f3f8042528e0127d7a4d84c767, nonce: 0, base_fee_per_gas: Some(15796076737), extra_data: Bytes(0xda83010c01846765746888676f312e32302e378777696e646f7773) }, hash: 0xb2e63da8e5dce7910a664f106e816e6be07b3be8884b38da79fe8428388949ce }, body: ...

2023-08-04T12:28:34.040478Z  INFO reth::cli: Status connected_peers=83 latest_block=17841616
2023-08-04T12:29:04.040804Z  INFO reth::cli: Status connected_peers=83 latest_block=17841616
2023-08-04T12:29:18.023224Z  INFO net: Session established remote_addr=71.198.5.227:30303 client_version=besu/v23.4.4/linux-x86_64/openjdk-java-17 peer_id=0x301eebb19b029ad99093bbc972808f8bf39ff26d48b74cd306cb37f911cec9131fed2435b31acf109b7f1b9ce475fb6198c5e1d24d8d3417bdd73d19000226e7 total_active=84

consensus (prysm):

time="2023-08-04 12:26:41" level=info msg="Peer summary" activePeers=49 inbound=38 outbound=11 prefix=p2p
time="2023-08-04 12:26:50" level=info msg="Synced new block" block=0x4c2eae35... epoch=219604 finalizedEpoch=219602 finalizedRoot=0x8b3c9c62... prefix=blockchain slot=7027332
time="2023-08-04 12:26:50" level=info msg="Finished applying state transition" attestations=128 payloadHash=0x62566a5797b5 prefix=blockchain slot=7027332 syncBitsCount=501 txCount=172
time="2023-08-04 12:27:01" level=info msg="Synced new block" block=0x6d55164a... epoch=219604 finalizedEpoch=219602 finalizedRoot=0x8b3c9c62... prefix=blockchain slot=7027333
time="2023-08-04 12:27:01" level=info msg="Finished applying state transition" attestations=128 payloadHash=0xb7bd835979bc prefix=blockchain slot=7027333 syncBitsCount=504 txCount=97
time="2023-08-04 12:27:13" level=info msg="Synced new block" block=0xcd8d9a61... epoch=219604 finalizedEpoch=219602 finalizedRoot=0x8b3c9c62... prefix=blockchain slot=7027334
time="2023-08-04 12:27:13" level=info msg="Finished applying state transition" attestations=128 payloadHash=0x076674f27eb8 prefix=blockchain slot=7027334 syncBitsCount=505 txCount=142
time="2023-08-04 12:27:25" level=info msg="Synced new block" block=0x185c612b... epoch=219604 finalizedEpoch=219602 finalizedRoot=0x8b3c9c62... prefix=blockchain slot=7027335
time="2023-08-04 12:27:25" level=info msg="Finished applying state transition" attestations=71 payloadHash=0xbc9ea4f4a6a6 prefix=blockchain slot=7027335 syncBitsCount=506 txCount=144
time="2023-08-04 12:27:37" level=info msg="Synced new block" block=0x6c33a166... epoch=219604 finalizedEpoch=219602 finalizedRoot=0x8b3c9c62... prefix=blockchain slot=7027336
time="2023-08-04 12:27:37" level=info msg="Finished applying state transition" attestations=128 payloadHash=0xcae2aa00f387 prefix=blockchain slot=7027336 syncBitsCount=504 txCount=130
time="2023-08-04 12:27:41" level=info msg="Peer summary" activePeers=55 inbound=44 outbound=11 prefix=p2p
time="2023-08-04 12:27:46" level=warning msg="Pruned invalid blocks" blockRoot=0x225216002a23c671ff562837c7a8b8c4719bbea5e9fb846bae9035f08e4a1a64 invalidChildrenCount=0 prefix=blockchain
time="2023-08-04 12:27:46" level=error msg="Could not handle p2p pubsub" error="could not notify the engine of the new payload: received an INVALID payload from execution engine" prefix=sync topic="/eth2/bba4da96/beacon_block/ssz_snappy"
time="2023-08-04 12:28:41" level=info msg="Peer summary" activePeers=51 inbound=40 outbound=11 prefix=p2p
time="2023-08-04 12:29:41" level=info msg="Peer summary" activePeers=28 inbound=25 outbound=3 prefix=p2p
time="2023-08-04 12:30:41" level=info msg="Peer summary" activePeers=54 inbound=48 outbound=5 prefix=p2p
time="2023-08-04 12:31:01" level=info msg="error in BlocksByRange batch" error="throttled by rate limiter: rate limited" prefix=sync
time="2023-08-04 12:31:41" level=info msg="Peer summary" activePeers=49 inbound=42 outbound=7 prefix=p2p
time="2023-08-04 12:32:35" level=warning msg="Execution client is not syncing" prefix=powchain
time="2023-08-04 12:32:41" level=info msg="Peer summary" activePeers=52 inbound=47 outbound=5 prefix=p2p
time="2023-08-04 12:32:49" level=warning msg="Execution client is not syncing" prefix=powchain
time="2023-08-04 12:33:03" level=warning msg="Execution client is not syncing" prefix=powchain
time="2023-08-04 12:33:17" level=warning msg="Execution client is not syncing" prefix=powchain
time="2023-08-04 12:33:31" level=warning msg="Execution client is not syncing" prefix=powchain
time="2023-08-04 12:33:41" level=info msg="Peer summary" activePeers=53 inbound=50 outbound=3 prefix=p2p
time="2023-08-04 12:33:45" level=warning msg="Execution client is not syncing" prefix=powchain
time="2023-08-04 12:33:59" level=warning msg="Execution client is not syncing" prefix=powchain
time="2023-08-04 12:34:13" level=warning msg="Execution client is not syncing" prefix=powchain
time="2023-08-04 12:34:27" level=warning msg="Execution client is not syncing" prefix=powchain
time="2023-08-04 12:34:34" level=info msg="error in BlocksByRange batch" error="throttled by rate limiter: rate limited" prefix=sync
time="2023-08-04 12:34:34" level=info msg="error in BlocksByRange batch" error="throttled by rate limiter: rate limited" prefix=sync
time="2023-08-04 12:34:35" level=info msg="error in BlocksByRange batch" error="throttled by rate limiter: rate limited" prefix=sync

validator:

time="2023-08-04 14:58:27" level=error msg="rpc error: code = Unavailable desc = Syncing to latest head, not ready to respond" prefix=validator
time="2023-08-04 14:58:27" level=error msg="Failed to update assignments" error="rpc error: code = Unavailable desc = Syncing to latest head, not ready to respond" prefix=validator
time="2023-08-04 14:58:39" level=error msg="rpc error: code = Unavailable desc = Syncing to latest head, not ready to respond" prefix=validator
time="2023-08-04 14:58:39" level=error msg="Failed to update assignments" error="rpc error: code = Unavailable desc = Syncing to latest head, not ready to respond" prefix=validator

Platform(s)

No response

What version/commit are you on?

v0.1.0-alpha.4

What database version are you on?

No response

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

[mattstam]

Closing, it would appear that this is a duplicate of #3879 and resolved in #3884. Looking forward to the next release! 🙏