Proposed block and mevboost timed out

[PanosChtz]

I've been using mevboost for some time and have proposed some blocks with mev normally. However a couple of days ago I noticed that mevboost timed out, fortunately my CL proposed the block but without mev.
Is there anything abnormal about this or is it just a random thing?
Posting logs from nimbus and mevboost below.

Jun 14 22:42:36 validator nimbus_beacon_node[2904275]: WRN 2023-06-14 22:42:36.990+00:00 Could not obtain blinded execution payload header topics="beacval" error="getBlindedExecutionPayload timed out" slot=6663211 validator_index=109040 head=a346460e:6663210

Jun 14 22:42:36 validator nimbus_beacon_node[2904275]: INF 2023-06-14 22:42:36.992+00:00 Payload builder error                      topics="beacval" slot=6663211 head=a346460e:6663210 validator=afe1ab14 err="getBlindedExecutionPayload timed out"

Jun 14 22:42:36 validator mev-boost[1063926]: time="2023-06-14T22:42:36Z" level=info msg="best bid" blockHash=0xdaee9f006ecc1b2442c303abbb0507c2373cc65a5b822fa7b4f95b44b881a2b4 blockNumber=17481214 method=getHeader parentHash=0xe5ff879d961c5d3ea5bfb455c65baebd92de7fa39c7df3e201d90b902cf180b2 pubkey=0xafe1ab147ad6b91cd77a79c4762bdf80a410c35e523a88b23082995b3a81cd633a05b08d987b6899b827ff9f50a30f41 relays=https://0x8b5d2e73e2a3a55c6c87b8b6eb92e0149a125c852751db1422fa951e42a09b82c142c3ea98d0d9930b056a3bc9896b8f@bloxroute.max-profit.blxrbdn.com/ slot=6663211 txRoot=0x3297a8df11f50691e7f7362be69739d6ccbf1d1c147b2f42f24a69937cbc7628 value=0.030212656458174002 version=v1.5.0

Jun 14 22:42:36 validator mev-boost[1063926]: time="2023-06-14T22:42:36Z" level=info msg="http: GET /eth/v1/builder/header/6663211/0xe5ff879d961c5d3ea5bfb455c65baebd92de7fa39c7df3e201d90b902cf180b2/0xafe1ab147ad6b91cd77a79c4762bdf80a410c35e523a88b23082995b3a81cd633a05b08d987b6899b827ff9f50a30f41 200" duration=0.142337 method=GET path=/eth/v1/builder/header/6663211/0xe5ff879d961c5d3ea5bfb455c65baebd92de7fa39c7df3e201d90b902cf180b2/0xafe1ab147ad6b91cd77a79c4762bdf80a410c35e523a88b23082995b3a81cd633a05b08d987b6899b827ff9f50a30f41 status=200 version=v1.5.0

[ralexstokes]

it looks like there may be some internal logic to nimbus that times out 1 second into the slot

so for some reason, your local node was just a little slow to build the block and rather than run the risk of having a missed slot via the mev-boost network, it just went w/ local building

id check in w/ the nimbus team to see if such a timeout exists

[tersec]

Yes, Nimbus has such internal logic, for the reasons noted; https://github.com/status-im/nimbus-eth2/blob/11f5250ce4e786625382282a00f2dfc87183d1fc/beacon_chain/spec/mev/bellatrix_mev.nim#L70 defines

  # Spec is 1 second, but mev-boost indirection can induce delay when the relay
  # itself has already consumed the entire second.
  BUILDER_PROPOSAL_DELAY_TOLERANCE* = 1500.milliseconds

which did change in v23.5.1 from v23.5.0, but increased from 1 second to 1.5 seconds.

So, if the getHeader call to mev-boost took 1.5 seconds, this is the intended result.

According to one client I checked logs of, 2023-06-14 22:42:35 is the timestamp of slot 6663211, and

WRN 2023-06-14 22:42:36.990 (timeout happened)

is consistent with this scenario, being almost 2 seconds after the slot start.

[PanosChtz]

I see - so CPU or network latency was responsible for this slowness? What can I do to prevent this in the future? I had 2 relays in the mevboost parameters, would remaining with only one relay decrease the likelihood of a timeout?

[PanosChtz]

My validator proposed another block today, and the exact same issue happened.
Nimbus log:

