From db848d210670dfb9ae973efb4907a10a67c722e2 Mon Sep 17 00:00:00 2001 From: Jonathan Fung <121899091+jonfung-dydx@users.noreply.github.com> Date: Thu, 4 Jan 2024 19:25:03 -0700 Subject: [PATCH] [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 --- .../protocol-build-and-push-snapshot.yml | 1 + .../off_chain_updates/off_chain_updates.go | 2 + protocol/lib/log/constants.go | 54 +++++++++++++ protocol/lib/log/utils.go | 42 +++++++++++ protocol/lib/tx_mode.go | 11 ++- protocol/lib/tx_mode_test.go | 10 ++- protocol/x/clob/abci.go | 34 ++++++--- protocol/x/clob/ante/clob.go | 75 ++++++++----------- protocol/x/clob/keeper/deleveraging.go | 34 ++++----- .../keeper/grpc_query_mev_node_to_node.go | 26 ++----- protocol/x/clob/keeper/liquidations.go | 8 +- protocol/x/clob/keeper/mev.go | 69 ++++++++--------- .../x/clob/keeper/msg_server_cancel_orders.go | 22 +++--- .../keeper/msg_server_cancel_orders_test.go | 27 +++---- .../x/clob/keeper/msg_server_place_order.go | 22 +++--- .../keeper/msg_server_place_order_test.go | 22 +++--- .../keeper/msg_server_proposed_operations.go | 16 +++- .../msg_server_proposed_operations_test.go | 1 - protocol/x/clob/keeper/order_state.go | 11 ++- protocol/x/clob/keeper/orders.go | 26 ++++--- protocol/x/clob/keeper/process_operations.go | 10 +-- .../x/clob/keeper/process_single_match.go | 9 ++- .../x/clob/keeper/stateful_order_state.go | 18 ++--- 23 files changed, 324 insertions(+), 226 deletions(-) create mode 100644 protocol/lib/log/constants.go create mode 100644 protocol/lib/log/utils.go diff --git a/.github/workflows/protocol-build-and-push-snapshot.yml b/.github/workflows/protocol-build-and-push-snapshot.yml index 51ffb24193..d3b346c391 100644 --- a/.github/workflows/protocol-build-and-push-snapshot.yml +++ b/.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 diff --git a/protocol/indexer/off_chain_updates/off_chain_updates.go b/protocol/indexer/off_chain_updates/off_chain_updates.go index 9ba02a2946..9a83dcd7c6 100644 --- a/protocol/indexer/off_chain_updates/off_chain_updates.go +++ b/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, diff --git a/protocol/lib/log/constants.go b/protocol/lib/log/constants.go new file mode 100644 index 0000000000..06e18a1a49 --- /dev/null +++ b/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" +) diff --git a/protocol/lib/log/utils.go b/protocol/lib/log/utils.go new file mode 100644 index 0000000000..2709889e82 --- /dev/null +++ b/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...)) +} diff --git a/protocol/lib/tx_mode.go b/protocol/lib/tx_mode.go index 66785a669a..b052886f9f 100644 --- a/protocol/lib/tx_mode.go +++ b/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 } } diff --git a/protocol/lib/tx_mode_test.go b/protocol/lib/tx_mode_test.go index 094acd2c88..4b32312a21 100644 --- a/protocol/lib/tx_mode_test.go +++ b/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))) } diff --git a/protocol/x/clob/abci.go b/protocol/x/clob/abci.go index f446d91e71..a3026bb688 100644 --- a/protocol/x/clob/abci.go +++ b/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. diff --git a/protocol/x/clob/ante/clob.go b/protocol/x/clob/ante/clob.go index 48e680aacb..3ad595d42c 100644 --- a/protocol/x/clob/ante/clob.go +++ b/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, ) } } diff --git a/protocol/x/clob/keeper/deleveraging.go b/protocol/x/clob/keeper/deleveraging.go index c063f1a7c6..fb51c720ef 100644 --- a/protocol/x/clob/keeper/deleveraging.go +++ b/protocol/x/clob/keeper/deleveraging.go @@ -13,6 +13,7 @@ import ( indexerevents "github.com/dydxprotocol/v4-chain/protocol/indexer/events" "github.com/dydxprotocol/v4-chain/protocol/indexer/indexer_manager" "github.com/dydxprotocol/v4-chain/protocol/lib" + "github.com/dydxprotocol/v4-chain/protocol/lib/log" "github.com/dydxprotocol/v4-chain/protocol/lib/metrics" assettypes "github.com/dydxprotocol/v4-chain/protocol/x/assets/types" "github.com/dydxprotocol/v4-chain/protocol/x/clob/types" @@ -33,6 +34,11 @@ func (k Keeper) MaybeDeleverageSubaccount( ) { lib.AssertCheckTxMode(ctx) + ctx = log.AddPersistentTagsToLogger(ctx, + log.PerpetualId, perpetualId, + log.Subaccount, subaccountId, + ) + shouldDeleverageAtBankruptcyPrice, shouldDeleverageAtOraclePrice, err := k.CanDeleverageSubaccount( ctx, subaccountId, @@ -58,11 +64,7 @@ func (k Keeper) MaybeDeleverageSubaccount( if !exists { // Early return to skip deleveraging if the subaccount does not have an open position for the perpetual. // This could happen if the subaccount's position was closed by other liquidation matches. - k.Logger(ctx).Debug( - "Subaccount does not have an open position for the perpetual that is being deleveraged", - "subaccount", subaccount, - "perpetualId", perpetualId, - ) + log.DebugLog(ctx, "Subaccount does not have an open position for the perpetual that is being deleveraged") return new(big.Int), nil } @@ -243,10 +245,9 @@ func (k Keeper) OffsetSubaccountPerpetualPosition( numSubaccounts := len(subaccountsWithOpenPositions) if numSubaccounts == 0 { liquidatedSubaccount := k.subaccountsKeeper.GetSubaccount(ctx, liquidatedSubaccountId) - k.Logger(ctx).Error( + log.ErrorLog( + ctx, "Failed to find subaccounts with open positions on opposite side of liquidated subaccount", - "blockHeight", ctx.BlockHeight(), - "perpetualId", perpetualId, "deltaQuantumsTotal", deltaQuantumsTotal, "liquidatedSubaccount", liquidatedSubaccount, ) @@ -294,11 +295,8 @@ func (k Keeper) OffsetSubaccountPerpetualPosition( ) if err != nil { liquidatedSubaccount := k.subaccountsKeeper.GetSubaccount(ctx, liquidatedSubaccountId) - k.Logger(ctx).Error( - "Encountered error when getting quote quantums for deleveraging", - "error", err, - "blockHeight", ctx.BlockHeight(), - "perpetualId", perpetualId, + log.ErrorLogWithError(ctx, "Encountered error when getting quote quantums for deleveraging", + err, "deltaBaseQuantums", deltaBaseQuantums, "liquidatedSubaccount", liquidatedSubaccount, "offsettingSubaccount", offsettingSubaccount, @@ -351,9 +349,8 @@ func (k Keeper) OffsetSubaccountPerpetualPosition( // TODO(CLOB-75): Support deleveraging subaccounts with non overlapping bankruptcy prices. liquidatedSubaccount := k.subaccountsKeeper.GetSubaccount(ctx, liquidatedSubaccountId) offsettingSubaccount := k.subaccountsKeeper.GetSubaccount(ctx, *offsettingSubaccount.Id) - k.Logger(ctx).Debug( - "Encountered error when processing deleveraging", - "error", err, + log.DebugLog(ctx, "Encountered error when processing deleveraging", + err, "blockHeight", ctx.BlockHeight(), "checkTx", ctx.IsCheckTx(), "perpetualId", perpetualId, @@ -609,11 +606,12 @@ func (k Keeper) DeleverageSubaccounts( perpetualId := subaccountsToDeleverage[i].PerpetualId _, err := k.MaybeDeleverageSubaccount(ctx, subaccountId, perpetualId) if err != nil { - k.Logger(ctx).Error( + log.ErrorLogWithError( + ctx, "Failed to deleverage subaccount.", + err, "subaccount", subaccountId, "perpetualId", perpetualId, - "error", err, ) return err } diff --git a/protocol/x/clob/keeper/grpc_query_mev_node_to_node.go b/protocol/x/clob/keeper/grpc_query_mev_node_to_node.go index a2f48c716f..b21f36dce7 100644 --- a/protocol/x/clob/keeper/grpc_query_mev_node_to_node.go +++ b/protocol/x/clob/keeper/grpc_query_mev_node_to_node.go @@ -2,10 +2,10 @@ package keeper import ( "context" - "fmt" "math/big" sdk "github.com/cosmos/cosmos-sdk/types" + "github.com/dydxprotocol/v4-chain/protocol/lib/log" "github.com/dydxprotocol/v4-chain/protocol/x/clob/types" "google.golang.org/grpc/codes" "google.golang.org/grpc/status" @@ -22,12 +22,8 @@ func (k Keeper) MevNodeToNodeCalculation( // Validate that the request is valid. if err := validateMevNodeToNodeRequest(req); err != nil { - k.Logger(ctx).Error( - fmt.Sprintf( - "Failed to validate MEV node to node calculation request: Error: %+v, request: %+v", - err.Error(), - req, - ), + log.ErrorLogWithError(ctx, "Failed to validate MEV node to node calculation request", err, + "mev_calculation_request", req, ) return nil, err } @@ -39,12 +35,8 @@ func (k Keeper) MevNodeToNodeCalculation( blockProposerPnL, req.BlockProposerMatches, ); err != nil { - k.Logger(ctx).Error( - fmt.Sprintf( - "Failed to calculate match PnL for block proposer: Error: %+v, MEV matches: %+v", - err.Error(), - req.BlockProposerMatches, - ), + log.ErrorLogWithError(ctx, "Failed to calculate match PnL for block proposer", err, + "mev_matches", req.BlockProposerMatches, ) return nil, err } @@ -54,12 +46,8 @@ func (k Keeper) MevNodeToNodeCalculation( validatorPnL, req.ValidatorMevMetrics.ValidatorMevMatches, ); err != nil { - k.Logger(ctx).Error( - fmt.Sprintf( - "Failed to calculate match PnL for validator: Error: %+v, MEV matches: %+v", - err.Error(), - req.ValidatorMevMetrics.ValidatorMevMatches, - ), + log.ErrorLogWithError(ctx, "Failed to calculate match PnL for validator", err, + "mev_matches", req.ValidatorMevMetrics.ValidatorMevMatches, ) return nil, err } diff --git a/protocol/x/clob/keeper/liquidations.go b/protocol/x/clob/keeper/liquidations.go index f185c89165..8033581a43 100644 --- a/protocol/x/clob/keeper/liquidations.go +++ b/protocol/x/clob/keeper/liquidations.go @@ -13,6 +13,7 @@ import ( "github.com/cosmos/cosmos-sdk/telemetry" sdk "github.com/cosmos/cosmos-sdk/types" "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/types" satypes "github.com/dydxprotocol/v4-chain/protocol/x/subaccounts/types" @@ -124,10 +125,11 @@ func (k Keeper) LiquidateSubaccountsAgainstOrderbook( // Exception for liquidation which conflicts with clob pair status. This is expected for liquidations generated // for subaccounts with open positions in final settlement markets. if err != nil && !errors.Is(err, types.ErrLiquidationConflictsWithClobPairStatus) { - k.Logger(ctx).Error( + log.ErrorLogWithError( + ctx, "Failed to liquidate subaccount", + err, "liquidationOrder", *liquidationOrder, - "error", err, ) return nil, err } @@ -1126,7 +1128,7 @@ func (k Keeper) validateMatchedLiquidation( // Validate that processing the liquidation fill does not leave insufficient funds // in the insurance fund (such that the liquidation couldn't have possibly continued). if !k.IsValidInsuranceFundDelta(ctx, insuranceFundDelta) { - k.Logger(ctx).Debug("ProcessMatches: insurance fund has insufficient balance to process the liquidation.") + log.DebugLog(ctx, "ProcessMatches: insurance fund has insufficient balance to process the liquidation.") return nil, errorsmod.Wrapf( types.ErrInsuranceFundHasInsufficientFunds, "Liquidation order %v, insurance fund delta %v", diff --git a/protocol/x/clob/keeper/mev.go b/protocol/x/clob/keeper/mev.go index 0b1a6605f6..1f5e29a681 100644 --- a/protocol/x/clob/keeper/mev.go +++ b/protocol/x/clob/keeper/mev.go @@ -9,6 +9,7 @@ import ( sdk "github.com/cosmos/cosmos-sdk/types" "github.com/dydxprotocol/v4-chain/protocol/app/process" "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/mev_telemetry" "github.com/dydxprotocol/v4-chain/protocol/x/clob/types" @@ -76,13 +77,18 @@ func (k Keeper) RecordMevMetrics( // Recover from any panics that occur during MEV calculation. defer func() { if r := recover(); r != nil { - k.Logger(ctx).Error( - "panic when recording mev metrics", - "panic", - r, - "stack trace", - string(debug.Stack()), - ) + err, ok := r.(error) + if !ok { + log.ErrorLog(ctx, "panic when recording mev metrics", + log.StackTrace, + string(debug.Stack()), + ) + } else { + log.ErrorLogWithError(ctx, "panic when recording mev metrics", err, + log.StackTrace, + string(debug.Stack()), + ) + } } }() @@ -101,12 +107,9 @@ func (k Keeper) RecordMevMetrics( msgProposedOperations.GetOperationsQueue(), ) if err != nil { - k.Logger(ctx).Error( - fmt.Sprintf( - "Failed to create MEV matches for block proposer operations: Error: %+v, Operations: %+v", - err.Error(), - msgProposedOperations.GetOperationsQueue(), - ), + log.ErrorLogWithError(ctx, "Failed to create MEV matches for block proposer operations", err, + log.OperationsQueue, + msgProposedOperations.GetOperationsQueue(), ) metrics.IncrCounter( metrics.ClobMevErrorCount, @@ -119,12 +122,9 @@ func (k Keeper) RecordMevMetrics( blockProposerPnL, blockProposerMevMatches, ); err != nil { - k.Logger(ctx).Error( - fmt.Sprintf( - "Failed to calculate match PnL for block proposer: Error: %+v, MEV matches: %+v", - err.Error(), - blockProposerMevMatches, - ), + log.ErrorLogWithError(ctx, "Failed to calculate match PnL for block proposer", err, + log.MevMatches, + blockProposerMevMatches, ) metrics.IncrCounter( metrics.ClobMevErrorCount, @@ -139,12 +139,9 @@ func (k Keeper) RecordMevMetrics( k.GetOperations(ctx).GetOperationsQueue(), ) if err != nil { - k.Logger(ctx).Error( - fmt.Sprintf( - "Failed to create MEV matches for validator operations: Error: %+v, Operations: %+v", - err.Error(), - k.GetOperations(ctx).GetOperationsQueue(), - ), + log.ErrorLogWithError(ctx, "Failed to create MEV matches for validator operations", err, + log.OperationsQueue, + k.GetOperations(ctx).GetOperationsQueue(), ) metrics.IncrCounter( metrics.ClobMevErrorCount, @@ -157,12 +154,9 @@ func (k Keeper) RecordMevMetrics( validatorPnL, validatorMevMatches, ); err != nil { - k.Logger(ctx).Error( - fmt.Sprintf( - "Failed to calculate match PnL for validator: Error: %+v, MEV matches: %+v", - err.Error(), - validatorMevMatches, - ), + log.ErrorLogWithError(ctx, "Failed to calculate match PnL for validator", err, + log.MevMatches, + validatorMevMatches, ) metrics.IncrCounter( metrics.ClobMevErrorCount, @@ -239,7 +233,7 @@ func (k Keeper) RecordMevMetrics( // Add label for consensus round if available. consensusRound, ok := ctx.Value(process.ConsensusRound).(int64) if !ok { - k.Logger(ctx).Error("Failed to get consensus round") + log.ErrorLog(ctx, "Failed to get consensus round") metrics.IncrCounter( metrics.ClobMevErrorCount, 1, @@ -251,13 +245,10 @@ func (k Keeper) RecordMevMetrics( proposerConsAddress := sdk.ConsAddress(ctx.BlockHeader().ProposerAddress) proposer, err := stakingKeeper.GetValidatorByConsAddr(ctx, proposerConsAddress) if err != nil { - k.Logger(ctx).Error( - "Failed to get proposer by consensus address", - "proposer", - proposerConsAddress.String(), - "err", - err, + log.ErrorLogWithError(ctx, "Failed to get proposer by consensus address", err, + log.Proposer, proposerConsAddress.String(), ) + metrics.IncrCounter( metrics.ClobMevErrorCount, 1, @@ -278,6 +269,8 @@ func (k Keeper) RecordMevMetrics( ) // Log MEV metric. + // TODO(CLOB-1051) change to use new logger library. Be careful the values are not changed + // because mev dashboards rely on this log. k.Logger(ctx).Info( "Measuring MEV for proposed matches", metrics.Mev, diff --git a/protocol/x/clob/keeper/msg_server_cancel_orders.go b/protocol/x/clob/keeper/msg_server_cancel_orders.go index 0e98d57884..63c9482536 100644 --- a/protocol/x/clob/keeper/msg_server_cancel_orders.go +++ b/protocol/x/clob/keeper/msg_server_cancel_orders.go @@ -12,7 +12,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" - errorlib "github.com/dydxprotocol/v4-chain/protocol/lib/error" + "github.com/dydxprotocol/v4-chain/protocol/lib/log" "github.com/dydxprotocol/v4-chain/protocol/lib/metrics" "github.com/dydxprotocol/v4-chain/protocol/x/clob/types" ) @@ -24,6 +24,16 @@ func (k msgServer) CancelOrder( ) (resp *types.MsgCancelOrderResponse, err error) { ctx := sdk.UnwrapSDKContext(goCtx) + // Attach various logging tags relative to this request. These should be static with no changes. + ctx = log.AddPersistentTagsToLogger(ctx, + log.Module, log.Clob, + log.ProposerConsAddress, sdk.ConsAddress(ctx.BlockHeader().ProposerAddress), + log.Callback, lib.TxMode(ctx), + log.BlockHeight, ctx.BlockHeight(), + log.Handler, log.CancelOrder, + log.Msg, msg, + ) + defer func() { metrics.IncrSuccessOrErrorCounter( err, @@ -56,17 +66,11 @@ func (k msgServer) CancelOrder( "Error: %s", err.Error(), ) - k.Keeper.Logger(ctx).Info( - err.Error(), - metrics.BlockHeight, ctx.BlockHeight(), - metrics.Handler, "CancelOrder", - metrics.Callback, metrics.DeliverTx, - metrics.Msg, msg, - ) + log.InfoLog(ctx, "Cancel Order Expected Error", log.Error, err) return } } - errorlib.LogDeliverTxError(k.Keeper.Logger(ctx), err, ctx.BlockHeight(), "CancelOrder", msg) + log.ErrorLogWithError(ctx, "Error cancelling order", err) } }() diff --git a/protocol/x/clob/keeper/msg_server_cancel_orders_test.go b/protocol/x/clob/keeper/msg_server_cancel_orders_test.go index dbfa6e7f77..e74daa2d0c 100644 --- a/protocol/x/clob/keeper/msg_server_cancel_orders_test.go +++ b/protocol/x/clob/keeper/msg_server_cancel_orders_test.go @@ -5,8 +5,6 @@ import ( "testing" "time" - errorsmod "cosmossdk.io/errors" - indexerevents "github.com/dydxprotocol/v4-chain/protocol/indexer/events" "github.com/dydxprotocol/v4-chain/protocol/indexer/indexer_manager" indexershared "github.com/dydxprotocol/v4-chain/protocol/indexer/shared" @@ -68,20 +66,15 @@ func TestCancelOrder_InfoLogIfOrderNotFound(t *testing.T) { ctx := ks.Ctx.WithBlockHeight(2) ctx = ctx.WithIsCheckTx(false).WithIsReCheckTx(false) mockLogger := &mocks.Logger{} - mockLogger.On("With", mock.Anything, mock.Anything, mock.Anything, mock.Anything, - mock.Anything, mock.Anything, mock.Anything, mock.Anything).Return(mockLogger) - mockLogger.On("Info", - errorsmod.Wrapf( - types.ErrStatefulOrderCancellationFailedForAlreadyRemovedOrder, - "Error: %s", - errorsmod.Wrapf( - types.ErrStatefulOrderDoesNotExist, - "Order Id to cancel does not exist. OrderId : %+v", - orderToCancel.OrderId, - ).Error(), - ).Error(), + mockLogger.On("With", + mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything, + ).Return(mockLogger) + mockLogger.On("Info", + mock.Anything, + mock.Anything, + mock.AnythingOfType("*errors.wrappedError"), ).Return() ctx = ctx.WithLogger(mockLogger) ctx = ctx.WithBlockTime(time.Unix(int64(2), 0)) @@ -114,11 +107,13 @@ func TestCancelOrder_ErrorLogIfGTBTTooLow(t *testing.T) { ctx := ks.Ctx.WithBlockHeight(2) ctx = ctx.WithIsCheckTx(false).WithIsReCheckTx(false) mockLogger := &mocks.Logger{} - mockLogger.On("With", mock.Anything, mock.Anything, mock.Anything, mock.Anything, + mockLogger.On("With", + mock.Anything, mock.Anything, mock.Anything, mock.Anything, + mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything).Return(mockLogger) mockLogger.On( "Error", - types.ErrTimeExceedsGoodTilBlockTime.Error(), + "Error cancelling order", mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything, ).Return() diff --git a/protocol/x/clob/keeper/msg_server_place_order.go b/protocol/x/clob/keeper/msg_server_place_order.go index 5384cf304c..f56305ba2e 100644 --- a/protocol/x/clob/keeper/msg_server_place_order.go +++ b/protocol/x/clob/keeper/msg_server_place_order.go @@ -11,7 +11,7 @@ import ( indexerevents "github.com/dydxprotocol/v4-chain/protocol/indexer/events" "github.com/dydxprotocol/v4-chain/protocol/indexer/indexer_manager" "github.com/dydxprotocol/v4-chain/protocol/lib" - errorlib "github.com/dydxprotocol/v4-chain/protocol/lib/error" + "github.com/dydxprotocol/v4-chain/protocol/lib/log" "github.com/dydxprotocol/v4-chain/protocol/lib/metrics" "github.com/dydxprotocol/v4-chain/protocol/x/clob/types" ) @@ -25,6 +25,16 @@ func (k msgServer) PlaceOrder(goCtx context.Context, msg *types.MsgPlaceOrder) ( ) { ctx := sdk.UnwrapSDKContext(goCtx) + // Attach various logging tags relative to this request. These should be static with no changes. + ctx = log.AddPersistentTagsToLogger(ctx, + log.Module, log.Clob, + log.ProposerConsAddress, sdk.ConsAddress(ctx.BlockHeader().ProposerAddress), + log.Callback, lib.TxMode(ctx), + log.BlockHeight, ctx.BlockHeight(), + log.Handler, log.PlaceOrder, + log.Msg, msg, + ) + defer func() { metrics.IncrSuccessOrErrorCounter( err, @@ -44,16 +54,10 @@ func (k msgServer) PlaceOrder(goCtx context.Context, msg *types.MsgPlaceOrder) ( 1, msg.Order.GetOrderLabels(), ) - k.Keeper.Logger(ctx).Info( - err.Error(), - metrics.BlockHeight, ctx.BlockHeight(), - metrics.Handler, "PlaceOrder", - metrics.Callback, metrics.DeliverTx, - metrics.Msg, msg, - ) + log.InfoLog(ctx, "Place Order Expected Error", log.Error, err) return } - errorlib.LogDeliverTxError(k.Keeper.Logger(ctx), err, ctx.BlockHeight(), "PlaceOrder", msg) + log.ErrorLogWithError(ctx, "Error placing order", err) } }() diff --git a/protocol/x/clob/keeper/msg_server_place_order_test.go b/protocol/x/clob/keeper/msg_server_place_order_test.go index 3543f7e3c5..39ce10a079 100644 --- a/protocol/x/clob/keeper/msg_server_place_order_test.go +++ b/protocol/x/clob/keeper/msg_server_place_order_test.go @@ -6,7 +6,6 @@ import ( "testing" "time" - errorsmod "cosmossdk.io/errors" indexerevents "github.com/dydxprotocol/v4-chain/protocol/indexer/events" "github.com/dydxprotocol/v4-chain/protocol/indexer/indexer_manager" "github.com/dydxprotocol/v4-chain/protocol/lib" @@ -88,24 +87,21 @@ func TestPlaceOrder_Error(t *testing.T) { msgServer := keeper.NewMsgServerImpl(ks.ClobKeeper) mockLogger := &mocks.Logger{} - mockLogger.On("With", mock.Anything, mock.Anything, mock.Anything, mock.Anything, - mock.Anything, mock.Anything, mock.Anything, mock.Anything).Return(mockLogger) + mockLogger.On("With", + mock.Anything, mock.Anything, mock.Anything, mock.Anything, + mock.Anything, mock.Anything, mock.Anything, mock.Anything, + mock.Anything, mock.Anything, mock.Anything, mock.Anything, + ).Return(mockLogger) if errors.Is(tc.ExpectedError, types.ErrStatefulOrderCollateralizationCheckFailed) { mockLogger.On("Info", - errorsmod.Wrapf( - types.ErrStatefulOrderCollateralizationCheckFailed, - "PlaceStatefulOrder: order (%+v), result (%s)", - tc.StatefulOrderPlacement, - satypes.NewlyUndercollateralized.String(), - ).Error(), - mock.Anything, mock.Anything, mock.Anything, mock.Anything, - mock.Anything, mock.Anything, mock.Anything, mock.Anything, + mock.Anything, + mock.Anything, + mock.AnythingOfType("*errors.wrappedError"), ).Return() } else { mockLogger.On("Error", + "Error placing order", mock.Anything, - mock.Anything, mock.Anything, mock.Anything, mock.Anything, - mock.Anything, mock.Anything, mock.Anything, mock.Anything, ).Return() } ks.Ctx = ks.Ctx.WithLogger(mockLogger) diff --git a/protocol/x/clob/keeper/msg_server_proposed_operations.go b/protocol/x/clob/keeper/msg_server_proposed_operations.go index fc077039fa..6770ddd9e9 100644 --- a/protocol/x/clob/keeper/msg_server_proposed_operations.go +++ b/protocol/x/clob/keeper/msg_server_proposed_operations.go @@ -4,7 +4,8 @@ import ( "context" sdk "github.com/cosmos/cosmos-sdk/types" - errorlib "github.com/dydxprotocol/v4-chain/protocol/lib/error" + "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/types" ) @@ -15,10 +16,21 @@ func (k msgServer) ProposedOperations( ) (resp *types.MsgProposedOperationsResponse, err error) { ctx := sdk.UnwrapSDKContext(goCtx) + // Attach various logging tags relative to this request. These should be static with no changes. + ctx = log.AddPersistentTagsToLogger(ctx, + log.Module, log.Clob, + log.ProposerConsAddress, sdk.ConsAddress(ctx.BlockHeader().ProposerAddress), + log.Callback, lib.TxMode(ctx), + log.BlockHeight, ctx.BlockHeight(), + log.Handler, log.ProposedOperations, + // Consider not appending this because it's massive + // metrics.Msg, msg, + ) + defer func() { metrics.IncrSuccessOrErrorCounter(err, types.ModuleName, metrics.ProposedOperations, metrics.DeliverTx) if err != nil { - errorlib.LogDeliverTxError(k.Keeper.Logger(ctx), err, ctx.BlockHeight(), "ProposedOperations", msg) + log.ErrorLogWithError(ctx, "Error in Proposed Operations", err) } }() diff --git a/protocol/x/clob/keeper/msg_server_proposed_operations_test.go b/protocol/x/clob/keeper/msg_server_proposed_operations_test.go index fb89737306..000b317f9e 100644 --- a/protocol/x/clob/keeper/msg_server_proposed_operations_test.go +++ b/protocol/x/clob/keeper/msg_server_proposed_operations_test.go @@ -38,7 +38,6 @@ func TestProposedOperations(t *testing.T) { mock.Anything, mock.Anything, mock.Anything, mock.Anything, }..., ).Return() - mck.On("Logger", ctx).Return(mockLogger) }, expectedErr: testError, }, diff --git a/protocol/x/clob/keeper/order_state.go b/protocol/x/clob/keeper/order_state.go index daabbcfb0d..814684e141 100644 --- a/protocol/x/clob/keeper/order_state.go +++ b/protocol/x/clob/keeper/order_state.go @@ -1,11 +1,10 @@ package keeper import ( - "fmt" - "cosmossdk.io/store/prefix" sdk "github.com/cosmos/cosmos-sdk/types" "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" @@ -215,11 +214,11 @@ func (k Keeper) PruneOrdersForBlockHeight(ctx sdk.Context, blockHeight uint32) ( prunedOrderIds = append(prunedOrderIds, orderId) if prunableBlockHeight < blockHeight { - k.Logger(ctx).Error(fmt.Sprintf( - "prunableBlockHeight %v is less than blockHeight %v in PruneOrdersForBlockHeight, this should never happen.", + log.ErrorLog(ctx, + "prunableBlockHeight is less than blockHeight in PruneOrdersForBlockHeight, this should never happen.", + log.PrunableBlockHeight, prunableBlockHeight, - blockHeight, - )) + ) } } } diff --git a/protocol/x/clob/keeper/orders.go b/protocol/x/clob/keeper/orders.go index 6ecf9e0fd5..9b6cd2c687 100644 --- a/protocol/x/clob/keeper/orders.go +++ b/protocol/x/clob/keeper/orders.go @@ -16,6 +16,7 @@ import ( "github.com/dydxprotocol/v4-chain/protocol/indexer/off_chain_updates" 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/types" satypes "github.com/dydxprotocol/v4-chain/protocol/x/subaccounts/types" @@ -438,12 +439,10 @@ func (k Keeper) PlaceStatefulOrdersFromLastBlock( // Error log if this is a conditional orders and it doesn't exist in triggered state, since it // can't have been canceled. if orderId.IsConditionalOrder() { - k.Logger(ctx).Error( - fmt.Sprintf( - "PlaceStatefulOrdersFromLastBlock: Triggered conditional Order ID %+v doesn't exist in state", - orderId, - ), - ) + log.ErrorLog(ctx, fmt.Sprintf( + "PlaceStatefulOrdersFromLastBlock: Triggered conditional Order ID %+v doesn't exist in state", + orderId, + )) } // Order does not exist in state and therefore should not be placed. This likely @@ -460,7 +459,7 @@ func (k Keeper) PlaceStatefulOrdersFromLastBlock( ) if err != nil { - k.Logger(ctx).Debug( + log.DebugLog(ctx, fmt.Sprintf( "MustPlaceStatefulOrdersFromLastBlock: PlaceOrder() returned an error %+v for order %+v", err, @@ -566,7 +565,8 @@ func (k Keeper) PerformOrderCancellationStatefulValidation( prevBlockHeight := previousBlockInfo.Height currBlockHeight := uint32(ctx.BlockHeight()) if lib.IsDeliverTxMode(ctx) && prevBlockHeight != currBlockHeight-1 { - k.Logger(ctx).Error( + log.ErrorLog( + ctx, "PerformOrderCancellationStatefulValidation: prev block height is not one below"+ "current block height in DeliverTx", "previousBlockHeight", prevBlockHeight, @@ -577,7 +577,8 @@ func (k Keeper) PerformOrderCancellationStatefulValidation( // CheckTx or ReCheckTx if !lib.IsDeliverTxMode(ctx) && currBlockHeight > 1 && prevBlockHeight != currBlockHeight { - k.Logger(ctx).Error( + log.ErrorLog( + ctx, "PerformOrderCancellationStatefulValidation: prev block height is not equal to current block height"+ metrics.Callback, metrics.GetCallbackMetricFromCtx(ctx), "previousBlockHeight", prevBlockHeight, @@ -992,7 +993,8 @@ func (k Keeper) AddOrderToOrderbookCollatCheck( ) if satypes.ErrIntegerOverflow.Is(err) { // TODO(DEC-1701): Determine best action to take if the oracle price overflows max uint64 - k.Logger(ctx).Error( + log.ErrorLog( + ctx, fmt.Sprintf( "Integer overflow: oracle price (subticks) exceeded uint64 max. "+ "perpetual ID = (%d), oracle price = (%+v), is buy = (%t)", @@ -1183,9 +1185,9 @@ func (k Keeper) InitStatefulOrders( if err != nil { // TODO(DEC-847): Revisit this error log once `MsgRemoveOrder` is implemented, // since it should potentially be a panic. - k.Logger(ctx).Error( + log.ErrorLogWithError( + ctx, "InitStatefulOrders: PlaceOrder() returned an error", - "error", err, ) } diff --git a/protocol/x/clob/keeper/process_operations.go b/protocol/x/clob/keeper/process_operations.go index edab7c0e40..6f4ed519d5 100644 --- a/protocol/x/clob/keeper/process_operations.go +++ b/protocol/x/clob/keeper/process_operations.go @@ -13,6 +13,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/types" satypes "github.com/dydxprotocol/v4-chain/protocol/x/subaccounts/types" @@ -37,13 +38,8 @@ func (k Keeper) ProcessProposerOperations( return errorsmod.Wrapf(types.ErrInvalidMsgProposedOperations, "Error: %+v", err) } - k.Logger(ctx).Debug( - "Processing operations queue", - "operationsQueue", - types.GetInternalOperationsQueueTextString(operations), - "block", - ctx.BlockHeight(), - ) + log.DebugLog(ctx, "Processing operations queue", + log.OperationsQueue, types.GetInternalOperationsQueueTextString(operations)) // Write results of the operations queue to state. Performs stateful validation as well. if err := k.ProcessInternalOperations(ctx, operations); err != nil { diff --git a/protocol/x/clob/keeper/process_single_match.go b/protocol/x/clob/keeper/process_single_match.go index 6139cfaaff..e1e12b7948 100644 --- a/protocol/x/clob/keeper/process_single_match.go +++ b/protocol/x/clob/keeper/process_single_match.go @@ -11,6 +11,7 @@ import ( sdk "github.com/cosmos/cosmos-sdk/types" "github.com/dydxprotocol/v4-chain/protocol/indexer/off_chain_updates" "github.com/dydxprotocol/v4-chain/protocol/lib" + "github.com/dydxprotocol/v4-chain/protocol/lib/log" "github.com/dydxprotocol/v4-chain/protocol/lib/metrics" assettypes "github.com/dydxprotocol/v4-chain/protocol/x/assets/types" "github.com/dydxprotocol/v4-chain/protocol/x/clob/types" @@ -56,7 +57,7 @@ func (k Keeper) ProcessSingleMatch( ctx, satypes.Update{SubaccountId: *takerSubaccount.Id}, ) - k.Logger(ctx).Error( + log.ErrorLog(ctx, "collateralization check failed for liquidation", "takerSubaccount", fmt.Sprintf("%+v", takerSubaccount), "takerTNC", takerTnc, @@ -115,7 +116,8 @@ func (k Keeper) ProcessSingleMatch( // it's possible to have zero `quoteQuantums` for a non-zero amount of `baseQuantums`. // This could mean that it's possible that a maker sell order on the book // at a very unfavorable price (subticks) could receive `0` `quoteQuantums` amount. - k.Logger(ctx).Error( + log.ErrorLog( + ctx, "Match resulted in zero quote quantums", "MakerOrder", fmt.Sprintf("%+v", matchWithOrders.MakerOrder), @@ -513,7 +515,8 @@ func (k Keeper) setOrderFillAmountsAndPruning( // the same `OrderId` with a lower `GoodTilBlock` first if the proposer is using this unmodified application, // but it's still not necessarily guaranteed due to MEV. if curPruneableBlockHeight > order.GetGoodTilBlock()+types.ShortBlockWindow { - k.Logger(ctx).Info( + log.InfoLog( + ctx, "Found an `orderId` in ProcessProposerMatches which had a lower GoodTilBlock than"+ " a previous order in the list of fills. This could mean a lower priority order was allowed on the book.", "orderId", diff --git a/protocol/x/clob/keeper/stateful_order_state.go b/protocol/x/clob/keeper/stateful_order_state.go index 626e069bc8..996710a169 100644 --- a/protocol/x/clob/keeper/stateful_order_state.go +++ b/protocol/x/clob/keeper/stateful_order_state.go @@ -1,22 +1,23 @@ package keeper import ( - storetypes "cosmossdk.io/store/types" "fmt" - cmtlog "github.com/cometbft/cometbft/libs/log" - dbm "github.com/cosmos/cosmos-db" "sort" "time" + storetypes "cosmossdk.io/store/types" + dbm "github.com/cosmos/cosmos-db" + "cosmossdk.io/store/prefix" + cometbftlog "github.com/cometbft/cometbft/libs/log" "github.com/cosmos/cosmos-sdk/telemetry" sdk "github.com/cosmos/cosmos-sdk/types" gogotypes "github.com/cosmos/gogoproto/types" "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/types" satypes "github.com/dydxprotocol/v4-chain/protocol/x/subaccounts/types" - gometrics "github.com/hashicorp/go-metrics" ) // TODO(CLOB-739) Rename all functions in this file to StatefulOrder instead of LongTermOrder @@ -74,7 +75,7 @@ func (k Keeper) SetLongTermOrderPlacement( telemetry.IncrCounterWithLabels( []string{types.ModuleName, metrics.StatefulOrder, metrics.Count}, 1, - []gometrics.Label{ + []metrics.Label{ metrics.GetLabelForIntValue(metrics.ClobPairId, int(order.GetClobPairId())), metrics.GetLabelForBoolValue(metrics.Conditional, order.OrderId.IsConditionalOrder()), }, @@ -155,9 +156,8 @@ func (k Keeper) DeleteLongTermOrderPlacement( orderKey := orderId.ToStateKey() if memStore.Has(orderKey) { if count == 0 { - k.Logger(ctx).Error( - "Stateful order count is zero but order is in the memstore. Underflow", - "orderId", cmtlog.NewLazySprintf("%+v", orderId), + log.ErrorLog(ctx, "Stateful order count is zero but order is in the memstore. Underflow", + "orderId", cometbftlog.NewLazySprintf("%+v", orderId), ) } else { count-- @@ -176,7 +176,7 @@ func (k Keeper) DeleteLongTermOrderPlacement( telemetry.IncrCounterWithLabels( []string{types.ModuleName, metrics.StatefulOrderRemoved, metrics.Count}, 1, - []gometrics.Label{ + []metrics.Label{ metrics.GetLabelForIntValue(metrics.ClobPairId, int(orderId.GetClobPairId())), metrics.GetLabelForBoolValue(metrics.Conditional, orderId.IsConditionalOrder()), },