Validator block proposal missing

[jplelievre]

Waiting 259 days and missed a block proposal today...
I have seen multiple subreddit post with the same error lately and wondering if there is not a bug or something wrong with mev-boost.
In my case I missed 2,29 ethereum tips, so it is a lot of money... and never missed a block proposal before enabling mev-boost.
Have you any advice or configuration change to avoid this error in the future?

Thanks,

Environment :

Rocky Linux 8.8
Lighthouse 4.1.0
Geth 1.11.6
Mev-boost 1.5.0

Mev-boost service configuration :

[Unit]
Description=Maximal Extractable Value Boost (Mainnet)
Wants=network-online.target
After=network-online.target

[Service]
Type=simple
User=mevboost
Group=mevboost
Restart=always
RestartSec=5
ExecStart=/usr/local/bin/mev-boost
-mainnet
-relay-check
-relays https://0xac6e77dfe25ecd6110b8e780608cce0dab71fdd5ebea22a16c0205200f2f8e2e3ad3b71d3499c54ad14d6c21b41a37ae@boost-relay.flashbots.net,https://0xa1559ace749633b997cb3fdacffb890aeebdb0f5a3
b6aaa7eeeaf1a38af0a8fe88b9e4b1f61f236d2e64d95733327a62@relay.ultrasound.money

[Install]
WantedBy=default.target

Internet connection speed :

ISP: Free SAS
Idle Latency: 15.45 ms (jitter: 0.33ms, low: 15.24ms, high: 16.00ms)
Download: 935.23 Mbps (data used: 1.6 GB)
44.42 ms (jitter: 24.14ms, low: 15.42ms, high: 362.09ms)
Upload: 626.76 Mbps (data used: 1.1 GB)
16.18 ms (jitter: 2.11ms, low: 15.16ms, high: 38.19ms)
Packet Loss: 0.0%

Mev-boost logs :

