Skip to content

app, helper, metrics: add milestone/vote-extension/bor-RPC observability metrics - #643

Open
lucca30 wants to merge 6 commits into
developfrom
lucca/observability-metrics
Open

lucca30 wants to merge 6 commits into
developfrom
lucca/observability-metrics

Conversation

@lucca30

@lucca30 lucca30 commented Sep 7, 2026

Copy link
Copy Markdown
Contributor

Summary

Adds 7 new Prometheus metrics closing observability gaps identified in a cross-model (Codex + Claude) convergence review of heimdall-v2's milestone-finality-latency instrumentation, targeting the Stage A (create→propose) and Stage B (propose→majority) latency questions:

  • heimdallv2_milestone_no_new_headers_total — ExtendVote turns that skipped proposition generation because Bor had no new header
  • heimdallv2_bor_rpc_call_duration_seconds{method} — latency of individual Bor RPC calls (previously zero visibility)
  • heimdallv2_abci_extend_vote_elapsed_seconds{phase} — wall-clock elapsed at each ExtendVote budget checkpoint, pairing with the existing extend_vote_budget_exhausted_total counter
  • heimdallv2_milestone_majority_found_total{threshold} — success-side counter for 2/3 and 1/3 majority search, giving failure counters a denominator
  • heimdallv2_abci_vote_extension_rejected_total{reason} — counts each of VerifyVoteExtension's 7 REJECT branches; a rejected vote extension doesn't count toward the next height's majority threshold, making this a direct upstream cause of Stage B non-convergence
  • heimdallv2_milestone_proposition_generation_duration_seconds — end-to-end time inside GenMilestoneProposition, showing how much of the ExtendVote budget the milestone path consumes versus the side-tx loop
  • heimdallv2_milestone_majority_commit_suppressed_total{reason} — a 2/3 majority proposition was found but not committed (ValidateMilestoneProposition failure or the Rio last-span-same-block guard); without this, a validate-failure storm is indistinguishable from healthy convergence in majority_found_total

Full candidate list, source citations, and the 6-round Codex/Claude convergence log: investigations/heimdall-observability-metrics-brainstorm.md in agent-zero (not part of this diff).

All labels are bounded enums over code branches (never per-entity/free-form) per the convergence review's cardinality guardrails; no validator-identity label is used anywhere in this diff.

