Receipt not available

[come-maiz]

Description

I'm testing teku + nethermind + mev-boost in kiln following this guide:
https://github.com/flashbots/mev-boost/wiki/Testing/517aa17d3f05bc4bd3d7985a630e9b41a510b4fd

Sometimes, this trace appear:

2022-07-20 14:51:36.655 INFO  - Syncing     *** Target slot: 943433, Head slot: 199743, Remaining slots: 743690, Connected peers: 21
2022-07-20 14:51:50.024 INFO  - Syncing     *** Target slot: 943434, Head slot: 199799, Remaining slots: 743635, Connected peers: 23
2022-07-20 14:52:00.740 INFO  - Syncing     *** Target slot: 943435, Head slot: 199845, Remaining slots: 743590, Connected peers: 22
2022-07-20 14:52:09.514 WARN  - Retrying with next eth1 endpoint                                                                                                            
java.util.concurrent.CompletionException: tech.pegasys.teku.beacon.pow.exception.RejectedRequestException: -32001: Receipt not available for 'From' block '215037'.
at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:314) ~[?:?]                                        
at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:319) ~[?:?]                                      
at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:645) ~[?:?]                                       
at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?]                                                                                   at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2073) ~[?:?] 
at tech.pegasys.teku.infrastructure.async.SafeFuture.lambda$propagateResult$3(SafeFuture.java:147) ~[teku-infrastructure-async-develop.jar:22.6.1+72-g2b6c1c1]              at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859) ~[?:?]
at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:837) ~[?:?]                                
at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?]
at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2073) ~[?:?] 
at org.web3j.utils.Async.lambda$run$1(Async.java:38) ~[core-4.9.3.jar:?]
at java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1736) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
at java.lang.Thread.run(Thread.java:829) ~[?:?]
Caused by: tech.pegasys.teku.beacon.pow.exception.RejectedRequestException: -32001: Receipt not available for 'From' block '215037'.
at tech.pegasys.teku.beacon.pow.Web3jEth1Provider.lambda$sendAsync$6(Web3jEth1Provider.java:151) ~[teku-beacon-pow-develop.jar:22.6.1+72-g2b6c1c1]
at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:642) ~[?:?]
... 12 more
2022-07-20 14:52:09.536 WARN  - Request for eth1 deposit logs from 10000 blocks failed. Retrying with a smaller block range.
2022-07-20 14:52:12.456 INFO  - Syncing     *** Target slot: 943436, Head slot: 199901, Remaining slots: 743535, Connected peers: 22
2022-07-20 14:52:24.606 INFO  - Syncing     *** Target slot: 943437, Head slot: 199967, Remaining slots: 743470, Connected peers: 22
2022-07-20 14:52:36.807 INFO  - Syncing     *** Target slot: 943438, Head slot: 200013, Remaining slots: 743425, Connected peers: 23
2022-07-20 14:52:48.863 INFO  - Syncing     *** Target slot: 943439, Head slot: 200069, Remaining slots: 743370, Connected peers: 25

It doesn't seem to stop syncing or to affect anything so far.

Steps to Reproduce (Bug)

Follow the steps in https://github.com/flashbots/mev-boost/wiki/Testing/517aa17d3f05bc4bd3d7985a630e9b41a510b4fd

Expected behavior:

Teku starts proposing blocks served by mev-boost.

Actual behavior:

An error trace appears in the logs. Sync is still ongoing, so things seem to be going well.

Frequency:

It happens for some blocks. I see 146527, 148124, 148328, 148747, 149424, 149795, 149960, 150476, 150723, 151226, 152151, 152923, 152996, 153125, 153526, 153670, 154242, 155002, 155089, 155896...

Versions (Add all that apply)

• Software version: teku/v22.6.1+72-g2b6c1c1/linux-x86_64/-privatebuild-openjdk64bitservervm-java-11
  $ java --version
  openjdk 11.0.15 2022-04-19
  OpenJDK Runtime Environment (build 11.0.15+10-Ubuntu-0ubuntu0.22.04.1)
  OpenJDK 64-Bit Server VM (build 11.0.15+10-Ubuntu-0ubuntu0.22.04.1, mixed mode, sharing)

* OS Name & Version: 

$ cat /etc/*release
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=22.04
DISTRIB_CODENAME=jammy
DISTRIB_DESCRIPTION="Ubuntu 22.04 LTS"
PRETTY_NAME="Ubuntu 22.04 LTS"
NAME="Ubuntu"
VERSION_ID="22.04"
VERSION="22.04 LTS (Jammy Jellyfish)"
VERSION_CODENAME=jammy
ID=ubuntu
ID_LIKE=debian
HOME_URL="https://www.ubuntu.com/"
SUPPORT_URL="https://help.ubuntu.com/"
BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/"
PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy"
UBUNTU_CODENAME=jammy

* Cloud VM, type, size: digital ocean

[ajsutton]

This is an error coming from Nethermind. It doesn't appear to have receipts for the requested block range and so returned an error. Teku requires the receipts for all deposit events on the execution chain so that it can build up the Deposit Merkle tree (which is used when proposing blocks).

In this case it seems to have had a secondary eth1-endpoint specified which it fell back to using and that endpoint was able to supply the logs for those blocks so it's most likely resolved itself. If you're continuing to see errors about these requests failing or having missing deposits, then you'll likely need to fix the Nethermind configuration to ensure it downloads all historic receipts (for kiln it would be simplest to go all the way back to genesis since the chain was new).

Will close this issue for now but feel free to reach out if you have further questions etc either on our Discord or posting a response here.

[come-maiz]

Thanks for the info. I'll check nethermind.

Just, my suggestion is not to show the exception traceback but to give some pointers to check at the execution client for the missing information.

I have only nethermind running, so I don't understand where that secondary endpoint came from, but I agree it seems it healed itself, or at least continued trying to sync.