Sep 05 02:58:11 validator nimbus_beacon_node[131573]: INF 2023-09-05 02:58:11.000+00:00 Slot start                                 topics="beacnde" slot=7254889 epoch=226715 sync=synced peers=160 head=96bb67ed:7254888 finalized=226713:49ce329d delay=392us833ns
Sep 05 02:58:14 validator nimbus_beacon_node[131573]: INF 2023-09-05 02:58:14.038+00:00 Missed multiple heartbeats                 topics="libp2p gossipsub" heartbeat=GossipSub delay=2s182ms167us710ns hinterval=700ms
Sep 05 02:58:14 validator nimbus_beacon_node[131573]: WRN 2023-09-05 02:58:14.051+00:00 Could not obtain blinded execution payload header topics="beacval" error="getBlindedExecutionPayload timed out" slot=7254889 validator_index=109040 head=96bb67ed:7254888
Sep 05 02:58:14 validator nimbus_beacon_node[131573]: INF 2023-09-05 02:58:14.876+00:00 Payload builder error                      topics="beacval" slot=7254889 head=96bb67ed:7254888 validator=afe1ab14 err="getBlindedExecutionPayload timed out"
Sep 05 02:58:15 validator nimbus_beacon_node[131573]: NOT 2023-09-05 02:58:15.151+00:00 Block sent                                 blockRoot=5b812602 blck="(slot: 7254889, proposer_index: 109040, parent_root: \"96bb67ed\", state_root: \"2e3c3b70\", eth1data: (deposit_root: 2ef7b8f8804117976cc8f3d24944c375826cec284a0db0a6c9d632b387e6f863, deposit_count: 946993, block_hash: e88a7ba924d07fd0ccd333912bb3fcd55f8a95cf0171e010eb560b8cdd17bdaf), graffiti: \"Lailapa Taxi 2001\", proposer_slashings_len: 0, attester_slashings_len: 0, attestations_len: 75, deposits_len: 0, voluntary_exits_len: 0, sync_committee_participants: 509, block_number: 18067445, fee_recipient: \"0xa7fae5fae8e8df64f4ab835b1717206aff249960\", bls_to_execution_changes_len: 0, blob_kzg_commitments_len: 0)" signature=a452cfba delay=3s913ms389us455ns
Sep 05 02:58:16 validator nimbus_beacon_node[131573]: NOT 2023-09-05 02:58:16.647+00:00 Block proposed                             topics="beacval" blockRoot=5b812602 blck="(slot: 7254889, proposer_index: 109040, parent_root: \"96bb67ed\", state_root: \"2e3c3b70\", eth1data: (deposit_root: 2ef7b8f8804117976cc8f3d24944c375826cec284a0db0a6c9d632b387e6f863, deposit_count: 946993, block_hash: e88a7ba924d07fd0ccd333912bb3fcd55f8a95cf0171e010eb560b8cdd17bdaf), graffiti: \"Lailapa Taxi 2001\", proposer_slashings_len: 0, attester_slashings_len: 0, attestations_len: 75, deposits_len: 0, voluntary_exits_len: 0, sync_committee_participants: 509, block_number: 18067445, fee_recipient: \"0xa7fae5fae8e8df64f4ab835b1717206aff249960\", bls_to_execution_changes_len: 0, blob_kzg_commitments_len: 0)" signature=a452cfba validator=afe1ab14
Sep 05 02:58:21 validator nimbus_beacon_node[131573]: INF 2023-09-05 02:58:21.216+00:00 Slot end                                   topics="beacnde" slot=7254889 nextActionWait=37s783ms505us443ns nextAttestationSlot=7254893 nextProposalSlot=-1 syncCommitteeDuties=none head=5b812602:7254889

mevboost log (nothing seems to be going on here? This time mevboost didn't even get a request from nimbus?):

Sep 05 02:56:38 validator mev-boost[935]: time="2023-09-05T02:56:38.001Z" level=info msg="http: GET /eth/v1/builder/status 200" duration=0.200049 method=GET path=/eth/v1/builder/status status=200 version=v1.6
Sep 05 02:56:39 validator mev-boost[935]: time="2023-09-05T02:56:39.691Z" level=info msg="http: POST /eth/v1/builder/validators 200" duration=0.139871 method=POST path=/eth/v1/builder/validators status=200 version=v1.6
Sep 05 03:03:01 validator mev-boost[935]: time="2023-09-05T03:03:01.022Z" level=info msg="http: GET /eth/v1/builder/status 200" duration=0.156145 method=GET path=/eth/v1/builder/status status=200 version=v1.6
Sep 05 03:03:01 validator mev-boost[935]: time="2023-09-05T03:03:01.784Z" level=info msg="http: POST /eth/v1/builder/validators 200" duration=0.070375 method=POST path=/eth/v1/builder/validators status=200 version=v1.6

Using most up-to date clients.