May 21 17:57:11 ethstake1.local mev-boost[1139609]: time="2023-05-21T17:57:11+02:00" level=info msg="http: POST /eth/v1/builder/validators 200" duration=0.099271 method=POST path=/eth/v1/builder/va
lidators status=200 version=v1.5.0
May 21 18:00:38 ethstake1.local mev-boost[1139609]: time="2023-05-21T18:00:38+02:00" level=info msg="best bid" blockHash=0x55b9bbadb92dd4be4d10a0ffb2affcbed4e6056a6ba6372d7bcaf35799e413de blockNumb
er=17308790 method=getHeader parentHash=0x467978a22952fcc82d23ef4a1b3ba75b637a86fb6bd35934b8f5e7bcad1090b9 pubkey=0xb28b4c8805056122b8793da25c9d1ce53a04e81bbc40f51d06ac78d52d1eae32b24ea946208897de6
cd6524ec5c2eead relays="https://0xa1559ace749633b997cb3fdacffb890aeebdb0f5a3b6aaa7eeeaf1a38af0a8fe88b9e4b1f61f236d2e64d95733327a62@relay.ultrasound.money" slot=6488401 txRoot=0x392c260d78b53f8f8038
2c2cb70565a178f0dad552563f8aaefd8631445ab443 value=2.299343265057725978 version=v1.5.0
May 21 18:00:38 ethstake1.local mev-boost[1139609]: time="2023-05-21T18:00:38+02:00" level=info msg="http: GET /eth/v1/builder/header/6488401/0x467978a22952fcc82d23ef4a1b3ba75b637a86fb6bd35934b8f5e
7bcad1090b9/0xb28b4c8805056122b8793da25c9d1ce53a04e81bbc40f51d06ac78d52d1eae32b24ea946208897de6cd6524ec5c2eead 200" duration=0.231985 method=GET path=/eth/v1/builder/header/6488401/0x467978a22952fc
c82d23ef4a1b3ba75b637a86fb6bd35934b8f5e7bcad1090b9/0xb28b4c8805056122b8793da25c9d1ce53a04e81bbc40f51d06ac78d52d1eae32b24ea946208897de6cd6524ec5c2eead status=200 version=v1.5.0
May 21 18:00:39 ethstake1.local mev-boost[1139609]: time="2023-05-21T18:00:39+02:00" level=warning msg="error making request to relay, retrying" blockHash=0x55b9bbadb92dd4be4d10a0ffb2affcbed4e6056a
6ba6372d7bcaf35799e413de error="HTTP error response: 400 / {"code":400,"message":"sent too late - 4049 ms into slot"}\n" method=getPayload parentHash=0x467978a22952fcc82d23ef4a1b3ba75b637a86f
b6bd35934b8f5e7bcad1090b9 slot=6488401 url="https://relay.ultrasound.money/eth/v1/builder/blinded_blocks" version=v1.5.0
May 21 18:00:39 ethstake1.local mev-boost[1139609]: time="2023-05-21T18:00:39+02:00" level=warning msg="error making request to relay, retrying" blockHash=0x55b9bbadb92dd4be4d10a0ffb2affcbed4e6056a
6ba6372d7bcaf35799e413de error="HTTP error response: 400 / {"code":400,"message":"sent too late - 4251 ms into slot"}\n" method=getPayload parentHash=0x467978a22952fcc82d23ef4a1b3ba75b637a86f
b6bd35934b8f5e7bcad1090b9 slot=6488401 url="https://relay.ultrasound.money/eth/v1/builder/blinded_blocks" version=v1.5.0
May 21 18:00:39 ethstake1.local mev-boost[1139609]: time="2023-05-21T18:00:39+02:00" level=warning msg="error making request to relay, retrying" blockHash=0x55b9bbadb92dd4be4d10a0ffb2affcbed4e6056a
6ba6372d7bcaf35799e413de error="HTTP error response: 400 / {"code":400,"message":"sent too late - 4436 ms into slot"}\n" method=getPayload parentHash=0x467978a22952fcc82d23ef4a1b3ba75b637a86f
b6bd35934b8f5e7bcad1090b9 slot=6488401 url="https://relay.ultrasound.money/eth/v1/builder/blinded_blocks" version=v1.5.0
May 21 18:00:39 ethstake1.local mev-boost[1139609]: time="2023-05-21T18:00:39+02:00" level=warning msg="error making request to relay, retrying" blockHash=0x55b9bbadb92dd4be4d10a0ffb2affcbed4e6056a
6ba6372d7bcaf35799e413de error="HTTP error response: 400 / {"code":400,"message":"sent too late - 4620 ms into slot"}\n" method=getPayload parentHash=0x467978a22952fcc82d23ef4a1b3ba75b637a86f
b6bd35934b8f5e7bcad1090b9 slot=6488401 url="https://relay.ultrasound.money/eth/v1/builder/blinded_blocks" version=v1.5.0
May 21 18:00:39 ethstake1.local mev-boost[1139609]: time="2023-05-21T18:00:39+02:00" level=warning msg="error making request to relay, retrying" blockHash=0x55b9bbadb92dd4be4d10a0ffb2affcbed4e6056a
6ba6372d7bcaf35799e413de error="HTTP error response: 400 / {"code":400,"message":"sent too late - 4809 ms into slot"}\n" method=getPayload parentHash=0x467978a22952fcc82d23ef4a1b3ba75b637a86f
b6bd35934b8f5e7bcad1090b9 slot=6488401 url="https://relay.ultrasound.money/eth/v1/builder/blinded_blocks" version=v1.5.0
May 21 18:00:39 ethstake1.local mev-boost[1139609]: time="2023-05-21T18:00:39+02:00" level=error msg="error making request to relay" blockHash=0x55b9bbadb92dd4be4d10a0ffb2affcbed4e6056a6ba6372d7bca
f35799e413de error="max retries exceeded" method=getPayload parentHash=0x467978a22952fcc82d23ef4a1b3ba75b637a86fb6bd35934b8f5e7bcad1090b9 slot=6488401 url="https://relay.ultrasound.money/eth/v1/bui
lder/blinded_blocks" version=v1.5.0
May 21 18:00:39 ethstake1.local mev-boost[1139609]: time="2023-05-21T18:00:39+02:00" level=error msg="no payload received from relay!" blockHash=0x55b9bbadb92dd4be4d10a0ffb2affcbed4e6056a6ba6372d7b
caf35799e413de method=getPayload parentHash=0x467978a22952fcc82d23ef4a1b3ba75b637a86fb6bd35934b8f5e7bcad1090b9 relays="https://0xa1559ace749633b997cb3fdacffb890aeebdb0f5a3b6aaa7eeeaf1a38af0a8fe88b9
[email protected]" slot=6488401 version=v1.5.0
May 21 18:00:39 ethstake1.local mev-boost[1139609]: time="2023-05-21T18:00:39+02:00" level=info msg="http: POST /eth/v1/builder/blinded_blocks 502" duration=0.973313 method=POST path=/eth/v1/builde
r/blinded_blocks status=502 version=v1.5.0
May 21 18:03:35 ethstake1.local mev-boost[1139609]: time="2023-05-21T18:03:35+02:00" level=info msg="http: POST /eth/v1/builder/validators 200" duration=0.104025 method=POST path=/eth/v1/builder/va
lidators status=200 version=v1.5.0

