Skip to content

Nimbus Validator timeout issues with Obol Charon #4675

Open
Open
Nimbus Validator timeout issues with Obol Charon#4675
Labels
protocolProtocol Team tickets

Description

@thoutenbos
thoutenbos
opened on Sep 1, 2026

Summary

On a steady-state 4-node cluster (hours of uptime, no restarts), a subset of GET /eth/v1/validator/attestation_data requests from the Nimbus validator client are never answered by Charon. They hang until the VC's own client-side timeout cancels them (~4.0s, occasionally ~10.0s for aggregate_beacon_committee_selections), rather than Charon responding or erroring on its own. A packet capture of the relevant beacon-node call in one such window shows the beacon node itself responding in ~30ms, so the request is not waiting on the beacon node. Two pprof goroutine dumps, taken ~16 minutes apart during separate live hangs, both show the request parked inside DutyDB.AwaitAttestation. This reproduces repeatedly (roughly 15-25% of attester duties in the observed windows) and is not limited to a startup window — the two goroutine dumps were both taken well after the cluster had settled.

Charon version

v1.10.3 (obolnetwork/charon/v1.10.3-e60c838, amd64-linux)

Environment

  • 4-node DV cluster
  • Consensus protocol: QBFT v2.0
  • Beacon node behind Charon: Nimbus BN v26.7.0 and v26.8.0
  • Validator client: Nimbus VC v26.7.0 and v26.8.0
  • CPU, memory, and disk I/O all nominal throughout the observation window
    (see Metrics below)

Expected behavior

attestation_data should be answered within tens of milliseconds, as it is for the majority of duties — for example:

11:57:15.000 DEBG qbft QBFT consensus instance starting {"duty": "15119384/attester", ...}
11:57:15.017 DEBG qbft QBFT upon rule triggered {"rule": "justified_pre_prepare", "round": 1, "duty": "15119384/attester"}
11:57:15.020 DEBG qbft QBFT upon rule triggered {"rule": "quorum_prepares", "round": 1, "duty": "15119384/attester"}
11:57:15.046 DEBG qbft QBFT upon rule triggered {"rule": "quorum_commits", "round": 1, "duty": "15119384/attester"}
11:57:15.046 DEBG qbft QBFT consensus decided {"duty": "attester", "slot": 15119384, "round": 1, ...}
11:57:15.080 INFO bcast Successfully submitted v2 attestations to beacon node {"delay": "80.726095ms", "duty": "15119384/attester", ...}

Actual behavior

For the affected duties, no qbft component log line appears at all for that duty — no consensus start, no round activity — while the duties immediately before and after it in the same log complete normally as above. The corresponding attestation_data request instead sits until the VC cancels it:

DEBG vapi Validator api 4xx response {"status_code": 408, "message": "client cancelled request",
  "error": "api error[status=408,msg=client cancelled request]: context canceled",
  "duration": "4.003078158s", "vapi_endpoint": "attestation_data"}

Evidence

General timing pattern

Across every observed instance (failing and succeeding duties alike), Charon issues GET /eth/v1/beacon/blocks/head/root to the upstream beacon node a consistent ~2.00s after the SSE head event for that slot. For failing duties, this call is the last thing logged before the VC's request is cancelled 4.00-4.05s later; for succeeding duties, consensus has already decided before this call fires. Three concrete, timestamp-correlated instances are below.

Instance 1 — packet capture

Charon debug log (all times CEST, UTC+2):

Sep 01 11:33:26 eth charon[40072]: 11:33:26.650 DEBG vapi Proxying request to beacon node {"url": "http://127.0.0.1:5052", "vapi_proxy_method": "GET", "vapi_proxy_path": "/eth/v1/beacon/blocks/head/root"}
Sep 01 11:33:30 eth charon[40072]: 11:33:30.652 DEBG vapi Validator api 4xx response {"status_code": 408, "message": "client cancelled request", "error": "api error[status=408,msg=client cancelled request]: context canceled", "duration": "4.00201019s", "vapi_endpoint": "attestation_data"}

tcpdump of the same call (frame times are UTC, i.e. 2 hours behind the CEST log timestamps above — 09:33:26.65 in the
capture is the same instant as 11:33:26.650 in the log):

No.   Time              Source      Destination  Protocol  Length  Info
459   09:33:26.650408   127.0.0.1   127.0.0.1    TCP       74      36352 -> 5052 [SYN] ...
460   09:33:26.650419   127.0.0.1   127.0.0.1    TCP       74      5052 -> 36352 [SYN, ACK] ...
461   09:33:26.650427   127.0.0.1   127.0.0.1    TCP       66      36352 -> 5052 [ACK] ...
462   09:33:26.650540   127.0.0.1   127.0.0.1    HTTP      217     GET /eth/v1/beacon/blocks/head/root HTTP/1.1
463   09:33:26.650547   127.0.0.1   127.0.0.1    TCP       66      5052 -> 36352 [ACK] ...
464   09:33:26.680164   127.0.0.1   127.0.0.1    TCP       235     5052 -> 36352 [PSH, ACK] [TCP PDU reassembled in 466]
465   09:33:26.680172   127.0.0.1   127.0.0.1    TCP       66      36352 -> 5052 [ACK] ...
466   09:33:26.680180   127.0.0.1   127.0.0.1    HTTP/JSON 199     HTTP/1.1 200 OK , JSON (application/json)
467   09:33:26.680183   127.0.0.1   127.0.0.1    TCP       66      36352 -> 5052 [ACK] ...
468   09:33:26.680192   127.0.0.1   127.0.0.1    TCP       66      5052 -> 36352 [FIN, ACK] ...
469   09:33:26.680276   127.0.0.1   127.0.0.1    TCP       66      36352 -> 5052 [FIN, ACK] ...
470   09:33:26.680292   127.0.0.1   127.0.0.1    TCP       66      5052 -> 36352 [ACK] ...

The SYN at frame 459 (09:33:26.650408) lines up with the Proxying request log line at 11:33:26.650. The full TCP exchange — connect, request, 200 OK JSON response, teardown — completes by 09:33:26.680292, roughly 30ms after it started. The attestation_data request is not cancelled until 11:33:30.652, exactly 4.00201019s after the Proxying request log line.

Instance 2 — pprof dump correlated with log, duty 15119321

Charon debug log:

11:44:38.056 DEBG app-start SSE head event {"slot": 15119321, ...}
11:44:40.058 DEBG vapi Proxying request to beacon node {"url": "http://127.0.0.1:5052", "vapi_proxy_method": "GET", "vapi_proxy_path": "/eth/v1/beacon/blocks/head/root"}
11:44:44.061 DEBG vapi Validator api 4xx response {"status_code": 408, "duration": "4.003078158s", "vapi_endpoint": "attestation_data"}
11:44:45.009 DEBG vapi Validator api 4xx response {"status_code": 408, "duration": "10.000526116s", "vapi_endpoint": "aggregate_beacon_committee_selections"}

A pprof goroutine dump was taken at 11:44:41 — i.e. during the hang, between the Proxying request line and the eventual 408:

$ date && curl http://127.0.0.1:3700/debug/pprof/goroutine?debug=2
Tue Sep  1 11:44:41 CEST 2026
...
goroutine 3642 [select]:
github.com/obolnetwork/charon/core/dutydb.(*MemDB).AwaitAttestation(0x3c0fc45c3b00, {0x21f49c8, 0x3c0fc4c8fa40}, 0xe6b3d9, 0x0)
	/workspace/core/dutydb/memory.go:198 +0x527
github.com/obolnetwork/charon/core/validatorapi.Component.AttestationData({...}, ...)
	/workspace/core/validatorapi/validatorapi.go:266 +0x24f
github.com/obolnetwork/charon/core/validatorapi.NewRouter.attestationData.func5(...)
	/workspace/core/validatorapi/router.go:524 +0xb9
...

0xe6b3d9 = decimal 15119321, i.e. this goroutine is the exact request shown timing out in the log above.

The same dump also shows a second request, for aggregate_beacon_committee_selections, blocked the same way in a different
component:

goroutine 3424 [select]:
github.com/obolnetwork/charon/core/aggsigdb.(*MemDB).Await(0x3c0fc4a1cba0, {0x21f49c8, 0x3c0fc5501950}, {0x3c0fc52631f0?, 0x0?}, {0x3c0fc52631f0, 0x62})
	/workspace/core/aggsigdb/memory.go:106 +0x308
github.com/obolnetwork/charon/core/validatorapi.Component.BeaconCommitteeSelections({...}, ...)
	/workspace/core/validatorapi/validatorapi.go:793 +0x827
...

And two further goroutines, for earlier slots, blocked in the same AggSigDB.Await call but with no live HTTP request attached — these were spawned via the async-retry wrapper:

goroutine 1056 [select, 1 minutes]:
github.com/obolnetwork/charon/core/aggsigdb.(*MemDB).Await(...)
	/workspace/core/aggsigdb/memory.go:106 +0x308
github.com/obolnetwork/charon/core/fetcher.(*Fetcher).fetchAggregatorData(...)
	/workspace/core/fetcher/fetcher.go:291 +0x2ed
github.com/obolnetwork/charon/core/fetcher.(*Fetcher).Fetch(...)
	/workspace/core/fetcher/fetcher.go:159 +0xa67