Executed tests

  • go build ./..., go vet ./app/... ./helper/... ./metrics/..., go test ./app/... ./helper/... ./metrics/... — all passing (467 tests, 6 packages)
  • gofumpt -l and golangci-lint run --new-from-rev=origin/develop — clean on every touched line
  • Added direct unit tests for all 7 new metric recorders plus before/after assertions on the existing app/helper tests that exercise the newly-instrumented branches, closing the initial coverage/mutation-testing gaps CI caught — codecov/patch is green and diffguard's mutation-testing score is 96.7% (29/30 killed, see below for the one remaining survivor)
  • Claude Code review (@claude review) caught a real bug: ExtendVoteElapsedSeconds was only ever recorded on the already-budget-exhausted path, making the histogram a duplicate of the existing exhaustion counter instead of showing the full elapsed-time distribution needed to tune extendVoteBudget from tail latency. Fixed in c2f4759 to record at every budget checkpoint regardless of outcome.
  • govulncheck — 7 findings, all pre-existing (grpc/stdlib version, traced through app/app.go, x/bor/grpc/*, helper/query.go), none touching this diff's lines
  • Live kurtosis devnet (4 heimdall-v2 validators + 1 RPC node, this branch): confirmed heimdallv2_milestone_no_new_headers_total, heimdallv2_bor_rpc_call_duration_seconds, heimdallv2_milestone_majority_found_total, and heimdallv2_milestone_proposition_generation_duration_seconds populate with real data; confirmed extend_vote_elapsed_seconds, vote_extension_rejected_total, and majority_commit_suppressed_total are correctly registered but empty (each requires a fault/degraded condition — budget exhaustion, invalid vote extension, or a commit-suppression path — that a healthy 4-validator devnet doesn't naturally trigger)
  • Confirmed the Grafana Alloy scrape allowlist already covers all 7 new metric names via the heimdallv2_.* catch-all added in 0xPolygon/pos-ops#950

Known CI deviations

Diffguard's Quality metrics check is red on two items, neither of which reflects a real gap in this diff:

  1. Churn-weighted-complexity WARN: PreBlocker (complexity 61) and ExtendVoteHandler (complexity 27) are flagged because diffguard scores at function granularity and both are among the most heavily-churned functions in the repo (161 commits each). Any diff touching either function trips this warning, independent of diff size. Reducing either function's complexity would mean restructuring consensus-critical code (both are covered by .claude/rules/consensus-critical.md) well outside this PR's scope.
  2. One surviving mutant (app/abci.go, the logger.Warn(...) call on the ExtendVote side-tx-loop budget-exhaustion path): a log-statement-deletion mutant. This repo has no log-capture test harness/pattern to assert on structured logger output content, and introducing one for a single log line is disproportionate to the gap. Mutation score is 96.7% (29/30) overall, well above the 90% bar; only this one log-line mutant remains unaddressed.

Flagging both for reviewer discussion per team standard rather than silently overriding.

Rollout notes

Not consensus-affecting — purely additive Prometheus counters/histograms and one wall-clock timing call inside ExtendVoteHandler (already non-deterministic/RPC-calling by design). No hard fork required. No operator action needed beyond the already-merged pos-ops scrape-config fix.

lucca30 and others added 2 commits September 7, 2026 12:25
Adds the 5 highest-priority metrics from a 6-round cross-model
convergence review of heimdall-v2's milestone-latency observability
gaps (agent-zero investigations/heimdall-observability-metrics-brainstorm.md):

- heimdallv2_milestone_no_new_headers_total: ExtendVote turns that
  skipped milestone proposition generation because Bor had no new
  header (previously Debug-only, invisible on mainnet's info log level)
- heimdallv2_milestone_majority_found_total{threshold}: success-side
  counter for 2/3 and 1/3 milestone proposition majority, the missing
  denominator for majority-search failure rates
- heimdallv2_abci_extend_vote_elapsed_seconds{phase}: elapsed-time
  distribution at each ExtendVote budget checkpoint, to tune
  extendVoteBudget against real tail latency
- heimdallv2_abci_vote_extension_rejected_total{reason}: the 7 REJECT
  branches in VerifyVoteExtensionHandler, previously Error-log-only
  with zero metric coverage despite being a direct upstream cause of
  milestone majority non-convergence
- heimdallv2_bor_rpc_call_duration_seconds{method}: latency of the two
  Bor RPC calls used in milestone proposition generation, previously
  entirely unmeasured on live mainnet

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01Y5RCKmqq2pVtZXHFa7JSwr
…ervability

Adds heimdallv2_milestone_majority_commit_suppressed_total{reason} to
distinguish a validate-failure/Rio-guard suppression from healthy
convergence at the 2/3 majority branch (pairs with the existing
majority_found_total success counter), and
heimdallv2_milestone_proposition_generation_duration_seconds to show how
much of the ExtendVote budget GenMilestoneProposition consumes end-to-end,
complementing the per-RPC-call bor_rpc_call_duration_seconds histogram.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01Y5RCKmqq2pVtZXHFa7JSwr
@lucca30
lucca30 marked this pull request as ready for review September 7, 2026 23:35

@claude claude Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

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

Claude Code Review

This repository is configured for manual code reviews. Comment @claude review for a one-time review, or @claude review always to subscribe this PR to a review on every future push.

Tip: disable this comment in your organization's Code Review settings.

@codecov

codecov Bot commented Sep 7, 2026

Copy link
Copy Markdown

Codecov Report

✅ All modified and coverable lines are covered by tests.
✅ Project coverage is 51.0%. Comparing base (7b5d6c0) to head (9ecc5c2).

Additional details and impacted files

Impacted file tree graph

@@            Coverage Diff            @@
##           develop    #643     +/-   ##
=========================================
+ Coverage     50.9%   51.0%   +0.1%     
=========================================
  Files          183     183             
  Lines        20059   20080     +21     
=========================================
+ Hits         10219   10253     +34     
+ Misses        8540    8530     -10     
+ Partials      1300    1297      -3     
Files with missing lines Coverage Δ
app/abci.go 66.7% <100.0%> (+2.1%) ⬆️
helper/call.go 32.6% <100.0%> (+1.4%) ⬆️

... and 4 files with indirect coverage changes

Files with missing lines Coverage Δ
app/abci.go 66.7% <100.0%> (+2.1%) ⬆️
helper/call.go 32.6% <100.0%> (+1.4%) ⬆️

... and 4 files with indirect coverage changes

🚀 New features to boost your workflow:
  • ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

lucca30 and others added 2 commits September 7, 2026 20:24
CI flagged 71.4% patch coverage and an 8.0% mutation-testing kill rate on
the new metric recorder calls added in the prior two commits. Adds direct
unit tests for each RecordXxx function in metrics/, and adds before/after
assertions (via prometheus/client_golang/testutil) to existing app/abci_test.go
and helper/call_dispatcher_test.go tests that already exercise the
instrumented branches, plus two new PreBlocker tests for the previously
untested commit-suppression paths (validate_failed, rio_last_span_same_block).

Also fixes two mislabeled VerifyVoteExtensionHandler test fixtures that
didn't actually trigger the rejection reason their test case names claimed.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01Y5RCKmqq2pVtZXHFa7JSwr
…estone metrics

Adds a fixture that passes rejectUnknownVoteExtFields (packed varint field
treated as opaque by strict unknown-field checking) but fails gogoproto's
actual Unmarshal, isolating the unmarshal_failed rejection reason from
unknown_fields. Adds a PreBlocker test with Ithaca active and no span
recorded, driving handlePendingMilestone's GetLastSpan failure to confirm
PreBlocker propagates the error instead of swallowing it.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01Y5RCKmqq2pVtZXHFa7JSwr
@lucca30

lucca30 commented Sep 8, 2026

Copy link
Copy Markdown
Contributor Author

@claude review

@claude claude Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

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

Nothing blocking. The comments below are optional suggestions. There is no need to push a fix for them before merging.

Comment thread metrics/abci.go
Comment on lines 128 to +142
[]string{"phase"},
)

// ExtendVoteElapsedSeconds tracks how much wall-clock time had elapsed inside
// ExtendVote, labeled by the same phase values as ExtendVoteBudgetExhaustedTotal,
// at the moment each phase's budget check ran (regardless of whether the budget
// was exhausted). Pairs with that counter as a distribution: the counter says how
// often the budget is hit, this says how close every turn runs to it, which is
// what's needed to tune extendVoteBudget against real tail latency.
ExtendVoteElapsedSeconds = promauto.NewHistogramVec(
prometheus.HistogramOpts{
Namespace: Namespace,
Subsystem: "abci",
Name: "extend_vote_elapsed_seconds",
Help: "Wall-clock time elapsed inside ExtendVote at each budget checkpoint, labeled by phase",

Copy link
Copy Markdown

Choose a reason for hiding this comment

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

🟡 (optional) ExtendVoteElapsedSeconds is documented as observing wall-clock elapsed "at the moment each phase's budget check ran (regardless of whether the budget was exhausted)", but RecordExtendVoteElapsed is only ever called from inside the already-exhausted branches in app/abci.go (lines 398, 469), so every sample is >= the budget deadline by construction. Operators get a histogram that cannot show "how close every turn runs to" the budget for healthy turns as the doc/PR claims -- it only restates the exhausted-counter's condition with added magnitude, losing the tail-latency-tuning signal it was built for. …

Extended reasoning...

…Fix: either record elapsed unconditionally at each checkpoint (success and exhausted paths) so the histogram covers the full distribution, or correct the doc comment to state it only measures overshoot past the deadline.

In app/abci.go, metrics.RecordExtendVoteElapsed("side_tx_loop", startTime) and metrics.RecordExtendVoteElapsed("pre_milestone", startTime) are each placed only inside the if budgetActive && !time.Now().Before(deadline) block, i.e. the same condition that also fires RecordExtendVoteBudgetExhausted. There is no call on the non-exhausted path through either checkpoint. As a result every observation in ExtendVoteElapsedSeconds is at or beyond extendVoteBudget, so the histogram cannot be used, as the code comment and PR description claim, to see how close normal (non-exhausted) turns run to the budget -- it silently degenerates into a duplicate/derivative of the existing counter, undermining the stated goal of tuning extendVoteBudget from tail latency.

Verification: nit. The candidate accurately describes the code. RecordExtendVoteElapsed has exactly two non-test call sites (Grep confirms), both inside budget-exhausted branches: app/abci.go:398 sits inside if budgetActive && !time.Now().Before(deadline) (same block as RecordExtendVoteBudgetExhausted("side_tx_loop"), followed by break), and app/abci.go:469 sits inside the identical guard for… | nit.…

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

Confirmed — both call sites sat inside the exhausted branch, so the histogram was degenerate. Fixed in c2f4759: RecordExtendVoteElapsed now fires whenever budgetActive is true, at each checkpoint, regardless of whether that particular check found the budget exhausted.

lucca30 and others added 2 commits September 7, 2026 21:20
…xhaustion

Claude Code review caught that both RecordExtendVoteElapsed call sites sat
inside the already-exhausted branch (same guard as RecordExtendVoteBudgetExhausted),
so every observation was >= extendVoteBudget by construction. This made the
histogram a duplicate/derivative of the existing counter instead of showing
the full elapsed-time distribution the doc comment and PR description claim
it does, losing the tail-latency-tuning signal it was built for. Moves both
calls to fire whenever budgetActive, independent of whether that particular
check found the budget exhausted.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01Y5RCKmqq2pVtZXHFa7JSwr
…tx-loop checkpoint

Nesting the elapsed-time recording inside a budgetActive block shifted the
existing (pre-existing, previously untested) RecordExtendVoteBudgetExhausted
call for phase=side_tx_loop, surfacing it as a new mutation-testing target.
Adds the missing before/after counter assertion alongside the existing
histogram assertions in the same test.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01Y5RCKmqq2pVtZXHFa7JSwr
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant