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

app/abci.go

@@ -395,6 +395,7 @@ func (app *HeimdallApp) ExtendVoteHandler() sdk.ExtendVoteHandler {
 		for _, rawTx := range txs {
 			if budgetActive && !time.Now().Before(deadline) {
 				metrics.RecordExtendVoteBudgetExhausted("side_tx_loop")
+				metrics.RecordExtendVoteElapsed("side_tx_loop", startTime)
 				logger.Warn("extend vote budget exhausted, returning partial response",
 					"processed_side_handlers", len(sideTxRes),
 					"elapsed", time.Since(startTime))
@@ -465,13 +466,17 @@ func (app *HeimdallApp) ExtendVoteHandler() sdk.ExtendVoteHandler {
 		var milestoneProp *milestoneTypes.MilestoneProposition
 		if budgetActive && !time.Now().Before(deadline) {
 			metrics.RecordExtendVoteBudgetExhausted("pre_milestone")
+			metrics.RecordExtendVoteElapsed("pre_milestone", startTime)
 			logger.Warn("extend vote budget exhausted before milestone proposition, skipping",
 				"elapsed", time.Since(startTime))
 		} else {
+			genStart := time.Now()
 			milestoneProp, err = milestoneAbci.GenMilestoneProposition(ctx, &app.BorKeeper, &app.MilestoneKeeper, app.caller, getBlockAuthor)
+			metrics.RecordMilestoneGenerationDuration(genStart)
 		}
 		if err != nil {
 			if errors.Is(err, milestoneAbci.ErrNoNewHeadersFound) {
+				metrics.RecordMilestoneNoNewHeaders()
 				logger.Debug("No new headers found for generating milestone proposition, continuing without it")
 			} else {
 				logger.Warn("Error occurred while generating milestone proposition", "error", err)
@@ -532,30 +537,35 @@ func (app *HeimdallApp) VerifyVoteExtensionHandler() sdk.VerifyVoteExtensionHand
 		}
 
 		if err := rejectUnknownVoteExtFields(req.VoteExtension); err != nil {
+			metrics.RecordVoteExtensionRejected("unknown_fields")
 			logger.Error(heimdallTypes.ErrAlertVoteExtensionRejected+" Error while checking unknown fields in VoteExtension", "validator", valAddr, "error", err)
 			return &abci.ResponseVerifyVoteExtension{Status: abci.ResponseVerifyVoteExtension_REJECT}, nil
 		}
 
 		var voteExtension sidetxs.VoteExtension
 		if err := proto.Unmarshal(req.VoteExtension, &voteExtension); err != nil {
+			metrics.RecordVoteExtensionRejected("unmarshal_failed")
 			logger.Error(heimdallTypes.ErrAlertVoteExtensionRejected+" Error while unmarshalling VoteExtension", "validator", valAddr, "error", err)
 			return &abci.ResponseVerifyVoteExtension{Status: abci.ResponseVerifyVoteExtension_REJECT}, nil
 		}
 
 		// ensure block height and hash match
 		if req.Height != voteExtension.Height {
+			metrics.RecordVoteExtensionRejected("height_mismatch")
 			logger.Error(heimdallTypes.ErrAlertVoteExtensionRejected, "block height", req.Height, "consolidatedSideTxResponse height", voteExtension.Height, "validator", valAddr)
 			return &abci.ResponseVerifyVoteExtension{Status: abci.ResponseVerifyVoteExtension_REJECT}, nil
 		}
 
 		if !bytes.Equal(req.Hash, voteExtension.BlockHash) {
+			metrics.RecordVoteExtensionRejected("hash_mismatch")
 			logger.Error(heimdallTypes.ErrAlertVoteExtensionRejected, "block hash", common.Bytes2Hex(req.Hash), "consolidatedSideTxResponse blockHash", common.Bytes2Hex(voteExtension.BlockHash), "validator", valAddr)
 			return &abci.ResponseVerifyVoteExtension{Status: abci.ResponseVerifyVoteExtension_REJECT}, nil
 		}
 
 		// check for duplicate votes
 		txHash, err := validateSideTxResponses(voteExtension.SideTxResponses)
 		if err != nil {
+			metrics.RecordVoteExtensionRejected("invalid_side_tx_responses")
 			logger.Error(heimdallTypes.ErrAlertVoteExtensionRejected, "validator", valAddr, "tx hash", common.Bytes2Hex(txHash), "error", err)
 			return &abci.ResponseVerifyVoteExtension{Status: abci.ResponseVerifyVoteExtension_REJECT}, nil
 		}
@@ -565,6 +575,7 @@ func (app *HeimdallApp) VerifyVoteExtensionHandler() sdk.VerifyVoteExtensionHand
 			tolerateBorErr := errors.Is(err, borTypes.ErrFailedToQueryBor) ||
 				(helper.IsZurichHardfork(req.Height) && errors.Is(err, borTypes.ErrBorBlockNotFound))
 			if helper.IsPhuketHardfork(req.Height) && !tolerateBorErr {
+				metrics.RecordVoteExtensionRejected("nonrp_rejected")
 				logger.Error(heimdallTypes.ErrAlertNonRpVoteExtensionRejected, "validator", valAddr, "error", err)
 				return &abci.ResponseVerifyVoteExtension{Status: abci.ResponseVerifyVoteExtension_REJECT}, nil
 			}
@@ -576,6 +587,7 @@ func (app *HeimdallApp) VerifyVoteExtensionHandler() sdk.VerifyVoteExtensionHand
 		// avoids ambiguity at the activation boundary and for direct handler callers.
 		milestoneCtx := ctx.WithBlockHeight(voteExtension.Height)
 		if err := milestoneAbci.ValidateMilestoneProposition(milestoneCtx, &app.MilestoneKeeper, voteExtension.MilestoneProposition); err != nil {
+			metrics.RecordVoteExtensionRejected("milestone_proposition_rejected")
 			logger.Error(heimdallTypes.ErrAlertMilestonePropositionVoteExtensionRejected, "validator", valAddr, "error", err)
 			return &abci.ResponseVerifyVoteExtension{Status: abci.ResponseVerifyVoteExtension_REJECT}, nil
 		}
@@ -730,14 +742,17 @@ func (app *HeimdallApp) PreBlocker(ctx sdk.Context, req *abci.RequestFinalizeBlo
 		if err := milestoneAbci.ValidateMilestoneProposition(milestoneCtx, &app.MilestoneKeeper, majorityMilestone); err != nil {
 			logger.Warn("Invalid milestone proposition", "error", err, "height", req.Height, "majorityMilestone", majorityMilestone)
 			// We don't want to halt consensus because of an invalid majority milestone proposition
+			metrics.RecordMilestoneMajorityCommitSuppressed("validate_failed")
 		} else if helper.IsRio(majorityMilestone.StartBlockNumber) && ctx.BlockHeight() == int64(lastSpanHeimdallBlock)+1 {
 			logger.Info("Last span was created in the previous block, skipping milestone addition", "lastSpanHeimdallBlock", lastSpanHeimdallBlock, "currentBlock", ctx.BlockHeight())
+			metrics.RecordMilestoneMajorityCommitSuppressed("rio_last_span_same_block")
 		} else {
 			logger.Info("2/3rd majority reached on milestone proposition",
 				"startBlock", majorityMilestone.StartBlockNumber,
 				"endBlock", majorityMilestone.StartBlockNumber+uint64(len(majorityMilestone.BlockHashes)-1),
 				"blockHashes", strutil.HashesToString(majorityMilestone.BlockHashes),
 			)
+			metrics.RecordMilestoneMajorityFound("two_thirds")
 			isValidMilestone = true
 		}
 	}
@@ -817,8 +832,11 @@ func (app *HeimdallApp) PreBlocker(ctx sdk.Context, req *abci.RequestFinalizeBlo
 			if err := app.checkAndRotateCurrentSpan(ctx); err != nil {
 				return nil, err
 			}
-		} else if err := app.handlePendingMilestone(ctx, pendingMilestone, validatorSet, extVoteInfo, minMajorityVP); err != nil {
-			return nil, err
+		} else {
+			metrics.RecordMilestoneMajorityFound("one_third")
+			if err := app.handlePendingMilestone(ctx, pendingMilestone, validatorSet, extVoteInfo, minMajorityVP); err != nil {
+				return nil, err
+			}
 		}
 	}
 

helper/call.go

@@ -27,6 +27,7 @@ import (
 	"github.com/0xPolygon/heimdall-v2/contracts/statereceiver"
 	"github.com/0xPolygon/heimdall-v2/contracts/statesender"
 	"github.com/0xPolygon/heimdall-v2/contracts/validatorset"
+	"github.com/0xPolygon/heimdall-v2/metrics"
 	borgrpc "github.com/0xPolygon/heimdall-v2/x/bor/grpc"
 	"github.com/0xPolygon/heimdall-v2/x/stake/types"
 )
@@ -593,6 +594,8 @@ func (c *ContractCaller) GetMainChainBlockTime(ctx context.Context, blockNum uin
 
 // GetBorChainBlock returns bor chain block header
 func (c *ContractCaller) GetBorChainBlock(ctx context.Context, blockNum *big.Int) (header *ethTypes.Header, err error) {
+	defer metrics.RecordBorRPCCallDuration("get_bor_chain_block", time.Now())
+
 	ctx, cancel := context.WithTimeout(ctx, c.BorChainTimeout)
 	defer cancel()
 
@@ -631,6 +634,8 @@ func (c *ContractCaller) GetBorChainBlock(ctx context.Context, blockNum *big.Int
 // In both paths, it tries to get blocks from the range interval
 // but returns only the ones found on the chain.
 func (c *ContractCaller) GetBorChainBlockInfoInBatch(ctx context.Context, start, end int64) ([]*ethTypes.Header, []uint64, []common.Address, error) {
+	defer metrics.RecordBorRPCCallDuration("get_bor_chain_block_info_in_batch", time.Now())
+
 	if start < 0 || end < 0 || end < start {
 		return nil, nil, nil, fmt.Errorf("invalid range [%d,%d]", start, end)
 	}

metrics/abci.go

@@ -127,6 +127,112 @@ var (
 		},
 		[]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",
+			Buckets:   prometheus.DefBuckets,
+		},
+		[]string{"phase"},
+	)
+
+	// MilestoneNoNewHeadersTotal counts ExtendVote turns that skipped milestone
+	// proposition generation because Bor had no new header since the last one
+	// used (ErrNoNewHeadersFound). This is the direct upstream trigger for the
+	// milestone-proposition-generation retry/wait design work.
+	MilestoneNoNewHeadersTotal = promauto.NewCounter(
+		prometheus.CounterOpts{
+			Namespace: Namespace,
+			Subsystem: "milestone",
+			Name:      "no_new_headers_total",
+			Help:      "Number of ExtendVote turns that skipped milestone proposition generation because Bor had no new header",
+		},
+	)
+
+	// MilestoneMajorityFoundTotal counts PreBlocker turns that found a supported
+	// milestone proposition, labeled by the voting-power threshold that was met:
+	// "two_thirds" (proposition committed) or "one_third" (pending, span rotation
+	// deferred). This is the success-side denominator for the majority-search
+	// failure counters — without it, failure counts have no rate to be a fraction of.
+	MilestoneMajorityFoundTotal = promauto.NewCounterVec(
+		prometheus.CounterOpts{
+			Namespace: Namespace,
+			Subsystem: "milestone",
+			Name:      "majority_found_total",
+			Help:      "Number of PreBlocker turns that found a supported milestone proposition, labeled by voting-power threshold",
+		},
+		[]string{"threshold"},
+	)
+
+	// VoteExtensionRejectedTotal counts VerifyVoteExtension turns that rejected a
+	// peer's vote extension, labeled by the specific validation failure. A
+	// rejected vote extension does not count toward the 2/3 (or 1/3) majority
+	// threshold at the next height, making this a direct upstream cause of
+	// milestone majority non-convergence.
+	VoteExtensionRejectedTotal = promauto.NewCounterVec(
+		prometheus.CounterOpts{
+			Namespace: Namespace,
+			Subsystem: "abci",
+			Name:      "vote_extension_rejected_total",
+			Help:      "Number of VerifyVoteExtension turns that rejected a peer's vote extension, labeled by reason",
+		},
+		[]string{"reason"},
+	)
+
+	// BorRPCCallDuration tracks the latency of individual Bor RPC calls made by
+	// heimdall-v2, labeled by method. method must stay a bounded set of
+	// wrapper/RPC names — never an endpoint URL, block number, tx hash, or error.
+	BorRPCCallDuration = promauto.NewHistogramVec(
+		prometheus.HistogramOpts{
+			Namespace: Namespace,
+			Subsystem: "bor",
+			Name:      "rpc_call_duration_seconds",
+			Help:      "Latency of Bor RPC calls made by heimdall-v2, labeled by method",
+			Buckets:   prometheus.DefBuckets,
+		},
+		[]string{"method"},
+	)
+
+	// MilestoneMajorityCommitSuppressedTotal counts PreBlocker turns that found
+	// a supported (2/3) milestone proposition that was NOT committed, labeled
+	// by why: "validate_failed" (ValidateMilestoneProposition rejected it) or
+	// "rio_last_span_same_block" (the Rio guard skipped it because the last
+	// span was created in the previous block). Pairs with
+	// MilestoneMajorityFoundTotal{threshold="two_thirds"}: without this, a
+	// validate-failure storm is indistinguishable from healthy convergence.
+	MilestoneMajorityCommitSuppressedTotal = promauto.NewCounterVec(
+		prometheus.CounterOpts{
+			Namespace: Namespace,
+			Subsystem: "milestone",
+			Name:      "majority_commit_suppressed_total",
+			Help:      "Number of PreBlocker turns with a 2/3 majority milestone proposition that was found but not committed, labeled by reason",
+		},
+		[]string{"reason"},
+	)
+
+	// MilestoneGenerationDuration tracks the end-to-end wall-clock time spent
+	// inside GenMilestoneProposition, which makes multiple Bor RPC calls
+	// (GetBorChainBlock, GetBorChainBlockInfoInBatch). Complements
+	// BorRPCCallDuration by showing how much of the ExtendVote budget the
+	// milestone-proposition path consumes as a whole, versus the side-tx loop.
+	MilestoneGenerationDuration = promauto.NewHistogram(
+		prometheus.HistogramOpts{
+			Namespace: Namespace,
+			Subsystem: "milestone",
+			Name:      "proposition_generation_duration_seconds",
+			Help:      "Wall-clock time spent generating a milestone proposition (GenMilestoneProposition)",
+			Buckets:   prometheus.DefBuckets,
+		},
+	)
 )
 
 // RecordABCIHandlerDuration records the time taken for any ABCI handler.
@@ -140,3 +246,45 @@ func RecordABCIHandlerDuration(metric prometheus.Summary, start time.Time) {
 func RecordExtendVoteBudgetExhausted(phase string) {
 	ExtendVoteBudgetExhaustedTotal.WithLabelValues(phase).Inc()
 }
+
+// RecordExtendVoteElapsed observes the elapsed time since start against the
+// given phase's histogram.
+func RecordExtendVoteElapsed(phase string, start time.Time) {
+	ExtendVoteElapsedSeconds.WithLabelValues(phase).Observe(time.Since(start).Seconds())
+}
+
+// RecordMilestoneNoNewHeaders increments the counter for ExtendVote turns
+// that skipped milestone proposition generation due to no new Bor header.
+func RecordMilestoneNoNewHeaders() {
+	MilestoneNoNewHeadersTotal.Inc()
+}
+
+// RecordMilestoneMajorityFound increments the majority-found counter for the
+// given voting-power threshold ("two_thirds" or "one_third").
+func RecordMilestoneMajorityFound(threshold string) {
+	MilestoneMajorityFoundTotal.WithLabelValues(threshold).Inc()
+}
+
+// RecordVoteExtensionRejected increments the vote-extension-rejection counter
+// for the given reason.
+func RecordVoteExtensionRejected(reason string) {
+	VoteExtensionRejectedTotal.WithLabelValues(reason).Inc()
+}
+
+// RecordBorRPCCallDuration observes the elapsed time since start against the
+// given Bor RPC method's histogram.
+func RecordBorRPCCallDuration(method string, start time.Time) {
+	BorRPCCallDuration.WithLabelValues(method).Observe(time.Since(start).Seconds())
+}
+
+// RecordMilestoneMajorityCommitSuppressed increments the commit-suppressed
+// counter for the given reason.
+func RecordMilestoneMajorityCommitSuppressed(reason string) {
+	MilestoneMajorityCommitSuppressedTotal.WithLabelValues(reason).Inc()
+}
+
+// RecordMilestoneGenerationDuration observes the elapsed time since start
+// against the milestone-proposition-generation histogram.
+func RecordMilestoneGenerationDuration(start time.Time) {
+	MilestoneGenerationDuration.Observe(time.Since(start).Seconds())
+}