github.com/obolnetwork/charon/app.wireCoreWorkflow.WithAsyncRetry.func12.1.1(...)
	/workspace/core/retry.go:17 +0x32
github.com/obolnetwork/charon/app/retry.(*Retryer[...]).DoAsync(...)
	/workspace/app/retry/retry.go:135 +0x72e
...

goroutine 2668 [select]:
(identical stack, different slot)

Instance 3 — second pprof dump, ~16 minutes later, duty 15119385

Charon debug log:

11:57:26.421 DEBG app-start SSE head event {"slot": 15119385, ...}
11:57:28.422 DEBG vapi Proxying request to beacon node {"url": "http://127.0.0.1:5052", "vapi_proxy_method": "GET", "vapi_proxy_path": "/eth/v1/beacon/blocks/head/root"}
11:57:32.425 DEBG vapi Validator api 4xx response {"status_code": 408, "duration": "4.003295409s", "vapi_endpoint": "attestation_data"}

pprof dump taken at 11:57:30, again during the hang:

$ date && curl http://127.0.0.1:3700/debug/pprof/goroutine?debug=2
Tue Sep  1 11:57:30 CEST 2026
...
goroutine 34489 [select]:
github.com/obolnetwork/charon/core/dutydb.(*MemDB).AwaitAttestation(0x3c0fc45c3b00, {0x21f49c8, 0x3c0fc576b7a0}, 0xe6b419, 0x0)
	/workspace/core/dutydb/memory.go:198 +0x527
github.com/obolnetwork/charon/core/validatorapi.Component.AttestationData({...}, ...)
	/workspace/core/validatorapi/validatorapi.go:266 +0x24f
...

0xe6b419 = decimal 15119385, again matching the request shown timing out above. Duties 15119384 and 15119386 (immediately before and after) both completed normally, as shown in the "Expected behavior" section.

Metrics reviewed

/metrics on the beacon node, captured during an active hang window:

  • ticks_delay (time to run the beacon node's onSecond loop; nominal is
    ~1.0): 1.000878542
  • Per-block processing fields logged alongside each Block resolved line
    (sigVerifyDur, stateVerifyDur, stateDataDur, putBlockDur):
    consistently ~10-30ms across both successful and failing slots, with no
    correlation to which duties fail
  • process_cpu_seconds_total, nim_gc_mem_bytes,
    sqlite3_memory_used_bytes, db_checkpoint_seconds_total: nothing
    anomalous in the captured snapshot

What we've ruled out

  • Slow response from the upstream beacon node — Instance 1's packet
    capture shows the specific call Charon makes to the beacon node completing
    in ~30ms.
  • Network/loopback issues — same packet capture: clean SYN/ACK, request,
    200 OK, and teardown with no retransmissions.
  • Host resource exhaustion — CPU, disk I/O, and memory were all normal
    during the observation windows; the beacon node's own event-loop-lag metric
    (ticks_delay) stayed at its nominal ~1.0 value.
  • Other VC — Seems to only happen using Nimbus VC

Additional info

  • We have a live, currently-affected v1.10.3 cluster and can gather further
    debug logs, additional pprof dumps (CPU, block, or mutex profiles), or test
    a patched/instrumented build if that would help.
  • Happy to attach the complete raw logs and full goroutine dumps (trimmed
    above for readability) if useful.
  • If this is already addressed in a later release, a pointer to
    the relevant change would be appreciated so we can upgrade and confirm.

