chore(logging): Add debug and error logging (#483)

* Add debug and error logging

* Fix null pointer dereference

* Add more debug log statements

* Add error log to requireVpool

* Start localnet in debug mode

Co-authored-by: AgentSmithMatrix <[email protected]>

scripts/localnet.sh

@@ -110,4 +110,4 @@ fi
 
 # Start the network
 echo_info "Starting $CHAIN_ID in $CHAIN_DIR..."
-$BINARY start --home $CHAIN_DIR
+$BINARY start --home $CHAIN_DIR --log_level debug

x/perp/keeper/calc.go

@@ -78,12 +78,13 @@ abs(vSize * fundingRate). Funding payments act to converge the mark price
 (vPrice) and index price (average price on major exchanges).
 
 Returns:
-- freeCollateral: Amount of collateral (margin) that can be removed from the
+- accountExcessEquity: Amount of collateral (margin) that can be removed from the
 position without making it go underwater.
-- error
+- err: error
 */
-func (k Keeper) calcFreeCollateral(ctx sdk.Context, pos types.Position, fundingPayment sdk.Dec,
-) (sdk.Int, error) {
+func (k Keeper) calcFreeCollateral(
+	ctx sdk.Context, pos types.Position, fundingPayment sdk.Dec,
+) (accountExcessEquity sdk.Int, err error) {
 	pair, err := common.NewTokenPairFromStr(pos.Pair)
 	if err != nil {
 		return sdk.Int{}, err
@@ -102,9 +103,8 @@ func (k Keeper) calcFreeCollateral(ctx sdk.Context, pos types.Position, fundingP
 	if err != nil {
 		return sdk.Int{}, err
 	}
-	freeMargin := pos.Margin.Sub(fundingPayment)
-	accountValue := unrealizedPnL.Add(freeMargin)
-	minCollateral := sdk.MinDec(accountValue, freeMargin)
+	remainingMargin := pos.Margin.Sub(fundingPayment)
+	minAccountValue := sdk.MinDec(remainingMargin, remainingMargin.Add(unrealizedPnL))
 
 	// Get margin requirement. This rounds up, so 16.5 margin required -> 17
 	var marginRequirement sdk.Int
@@ -115,8 +115,13 @@ func (k Keeper) calcFreeCollateral(ctx sdk.Context, pos types.Position, fundingP
 		// if short, use current notional
 		marginRequirement = initMarginRatio.Mul(positionNotional).RoundInt()
 	}
-	freeCollateral := minCollateral.Sub(marginRequirement.ToDec()).TruncateInt()
-	return freeCollateral, nil
+	accountExcessEquity = minAccountValue.Sub(marginRequirement.ToDec()).TruncateInt()
+	k.Logger(ctx).Debug(
+		"calc_free_collateral",
+		"amount",
+		accountExcessEquity.String(),
+	)
+	return accountExcessEquity, nil
 }
 
 /* CalcPerpTxFee calculates the total tx fee for exchanging `quoteAmt` of tokens on

x/perp/keeper/clearing_house.go

@@ -236,6 +236,12 @@ func (k Keeper) increasePosition(
 	}
 
 	events.EmitInternalPositionResponseEvent(ctx, positionResp, "increase_position")
+
+	k.Logger(ctx).Debug("increase_position",
+		"positionResp",
+		positionResp.String(),
+	)
+
 	return positionResp, nil
 }
 
@@ -246,6 +252,11 @@ func (k Keeper) getLatestCumulativePremiumFraction(
 ) (sdk.Dec, error) {
 	pairMetadata, err := k.PairMetadata().Get(ctx, pair)
 	if err != nil {
+		k.Logger(ctx).Error(
+			err.Error(),
+			"pair",
+			pair.String(),
+		)
 		return sdk.Dec{}, err
 	}
 	// this should never fail
@@ -269,16 +280,16 @@ Returns:
 */
 func (k Keeper) getPositionNotionalAndUnrealizedPnL(
 	ctx sdk.Context,
-	position types.Position,
+	currentPosition types.Position,
 	pnlCalcOption types.PnLCalcOption,
 ) (positionNotional sdk.Dec, unrealizedPnL sdk.Dec, err error) {
-	positionSizeAbs := position.Size_.Abs()
+	positionSizeAbs := currentPosition.Size_.Abs()
 	if positionSizeAbs.IsZero() {
 		return sdk.ZeroDec(), sdk.ZeroDec(), nil
 	}
 
 	var baseAssetDirection vpooltypes.Direction
-	if position.Size_.IsPositive() {
+	if currentPosition.Size_.IsPositive() {
 		// LONG
 		baseAssetDirection = vpooltypes.Direction_ADD_TO_POOL
 	} else {
@@ -290,48 +301,60 @@ func (k Keeper) getPositionNotionalAndUnrealizedPnL(
 	case types.PnLCalcOption_TWAP:
 		positionNotional, err = k.VpoolKeeper.GetBaseAssetTWAP(
 			ctx,
-			common.TokenPair(position.Pair),
+			common.TokenPair(currentPosition.Pair),
 			baseAssetDirection,
 			positionSizeAbs,
 			/*lookbackInterval=*/ 15*time.Minute,
 		)
 		if err != nil {
+			k.Logger(ctx).Error(err.Error(), "calc_option", pnlCalcOption.String())
 			return sdk.ZeroDec(), sdk.ZeroDec(), err
 		}
 	case types.PnLCalcOption_SPOT_PRICE:
 		positionNotional, err = k.VpoolKeeper.GetBaseAssetPrice(
 			ctx,
-			common.TokenPair(position.Pair),
+			common.TokenPair(currentPosition.Pair),
 			baseAssetDirection,
 			positionSizeAbs,
 		)
 		if err != nil {
+			k.Logger(ctx).Error(err.Error(), "calc_option", pnlCalcOption.String())
 			return sdk.ZeroDec(), sdk.ZeroDec(), err
 		}
 	case types.PnLCalcOption_ORACLE:
 		oraclePrice, err := k.VpoolKeeper.GetUnderlyingPrice(
-			ctx, common.TokenPair(position.Pair))
+			ctx, common.TokenPair(currentPosition.Pair))
 		if err != nil {
+			k.Logger(ctx).Error(err.Error(), "calc_option", pnlCalcOption.String())
 			return sdk.ZeroDec(), sdk.ZeroDec(), err
 		}
 		positionNotional = oraclePrice.Mul(positionSizeAbs)
 	default:
 		panic("unrecognized pnl calc option: " + pnlCalcOption.String())
 	}
 
-	if positionNotional.Equal(position.OpenNotional) {
+	if positionNotional.Equal(currentPosition.OpenNotional) {
 		// if position notional and open notional are the same, then early return
 		return positionNotional, sdk.ZeroDec(), nil
 	}
 
-	if position.Size_.IsPositive() {
+	if currentPosition.Size_.IsPositive() {
 		// LONG
-		unrealizedPnL = positionNotional.Sub(position.OpenNotional)
+		unrealizedPnL = positionNotional.Sub(currentPosition.OpenNotional)
 	} else {
 		// SHORT
-		unrealizedPnL = position.OpenNotional.Sub(positionNotional)
+		unrealizedPnL = currentPosition.OpenNotional.Sub(positionNotional)
 	}
 
+	k.Logger(ctx).Debug("get_position_notional_and_unrealized_pnl",
+		"position",
+		currentPosition.String(),
+		"position_notional",
+		positionNotional.String(),
+		"unrealized_pnl",
+		unrealizedPnL.String(),
+	)
+
 	return positionNotional, unrealizedPnL, nil
 }
 
@@ -490,6 +513,12 @@ func (k Keeper) decreasePosition(
 		BlockNumber:                         ctx.BlockHeight(),
 	}
 	events.EmitInternalPositionResponseEvent(ctx, positionResp, "decrease_position")
+
+	k.Logger(ctx).Debug("decrease_position",
+		"positionResp",
+		positionResp.String(),
+	)
+
 	return positionResp, nil
 }
 
@@ -587,6 +616,12 @@ func (k Keeper) closeAndOpenReversePosition(
 
 	events.EmitInternalPositionResponseEvent(
 		ctx, positionResp, "close_and_open_reverse_position")
+
+	k.Logger(ctx).Debug("close_and_open_reverse_position",
+		"positionResp",
+		positionResp.String(),
+	)
+
 	return positionResp, nil
 }
 
@@ -679,6 +714,12 @@ func (k Keeper) closePositionEntirely(
 
 	events.EmitInternalPositionResponseEvent(
 		ctx, positionResp, "close_position_entirely")
+
+	k.Logger(ctx).Debug("close_position_entirely",
+		"positionResp",
+		positionResp.String(),
+	)
+
 	return positionResp, nil
 }
 
@@ -745,6 +786,13 @@ func (k Keeper) getPreferencePositionNotionalAndUnrealizedPnL(
 		types.PnLCalcOption_SPOT_PRICE,
 	)
 	if err != nil {
+		k.Logger(ctx).Error(
+			err.Error(),
+			"calc_option",
+			types.PnLCalcOption_SPOT_PRICE.String(),
+			"preference_option",
+			pnLPreferenceOption.String(),
+		)
 		return sdk.Dec{}, sdk.Dec{}, err
 	}
 
@@ -754,6 +802,13 @@ func (k Keeper) getPreferencePositionNotionalAndUnrealizedPnL(
 		types.PnLCalcOption_TWAP,
 	)
 	if err != nil {
+		k.Logger(ctx).Error(
+			err.Error(),
+			"calc_option",
+			types.PnLCalcOption_TWAP.String(),
+			"preference_option",
+			pnLPreferenceOption.String(),
+		)
 		return sdk.Dec{}, sdk.Dec{}, err
 	}
 
@@ -807,9 +862,27 @@ func (k Keeper) swapQuoteForBase(
 	baseAmount, err = k.VpoolKeeper.SwapQuoteForBase(
 		ctx, pair, quoteAssetDirection, quoteAssetAmount, baseAssetLimit)
 	if err != nil {
+		k.Logger(ctx).Error(
+			err.Error(),
+			"pair",
+			pair.String(),
+			"side",
+			side.String(),
+			"quoteAssetAmount",
+			quoteAssetAmount.String(),
+			"baseAssetLimit",
+			baseAssetLimit.String(),
+		)
 		return sdk.Dec{}, err
 	}
 
+	k.Logger(ctx).Debug("swap_quote_for_base",
+		"side",
+		side.String(),
+		"baseAmt",
+		baseAmount.Abs(),
+	)
+
 	if side == types.Side_BUY {
 		return baseAmount, nil
 	} else {

x/perp/keeper/clearing_house_test.go

@@ -15,6 +15,7 @@ import (
 	"github.com/golang/mock/gomock"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
+	"github.com/tendermint/tendermint/libs/log"
 	tmproto "github.com/tendermint/tendermint/proto/tendermint/types"
 	tmdb "github.com/tendermint/tm-db"
 
@@ -123,7 +124,7 @@ func getKeeper(t *testing.T) (Keeper, mockedDependencies, sdk.Context) {
 		mockedVpoolKeeper,
 	)
 
-	ctx := sdk.NewContext(commitMultiStore, tmproto.Header{}, false, nil)
+	ctx := sdk.NewContext(commitMultiStore, tmproto.Header{}, false, log.NewNopLogger())
 
 	return k, mockedDependencies{
 		mockAccountKeeper:   mockedAccountKeeper,