add logs for debug

Author: pthmas

protocol/app/app.go

@@ -100,6 +100,9 @@ import (
 	"github.com/spf13/cast"
 	"google.golang.org/grpc"
 
+	// Project logging helper for consistent logs with context
+	applog "github.com/dydxprotocol/v4-chain/protocol/lib/log"
+
 	// App
 	appconstants "github.com/dydxprotocol/v4-chain/protocol/app/constants"
 	"github.com/dydxprotocol/v4-chain/protocol/app/flags"
@@ -355,6 +358,9 @@ type App struct {
 	VaultKeeper vaultmodulekeeper.Keeper
 	// this line is used by starport scaffolding # stargate/app/keeperDeclaration
 
+	// Instrumentation: store wall-clock when BeginBlock starts for execution duration metrics.
+	beginBlockStartTime time.Time
+
 	ModuleManager *module.Manager
 	ModuleBasics  module.BasicManager
 
@@ -1816,20 +1822,47 @@ func (app *App) BeginBlocker(ctx sdk.Context) (sdk.BeginBlock, error) {
 	proposerAddr := sdk.ConsAddress(ctx.BlockHeader().ProposerAddress)
 	middleware.Logger = ctx.Logger().With("proposer_cons_addr", proposerAddr.String())
 
+	// Record start time and compute consensus lag (header time to now) before execution.
+	app.beginBlockStartTime = time.Now()
+	consensusLag := app.beginBlockStartTime.Sub(ctx.BlockTime())
+	applog.InfoLog(
+		ctx,
+		"PIERRICK: BeginBlock timing",
+		"height", ctx.BlockHeight(),
+		"consensus_lag_ms", consensusLag.Milliseconds(),
+	)
+
 	return app.ModuleManager.BeginBlock(ctx)
 }
 
 // EndBlocker application updates every end block
 func (app *App) EndBlocker(ctx sdk.Context) (sdk.EndBlock, error) {
-	// Measure the lag between current timestamp and the end blocker time stamp
-	// as an indicator of whether the node is lagging behind.
+	// Measure total lag vs header time for tip heuristic.
 	metrics.ModuleMeasureSince(metrics.EndBlocker, metrics.EndBlockerLag, ctx.BlockTime())
 
+	// Execution duration since BeginBlock start.
+	execDurationMs := int64(0)
+	if !app.beginBlockStartTime.IsZero() {
+		execDurationMs = time.Since(app.beginBlockStartTime).Milliseconds()
+	}
+
+	// Total lag includes consensus delay + execution time.
+	totalLag := time.Since(ctx.BlockTime())
+	const tipThresholdSeconds = 3
+	atTip := totalLag <= tipThresholdSeconds*time.Second
+
+	applog.InfoLog(
+		ctx,
+		"PIERRICK: EndBlock timing",
+		"height", ctx.BlockHeight(),
+		"exec_duration_ms", execDurationMs,
+		"total_lag_ms", totalLag.Milliseconds(),
+		"at_tip", atTip,
+	)
+
 	ctx = ctx.WithExecMode(lib.ExecModeEndBlock)
 
 	// Reset the logger for middleware.
-	// Note that the middleware is only used by `CheckTx` and `DeliverTx`, and not `EndBlocker`.
-	// Panics from `EndBlocker` will not be logged by the middleware and will lead to consensus failures.
 	middleware.Logger = app.Logger()
 
 	response, err := app.ModuleManager.EndBlock(ctx)

protocol/app/process/full_node_process_proposal.go

@@ -4,6 +4,8 @@ import (
 	abci "github.com/cometbft/cometbft/abci/types"
 	"github.com/cosmos/cosmos-sdk/client"
 	sdk "github.com/cosmos/cosmos-sdk/types"
+
+	"github.com/dydxprotocol/v4-chain/protocol/lib/log"
 )
 
 // FullNodeProcessProposalHandler is the `ProcessProposal` implementation for full-nodes.
@@ -25,6 +27,14 @@ func FullNodeProcessProposalHandler(
 		// Always return `abci.ResponseProcessProposal_ACCEPT`
 		response := &abci.ResponseProcessProposal{Status: abci.ResponseProcessProposal_ACCEPT}
 
+		// Entry log to confirm FullNodeProcessProposalHandler invocation.
+		log.InfoLog(
+			ctx,
+			"PIERRICK: FullNodeProcessProposalHandler invoked",
+			"height", ctx.BlockHeight(),
+			"num_txs", len(req.Txs),
+		)
+
 		// Update the current block height and consensus round.
 		if ctx.BlockHeight() != currentBlockHeight {
 			currentBlockHeight = ctx.BlockHeight()
@@ -36,6 +46,8 @@ func FullNodeProcessProposalHandler(
 
 		txs, err := DecodeProcessProposalTxs(ctx, txConfig.TxDecoder(), req, bridgeKeeepr, pricesTxDecoder)
 		if err != nil {
+			log.ErrorLogWithError(ctx, "PIERRICK: FullNodeProcessProposalHandler decode failed; returning ACCEPT", err)
+			log.InfoLog(ctx, "PIERRICK: FullNodeProcessProposalHandler returning", "status", response.Status.String())
 			return response, nil
 		}
 
@@ -44,6 +56,8 @@ func FullNodeProcessProposalHandler(
 		// would fail due to missing index prices.
 		err = txs.ProposedOperationsTx.Validate()
 		if err != nil {
+			log.ErrorLogWithError(ctx, "PIERRICK: FullNodeProcessProposalHandler ProposedOperationsTx.Validate failed; returning ACCEPT", err)
+			log.InfoLog(ctx, "PIERRICK: FullNodeProcessProposalHandler returning", "status", response.Status.String())
 			return response, nil
 		}
 
@@ -52,6 +66,7 @@ func FullNodeProcessProposalHandler(
 			clobKeeper.RecordMevMetrics(ctx, stakingKeeper, perpetualKeeper, txs.ProposedOperationsTx.msg)
 		}
 
+		log.InfoLog(ctx, "PIERRICK: FullNodeProcessProposalHandler returning", "status", response.Status.String())
 		return response, nil
 	}
 }