Skip to content

cl/beacon: report a failing payload poll once, and an unregistered fee recipient at all - #23274

Open
lystopad wants to merge 3 commits into
mainfrom
feature/lystopad/production-logging
Open

cl/beacon: report a failing payload poll once, and an unregistered fee recipient at all#23274
lystopad wants to merge 3 commits into
mainfrom
feature/lystopad/production-logging

Conversation

@lystopad

@lystopad lystopad commented Aug 14, 2026

Copy link
Copy Markdown
Member

Split out of #23105, which grew too large to review in one piece.

A failing window reported once

pollAssembledPayload retries at the retry cadence, so a slot whose payload never arrived reported itself once per attempt and buried everything else in that slot.

It is now reported when the window is over, once, carrying the slot, how many attempts failed and the first reason — the first rather than the last, because a hundred repeats of "connection refused" followed by one "still syncing" should not be attributed to the latter.

Two cases stay silent:

  • a window that fails and then succeeds. That is a healthy slot.
  • a caller that went away. A validator client timing out or a node shutting down cancels the request context, which comes back through the collection call; that is the slot ending, not the execution layer failing.

A failure that happened before the caller left is still reported, since giving up is often the consequence of it.

An unregistered fee recipient is worth saying once

Production falls back to the zero address when nothing is registered for the proposer, which gives that block's fees away, and said nothing about it.

It now warns once per proposer, claimed in one step so that block template requests for the same slot arriving together do not each decide they are the first, and bounded so an unregistered proposer cannot accumulate. A dev chain rotates through 64 proposers and never registers any of them, so remembering only the most recent one warned on nearly every proposal.

The warning names the registration it consulted rather than claiming none exists anywhere: under Gloas a signed proposer preference can carry one, which this lookup does not read. That is #23300.

Scope

An earlier revision of this PR also changed how failures travel out of block production — returning causes instead of logging them, with a single owner at produceBlock's error boundary. That was asked for in review and is worth doing, but it is a change to production error handling rather than to observability, and it was only half done: four of eleven failure paths in the body goroutine carried their cause, while the other seven still logged and then let the boundary report a cause-less failure on top. Two records where the PR claimed one.

It is out of this PR and will follow separately, where it can be done across all of those paths and reviewed as what it is.

Part of a series splitting #23105.

@lystopad lystopad self-assigned this Aug 14, 2026
@lystopad lystopad added the Caplin Caplin: Consensus Layer, Beacon API label Aug 14, 2026
@lystopad
lystopad enabled auto-merge August 14, 2026 06:42
@lystopad
lystopad requested review from AskAlexSharov and yperbasis and a lite review from Copilot August 14, 2026 06:42

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

This PR improves Caplin block-production observability by reducing noisy error logs during execution-payload polling and by warning when a proposer has no registered fee recipient (to avoid silently building with the zero address).

Changes:

  • De-duplicates repeated payload-polling failure logs by emitting the first failure plus a single end-of-window summary.
  • Emits a Warn log when no fee recipient is registered for the proposer and block production will use the zero address.

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

