From 3ebe8b0e3ae7ed760bcb403c03e3e9fe5554fb60 Mon Sep 17 00:00:00 2001 From: Stephen Buttolph Date: Tue, 17 Dec 2024 14:34:37 -0500 Subject: [PATCH] Improve block building and verification logging --- vms/components/gas/state.go | 3 +- vms/platformvm/block/builder/builder.go | 57 +++++++++++++++++++++-- vms/platformvm/block/executor/verifier.go | 4 +- vms/platformvm/network/gossip.go | 6 +++ 4 files changed, 63 insertions(+), 7 deletions(-) diff --git a/vms/components/gas/state.go b/vms/components/gas/state.go index e3c1c3eb3603..03c4b74cd814 100644 --- a/vms/components/gas/state.go +++ b/vms/components/gas/state.go @@ -5,6 +5,7 @@ package gas import ( "errors" + "fmt" "math" safemath "github.com/ava-labs/avalanchego/utils/math" @@ -44,7 +45,7 @@ func (s State) AdvanceTime( func (s State) ConsumeGas(gas Gas) (State, error) { newCapacity, err := safemath.Sub(uint64(s.Capacity), uint64(gas)) if err != nil { - return State{}, ErrInsufficientCapacity + return State{}, fmt.Errorf("%w: capacity (%d) < gas (%d)", ErrInsufficientCapacity, s.Capacity, gas) } newExcess, err := safemath.Add(uint64(s.Excess), uint64(gas)) diff --git a/vms/platformvm/block/builder/builder.go b/vms/platformvm/block/builder/builder.go index 410d3285a9e7..bf017d217929 100644 --- a/vms/platformvm/block/builder/builder.go +++ b/vms/platformvm/block/builder/builder.go @@ -355,6 +355,9 @@ func buildBlock( ) } if err != nil { + builder.txExecutorBackend.Ctx.Log.Warn("failed to pack block transactions", + zap.Error(err), + ) return nil, fmt.Errorf("failed to pack block txs: %w", err) } @@ -485,9 +488,26 @@ func packEtnaBlockTxs( blockComplexity gas.Dimensions feeCalculator = state.PickFeeCalculator(backend.Config, stateDiff) ) + + backend.Ctx.Log.Debug("starting to pack block txs", + zap.Stringer("parentID", parentID), + zap.Time("blockTimestamp", timestamp), + zap.Uint64("capacity", uint64(capacity)), + zap.Int("mempoolLen", mempool.Len()), + ) for { + currentBlockGas, err := blockComplexity.ToGas(backend.Config.DynamicFeeConfig.Weights) + if err != nil { + return nil, err + } + tx, exists := mempool.Peek() if !exists { + backend.Ctx.Log.Debug("mempool is empty", + zap.Uint64("capacity", uint64(capacity)), + zap.Uint64("blockGas", uint64(currentBlockGas)), + zap.Int("blockLen", len(blockTxs)), + ) break } @@ -504,6 +524,12 @@ func packEtnaBlockTxs( return nil, err } if newBlockGas > capacity { + backend.Ctx.Log.Debug("block is full", + zap.Uint64("nextBlockGas", uint64(newBlockGas)), + zap.Uint64("capacity", uint64(capacity)), + zap.Uint64("blockGas", uint64(currentBlockGas)), + zap.Int("blockLen", len(blockTxs)), + ) break } @@ -549,6 +575,7 @@ func executeTx( // Invariant: [tx] has already been syntactically verified. + txID := tx.ID() err := txexecutor.VerifyWarpMessages( ctx, backend.Ctx.NetworkID, @@ -557,7 +584,11 @@ func executeTx( tx.Unsigned, ) if err != nil { - txID := tx.ID() + backend.Ctx.Log.Debug("transaction failed warp verification", + zap.Stringer("txID", txID), + zap.Error(err), + ) + mempool.MarkDropped(txID, err) return false, nil } @@ -574,23 +605,41 @@ func executeTx( txDiff, ) if err != nil { - txID := tx.ID() + backend.Ctx.Log.Debug("transaction failed execution", + zap.Stringer("txID", txID), + zap.Error(err), + ) + mempool.MarkDropped(txID, err) return false, nil } if inputs.Overlaps(txInputs) { - txID := tx.ID() + // This log is a warn because the mempool should not have allowed this + // transaction to be included. + backend.Ctx.Log.Warn("transaction conflicts with prior transaction", + zap.Stringer("txID", txID), + zap.Error(err), + ) + mempool.MarkDropped(txID, blockexecutor.ErrConflictingBlockTxs) return false, nil } if err := manager.VerifyUniqueInputs(parentID, txInputs); err != nil { - txID := tx.ID() + backend.Ctx.Log.Debug("transaction conflicts with ancestor's import transaction", + zap.Stringer("txID", txID), + zap.Error(err), + ) + mempool.MarkDropped(txID, err) return false, nil } inputs.Union(txInputs) + backend.Ctx.Log.Debug("successfully executed transaction", + zap.Stringer("txID", txID), + zap.Error(err), + ) txDiff.AddTx(tx, status.Committed) return true, txDiff.Apply(stateDiff) } diff --git a/vms/platformvm/block/executor/verifier.go b/vms/platformvm/block/executor/verifier.go index 365cc5a98838..f76b5c078117 100644 --- a/vms/platformvm/block/executor/verifier.go +++ b/vms/platformvm/block/executor/verifier.go @@ -525,14 +525,14 @@ func (v *verifier) processStandardTxs(txs []*txs.Tx, feeCalculator txfee.Calcula blockComplexity, err = blockComplexity.Add(&txComplexity) if err != nil { - return nil, nil, nil, 0, err + return nil, nil, nil, 0, fmt.Errorf("block complexity overflow: %w", err) } } var err error gasConsumed, err = blockComplexity.ToGas(v.txExecutorBackend.Config.DynamicFeeConfig.Weights) if err != nil { - return nil, nil, nil, 0, err + return nil, nil, nil, 0, fmt.Errorf("block gas overflow: %w", err) } // If this block exceeds the available capacity, ConsumeGas will return diff --git a/vms/platformvm/network/gossip.go b/vms/platformvm/network/gossip.go index 43e730b90e31..70992c04eecf 100644 --- a/vms/platformvm/network/gossip.go +++ b/vms/platformvm/network/gossip.go @@ -10,6 +10,7 @@ import ( "time" "github.com/prometheus/client_golang/prometheus" + "go.uber.org/zap" "github.com/ava-labs/avalanchego/ids" "github.com/ava-labs/avalanchego/network/p2p" @@ -108,6 +109,11 @@ func (g *gossipMempool) Add(tx *txs.Tx) error { } if err := g.txVerifier.VerifyTx(tx); err != nil { + g.log.Debug("transaction failed verification", + zap.Stringer("txID", txID), + zap.Error(err), + ) + g.Mempool.MarkDropped(txID, err) return fmt.Errorf("failed verification: %w", err) }