Repository navigation
Conversation
Alerting on slow block production relied on log lines that each cover only part of the path: "Commit new sealing work" times fill and finalize, "Successfully sealed new block" times seal, gate and write. worker/build_to_announce covers both, but its decaying percentiles stay high for hours after one slow block and cannot count events. - worker/build_to_announce now starts when the producer was first allowed to build: the later of the commitWork start and the parent slot boundary. Prepare work is included; the deliberate Giugliano wait for the boundary is not. Both announce paths use the same start. - worker/build_to_announce/over2s and /over4s count announcements slower than 2s and 4s, independent of the scrape interval. - worker/producer/stalled holds the block number this node is stuck on as primary producer (0 otherwise): set when the next block is not announced within 2s of being allowed to build it, cleared by the announcement, a new head, or stopping the miner. worker/producer/stalls counts stall episodes. - Bor.IsPrimaryProducer reports whether the local signer is the in-turn producer. It shares IsAuthorizedSigner's checks, which now go through one succession lookup with unchanged behavior. The producer check reads the snapshot (possibly a span lookup), so it runs only when the stall clock expires, off the production path.
…heck After Rio each span has a single producer, so the authorized signer is the producer and the existing IsAuthorizedSigner (already used by the sequencer) answers "is this node the current producer". Drop the new IsPrimaryProducer helper and its refactor; consensus/bor is unchanged relative to the base. The stall check only runs after Rio: before it every validator is authorized, so no single node would be singled out.
Codecov Report✅ All modified and coverable lines are covered by tests. Additional details and impacted files@@ Coverage Diff @@
## lmartins/backmerge-v2.10.2 #2478 +/- ##
==============================================================
+ Coverage 57.60% 57.65% +0.05%
==============================================================
Files 959 960 +1
Lines 176094 176239 +145
==============================================================
+ Hits 101433 101611 +178
+ Misses 68984 68957 -27
+ Partials 5677 5671 -6
... and 19 files with indirect coverage changes
🚀 New features to boost your workflow:
|
|
@claude review |
![claude[bot]](https://avatars.githubusercontent.com/in/1236702?s=60&v=4){kind=small}
There was a problem hiding this comment.
Nothing blocking. The comments below are optional suggestions. There is no need to push a fix for them before merging.
Beyond the inline finding on producerStallWatch re-arming without a generation token, I also checked two other angles and ruled them out: the stall watch's time.AfterFunc design means no goroutine is spawned until expiry and resetLocked/close always Stop the timer, so there's no unbounded goroutine growth; and buildStart is captured at commitWork entry per real block, so an optional pre-Rio empty pre-seal commit doesn't skew the build_to_announce start for the sealed block.
Extended reasoning...
The diff adds a producer-stall and slow-announce metrics feature to miner/, touching producer timing and Giugliano/Rio fork-gated logic flagged as hardfork-shaped and consensus-adjacent by the repo's own rules, though it changes no consensus value (metrics only). No auth/crypto/injection surface is touched. A CONFIRMED race (duplicate watch arming on same-height head events) is already queued as an inline finding, which is reason enough to keep a human in the loop; I'm adding only the two ruled-out checks above since they're not already visible in the PR thread.
| func (s *producerStallWatch) expire(height uint64, next *types.Header) { | ||
| if !s.pending(height) { | ||
| return | ||
| } | ||
|
|
||
| // Called without the lock: the producer check can block on a span lookup. | ||
| if s.headNumber() >= height || !s.isProducer(next) { | ||
| return | ||
| } | ||
|
|
||
| s.mu.Lock() | ||
| defer s.mu.Unlock() | ||
|
|
||
| if s.closed || s.height != height || s.isStalled { | ||
| return | ||
| } | ||
|
|
||
| s.isStalled = true | ||
| s.stalled.Update(int64(height)) | ||
| s.stalls.Inc(1) | ||
| } |
There was a problem hiding this comment.
🟡 (optional) A one-block tip reorg (or startCh+chainHeadCh landing on the same next-block height) can trigger a false worker/producer/stalled alert and spurious worker/producer/stalls increment. watch() at production_monitor.go:172 re-arms a watch for the same height without any epoch/generation token; if the prior timer already fired and its goroutine is blocked in expire()'s unlocked isProducer/headNumber calls (production_monitor.go:237-257), it resumes after the rewatch, still finds s.height == height in pending()/expire(), and reports the block stalled using the old deadline even though the new watch has more time left. …
Why this was flagged
…Fix: tag each watch() call with a generation id (bumped in resetLocked) and have expire() compare the generation, not just height, before reporting, so a superseded watch's late callback is always a no-op.
Trigger: watchNextBlock (worker.go:1011/1022) computes next.Number = head.Number+1, so two head events whose heads share a number (sibling block from a short reorg, or startCh and chainHeadCh firing close together at startup) call producerStallWatch.watch (production_monitor.go:172) twice for the same height. watch() calls resetLocked (production_monitor.go:266) which Stop()s the old timer and re-sets s.height to the identical value, then arms a fresh timer. If the old timer had already fired, Stop() returns false and its goroutine, already past the pending() check, is mid-flight in expire()'s unlocked isProducer/headNumber calls (production_monitor.go:245-246); on resuming it still finds s.height==height (production_monitor.go:250) and sets isStalled, incrementing stalled/stalls.
Verification: nit — The race is real and reachable. expire() (production_monitor.go:237) passes pending(height) at line 238, then runs the unlocked isProducer/headNumber check at line 243 (comment at 242 notes it "can block on a span lookup"). If a second watch() for the SAME height arrives during that window (watchNextBlock at worker.go:1011/1022 computes head.Number+1, so a 1-block tip reorg to a sibling at the same number re-watches the same H), resetLocked() (line 266) sets s.height→0 then watch() re-sets s.height = H (lines 186-187) and arms a fresh timer2 (line 188).
1 participant
Summary
Adds producer metrics that do not depend on log parsing or the scrape interval, so slow and stalled block production can be alerted on directly.
The "Slow block produced" alert reads log lines that each cover only part of the production path:
Commit new sealing worktimes fill and finalize, andSuccessfully sealed new blocktimes seal, gate and write. Each one missed a recent incident: mainnet block 95,080,502 (4.4s in finalize, sealed log 19ms) and Amoy block 49,266,577 (4s after seal, commit log 878ms).worker/build_to_announcecovers the whole path, but its decaying percentiles stay high for hours after one slow block and cannot count events.worker/build_to_announcecommitWorkstart and the parent slot boundary. Prepare work (sealing state, sequencer adoption read,bor.Prepare,makeEnv) is included; the deliberate Giugliano wait for the boundary is not. Same rule on the normal and pipelined paths.worker/build_to_announce/over2s,/over4sworker/producer/stalledworker/producer/stallsThe producer check uses the existing
Bor.IsAuthorizedSigner(as the sequencer does): after Rio each span has a single producer. It only runs after Rio, and only when the 2s clock expires, so its snapshot/span lookup stays off the production path. The stall clock uses the node's monotonic clock, not whole-second chain age, which reads 2 during normal operation.Suggested alert rules:
Stacked on #2473 (v2.10.2 backmerge, which brings
IsAuthorizedSignerinto develop). The base retargets todevelopwhen #2473 merges.Executed tests
go test -race ./miner/... ./consensus/bor/...: pass. New tests (run 25× under-race, no flakes) cover the 2s/4s threshold edges (exactly 2s/4s not counted, 1ms over counted), the slot-boundary start (head before/after the boundary, pre-Giugliano, non-Bor), every way the stall watch starts and clears (threshold, announcement, new head, stale announcement, stop/close, announcement racing the producer check), the producer check before/after Rio, and both announce paths.golangci-lintv2.11.4 (repo config): 0 issues;golangci-lint fmt: clean;go build ./...: ok.production_monitor.go:50: the timer update is a no-op when metrics are disabled, the test default.pipeline.go:1085: the existingpipelined: trueflag on a line this PR edits; production pipelining is disabled.worker.go:1011,:1022,:1531: the start/head/announce hooks. Applied by hand, each mutant failsTestWorkerStallWatchLifecycle/TestWorkerStallWatchFollowsChainHead; diffguard still reports them as surviving.No devnet or Kurtosis run yet.
Rollout notes
worker/build_to_announcevalues shift: the start moves earlier by the time spent in prepare (excluding the Giugliano boundary wait). Dashboards using it will see slightly higher values.Successfully sealed new blocklog can move to the counters above once this ships.