Comment thread cl/beacon/handler/block_production.go Outdated
Comment on lines +262 to +265
defer func() {
if failures > 1 && !collected {
log.Error("BlockProduction: payload polling kept failing", "attempts", failures, "err", lastErr)
}

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Correct — it counts error returns, not calls to get(), which differ whenever the builder is still working and get() returns no payload without erroring. Renamed the key to failures.

Comment thread cl/beacon/handler/block_production.go Outdated
@lystopad
lystopad force-pushed the feature/lystopad/production-logging branch from fd1d736 to 9add2b9 Compare August 14, 2026 06:53
@lystopad
lystopad requested a lite review from Copilot August 14, 2026 07:02

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Copilot reviewed 1 out of 1 changed files in this pull request and generated no new comments.

Suppressed comments (1)

cl/beacon/handler/block_production.go:275

  • The new per-slot log suppression still emits an Error on the first get() failure even if a payload is successfully collected later in the window. That contradicts the PR goal of avoiding alerts for contention that clears (healthy slots would still log an error). Consider deferring all error logging until the end, and only emitting the first error + summary when the window ultimately produces no payload.
			failures++
			lastErr = err
			if failures == 1 {
				log.Error("BlockProduction: Failed to get payload", "err", err)
			}

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Copilot reviewed 1 out of 1 changed files in this pull request and generated no new comments.

Suppressed comments (3)

cl/beacon/handler/block_production.go:274

  • This still raises an Error for a healthy slot: TestPollAssembledPayloadRetriesOnError returns an error once and then collects a payload, but this branch logs before collected can suppress it. That contradicts the stated requirement and the comment above that contention which clears must not alert. Retain the first error and emit both logs from the deferred failure-only path instead.
			if failures == 1 {
				log.Error("BlockProduction: Failed to get payload", "err", err)

cl/beacon/handler/block_production.go:264

  • The new log aggregation has no regression coverage. Existing tests already exercise a transient error, but do not assert that it emits no Error; there is also no terminal-error case asserting one first-error log plus one summary with the correct failure count. Add logger-capture tests for both paths so the suppression guarantee is enforced.

This issue also appears on line 273 of the same file.

	defer func() {
		if failures > 1 && !collected {
			log.Error("BlockProduction: payload polling kept failing", "failures", failures, "err", lastErr)

cl/beacon/handler/block_production.go:999

  • The new unregistered-recipient warning is not covered by a test, although this handler already has block-production tests. Add cases that capture logs for missing and registered recipients, asserting that only the missing registration emits this warning.
		feeRecipient, registered := a.validatorParams.GetFeeRecipient(proposerIndex)
		if !registered {
			// Building with the zero address gives the block's fees away, so say so rather than
			// leave it to be discovered from the produced block.
			log.Warn("BlockProduction: no fee recipient registered for proposer, using zero address",

@yperbasis

Copy link
Copy Markdown
Member

[P2] Suppress recovered polling errors

At block_production.go:273, the first error is logged immediately, even if a later retry returns a payload. collected only suppresses the final summary, so the existing error-then-success path still raises an Error for a healthy slot, contrary to the PR goal. Please defer both error logs until the function exits without collecting a payload.

@domiwei domiwei left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Two P2 observations:

  1. pollAssembledPayload still logs the first get() error immediately. An error -> successful payload sequence therefore leaves an Error on a healthy slot; collected only suppresses the deferred summary. This is the exact behavior the PR says it removes, so I think the narrow fix belongs here: retain the errors during polling and emit Error-level records only on an unsuccessful terminal exit. Please add focused log-capture coverage for recovered and terminal failures.

  2. On Gloas, a matching signed ProposerPreferences may already contain a fee recipient, while this warning checks only the legacy prepare_beacon_proposer map. That can make the generic “no fee recipient registered” wording inaccurate. This should not expand this PR into fixing the broader Gloas fee-recipient precedence/routing path. A small in-scope adjustment to make the warning explicitly about the missing legacy registration is enough; the routing question can be tracked separately.

@yperbasis yperbasis left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

While reviewing, two pre-existing bugs in this function came up. They are out of scope for this PR — recording them here:

  • bundles is dereferenced (len(bundles.Blobs)) with no nil check after ok == true. The remote engine-API client forwards resp.BlobsBundle unvalidated, so an external EL that replies to engine_getPayload with a null blobsBundle panics inside the wg.Go goroutine and crashes the process (the in-process path always returns a non-nil bundle).
  • executionValue = blockValue.Uint64() truncates the 256-bit wei value, so for a local block worth more than ~18.44 ETH the local-vs-builder comparisons and the value reported to the VC are wrong.

One more nit: the new suppression logic has no test. pollAssembledPayload already has direct unit tests, and the repo has log-capture helpers (e.g. the level recorder in execution/stagedsync/exec3_wrong_root_log_test.go) if you want to pin the log contract.

Comment thread cl/beacon/handler/block_production.go Outdated
)
defer func() {
if failures > 1 && !collected {
log.Error("BlockProduction: payload polling kept failing", "failures", failures, "err", lastErr)

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This summary also fires on context cancellation: ctx here is the HTTP request context, so a VC abort or a node shutdown mid-window turns into context canceled failures and gets reported as a persistent EL failure (same misreport class as #22102). Guard the defer with ctx.Err() == nil. Also, neither this line nor the first-failure log carries a slot key, so overlapping productions are hard to tell apart.

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Taken, and it turned out to be the better shape rather than an extra guard. pollAssembledPayload now returns the cause instead of logging it, and produceBeaconBody wraps it into executionErr.

That settles the cancellation problem at the root rather than filtering for it: a caller that went away produces no record at all, because nothing here logs any more. The same goes for contention that clears, so the collected flag and the deferred summary are both gone. The validator client now gets the cause instead of the bare failed to produce execution payload, and the slot comes from the caller's own error path.

Comment thread cl/beacon/handler/block_production.go Outdated
if err != nil {
log.Error("BlockProduction: Failed to get payload", "err", err)
failures++
lastErr = err

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Consider returning lastErr to the caller instead of only logging it: produceBeaconBody still replies to the VC with the cause-less failed to produce execution payload 500. Wrapping the cause into executionErr (as the requests-bundle path does) would surface it to the client, attach the slot via the caller's existing error log, and make the defer plus the collected flag unnecessary.

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done — this is what the previous reply refers to. The cause is wrapped into executionErr, so it reaches the caller and the validator client, and the defer and the collected flag are both gone.

On first versus last error, Copilot raised the same line from the other side: the first failure is the one kept, since it says what went wrong, together with the number of attempts, which says whether it was momentary. Overwriting with the last one discarded the original diagnostic.

Comment thread cl/beacon/handler/block_production.go Outdated
if !registered {
// Building with the zero address gives the block's fees away, so say so rather than
// leave it to be discovered from the produced block.
log.Warn("BlockProduction: no fee recipient registered for proposer, using zero address",

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In dev mode (--chain=dev) this fires every slot forever: devvalidator never calls prepare_beacon_proposer, and there is no fallback or dedup. Consider a per-proposer dedup or a dev-mode default fee recipient. Adding "slot", targetSlot would also help correlation.

Nit: the second half of the comment ("so say so…") restates the Warn; the first sentence is enough.

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed, and Copilot found the gap in my first attempt: I had kept only the most recently warned proposer, so alternating unregistered proposers each reset the other and both were reported repeatedly. It is a set now, so each proposer is reported once, and the test covers the 9, 10, 9 sequence.

The warning carries the slot. Comment trimmed to the first sentence.

On a dev-mode default fee recipient rather than deduplication: I left that out because it changes dev-chain behaviour, which is outside what this PR is for. Happy to do it separately if you would rather have it.

@lystopad

Copy link
Copy Markdown
Member Author

@yperbasis @domiwei — you are both right, and it was the half-fix: collected only suppressed the summary, so an error-then-success sequence still raised an Error on a healthy slot. Exactly what the PR claims to remove.

Nothing is reported now until the window closes without a payload, and then once, carrying the number of failed attempts and the last reason.

Added the log-capture coverage you asked for, in both directions: a poll that fails and then succeeds must emit no lvl=eror record at all, and a window that never produces must emit exactly one carrying the failure count and the last error. I checked both against the previous behaviour and confirmed they fail there — the assertions are on log level rather than on message wording, so they cannot pass by accident if the text changes.

On the fee recipient wording: taken as scoped. The warning now names the registration it actually consulted rather than claiming none exists anywhere:

BlockProduction: no fee recipient from prepare_beacon_proposer, using zero address

The Gloas precedence question — a signed proposer preference carrying a fee recipient that this lookup does not read — is left alone here. Happy to file it separately if you want it tracked.

Head is 68c7be0759, on top of the merge commit already on this branch rather than a force-push over it.

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Copilot reviewed 2 out of 2 changed files in this pull request and generated no new comments.

Suppressed comments (2)

cl/beacon/handler/block_production_test.go:787

  • This test assumes the scheduler will run a retry within a 50 ms wall-clock window. Under CI load, the deadline can be reached after the first call, so calls > 1 fails nondeterministically. Cancel after a known number of failed polls instead; the existing deadline test already covers deadline termination.
	require.Greater(t, calls, 1)

cl/beacon/handler/block_production.go:995

  • The new warning branch is not covered: the polling logs have tests, but nothing verifies that an unregistered proposer emits this warning while a registered proposer stays quiet. Please cover both cases so the second behavior described by this PR cannot regress unnoticed.
		if !registered {

@yperbasis yperbasis left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reviewed current head 68c7be0759.

Two P2 issues remain. The earlier inline threads became outdated because the lines moved, but the behavior is unchanged:

  1. Context cancellation is still reported as a payload-polling Error. The deferred log checks only collected and failures. Because this is the HTTP request context and it is passed into GetAssembledBlock, a validator-client abort or node shutdown can return context canceled, exit through ctx.Done(), and emit the new Error. I reproduced this with a focused regression test. Suppress routine cancellation or return the terminal error to the slot-aware caller.

  2. Under --chain=dev, the embedded dev validator never calls prepare_beacon_proposer, so the missing-registration warning fires on every proposal (every six seconds by default) and can repeat on template retries. Register a deliberate dev fee recipient or deduplicate the warning.

The focused cl/beacon/handler package tests pass; the added cancellation regression fails with lvl=eror ... err="context canceled" as described.

@lystopad

Copy link
Copy Markdown
Member Author

Both fixed in 33707d79a1, plus the two Copilot points.

Cancellation. Right — the deferred log checked only collected and failures, so a validator-client abort or a shutdown came out as an error about a healthy node. It is now excluded, both when the request context is done and when the last error is itself a cancellation. TestPollAssembledPayloadStaysQuietWhenTheCallerGoesAway covers it.

Dev chain. The warning is now once per proposer rather than once per proposal, so a chain whose validator never registers a fee recipient says it once instead of every six seconds. I chose deduplication over registering a dev fee recipient because the latter changes dev-chain behaviour, which is outside what this PR is for — say the word if you would rather have that.

Copilot, flaky assertion. require.Greater(t, calls, 1) did depend on the scheduler fitting a retry into a 50 ms window. Dropped; the test asserts the log contract, which is what it is for.

Copilot, untested warning. The lookup is now a method, so both directions are covered: a registered proposer stays quiet, an unregistered one warns once however many times it is asked, and a different unregistered proposer warns again.

Each of the four new tests fails against the previous behaviour — I checked rather than assuming, given I have shipped two vacuous tests in this series already.

On the two pre-existing bugs you recorded: agreed they are out of scope here. The nil bundles dereference looks like the more serious of the two, since an external EL replying with a null blobsBundle panics inside the wg.Go goroutine and takes the process down. Happy to file both, or take them in a follow-up — your call.

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Copilot reviewed 3 out of 3 changed files in this pull request and generated no new comments.

Suppressed comments (2)

cl/beacon/handler/block_production.go:291

  • Each retry overwrites the stored error, so the deferred record contains only the last failure and no first-failure report is emitted. This conflicts with the PR description's promise to report the first failure and then summarize the window, and can discard the original diagnostic when later retries fail differently. Preserve the first error for the final report, or update the stated contract and tests if a single last-error record is intentional.
			failures++
			lastErr = err

cl/beacon/handler/block_production.go:238

  • This only remembers the most recently warned proposer, not every proposer already warned about. If unregistered proposers alternate (for example, 9, 10, 9), proposer 9 is warned twice, so normal multi-validator operation can still emit one warning per proposal despite the stated once-per-proposer behavior. Track warned indices in a concurrency-safe set and add the alternating-proposer case to the test.
	if a.lastUnregisteredProposer.Swap(proposerIndex+1) != proposerIndex+1 {

@lystopad

Copy link
Copy Markdown
Member Author

All of it addressed in c7f15327ba. Two of your points had already been overtaken by the push that followed your review of 33707d79a1, so to be clear about which:

Warning dedup. You are right that a single slot only suppresses consecutive repeats, and that 64 rotating dev proposers defeat it entirely. It is now a bounded cache keyed by proposer index, matching slotWaitedForAttestationProduction on the same struct as you suggested — I had reached for a sync.Map first, which is unbounded and reachable with an arbitrary proposer index from the API. The test covers the alternating case.

The errors.Is(lastErr, ...) arms. Gone, along with the defer — I took your alternative shape rather than the predicate. pollAssembledPayload returns the cause, produceBeaconBody wraps it into executionErr, and nothing in the poll logs at all. That removes the case you flagged where a hung external EL loses its only detailed record, since the cause now reaches the validator client rather than being filtered on the way to a log.

While there, Copilot pointed out that propagating produced two records for one failure — produceBlock logs it with the slot, then the endpoint logged it again. The endpoint no longer repeats it.

capturePollLogs. Fixed: the writer takes a lock, which StreamHandler requires, and the assertions read back only BlockProduction: records so a straggler goroutine from another test cannot pollute them.

Nit. Description updated. The first error is the one kept, not the last, for exactly the reason you give — 150 connection-refused followed by one still-syncing should not be attributed to the latter.

Issues filed, both as separate reports:

@yperbasis yperbasis left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reviewed head c7f15327ba.

[P2] Request cancellation is still logged as a production failure — and the new description now claims it isn't. pollErr carrying the caller's cancellation reaches the unconditional log.Error("Failed to produce beacon body", ...) in produceBlock, so a validator-client disconnect or shutdown produces lvl=eror … context canceled, while the description says "a caller that went away produces no record". The tests assert quiet only inside pollAssembledPayload, the one layer that was already quiet. Please guard the owning log: skip (or demote to Debug) when errors.Is(err, context.Canceled) — but do not include DeadlineExceeded, which is how a hung EL surfaces — and add coverage through produceBlock with a canceled request context. Note the cancellation can arrive wrapped in emptyWindowError as well as bare, so errors.Is is required.

[P3] Removing the endpoint record made two produceBlock failures silent. The returns after GetBeaconProposerIndex and beaconBody.Blinded() never log, and the deleted Warn in GetEthV3ValidatorBlock was their only record. If produceBlock owns the record, it should own all its error exits — one log at the function's error boundary covers both.

[P3] The ctx-done exits drop the accumulated cause. return …, ctx.Err() discards attempts and firstErr, so a validator client that times out mid-window because polling was failing yields only "context canceled" upstream. When firstErr != nil, wrap it — fmt.Errorf("%w (no payload after %d attempts, first error: %v)", ctx.Err(), attempts, firstErr) — which keeps errors.Is(err, context.Canceled) matching, so it composes with the guard above.

Nit: "no payload after 1 attempts" reads badly in real logs — consider structured attempts=%d or fixing the plural.

Thanks for filing #23299 and #23300.

@lystopad
lystopad force-pushed the feature/lystopad/production-logging branch from c7f1532 to 33de6ff Compare August 17, 2026 11:03
@lystopad

Copy link
Copy Markdown
Member Author

All three addressed in 33de6ff7ab, rebased over #23280 which landed in the same function.

[P2] Cancellation reported as a production failure. Right — I had fixed the layer that was already quiet and left the one that actually logs. Reporting now happens at produceBlock's error boundary, and a caller that has already gone is not raised. DeadlineExceeded deliberately still is, for the reason you give: it is how an execution layer that stopped answering surfaces, and demoting it would remove the only sign. errors.Is throughout, since the cancellation arrives wrapped in emptyWindowError as often as bare.

[P3] The two silent exits. That is the same fix: the boundary covers every exit, so the returns after GetBeaconProposerIndex and beaconBody.Blinded() are reported now, where before neither the endpoint nor produceBlock said anything.

[P3] The ctx-done exits dropping the cause. Fixed as you suggested — the cause travels with the cancellation, so a validator client that timed out because polling was failing no longer yields a bare context canceled. errors.Is(err, context.Canceled) still matches, so it composes with the guard above.

Nit. Fixed: "1 attempt" rather than "1 attempts".

One thing I could not do the way you asked. Driving produceBlock with a cancelled request context needs an execution engine in the fixture, and setupTestingHandler does not provide one on this path — the goroutine nil-derefs on a.engine before reaching anything I changed. Rather than build that fixture here, I extracted the decision into reportProductionFailure and table-tested it directly: success, bare cancellation, cancellation wrapped by emptyWindowError, DeadlineExceeded, and a plain failure. That pins the classification but not the wiring into produceBlock, which I would rather say plainly than imply otherwise.

golangci-lint is clean for cl/beacon/.... The whole-tree run still reports db/seg/decompress.go:199: field residencyOnce is unused, which is pre-existing on main — I confirmed that with my changes stashed.

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Copilot reviewed 3 out of 3 changed files in this pull request and generated no new comments.

Suppressed comments (2)

cl/beacon/handler/block_production.go:304

  • Contains followed by Add is not atomic. Two concurrent block-production requests for the same unregistered proposer can both observe a miss and both emit the warning, violating the once-per-proposer contract. Use the cache's atomic ContainsOrAdd operation instead.
		firstTime = !a.unregisteredProposers.Contains(proposerIndex)
		a.unregisteredProposers.Add(proposerIndex, struct{}{})

cl/beacon/handler/block_production.go:755

  • This unconditional boundary report still duplicates several errors logged inside produceBeaconBody. For example, expected-withdrawal and ForkChoiceUpdate failures are logged at lines 1118/1142, then return with no execution payload, and this defer logs the resulting failure again. Route those causes into the returned error and remove the inner failure records so each failed production is actually recorded once.
	defer func() { reportProductionFailure(err, targetSlot) }()

@yperbasis yperbasis left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reviewed current head 33de6ff7ab, including the effect of merged #23333. Two issues remain.

[P2] Preserve caller cancellation when the polling deadline is also ready.

In pollAssembledPayload, ctx.Done() and deadlineTimer.C can both be ready. The select may choose the deadline arm, or the ticker arm may reach the post-select deadline check, and both paths return emptyWindowError without preserving ctx.Err(). reportProductionFailure then treats the result as a production failure and emits the Error this PR intends to suppress.

A focused 10,000-iteration regression test with a cancelled context and expired polling window lost the cancellation in roughly half the calls. Please check ctx.Err() before both emptyWindowError returns, or pass the request context to the reporting boundary, and cover the simultaneous cancellation/deadline case.

[P3] Make the once-per-proposer insertion atomic.

feeRecipientForProposal calls Contains and Add separately. Concurrent template requests can all observe the proposer as absent and each emit the warning. A focused test with 128 simultaneous calls produced two to four warning records. The underlying Hashicorp cache provides atomic ContainsOrAdd; please use an atomic operation and add concurrent coverage.

#23333 does not address either issue. It only releases the txpool lock when its caller is cancelled; it does not change polling termination or the proposer-warning cache.

@lystopad
lystopad force-pushed the feature/lystopad/production-logging branch from 33de6ff to ab53af5 Compare August 17, 2026 11:49
@lystopad

Copy link
Copy Markdown
Member Author

Both fixed in ab53af59f8, along with the two Copilot suppressed comments, which overlap with yours.

[P2] Cancellation lost when the deadline is also ready. You are right, and I should have caught this one: it is the same shape as the Stop select race in #23289, in code I had just been staring at. Both emptyWindowError returns now go through a check that gives a cancelled caller precedence, so it holds whichever arm the select picks and whichever way the post-select deadline check goes. TestPollAssembledPayloadPrefersCancellationOverAWindowClosingAtTheSameMoment runs 500 iterations with both ready before the call; it fails immediately against the previous code.

[P3] Non-atomic insertion. Fixed with ContainsOrAdd, which Copilot also pointed at. TestFeeRecipientWarnsOncePerProposerUnderConcurrentRequests fires 128 simultaneous calls for one proposer and requires exactly one record; it fails against Contains followed by Add.

Copilot's other one is worth taking too: the boundary report was duplicating failures the body goroutine had already logged — expected withdrawals and the forkchoice update both logged and then returned with no payload, so the boundary reported the resulting failure again. They carry their cause out into executionErr now, so those failures are recorded once and the record says what went wrong rather than only that production failed.

Thanks for checking #23333 against this; agreed it is unrelated — it only releases the txpool lock for its own cancelled caller.

make lintci is clean apart from db/seg/decompress.go:199: field residencyOnce is unused, and I owe a correction there: I described that as pre-existing on main in a couple of places, which is true but misleading. Its only user is residency_gate_linux.go, so it is unused on darwin only and CI never sees it. Not a defect, and nothing for anyone to act on.

@lystopad
lystopad force-pushed the feature/lystopad/production-logging branch from ab53af5 to 1808d49 Compare August 17, 2026 12:09
@lystopad

Copy link
Copy Markdown
Member Author

I have cut this PR back to what it was meant to be, and I owe an explanation rather than just a diff.

The claim in the previous revision was false. It said a failed production is recorded once at the boundary. Only four of eleven failure paths in the body goroutine carried their cause into executionErr; the other seven — invalid bundle, invalid peerdas bundle, invalid commitment length, invalid proof length, invalid blob length, the Gloas requests root, and the sync aggregate — still logged and returned, leaving executionErr nil. produceBeaconBody then returned the cause-less failed to produce execution payload, and the new boundary logged that on top. Two records for one failure, and the second one worse than the Failed to produce beacon body line it replaced, which at least carried localErr.

@copilot named two of those paths, I fixed exactly those two, and then wrote "every exit is covered once" here and in the PR body without checking the rest of the function. That was my mistake and I am sorry for the review time it cost.

So the error-propagation work is out of this PR. It was asked for and it is worth doing, but it is a change to how block production reports failure, not an observability change, and doing it properly means all eleven paths plus their tests. It will come as its own PR where it can be reviewed as that. This one is back to +58 −4 of production code, from +337 −34.

What is left is the two things the title promises:

  • the polling window reports once, when it is over, with the slot, the failure count and the first cause; silent when it recovers and when the caller went away, but still reporting failures that preceded the caller leaving, per @yperbasis's predicate;
  • the fee recipient warning, once per proposer, claimed atomically with ContainsOrAdd and bounded by an LRU.

Everything from the review rounds that belongs to this scope is kept: the slot key, the first-not-last error, the atomic claim, the bounded cache, and the log capture helper writing through a lock and filtering to block-production records.

Worth noting what this also removes: the select race @yperbasis found last round, where a cancelled caller and a closing window were both ready, existed only because of the propagation machinery. With reporting decided by whether any non-cancellation failure was seen, which arm the select takes no longer matters.

make lintci clean, go test -race green, and each new test verified to fail against the behaviour it replaces.

Copilot AI commented Aug 17, 2026

Copy link
Copy Markdown
Contributor

@lystopad I've opened a new pull request, #23340, to work on those changes. Once the pull request is ready, I'll request review from you.

@yperbasis yperbasis left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reviewed refreshed head 1808d497a7. The two previous findings are fixed, but one P2 remains.

[P2] Do not start another collection attempt after the caller is already gone.

pollAssembledPayload calls get() before checking ctx.Done(). When the build timer or retry ticker wins a select while cancellation is also ready, the next iteration can therefore call the execution layer with an already-cancelled context. The in-process ExecModule.GetAssembledBlock checks its semaphore first and can return chainreader.ErrExecutionBusy without consulting that context. The predicate at line 361 then treats this as a non-cancellation failure and the deferred report emits the Error that this PR says a departed caller must not produce.

A focused test using a cancelled context, an expired polling window, and ErrExecutionBusy emitted one Error in all 10 runs. Please check ctx.Err() immediately before get(). Any failures accumulated before cancellation remain in failures, so the defer will still report them as intended.

…e recipient at all

Polling retries at the retry cadence, so one slot whose payload never arrived reported itself
once per attempt and buried everything else in that slot. It is reported when the window is
over, once, with the slot, how many attempts failed and the first reason, which is the one that
says what went wrong. A window that recovers reports nothing, and neither does a caller that
went away: its own cancellation comes back through the collection call, and that is the slot
ending rather than the execution layer failing. A failure that happened before the caller left
is still reported, since giving up is often the consequence of it.

Production falls back to the zero address when nothing is registered for the proposer, which
gives that block's fees away, and said nothing. It now says so once per proposer, claimed in
one step so that requests for the same slot arriving together do not each decide they are the
first, and bounded so an unregistered proposer cannot accumulate.
The window's select can pick its timer or its ticker while cancellation is ready too, and the
next pass then called the execution layer with a context that had already ended. That call
takes the module's semaphore before it looks at a context, so it comes back as contention
rather than cancellation, which counts as a real failure and produces the record a departed
caller is not supposed to produce.

Failures seen before the caller left are still counted, and still reported: giving up is often
the consequence of them.
@lystopad
lystopad force-pushed the feature/lystopad/production-logging branch 2 times, most recently from 1808d49 to 8ac0352 Compare August 17, 2026 13:33
@yperbasis
yperbasis requested a balanced review from Copilot August 17, 2026 13:35

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copilot encountered an error and was unable to review this pull request. You can try again by re-requesting a review.

@lystopad

Copy link
Copy Markdown
Member Author

Fixed in 8ac0352941.

You are right, and the mechanism is the part I had not thought through: I was treating "the caller's cancellation comes back through get" as the only way cancellation shows up, but ExecModule.GetAssembledBlock takes its semaphore before it looks at a context, so a call made after the caller has gone returns contention instead. My predicate then counts that as a real failure, and the record a departed caller is not supposed to produce appears anyway.

ctx.Err() is checked immediately before get() now, so no collection is started for a caller that has gone — which also stops that call needlessly stopping the builder. Failures seen before the caller left are still counted and still reported, as you say.

TestPollAssembledPayloadDoesNotCollectAfterTheCallerHasGone uses a cancelled context, an expired window and a get that returns contention, and asserts the collection is never attempted. It fails on every run against the previous code.

That is the third distinct route by which a cancelled caller could reach that log — the deferred summary, the select over a closing window, and now the attempt made after the fact. Worth saying that the earlier two only existed because of machinery I had added and have since removed; this one is in the shape the PR now has, which is why it is worth having found.

make lintci clean apart from the darwin-only db/seg artefact, go test -race green on the package.

@yperbasis yperbasis left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Two P2 issues remain on head 8ac0352941.

  1. Caller cancellation is still reported by the outer layers. pollAssembledPayload returns only ok=false, so the caller loses whether cancellation ended polling. produceBeaconBody then creates failed to produce execution payload; produceBlock logs it as an Error, and the endpoint emits a Warn. A validator-client disconnect after a successful FCU is therefore not silent. The new tests capture only BlockProduction: records inside the helper, so they miss the outer Failed to produce beacon body record. Please preserve the terminal cause or status through the caller boundary and suppress the request context cancellation at the actual log owner, while keeping independent EL timeouts visible.

  2. A terminal polling failure still produces multiple Error records. The deferred summary logs the detailed polling failure, after which the nil-payload path reaches the generic Failed to produce beacon body Error. The endpoint adds another Warn. A focused reproduction with GetAssembledBlock returning boom produced two Error records before the endpoint. One boundary should own the polling failure record.

Focused verification is green:

  • go test ./cl/beacon/handler
  • go test -race ./cl/beacon/handler

Reporting once inside the polling loop was not enough: the loop returned only whether it had a
payload, so the layers above it invented a cause-less failure of their own, produceBlock logged
that, and the endpoint logged it again. A validator client disconnecting produced an error
about a healthy node, and a real polling failure produced several records, the useful one
buried among them.

Every failure in the body goroutine now carries its cause out, all ten of them rather than the
few that already did, and produceBlock reports once at its error boundary. A caller that has
already gone is not raised there; an execution layer that stopped answering still is, since
that arrives as a deadline rather than a cancellation.

The polling loop keeps its own accounting only to decide what to hand back: a caller that left
with nothing having failed took the slot with it, while anything that failed before that is
worth reporting however the window ended.

The log capture in tests no longer filters by message. Filtering to this file's own prefix is
what hid the outer records, so the tests agreed with a claim that was not true.
@lystopad

Copy link
Copy Markdown
Member Author

Both fixed in 4b58bb6a73, and this is me reversing a decision I made two rounds ago.

I cut the error propagation out of this PR because the version I had was half done — four of eleven failure paths carried their cause and the rest did not, so the claim of one record was false. Cutting it was the wrong correction. You are right that without it this PR cannot deliver its own title: the loop returned only whether it had a payload, so the layers above invented a cause-less failure, produceBlock logged that, and the endpoint logged it again. The right correction was to finish it, which is what this does — all ten paths in the body goroutine carry their cause now, not the few that already did.

Caller cancellation reaching the outer layers. produceBlock reports once at its error boundary and does not raise a caller that has already gone. A deadline still is raised, since that is how an execution layer that stopped answering arrives.

Multiple records for one terminal failure. One record, carrying the cause. The polling loop keeps its own accounting only to decide what to hand back: a caller that left with nothing having failed took the slot with it, anything that failed before that is reported however the window ended.

On the tests missing it — that is the part worth dwelling on. My capture helper filtered to this file's BlockProduction: prefix, so Failed to produce beacon body was invisible to it and my tests agreed with a claim that was not true. It captures everything at warning level and above now, and there are two tests that drive a real production through to a failing collection: one asserts exactly one error record carrying the cause, the other asserts no error record at all for an abandoned request. Reverting the boundary makes the second fail with precisely what you described, lvl=eror ... err="produceBeaconBody: context canceled".

I had told you I could not drive produceBlock in a test because the fixture has no execution engine. That was wrong: the fixture does not wire one, but the handler takes a mock directly, which is what these two do.

Production diff is +58 −0 in block_production.go; the rest is tests.

make lintci clean apart from the darwin-only db/seg artefact, go test -race green on the package.

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

Labels

Caplin Caplin: Consensus Layer, Beacon API

Projects

None yet

Development

Successfully merging this pull request may close these issues.

5 participants