[CLOB-1020] [CLOB-1048] Logging Library with Contextual Tags (#872)

* Introduce new library for contextualized logging tags

* migrate some files over

* spelling

* actually use the ctx

* fix tests about logging

* workflow to push and lint

* push a binary

* snapshot push

* migrate all in clob

* small fixes

* lint

* remove sentinel error in favor of log.ErrorLog

* properly expand key val tags

* nice comments

* fix tests

* pr comments

* pascalcase

* tests

* remove build and push

* fmt lint

* fix another test

.github/workflows/protocol-build-and-push-snapshot.yml

@@ -3,6 +3,7 @@ name: Protocol Build & Push Image to AWS ECR
 on:  # yamllint disable-line rule:truthy
   push:
     branches:
+      - jonfung/**
       - main
       - 'release/[a-z]+/v0.[0-9]+.x'  # e.g. release/protocol/v0.1.x
       - 'release/[a-z]+/v[0-9]+.x'  # e.g. release/protocol/v1.x

protocol/indexer/off_chain_updates/off_chain_updates.go

@@ -68,6 +68,7 @@ func MustCreateOrderUpdateMessage(
 }
 
 // CreateOrderUpdateMessage creates an off-chain update message for an order being updated.
+// TODO(CLOB-1051) take in ctx, not logger
 func CreateOrderUpdateMessage(
 	logger log.Logger,
 	orderId clobtypes.OrderId,
@@ -186,6 +187,7 @@ func CreateOrderRemoveMessage(
 // removed with the resulting removal status of the removed order. It attempts to look up the removal
 // reason using the given orderStatus & orderError. If the reason cannot be found, it logs an error
 // and falls back to the defaultRemovalReason. If defaultRemovalReason is ...UNSPECIFIED, it panics.
+// TODO(CLOB-1051) take in ctx, not logger
 func CreateOrderRemoveMessageWithDefaultReason(
 	logger log.Logger,
 	orderId clobtypes.OrderId,

protocol/lib/log/constants.go

@@ -0,0 +1,54 @@
+package log
+
+const (
+	SourceModuleKey = "source_module"
+	Error           = "error"
+)
+
+// Tag keys
+// Do not have anything generic in here. For example, `Status` is too vague
+// and can be clarified as `OrderStatus` or `DaemonHealthStatus`.
+const (
+	Module              = "module"
+	TxMode              = "tx_mode"
+	OperationsQueue     = "operations_queue"
+	Callback            = "callback"
+	BlockHeight         = "block_height"
+	Msg                 = "msg"
+	ProposerConsAddress = "proposer_cons_address"
+	Handler             = "handler"
+	Tx                  = "tx"
+	OrderHash           = "order_hash"
+	OrderStatus         = "order_status"
+	Subaccount          = "subaccount"
+	PerpetualId         = "perpetual_id"
+	MevMatches          = "mev_matches"
+	StackTrace          = "stack_trace"
+	Proposer            = "proposer"
+	PrunableBlockHeight = "prunable_block_height"
+
+	OrderSizeOptimisticallyFilledFromMatchingQuantums = "order_size_optimistically_filled_from_matching_quantums"
+	NewLocalValidatorOperationsQueue                  = "new_local_validator_operations_queue"
+	LocalValidatorOperationsQueue                     = "local_validator_operations_queue"
+)
+
+// Tag values
+const (
+	// Module tag values are prefixed with `x/`
+	Clob = "x/clob"
+
+	CheckTx   = "check_tx"
+	RecheckTx = "recheck_tx"
+	DeliverTx = "deliver_tx"
+)
+
+// Special tag values that should be PascalCased (i.e function names)
+const (
+	AnteHandler        = "AnteHandler"
+	PlaceOrder         = "PlaceOrder"
+	CancelOrder        = "CancelOrder"
+	ProposedOperations = "ProposedOperations"
+	BeginBlocker       = "BeginBlocker"
+	EndBlocker         = "EndBlocker"
+	PrepareCheckState  = "PrepareCheckState"
+)

protocol/lib/log/utils.go

@@ -0,0 +1,42 @@
+package log
+
+import (
+	"errors"
+
+	sdk "github.com/cosmos/cosmos-sdk/types"
+)
+
+// InfoLog reports msg as an info level log with specified key vals.
+// `keyvals` should be even number in length and be of alternating types (string, interface{}).
+func InfoLog(ctx sdk.Context, msg string, keyvals ...interface{}) {
+	ctx.Logger().Info(msg, keyvals...)
+}
+
+// DebugLog reports msg as a debug level log with specified key vals.
+// `keyvals` should be even number in length and be of alternating types (string, interface{}).
+func DebugLog(ctx sdk.Context, msg string, keyvals ...interface{}) {
+	ctx.Logger().Debug(msg, keyvals...)
+}
+
+// ErrorLogWithError reports msg as a error log with specified key vals,
+// as well as attaching the error object to the log for datadog error tracking.
+// `keyvals` should be even number in length and be of alternating types (string, interface{}).
+func ErrorLogWithError(ctx sdk.Context, msg string, err error, keyvals ...interface{}) {
+	ctx.Logger().Error(msg, append(keyvals, Error, err))
+}
+
+// ErrorLog reports msg as a error log. It constructs an error object on the fly with
+// the given message object.
+// Please try to define a new error and use `ErrorLogWithError` instead.
+// `keyvals` should be even number in length and be of alternating types (string, interface{}).
+func ErrorLog(ctx sdk.Context, msg string, keyvals ...interface{}) {
+	err := errors.New(msg)
+	ErrorLogWithError(ctx, msg, err, keyvals...)
+}
+
+// AddPersistentTagsToLogger returns a new sdk.Context with a logger that has new persistent
+// tags that are added to all logs emitted.
+// `keyvals` should be even number in length and be of alternating types (string, interface{}).
+func AddPersistentTagsToLogger(ctx sdk.Context, keyvals ...interface{}) sdk.Context {
+	return ctx.WithLogger(ctx.Logger().With(keyvals...))
+}

protocol/lib/tx_mode.go

@@ -1,6 +1,9 @@
 package lib
 
-import sdk "github.com/cosmos/cosmos-sdk/types"
+import (
+	sdk "github.com/cosmos/cosmos-sdk/types"
+	"github.com/dydxprotocol/v4-chain/protocol/lib/log"
+)
 
 func AssertDeliverTxMode(ctx sdk.Context) {
 	if ctx.IsCheckTx() || ctx.IsReCheckTx() {
@@ -21,10 +24,10 @@ func AssertCheckTxMode(ctx sdk.Context) {
 // TxMode returns a textual representation of the tx mode, one of `CheckTx`, `ReCheckTx`, or `DeliverTx`.
 func TxMode(ctx sdk.Context) string {
 	if ctx.IsReCheckTx() {
-		return "ReCheckTx"
+		return log.RecheckTx
 	} else if ctx.IsCheckTx() {
-		return "CheckTx"
+		return log.CheckTx
 	} else {
-		return "DeliverTx"
+		return log.DeliverTx
 	}
 }

protocol/lib/tx_mode_test.go

@@ -1,10 +1,12 @@
 package lib_test
 
 import (
+	"testing"
+
 	"github.com/dydxprotocol/v4-chain/protocol/lib"
+	"github.com/dydxprotocol/v4-chain/protocol/lib/log"
 	testApp "github.com/dydxprotocol/v4-chain/protocol/testutil/app"
 	"github.com/stretchr/testify/require"
-	"testing"
 )
 
 func TestAssertDeliverTxMode(t *testing.T) {
@@ -54,7 +56,7 @@ func TestTxMode(t *testing.T) {
 	// Initializing the chain returns a checkTx context so swap to a deliverTx context
 	ctx := tApp.InitChain().WithIsCheckTx(false)
 
-	require.Equal(t, "DeliverTx", lib.TxMode(ctx))
-	require.Equal(t, "CheckTx", lib.TxMode(ctx.WithIsCheckTx(true)))
-	require.Equal(t, "ReCheckTx", lib.TxMode(ctx.WithIsReCheckTx(true)))
+	require.Equal(t, log.DeliverTx, lib.TxMode(ctx))
+	require.Equal(t, log.CheckTx, lib.TxMode(ctx.WithIsCheckTx(true)))
+	require.Equal(t, log.RecheckTx, lib.TxMode(ctx.WithIsReCheckTx(true)))
 }

protocol/x/clob/abci.go

@@ -10,6 +10,7 @@ import (
 	"github.com/dydxprotocol/v4-chain/protocol/indexer/indexer_manager"
 	indexershared "github.com/dydxprotocol/v4-chain/protocol/indexer/shared"
 	"github.com/dydxprotocol/v4-chain/protocol/lib"
+	"github.com/dydxprotocol/v4-chain/protocol/lib/log"
 	"github.com/dydxprotocol/v4-chain/protocol/lib/metrics"
 	"github.com/dydxprotocol/v4-chain/protocol/x/clob/keeper"
 	"github.com/dydxprotocol/v4-chain/protocol/x/clob/types"
@@ -20,6 +21,11 @@ func BeginBlocker(
 	ctx sdk.Context,
 	keeper types.ClobKeeper,
 ) {
+	ctx = log.AddPersistentTagsToLogger(ctx,
+		log.Handler, log.BeginBlocker,
+		log.BlockHeight, ctx.BlockHeight(),
+	)
+
 	// Initialize the set of process proposer match events for the next block effectively
 	// removing any events that occurred in the last block.
 	keeper.MustSetProcessProposerMatchesEvents(
@@ -35,6 +41,11 @@ func EndBlocker(
 	ctx sdk.Context,
 	keeper keeper.Keeper,
 ) {
+	ctx = log.AddPersistentTagsToLogger(ctx,
+		log.Handler, log.EndBlocker,
+		log.BlockHeight, ctx.BlockHeight(),
+	)
+
 	processProposerMatchesEvents := keeper.GetProcessProposerMatchesEvents(ctx)
 
 	// Prune any fill amounts from state which are now past their `pruneableBlockHeight`.
@@ -117,6 +128,12 @@ func PrepareCheckState(
 	ctx sdk.Context,
 	keeper *keeper.Keeper,
 ) {
+	ctx = log.AddPersistentTagsToLogger(ctx,
+		log.Handler, log.PrepareCheckState,
+		// Prepare check state is for the next block.
+		log.BlockHeight, ctx.BlockHeight()+1,
+	)
+
 	// TODO(CORE-538): Is there a cleaner way to check to see if this is genesis?
 	if ctx.BlockHeight() == 0 || ctx.BlockHeight() == 1 {
 		return
@@ -135,12 +152,9 @@ func PrepareCheckState(
 
 	// 1. Remove all operations in the local validators operations queue from the memclob.
 	localValidatorOperationsQueue, shortTermOrderTxBytes := keeper.MemClob.GetOperationsToReplay(ctx)
-	keeper.Logger(ctx).Debug(
-		"Clearing local operations queue",
-		"localValidatorOperationsQueue",
-		types.GetInternalOperationsQueueTextString(localValidatorOperationsQueue),
-		"block",
-		ctx.BlockHeight(),
+
+	log.DebugLog(ctx, "Clearing local operations queue",
+		log.LocalValidatorOperationsQueue, types.GetInternalOperationsQueueTextString(localValidatorOperationsQueue),
 	)
 
 	keeper.MemClob.RemoveAndClearOperationsQueue(ctx, localValidatorOperationsQueue)
@@ -222,12 +236,10 @@ func PrepareCheckState(
 	keeper.SendOffchainMessages(offchainUpdates, nil, metrics.SendPrepareCheckStateOffchainUpdates)
 
 	newLocalValidatorOperationsQueue, _ := keeper.MemClob.GetOperationsToReplay(ctx)
-	keeper.Logger(ctx).Debug(
-		"Local operations queue after PrepareCheckState",
-		"newLocalValidatorOperationsQueue",
+
+	log.DebugLog(ctx, "Local operations queue after PrepareCheckState",
+		log.NewLocalValidatorOperationsQueue,
 		types.GetInternalOperationsQueueTextString(newLocalValidatorOperationsQueue),
-		"block",
-		ctx.BlockHeight(),
 	)
 
 	// Set per-orderbook gauges.

protocol/x/clob/ante/clob.go

@@ -3,10 +3,11 @@ package ante
 import (
 	errorsmod "cosmossdk.io/errors"
 	"github.com/cometbft/cometbft/crypto/tmhash"
-	cmtlog "github.com/cometbft/cometbft/libs/log"
+	cometbftlog "github.com/cometbft/cometbft/libs/log"
 	sdk "github.com/cosmos/cosmos-sdk/types"
 	sdkerrors "github.com/cosmos/cosmos-sdk/types/errors"
 	"github.com/dydxprotocol/v4-chain/protocol/lib"
+	"github.com/dydxprotocol/v4-chain/protocol/lib/log"
 	"github.com/dydxprotocol/v4-chain/protocol/x/clob/types"
 	satypes "github.com/dydxprotocol/v4-chain/protocol/x/subaccounts/types"
 )
@@ -62,8 +63,20 @@ func (cd ClobDecorator) AnteHandle(
 	msgs := tx.GetMsgs()
 	var msg = msgs[0]
 
+	// Set request-level logging tags
+	ctx = log.AddPersistentTagsToLogger(ctx,
+		log.Module, log.Clob,
+		log.Callback, lib.TxMode(ctx),
+		log.BlockHeight, ctx.BlockHeight()+1,
+		log.Msg, msg,
+	)
+
 	switch msg := msg.(type) {
 	case *types.MsgCancelOrder:
+		ctx = log.AddPersistentTagsToLogger(ctx,
+			log.Handler, log.CancelOrder,
+		)
+
 		if msg.OrderId.IsStatefulOrder() {
 			err = cd.clobKeeper.CancelStatefulOrder(ctx, msg)
 		} else {
@@ -76,35 +89,23 @@ func (cd ClobDecorator) AnteHandle(
 			// This guarantees that `MsgCancelOrder` has undergone stateless validation.
 			err = cd.clobKeeper.CancelShortTermOrder(ctx, msg)
 		}
-		cd.clobKeeper.Logger(ctx).Debug("Received new order cancelation",
-			"tx",
-			cmtlog.NewLazySprintf("%X", tmhash.Sum(ctx.TxBytes())),
-			"msg",
-			msg,
-			"err",
-			err,
-			"block",
-			ctx.BlockHeight(),
-			"txMode",
-			lib.TxMode(ctx),
+
+		log.DebugLog(ctx, "Received new order cancellation",
+			log.Tx, cometbftlog.NewLazySprintf("%X", tmhash.Sum(ctx.TxBytes())),
+			log.Error, err,
 		)
 
 	case *types.MsgPlaceOrder:
+		ctx = log.AddPersistentTagsToLogger(ctx,
+			log.Handler, log.PlaceOrder,
+		)
 		if msg.Order.OrderId.IsStatefulOrder() {
 			err = cd.clobKeeper.PlaceStatefulOrder(ctx, msg)
-			cd.clobKeeper.Logger(ctx).Debug("Received new stateful order",
-				"tx",
-				cmtlog.NewLazySprintf("%X", tmhash.Sum(ctx.TxBytes())),
-				"orderHash",
-				cmtlog.NewLazySprintf("%X", msg.Order.GetOrderHash()),
-				"msg",
-				msg,
-				"err",
-				err,
-				"block",
-				ctx.BlockHeight(),
-				"txMode",
-				lib.TxMode(ctx),
+
+			log.DebugLog(ctx, "Received new stateful order",
+				log.Tx, cometbftlog.NewLazySprintf("%X", tmhash.Sum(ctx.TxBytes())),
+				log.OrderHash, cometbftlog.NewLazySprintf("%X", msg.Order.GetOrderHash()),
+				log.Error, err,
 			)
 		} else {
 			// No need to process short term orders on `ReCheckTx`.
@@ -120,23 +121,13 @@ func (cd ClobDecorator) AnteHandle(
 				ctx,
 				msg,
 			)
-			cd.clobKeeper.Logger(ctx).Debug("Received new short term order",
-				"tx",
-				cmtlog.NewLazySprintf("%X", tmhash.Sum(ctx.TxBytes())),
-				"orderHash",
-				cmtlog.NewLazySprintf("%X", msg.Order.GetOrderHash()),
-				"msg",
-				msg,
-				"status",
-				status,
-				"orderSizeOptimisticallyFilledFromMatchingQuantums",
-				orderSizeOptimisticallyFilledFromMatchingQuantums,
-				"err",
-				err,
-				"block",
-				ctx.BlockHeight(),
-				"txMode",
-				lib.TxMode(ctx),
+
+			log.DebugLog(ctx, "Received new short term order",
+				log.Tx, cometbftlog.NewLazySprintf("%X", tmhash.Sum(ctx.TxBytes())),
+				log.OrderHash, cometbftlog.NewLazySprintf("%X", msg.Order.GetOrderHash()),
+				log.OrderStatus, status,
+				log.OrderSizeOptimisticallyFilledFromMatchingQuantums, orderSizeOptimisticallyFilledFromMatchingQuantums,
+				log.Error, err,
 			)
 		}
 	}