Activity

  1. github-actions
    added
    protocolProtocol Team tickets
    on Sep 1, 2026

  2. KaloyanTanev commented on Sep 8, 2026

    @KaloyanTanev
    KaloyanTanev
    on Sep 8, 2026
    Collaborator

    Thanks for reporting this @thoutenbos! Let me shed some light on how Charon behaves on attestation_data request from the VC:

    1. Charon requests attestation data from the BN at exactly 4s into the slot. N.B.: In the scenario where early fetch feature is enabled it will ask when it receives the SSE head event or at 4s into the slot, whichever comes first.
    2. Parallel to the above, we expect the VC to request attestation data at exactly 4s as well. We block this request and wait on a value to be written to Charon's DB.
    3. Parallel to the above, again at exactly 4s into the slot, QBFT consensus is started, on which Charon awaits attestation data from the leader node. If the current Charon node is a leader it proposes the value it fetched from step 1 and does QBFT rounds with the other nodes.
    4. Once the nodes decide on a value, it is saved to the DB. Then the request from step 2 is unblocked and Charon serves the agreed upon data to the VC.

    Having this flow in mind, it seems like steps 1 and 3 are not even started in Charon, which likely means Charon hasn't even scheduled those duties and hasn't initiated a fetch or QBFT instance on first place.

    1. Can you check if this is apparent for all Charon nodes in the cluster or only some specific ones?
    2. Can you distinguish if it's for some specific validators?
    3. Do you see any /eth/v1/validator/duties/attester/{epoch} requests failing in the metrics (likely seen as attesterDuties throughout Charon)? Or some errors with the duties cache in the logs / metrics?
    4. Have you ran by any chance any cluster edit commands?
    5. Can you sanity check if your validator_keys directory matches your cluster_lock.json in terms of amount of keys?

  3. thoutenbos commented on Sep 9, 2026

    @thoutenbos
    thoutenbos
    on Sep 9, 2026
    Author

    Thanks for the detailed breakdown of the request flow — that's very helpful context. Answers below, plus one new finding from correlating timestamps across the log lines.

    1. All nodes or only some?

    One other member had the same behaviour when using Nimbus VC but it was resolved by switching it to Lodestar VC.

    2. Specific validators?

    No — architecturally this shouldn't be validator-specific. attestation_data is scoped to (slot, committee_index), not to a validator pubkey, and the 408 cancellation log line itself carries no pubkey or committee_index — just status_code, duration, vapi_endpoint. Every duty in a failing slot shares the same underlying fetch.

    3. /eth/v1/validator/duties/attester/{epoch} failures or duties-cache errors?

    • Zero vapi_endpoint: duties* log lines in the last 24h, and no errors tied to duty scheduling.
    • The only duties-cache activity is periodic Reorg occurred through epoch transition, invalidating duties cache (DEBG, expected behavior) a few times a day — timing doesn't correlate with the steady hourly cancellation rate, so this doesn't look like the driver.

    4. Cluster edit commands run?

    No — confirmed, no cluster edit or other cluster-modifying commands have been run since setup.

    5. validator_keys/ vs cluster_lock.json key count?

    Confirmed matching.

    New finding: timing correlation across ~20 consecutive slots

    I pulled every Slot ticked / SSE head event / Proxying request to beacon node {blocks/head/root} / QBFT consensus decided / Validator api 4xx response line for a clean 5-minute window (slots 15178348-15178367, 5 of the 20 slots failed) and lined them up by timestamp. Two things stood out:

    a) The blocks/head/root proxy call fires at a fixed head_event + 2.000-2.002s offset, every single slot, success or failure alike — not "4s into the slot," and not tied to when the head event itself arrived (head event delay varied from 1.4s to 3.5s after slot tick across the sample; the +2.000s gap to the proxy call was constant regardless).

    b) For every one of the 5 failing slots in this sample, cancel_time − duration (the implied start of the request Charon is measuring) lands within ~1ms of that same blocks/head/root proxy-call timestamp — not the slot tick. Example (slot 15178351):

    16:30:35.000  Slot ticked                              {slot: 15178351}
16:30:38.429  SSE head event                           {slot: 15178351, delay: 3.429s}
16:30:40.430  Proxying request to beacon node           {vapi_proxy_path: /eth/v1/beacon/blocks/head/root}
16:30:44.432  Validator api 4xx response                {status_code: 408, duration: 4.001686912s}
              → implied start = 44.432 − 4.0017 = 40.430  (= proxy-call timestamp, exactly)

    No QBFT consensus instance starting line, no QBFT consensus decided, nothing else for that duty at all — matches your working theory that steps 1 and 3 never got underway. This held for all 5 failures in the sample (15178351, 352, 357, 358, 361) — none show a subsequent QBFT decision on this node.

    Happy to pull more samples, raise the log level, or grab another pprof dump around a live hang if useful — let me know what would help narrow it down further.

  4. thoutenbos commented on Sep 14, 2026

    @thoutenbos
    thoutenbos
    on Sep 14, 2026
    Author

    Update to Charon v1.11.0 and the issue remained the same
    Replacing Nimbus VC with Lighthouse VC and the issue disappears

  5. KaloyanTanev commented on Sep 15, 2026

    @KaloyanTanev
    KaloyanTanev
    on Sep 15, 2026
    Collaborator

    Can I ask you for Nimbus VC, Charon and your BN's logs for a period of 2 epochs, where those issues are apparent? If fine on your end, you can send them over in our Discord server, as I'm not sure a github issue will be able to accommodate the size of the files.

  6. b0a7 commented on Oct 8, 2026

    @b0a7
    b0a7
    on Oct 8, 2026
    Contributor

    might be related to status-im/nimbus-eth2#8962 ?

  7. KaloyanTanev commented on Oct 9, 2026

    @KaloyanTanev
    KaloyanTanev
    on Oct 9, 2026
    Collaborator

    Highly likely yes. From my observations it was the case that Nimbus was falsely sending attestation duties, irregardless if it had anything scheduled or not.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    protocolProtocol Team tickets

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions