Cherrypick logging updates to release branch (#649)

* Conditionally info log in PlaceOrder DeliverTx if collat check fails (#635) * conditionally info log in PlaceOrder DeliverTx if collat check fails * update logging and telemetry for conditional info logs in DeliverTx * lint * add proposer_cons_address to clob DeliverTx Logger (#644) * add proposer_cons_address to clob DeliverTx Logger * fix naming * add callback and always add addr * update tests that use the logger
dydxprotocol · Oct 17, 2023 · 8536149 · 8536149
1 parent a814748
commit 8536149
Show file tree

Hide file tree

Showing 7 changed files with 74 additions and 10 deletions.
diff --git a/protocol/lib/metrics/constants.go b/protocol/lib/metrics/constants.go
@@ -104,6 +104,7 @@ const (
 	LiquidateSubaccounts_PlaceLiquidations       = "liquidate_subaccounts_against_orderbook_place_liquidations"
 	LiquidateSubaccounts_Deleverage              = "liquidate_subaccounts_against_orderbook_deleverage"
 	CollateralizationCheck                       = "place_order_collateralization_check"
+	CollateralizationCheckFailed                 = "collateralization_check_failed"
 	CollateralizationCheckSubaccounts            = "collateralization_check_subaccounts"
 	Conditional                                  = "conditional"
 	ConditionalOrderTriggered                    = "conditional_order_triggered"
@@ -152,6 +153,7 @@ const (
 	ProcessOperations                            = "process_operations"
 	ProposedOperations                           = "proposed_operations"
 	Proposer                                     = "proposer"
+	ProposerConsAddress                          = "proposer_cons_addr"
 	QuoteQuantums                                = "quote_quantums"
 	RateLimit                                    = "rate_limit"
 	ReduceOnly                                   = "reduce_only"

diff --git a/protocol/x/clob/keeper/keeper.go b/protocol/x/clob/keeper/keeper.go
@@ -7,6 +7,7 @@ import (
 
 	"github.com/dydxprotocol/v4-chain/protocol/indexer/indexer_manager"
 	"github.com/dydxprotocol/v4-chain/protocol/lib"
+	"github.com/dydxprotocol/v4-chain/protocol/lib/metrics"
 	"github.com/dydxprotocol/v4-chain/protocol/x/clob/rate_limit"
 
 	"github.com/cometbft/cometbft/libs/log"
@@ -129,7 +130,12 @@ func (k Keeper) GetIndexerEventManager() indexer_manager.IndexerEventManager {
 }
 
 func (k Keeper) Logger(ctx sdk.Context) log.Logger {
-	return ctx.Logger().With(sdklog.ModuleKey, "x/clob")
+	return ctx.Logger().With(
+		sdklog.ModuleKey, "x/clob",
+		metrics.ProposerConsAddress, sdk.ConsAddress(ctx.BlockHeader().ProposerAddress),
+		metrics.CheckTx, ctx.IsCheckTx(),
+		metrics.ReCheckTx, ctx.IsReCheckTx(),
+	)
 }
 
 func (k Keeper) InitializeForGenesis(ctx sdk.Context) {

diff --git a/protocol/x/clob/keeper/mev_test.go b/protocol/x/clob/keeper/mev_test.go
@@ -1,10 +1,11 @@
 package keeper_test
 
 import (
-	sdkmath "cosmossdk.io/math"
 	"math/big"
 	"testing"
 
+	sdkmath "cosmossdk.io/math"
+
 	sdk "github.com/cosmos/cosmos-sdk/types"
 	authtypes "github.com/cosmos/cosmos-sdk/x/auth/types"
 	stakingtypes "github.com/cosmos/cosmos-sdk/x/staking/types"
@@ -975,7 +976,8 @@ func TestRecordMevMetrics(t *testing.T) {
 			}
 
 			mockLogger := &mocks.Logger{}
-			mockLogger.On("With", 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).Return(mockLogger)
 			mockLogger.On(
 				"Info",
 				"Measuring MEV for proposed matches",

diff --git a/protocol/x/clob/keeper/msg_server_cancel_orders.go b/protocol/x/clob/keeper/msg_server_cancel_orders.go
@@ -58,6 +58,10 @@ func (k msgServer) CancelOrder(
 					)
 					k.Keeper.Logger(ctx).Info(
 						err.Error(),
+						metrics.BlockHeight, ctx.BlockHeight(),
+						metrics.Handler, "CancelOrder",
+						metrics.Callback, metrics.DeliverTx,
+						metrics.Msg, msg,
 					)
 					return
 				}

diff --git a/protocol/x/clob/keeper/msg_server_cancel_orders_test.go b/protocol/x/clob/keeper/msg_server_cancel_orders_test.go
@@ -68,7 +68,8 @@ 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).Return(mockLogger)
+	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,
@@ -79,6 +80,8 @@ func TestCancelOrder_InfoLogIfOrderNotFound(t *testing.T) {
 				orderToCancel.OrderId,
 			).Error(),
 		).Error(),
+		mock.Anything, mock.Anything, mock.Anything, mock.Anything,
+		mock.Anything, mock.Anything, mock.Anything, mock.Anything,
 	).Return()
 	ctx = ctx.WithLogger(mockLogger)
 	ctx = ctx.WithBlockTime(time.Unix(int64(2), 0))
@@ -111,14 +114,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).Return(mockLogger)
+	mockLogger.On("With", mock.Anything, mock.Anything, mock.Anything, mock.Anything,
+		mock.Anything, mock.Anything, mock.Anything, mock.Anything).Return(mockLogger)
 	mockLogger.On(
 		"Error",
-		[]interface{}{
-			types.ErrTimeExceedsGoodTilBlockTime.Error(),
-			mock.Anything, mock.Anything, mock.Anything, mock.Anything,
-			mock.Anything, mock.Anything, mock.Anything, mock.Anything,
-		}...,
+		types.ErrTimeExceedsGoodTilBlockTime.Error(),
+		mock.Anything, mock.Anything, mock.Anything, mock.Anything,
+		mock.Anything, mock.Anything, mock.Anything, mock.Anything,
 	).Return()
 	ctx = ctx.WithLogger(mockLogger)
 	ctx = ctx.WithBlockTime(time.Unix(int64(2), 0))

diff --git a/protocol/x/clob/keeper/msg_server_place_order.go b/protocol/x/clob/keeper/msg_server_place_order.go
@@ -2,9 +2,11 @@ package keeper
 
 import (
 	"context"
+	"errors"
 
 	errorsmod "cosmossdk.io/errors"
 
+	"github.com/cosmos/cosmos-sdk/telemetry"
 	sdk "github.com/cosmos/cosmos-sdk/types"
 	indexerevents "github.com/dydxprotocol/v4-chain/protocol/indexer/events"
 	"github.com/dydxprotocol/v4-chain/protocol/indexer/indexer_manager"
@@ -32,6 +34,25 @@ func (k msgServer) PlaceOrder(goCtx context.Context, msg *types.MsgPlaceOrder) (
 			msg.Order.GetOrderLabels()...,
 		)
 		if err != nil {
+			if errors.Is(err, types.ErrStatefulOrderCollateralizationCheckFailed) {
+				telemetry.IncrCounterWithLabels(
+					[]string{
+						types.ModuleName,
+						metrics.PlaceOrder,
+						metrics.CollateralizationCheckFailed,
+					},
+					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,
+				)
+				return
+			}
 			errorlib.LogDeliverTxError(k.Keeper.Logger(ctx), err, ctx.BlockHeight(), "PlaceOrder", msg)
 		}
 	}()

diff --git a/protocol/x/clob/keeper/msg_server_place_order_test.go b/protocol/x/clob/keeper/msg_server_place_order_test.go
@@ -2,9 +2,11 @@ package keeper_test
 
 import (
 	"context"
+	"errors"
 	"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"
@@ -85,6 +87,29 @@ func TestPlaceOrder_Error(t *testing.T) {
 			ks := keepertest.NewClobKeepersTestContext(t, memClob, &mocks.BankKeeper{}, indexerEventManager)
 			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)
+			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,
+				).Return()
+			} else {
+				mockLogger.On("Error",
+					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)
+
 			require.NoError(t, keepertest.CreateUsdcAsset(ks.Ctx, ks.AssetsKeeper))
 			// Create test markets.
 			keepertest.CreateTestMarkets(t, ks.Ctx, ks.PricesKeeper)
@@ -170,6 +195,8 @@ func TestPlaceOrder_Error(t *testing.T) {
 			// Run MsgHandler for placement.
 			_, err = msgServer.PlaceOrder(ctx, &types.MsgPlaceOrder{Order: tc.StatefulOrderPlacement})
 			require.ErrorIs(t, err, tc.ExpectedError)
+
+			mockLogger.AssertExpectations(t)
 		})
 	}
 }