Lighthouse validator logs :

May 21 18:00:29 ethstake1.local lighthouse[623535]: May 21 16:00:29.001 INFO Connected to beacon node(s) synced: 1, available: 1, total: 1, service: notifier
May 21 18:00:29 ethstake1.local lighthouse[623535]: May 21 16:00:29.001 INFO All validators active slot: 6488400, epoch: 202762, total_validators: 1, active_validators: 1, current
_epoch_proposers: 1, service: notifier
May 21 18:00:35 ethstake1.local lighthouse[623535]: May 21 16:00:35.003 INFO Requesting unsigned block slot: 6488401, service: block
May 21 18:00:38 ethstake1.local lighthouse[623535]: May 21 16:00:38.935 INFO Received unsigned block slot: 6488401, service: block
May 21 18:00:38 ethstake1.local lighthouse[623535]: May 21 16:00:38.948 INFO Publishing signed block signing_time_ms: 11, slot: 6488401, service: block
May 21 18:00:39 ethstake1.local lighthouse[623535]: May 21 16:00:39.946 ERRO Error whilst producing a blinded block, cannot fallback because the block was signed, error: "Some endpoints failed, num
_failed: 1 http://localhost:5052/ => RequestFailed(Irrecoverable("Error from beacon node when publishing block: ServerMessage(ErrorMessage { code: 500, message: \"INTERNAL_SERVER_ERROR: Blind bl
ock proposal failed: Builder(ServerMessage(ErrorMessage { code: 502, message: \\\"no successful relay response\\\", stacktraces: [] }))\", stacktraces: [] })"))", service: block
May 21 18:00:39 ethstake1.local lighthouse[623535]: May 21 16:00:39.947 CRIT Error whilst producing block message: Irrecoverable("Some endpoints failed, num_failed: 1 http://localhost:50
52/ => RequestFailed(Irrecoverable("Error from beacon node when publishing block: ServerMessage(ErrorMessage { code: 500, message: \"INTERNAL_SERVER_ERROR: Blind block proposal failed: Builder(S
erverMessage(ErrorMessage { code: 502, message: \\\"no successful relay response\\\", stacktraces: [] }))\", stacktraces: [] })"))"), service: block

...skipping 1 line
May 21 18:00:41 ethstake1.local lighthouse[623535]: May 21 16:00:41.000 INFO All validators active slot: 6488401, epoch: 202762, total_validators: 1, active_validators: 1, current
_epoch_proposers: 1, service: notifier
May 21 18:00:46 ethstake1.local lighthouse[623535]: May 21 16:00:46.036 INFO Connected to beacon node endpoint: http://localhost:5052/, version: Lighthouse/v4.1.0-693886b/x86_64-linu
x

Lighthouse beacon logs :

May 21 18:00:17 ethstake1.local lighthouse[623513]: May 21 16:00:17.005 INFO Synced slot: 6488399, block: 0x4319…e99b, epoch: 202762, finalized_epoch: 202760, final
ized_root: 0xb0d8…2d99, exec_hash: 0x4846…9f7f (verified), peers: 82, service: slot_notifier
May 21 18:00:23 ethstake1.local lighthouse[623513]: May 21 16:00:23.027 INFO Prepared beacon proposer parent_root: 0x431942805b0f6e5d5118203514b2c66f5bff70c51c1ed0d114b7aa13ec45e99b,
validator: 12610, prepare_slot: 6488401, service: beacon
May 21 18:00:25 ethstake1.local lighthouse[623513]: May 21 16:00:25.357 INFO New block received root: 0x3ee4a8c68a4d02f13567e7e399d8c67f0ef4659ca8b52e0cd69382ee8da5912d, slot:
6488400
May 21 18:00:25 ethstake1.local lighthouse[623513]: May 21 16:00:25.935 INFO Prepared beacon proposer parent_root: 0x3ee4a8c68a4d02f13567e7e399d8c67f0ef4659ca8b52e0cd69382ee8da5912d,
validator: 12610, prepare_slot: 6488401, service: beacon
May 21 18:00:29 ethstake1.local lighthouse[623513]: May 21 16:00:29.002 INFO Synced slot: 6488400, block: 0x3ee4…912d, epoch: 202762, finalized_epoch: 202760, final
ized_root: 0xb0d8…2d99, exec_hash: 0x4679…90b9 (verified), peers: 88, service: slot_notifier
May 21 18:00:38 ethstake1.local lighthouse[623513]: May 21 16:00:38.545 INFO Requesting blinded header from connected builder, parent_hash: 0x467978a22952fcc82d23ef4a1b3ba75b637a86fb6bd35934b8f5e7b
cad1090b9, pubkey: 0xb28b4c8805056122b8793da25c9d1ce53a04e81bbc40f51d06ac78d52d1eae32b24ea946208897de6cd6524ec5c2eead, slot: Slot(6488401), service: exec
May 21 18:00:38 ethstake1.local lighthouse[623513]: May 21 16:00:38.781 INFO Requested blinded execution payload parent_hash: 0x467978a22952fcc82d23ef4a1b3ba75b637a86fb6bd35934b8f5e7bcad1090b9,
local_response_ms: 82, local_fee_recipient: 0x6a4f1fe4c77ecda51735805507b997894b5fb982, relay_response_ms: 236, relay_fee_recipient: 0x1f9090aae28b8a3dceadf281b0f12828e676c326, service: exec
May 21 18:00:38 ethstake1.local lighthouse[623513]: May 21 16:00:38.781 INFO Received local and builder payloads parent_hash: 0x467978a22952fcc82d23ef4a1b3ba75b637a86fb6bd35934b8f5e7bcad1090b9,
local_block_hash: 0x1a0345e6c0791ddeaa1aa4964567a2e4e0d93e1ec5e7ed5b387f73830af916c1, relay_block_hash: 0x55b9bbadb92dd4be4d10a0ffb2affcbed4e6056a6ba6372d7bcaf35799e413de, service: exec
May 21 18:00:38 ethstake1.local lighthouse[623513]: May 21 16:00:38.970 ERRO Block broadcast was delayed root: 0xd268499d82495f285399326f38fa29349ddcc70901eccdab27c11546971a3cfd, slot:
6488401, delay_ms: 3969, provenance: builder, msg: system may be overloaded, block may be orphaned
May 21 18:00:39 ethstake1.local lighthouse[623513]: May 21 16:00:39.944 WARN Builder failed to reveal payload parent_hash: "0x4679…90b9", block_root: 0xd268499d82495f285399326f38fa29349ddcc7
0901eccdab27c11546971a3cfd, relay_response_ms: 974, error: Builder(ServerMessage(ErrorMessage { code: 502, message: "no successful relay response", stacktraces: [] })), info: this is common behavio
ur for some builders and may not indicate an issue, service: exec
May 21 18:00:39 ethstake1.local lighthouse[623513]: May 21 16:00:39.945 WARN Error processing HTTP API request method: POST, path: /eth/v1/beacon/blinded_blocks, status: 500 Internal Server E
rror, elapsed: 995.172056ms
May 21 18:00:41 ethstake1.local lighthouse[623513]: May 21 16:00:41.001 INFO Synced slot: 6488401, block: … empty, epoch: 202762, finalized_epoch: 202760, final
ized_root: 0xb0d8…2d99, exec_hash: 0x4679…90b9 (verified), peers: 88, service: slot_notifier

Geth logs :

May 21 17:59:49 ethstake1.local geth[623818]: INFO [05-21|17:59:49.940] Chain head was updated number=17,308,786 hash=0dacb9..08672e root=313d48..6a94d0 elapsed=5.071822ms
May 21 18:00:01 ethstake1.local geth[623818]: INFO [05-21|18:00:01.425] Imported new potential chain segment number=17,308,787 hash=ac02ef..f85382 blocks=1 txs=177 mgas=20.831 elapsed=176.636m
s mgasps=117.931 dirty=1022.10MiB
May 21 18:00:01 ethstake1.local geth[623818]: INFO [05-21|18:00:01.630] Chain head was updated number=17,308,787 hash=ac02ef..f85382 root=440238..373742 elapsed=5.892012ms
May 21 18:00:13 ethstake1.local geth[623818]: INFO [05-21|18:00:13.544] Imported new potential chain segment number=17,308,788 hash=4846bc..b39f7f blocks=1 txs=563 mgas=28.498 elapsed=327.373m
s mgasps=87.049 dirty=1022.63MiB
May 21 18:00:13 ethstake1.local geth[623818]: INFO [05-21|18:00:13.817] Chain head was updated number=17,308,788 hash=4846bc..b39f7f root=2af664..ef4de5 elapsed=12.231796ms
May 21 18:00:25 ethstake1.local geth[623818]: INFO [05-21|18:00:25.698] Imported new potential chain segment number=17,308,789 hash=467978..1090b9 blocks=1 txs=198 mgas=17.127 elapsed=156.770m
s mgasps=109.246 dirty=1022.57MiB
May 21 18:00:25 ethstake1.local geth[623818]: INFO [05-21|18:00:25.930] Chain head was updated number=17,308,789 hash=467978..1090b9 root=b0daae..501e67 elapsed=8.833415ms
May 21 18:00:31 ethstake1.local geth[623818]: INFO [05-21|18:00:31.258] Starting work on payload id=0xf676267490e34227
May 21 18:00:31 ethstake1.local geth[623818]: INFO [05-21|18:00:31.879] Updated payload id=0xf676267490e34227 number=17,308,790 hash=16a816..7192dc txs=146 gas=15,356,722
fees=0.08419713087 root=75081d..8dbeb8 elapsed=620.746ms
May 21 18:00:33 ethstake1.local geth[623818]: INFO [05-21|18:00:33.968] Updated payload id=0xf676267490e34227 number=17,308,790 hash=f0aeff..8504c1 txs=181 gas=18,046,689
fees=0.1565930646 root=1bdaf0..0cd0a3 elapsed=87.547ms
May 21 18:00:36 ethstake1.local geth[623818]: INFO [05-21|18:00:36.081] Updated payload id=0xf676267490e34227 number=17,308,790 hash=6ba6a9..284e5d txs=202 gas=20,337,955
fees=0.1592364734 root=c1c907..17cf9c elapsed=112.834ms
May 21 18:00:38 ethstake1.local geth[623818]: INFO [05-21|18:00:38.317] Updated payload id=0xf676267490e34227 number=17,308,790 hash=1a0345..f916c1 txs=226 gas=23,659,356
fees=0.1606250069 root=47b483..16056b elapsed=235.263ms
May 21 18:00:38 ethstake1.local geth[623818]: INFO [05-21|18:00:38.554] Stopping work on payload id=0xf676267490e34227 reason=delivery
May 21 18:00:50 ethstake1.local geth[623818]: INFO [05-21|18:00:50.354] Imported new potential chain segment number=17,308,790 hash=35cb46..e134b9 blocks=1 txs=300 mgas=29.986 elapsed=364.200m
s mgasps=82.335 dirty=1022.46MiB
May 21 18:00:50 ethstake1.local geth[623818]: INFO [05-21|18:00:50.795] Chain head was updated number=17,308,790 hash=35cb46..e134b9 root=b4079f..d261a8 elapsed=8.559389ms
May 21 18:01:01 ethstake1.local geth[623818]: INFO [05-21|18:01:01.470] Imported new potential chain segment number=17,308,791 hash=f63ab5..2de1f0 blocks=1 txs=216 mgas=19.394 elapsed=389.033m
s mgasps=49.853 dirty=1022.53MiB
May 21 18:01:02 ethstake1.local geth[623818]: INFO [05-21|18:01:02.209] Chain head was updated number=17,308,791 hash=f63ab5..2de1f0 root=b15e1b..16bba7 elapsed=39.005056ms
May 21 18:01:12 ethstake1.local geth[623818]: INFO [05-21|18:01:12.898] Imported new potential chain segment number=17,308,792 hash=c76cdd..18a8da blocks=1 txs=154 mgas=10.917 elapsed=137.189m
s mgasps=79.577 dirty=1021.79MiB
May 21 18:01:13 ethstake1.local geth[623818]: INFO [05-21|18:01:13.074] Chain head was updated number=17,308,792 hash=c76cdd..18a8da root=ef1835..5eb9e5 elapsed=4.151622ms
May 21 18:01:24 ethstake1.local geth[623818]: INFO [05-21|18:01:24.612] Imported new potential chain segment number=17,308,793 hash=6e6104..1de798 blocks=1 txs=153 mgas=11.243 elapsed=200.568m
s mgasps=56.056 dirty=1022.12MiB
May 21 18:01:24 ethstake1.local geth[623818]: INFO [05-21|18:01:24.913] Chain head was updated number=17,308,793 hash=6e6104..1de798 root=6b1e67..12ed38 elapsed=4.385776ms
May 21 18:01:38 ethstake1.local geth[623818]: INFO [05-21|18:01:38.081] Imported new potential chain segment number=17,308,794 hash=3af4a3..f9825e blocks=1 txs=158 mgas=17.949 elapsed=182.529m
s mgasps=98.334 dirty=1022.10MiB
May 21 18:01:38 ethstake1.local geth[623818]: INFO [05-21|18:01:38.309] Chain head was updated number=17,308,794 hash=3af4a3..f9825e root=8d4c35..d4e67a elapsed=4.736565ms
May 21 18:01:49 ethstake1.local geth[623818]: INFO [05-21|18:01:49.411] Imported new potential chain segment number=17,308,795 hash=d652fe..40f949 blocks=1 txs=140 mgas=12.028 elapsed=138.475m
s mgasps=86.862 dirty=1021.97MiB
May 21 18:01:49 ethstake1.local geth[623818]: INFO [05-21|18:01:49.552] Chain head was updated number=17,308,795 hash=d652fe..40f949 root=5e3984..f22134 elapsed=3.158046ms
May 21 18:02:00 ethstake1.local geth[623818]: INFO [05-21|18:02:00.844] Imported new potential chain segment number=17,308,796 hash=ca6a8c..499fd7 blocks=1 txs=146 mgas=11.937 elapsed=197.200m
s mgasps=60.532 dirty=1021.86MiB

[Piradoxlanieve]

The same thing that happened to me has taken you more than 4 seconds to send and it has been rejected. #516
I have an issue open in prysm too, they seem to have released a flag to build in parallel, I don't know if their consensus client has worked on that.
Sorry my bad english.

[metachris]

Same issue as #516 -- network issues between proposer and ultrasound relay, making the getPayload request arrive too late at the relay and getting rejected (slot would have been missed anyway because any block after 4 seconds is rejected by the beacon network / CL clients).

For reference -- this was for slot 6,488,401 with start timestamp 1,684,684,835 (which is Sun May 21 2023 16:00:35 GMT+0000). getHeader response arrived at :38, which is already 3 seconds into the slot.

We may want to consider mev-boost not to return a header if it's past 3 seconds into the slot already 🤔 cc/ @ralexstokes
@michaelneuder @jtraglia @terencechain

Closing this issue now, as there's nothing else to do here.

[metachris]

opened an issue to discuss possible mitigations: #518

thanks for the report 🙏