From 337026d74cf422cfd2cea10a35e152407287b35a Mon Sep 17 00:00:00 2001 From: Walter White <101130700+NibiruHeisenberg@users.noreply.github.com> Date: Wed, 25 May 2022 16:42:51 -0400 Subject: [PATCH] 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 <98403347+AgentSmithMatrix@users.noreply.github.com> --- scripts/localnet.sh | 2 +- x/perp/keeper/calc.go | 23 ++-- x/perp/keeper/clearing_house.go | 93 +++++++++++++-- x/perp/keeper/clearing_house_test.go | 3 +- x/perp/keeper/margin.go | 162 ++++++++++++++++++++------- x/perp/keeper/margin_test.go | 11 +- x/vpool/keeper/util_test.go | 3 +- 7 files changed, 232 insertions(+), 65 deletions(-) diff --git a/scripts/localnet.sh b/scripts/localnet.sh index 225e13527..09799e51b 100755 --- a/scripts/localnet.sh +++ b/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 diff --git a/x/perp/keeper/calc.go b/x/perp/keeper/calc.go index e0441677c..0b99cc008 100644 --- a/x/perp/keeper/calc.go +++ b/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 diff --git a/x/perp/keeper/clearing_house.go b/x/perp/keeper/clearing_house.go index 3a51ca078..8abe13af9 100644 --- a/x/perp/keeper/clearing_house.go +++ b/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,28 +301,31 @@ 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) @@ -319,19 +333,28 @@ func (k Keeper) getPositionNotionalAndUnrealizedPnL( 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 { diff --git a/x/perp/keeper/clearing_house_test.go b/x/perp/keeper/clearing_house_test.go index 804679bde..887583f52 100644 --- a/x/perp/keeper/clearing_house_test.go +++ b/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, diff --git a/x/perp/keeper/margin.go b/x/perp/keeper/margin.go index 38dcfea3d..1b18558f3 100644 --- a/x/perp/keeper/margin.go +++ b/x/perp/keeper/margin.go @@ -18,54 +18,90 @@ func (k Keeper) AddMargin( goCtx context.Context, msg *types.MsgAddMargin, ) (res *types.MsgAddMarginResponse, err error) { // ------------- Message Setup ------------- - ctx := sdk.UnwrapSDKContext(goCtx) + // validate trader + if err = sdk.VerifyAddressFormat(msg.Sender); err != nil { + return nil, err + } + // validate margin amount addedMargin := msg.Margin.Amount if !addedMargin.IsPositive() { - return res, fmt.Errorf("margin must be positive, not: %v", addedMargin.String()) + err = fmt.Errorf("margin must be positive, not: %v", addedMargin.String()) + k.Logger(ctx).Debug( + err.Error(), + "margin_amount", + msg.Margin.Amount.String(), + ) + return nil, err } - // validate pair + // validate token pair pair, err := common.NewTokenPairFromStr(msg.TokenPair) if err != nil { - return res, err + k.Logger(ctx).Debug( + err.Error(), + "token_pair", + msg.TokenPair, + ) + return nil, err } - err = k.requireVpool(ctx, pair) - if err != nil { - return res, err + // validate vpool exists + if err = k.requireVpool(ctx, pair); err != nil { + return nil, err } // validate margin denom if msg.Margin.Denom != pair.GetQuoteTokenDenom() { - return res, fmt.Errorf("invalid margin denom") + err = fmt.Errorf("invalid margin denom") + k.Logger(ctx).Debug( + err.Error(), + "margin_denom", + msg.Margin.Denom, + "quote_token_denom", + pair.GetQuoteTokenDenom(), + ) + return nil, err } // ------------- AddMargin ------------- - position, err := k.Positions().Get(ctx, pair, msg.Sender) if err != nil { - return res, err + k.Logger(ctx).Debug( + err.Error(), + "pair", + pair.String(), + "trader", + msg.Sender.String(), + ) + return nil, err } position.Margin = position.Margin.Add(addedMargin.ToDec()) - coinToSend := sdk.NewCoin(pair.GetQuoteTokenDenom(), addedMargin) - vaultAddr := k.AccountKeeper.GetModuleAddress(types.VaultModuleAccount) if err = k.BankKeeper.SendCoinsFromAccountToModule( ctx, msg.Sender, types.VaultModuleAccount, sdk.NewCoins(coinToSend), ); err != nil { - return res, err + k.Logger(ctx).Debug( + err.Error(), + "trader", + msg.Sender.String(), + "coin", + coinToSend.String(), + ) + return nil, err } + events.EmitTransfer(ctx, /* coin */ coinToSend, - /* from */ vaultAddr, + /* from */ k.AccountKeeper.GetModuleAddress(types.VaultModuleAccount), /* to */ msg.Sender, ) k.Positions().Set(ctx, pair, msg.Sender, position) + // TODO(https://github.com/NibiruChain/nibiru/issues/323): calculate the funding payment fPayment := sdk.ZeroDec() events.EmitMarginChange(ctx, msg.Sender, pair.String(), addedMargin, fPayment) return &types.MsgAddMarginResponse{}, nil @@ -79,55 +115,84 @@ func (k Keeper) RemoveMargin( goCtx context.Context, msg *types.MsgRemoveMargin, ) (res *types.MsgRemoveMarginResponse, err error) { // ------------- Message Setup ------------- - ctx := sdk.UnwrapSDKContext(goCtx) // validate trader - if err = sdk.VerifyAddressFormat(msg.Sender); err != nil { return nil, err } // validate margin amount - margin := msg.Margin.Amount - if margin.LTE(sdk.ZeroInt()) { - return res, fmt.Errorf("margin must be positive, not: %v", margin.String()) + if !msg.Margin.Amount.IsPositive() { + err = fmt.Errorf("margin must be positive, not: %v", msg.Margin.Amount.String()) + k.Logger(ctx).Debug( + err.Error(), + "margin_amount", + msg.Margin.Amount.String(), + ) + return nil, err } - // validate pair + // validate token pair pair, err := common.NewTokenPairFromStr(msg.TokenPair) if err != nil { - return res, err + k.Logger(ctx).Debug( + err.Error(), + "token_pair", + msg.TokenPair, + ) + return nil, err } - err = k.requireVpool(ctx, pair) - if err != nil { - return res, err + + // validate vpool exists + if err = k.requireVpool(ctx, pair); err != nil { + return nil, err } // validate margin denom if msg.Margin.Denom != pair.GetQuoteTokenDenom() { - return res, fmt.Errorf("invalid margin denom") + err = fmt.Errorf("invalid margin denom") + k.Logger(ctx).Debug( + err.Error(), + "margin_denom", + msg.Margin.Denom, + "quote_token_denom", + pair.GetQuoteTokenDenom(), + ) + return nil, err } // ------------- RemoveMargin ------------- - position, err := k.Positions().Get(ctx, pair, msg.Sender) if err != nil { - return res, err + k.Logger(ctx).Debug( + err.Error(), + "pair", + pair.String(), + "trader", + msg.Sender.String(), + ) + return nil, err } - marginDelta := margin.Neg() + marginDelta := msg.Margin.Amount.Neg() remaining, err := k.CalcRemainMarginWithFundingPayment( ctx, *position, marginDelta.ToDec()) if err != nil { - return res, err + return nil, err } - position.Margin = remaining.Margin - position.LastUpdateCumulativePremiumFraction = remaining.LatestCumulativePremiumFraction if !remaining.BadDebt.IsZero() { - return res, fmt.Errorf("failed to remove margin; position has bad debt") + err = fmt.Errorf("failed to remove margin; position has bad debt") + k.Logger(ctx).Debug( + err.Error(), + "remaining_bad_debt", + remaining.BadDebt.String(), + ) + return nil, err } + position.Margin = remaining.Margin + position.LastUpdateCumulativePremiumFraction = remaining.LatestCumulativePremiumFraction freeCollateral, err := k.calcFreeCollateral( ctx, *position, remaining.FundingPayment) if err != nil { @@ -138,21 +203,34 @@ func (k Keeper) RemoveMargin( k.Positions().Set(ctx, pair, msg.Sender, position) - coinToSend := sdk.NewCoin(pair.GetQuoteTokenDenom(), margin) + coinToSend := sdk.NewCoin(pair.GetQuoteTokenDenom(), msg.Margin.Amount) err = k.BankKeeper.SendCoinsFromModuleToAccount( ctx, types.VaultModuleAccount, msg.Sender, sdk.NewCoins(coinToSend)) if err != nil { - return res, err + k.Logger(ctx).Debug( + err.Error(), + "to", + msg.Sender.String(), + "coin", + coinToSend.String(), + ) + return nil, err } - vaultAddr := k.AccountKeeper.GetModuleAddress(types.VaultModuleAccount) events.EmitTransfer(ctx, /* coin */ coinToSend, - /* from */ vaultAddr, + /* from */ k.AccountKeeper.GetModuleAddress(types.VaultModuleAccount), /* to */ msg.Sender, ) - events.EmitMarginChange(ctx, msg.Sender, pair.String(), margin, remaining.FundingPayment) + events.EmitMarginChange( + ctx, + msg.Sender, + pair.String(), + msg.Margin.Amount, + remaining.FundingPayment, + ) + return &types.MsgRemoveMarginResponse{ MarginOut: coinToSend, FundingPayment: remaining.FundingPayment, @@ -216,9 +294,15 @@ func (k Keeper) GetMarginRatio( return marginRatio, nil } -func (k *Keeper) requireVpool(ctx sdk.Context, pair common.TokenPair) error { +func (k Keeper) requireVpool(ctx sdk.Context, pair common.TokenPair) (err error) { if !k.VpoolKeeper.ExistsPool(ctx, pair) { - return fmt.Errorf("%v: %v", types.ErrPairNotFound.Error(), pair.String()) + err = fmt.Errorf("%v: %v", types.ErrPairNotFound.Error(), pair.String()) + k.Logger(ctx).Error( + err.Error(), + "pair", + pair.String(), + ) + return err } return nil } diff --git a/x/perp/keeper/margin_test.go b/x/perp/keeper/margin_test.go index 6eb20740a..f78bba9f9 100644 --- a/x/perp/keeper/margin_test.go +++ b/x/perp/keeper/margin_test.go @@ -290,15 +290,18 @@ func TestRemoveMargin(t *testing.T) { { name: "zero margin remove - fail", test: func() { - removeAmt := sdk.ZeroInt() - nibiruApp, ctx := testutil.NewNibiruApp(true) alice := sample.AccAddress() pair := common.TokenPair("osmo:nusd") goCtx := sdk.WrapSDKContext(ctx) msg := &types.MsgRemoveMargin{ - Sender: alice, TokenPair: pair.String(), - Margin: sdk.Coin{Denom: common.StableDenom, Amount: removeAmt}} + Sender: alice, + TokenPair: pair.String(), + Margin: sdk.Coin{ + Denom: common.StableDenom, + Amount: sdk.ZeroInt(), + }, + } _, err := nibiruApp.PerpKeeper.RemoveMargin(goCtx, msg) require.Error(t, err) require.ErrorContains(t, err, "margin must be positive") diff --git a/x/vpool/keeper/util_test.go b/x/vpool/keeper/util_test.go index d56bedc40..2762960a4 100644 --- a/x/vpool/keeper/util_test.go +++ b/x/vpool/keeper/util_test.go @@ -8,6 +8,7 @@ import ( "github.com/cosmos/cosmos-sdk/store" sdk "github.com/cosmos/cosmos-sdk/types" "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" @@ -31,7 +32,7 @@ func VpoolKeeper(t *testing.T, pricefeedKeeper types.PricefeedKeeper) ( storeKey, pricefeedKeeper, ) - ctx = sdk.NewContext(stateStore, tmproto.Header{}, false, nil) + ctx = sdk.NewContext(stateStore, tmproto.Header{}, false, log.NewNopLogger()) return vpoolKeeper, ctx }