[CORE-322] Escalate log level for missing smoothed prices, index pric…

…es, ~10s after protocol start (#198)

protocol/app/process/full_node_process_proposal_test.go

@@ -74,9 +74,9 @@ func TestFullNodeProcessProposalHandler(t *testing.T) {
 			_, bridgeKeeper, _, _, _, _, _ := keepertest.BridgeKeepers(t)
 
 			ctx, pricesKeeper, _, indexPriceCache, _, mockTimeProvider := keepertest.PricesKeepers(t)
+			mockTimeProvider.On("Now").Return(constants.TimeT)
 			keepertest.CreateTestMarkets(t, ctx, pricesKeeper)
 			indexPriceCache.UpdatePrices(constants.AtTimeTSingleExchangePriceUpdate)
-			mockTimeProvider.On("Now").Return(constants.TimeT)
 
 			mockClobKeeper := &mocks.ProcessClobKeeper{}
 			mockClobKeeper.On("RecordMevMetricsIsEnabled").Return(true)

protocol/app/process/market_prices_test.go

@@ -124,9 +124,9 @@ func TestUpdateMarketPricesTx_Validate(t *testing.T) {
 		t.Run(name, func(t *testing.T) {
 			// Setup.
 			ctx, k, _, indexPriceCache, _, mockTimeProvider := keepertest.PricesKeepers(t)
+			mockTimeProvider.On("Now").Return(constants.TimeT)
 			keepertest.CreateTestMarkets(t, ctx, k)
 			indexPriceCache.UpdatePrices(tc.indexPrices)
-			mockTimeProvider.On("Now").Return(constants.TimeT)
 			umpt, err := process.DecodeUpdateMarketPricesTx(ctx, k, constants.TestEncodingCfg.TxConfig.TxDecoder(), tc.txBytes)
 			require.NoError(t, err)
 

protocol/app/process/process_proposal_test.go

@@ -234,9 +234,9 @@ func TestProcessProposalHandler_Error(t *testing.T) {
 		t.Run(name, func(t *testing.T) {
 			// Setup.
 			ctx, pricesKeeper, _, indexPriceCache, marketToSmoothedPrices, mockTimeProvider := keepertest.PricesKeepers(t)
+			mockTimeProvider.On("Now").Return(constants.TimeT)
 			keepertest.CreateTestMarkets(t, ctx, pricesKeeper)
 			indexPriceCache.UpdatePrices(constants.AtTimeTSingleExchangePriceUpdate)
-			mockTimeProvider.On("Now").Return(constants.TimeT)
 
 			mockClobKeeper := &mocks.ProcessClobKeeper{}
 			mockClobKeeper.On("RecordMevMetricsIsEnabled").Return(true)

protocol/app/process/transactions_test.go

@@ -307,9 +307,9 @@ func TestProcessProposalTxs_Validate_Error(t *testing.T) {
 		t.Run(name, func(t *testing.T) {
 			// Setup.
 			ctx, pricesKeeper, _, indexPriceCache, _, mockTimeProvider := keepertest.PricesKeepers(t)
+			mockTimeProvider.On("Now").Return(constants.TimeT)
 			keepertest.CreateTestMarkets(t, ctx, pricesKeeper)
 			indexPriceCache.UpdatePrices(constants.AtTimeTSingleExchangePriceUpdate)
-			mockTimeProvider.On("Now").Return(constants.TimeT)
 
 			mockBridgeKeeper := &mocks.ProcessBridgeKeeper{}
 			mockBridgeKeeper.On("GetAcknowledgedEventInfo", mock.Anything).Return(
@@ -396,9 +396,9 @@ func TestProcessProposalTxs_Validate_Valid(t *testing.T) {
 		t.Run(name, func(t *testing.T) {
 			// Setup.
 			ctx, pricesKeeper, _, indexPriceCache, _, mockTimeProvider := keepertest.PricesKeepers(t)
+			mockTimeProvider.On("Now").Return(constants.TimeT)
 			keepertest.CreateTestMarkets(t, ctx, pricesKeeper)
 			indexPriceCache.UpdatePrices(constants.AtTimeTSingleExchangePriceUpdate)
-			mockTimeProvider.On("Now").Return(constants.TimeT)
 
 			mockBridgeKeeper := &mocks.ProcessBridgeKeeper{}
 			mockBridgeKeeper.On("GetAcknowledgedEventInfo", mock.Anything).Return(

protocol/testutil/keeper/assets.go

@@ -45,6 +45,7 @@ func AssetsKeepers(
 	bankKeeper *bankkeeper.BaseKeeper,
 	storeKey storetypes.StoreKey,
 ) {
+	var mockTimeProvider *mocks.TimeProvider
 	ctx = initKeepers(t, func(
 		db *tmdb.MemDB,
 		registry codectypes.InterfaceRegistry,
@@ -53,14 +54,15 @@ func AssetsKeepers(
 		transientStoreKey storetypes.StoreKey,
 	) []GenesisInitializer {
 		// Define necessary keepers here for unit tests
-		pricesKeeper, _, _, _, _ = createPricesKeeper(stateStore, db, cdc, transientStoreKey)
+		pricesKeeper, _, _, _, mockTimeProvider = createPricesKeeper(stateStore, db, cdc, transientStoreKey)
 		accountKeeper, _ = createAccountKeeper(stateStore, db, cdc, registry)
 		bankKeeper, _ = createBankKeeper(stateStore, db, cdc, accountKeeper)
 		keeper, storeKey = createAssetsKeeper(stateStore, db, cdc, pricesKeeper, transientStoreKey, msgSenderEnabled)
 
 		return []GenesisInitializer{pricesKeeper, keeper}
 	})
-
+	// Mock time provider response for market creation.
+	mockTimeProvider.On("Now").Return(constants.TimeT)
 	return ctx, keeper, pricesKeeper, accountKeeper, bankKeeper, storeKey
 }
 

protocol/testutil/keeper/clob.go

@@ -72,6 +72,7 @@ func NewClobKeepersTestContextWithUninitializedMemStore(
 	bankKeeper bankkeeper.Keeper,
 	indexerEventManager indexer_manager.IndexerEventManager,
 ) (ks ClobKeepersTestContext) {
+	var mockTimeProvider *mocks.TimeProvider
 	ks.Ctx = initKeepers(t, func(
 		db *db.MemDB,
 		registry codectypes.InterfaceRegistry,
@@ -80,7 +81,9 @@ func NewClobKeepersTestContextWithUninitializedMemStore(
 		indexerEventsTransientStoreKey storetypes.StoreKey,
 	) []GenesisInitializer {
 		// Define necessary keepers here for unit tests
-		ks.PricesKeeper, _, _, _, _ = createPricesKeeper(stateStore, db, cdc, indexerEventsTransientStoreKey)
+		ks.PricesKeeper, _, _, _, mockTimeProvider = createPricesKeeper(stateStore, db, cdc, indexerEventsTransientStoreKey)
+		// Mock time provider response for market creation.
+		mockTimeProvider.On("Now").Return(constants.TimeT)
 		epochsKeeper, _ := createEpochsKeeper(stateStore, db, cdc)
 		ks.PerpetualsKeeper, _ = createPerpetualsKeeper(
 			stateStore,

protocol/testutil/keeper/perpetuals.go

@@ -53,6 +53,7 @@ func PerpetualsKeepersWithClobHelpers(
 	epochsKeeper *epochskeeper.Keeper,
 	storeKey storetypes.StoreKey,
 ) {
+	var mockTimeProvider *mocks.TimeProvider
 	ctx = initKeepers(t, func(
 		db *tmdb.MemDB,
 		registry codectypes.InterfaceRegistry,
@@ -61,7 +62,7 @@ func PerpetualsKeepersWithClobHelpers(
 		transientStoreKey storetypes.StoreKey,
 	) []GenesisInitializer {
 		// Define necessary keepers here for unit tests
-		pricesKeeper, _, _, _, _ = createPricesKeeper(stateStore, db, cdc, transientStoreKey)
+		pricesKeeper, _, _, _, mockTimeProvider = createPricesKeeper(stateStore, db, cdc, transientStoreKey)
 		epochsKeeper, _ = createEpochsKeeper(stateStore, db, cdc)
 		keeper, storeKey = createPerpetualsKeeperWithClobHelpers(
 			stateStore,
@@ -76,6 +77,9 @@ func PerpetualsKeepersWithClobHelpers(
 		return []GenesisInitializer{pricesKeeper, keeper}
 	})
 
+	// Mock time provider response for market creation.
+	mockTimeProvider.On("Now").Return(constants.TimeT)
+
 	// Initialize perpetuals module parameters to default genesis values.
 	perpetuals.InitGenesis(ctx, *keeper, constants.Perpetuals_GenesisState_ParamsOnly)
 

protocol/testutil/keeper/sending.go

@@ -1,6 +1,7 @@
 package keeper
 
 import (
+	"github.com/dydxprotocol/v4-chain/protocol/testutil/constants"
 	"testing"
 
 	"github.com/dydxprotocol/v4-chain/protocol/indexer/indexer_manager"
@@ -42,6 +43,7 @@ func SendingKeepersWithSubaccountsKeeper(t testing.TB, saKeeper types.Subaccount
 	subaccountsKeeper types.SubaccountsKeeper,
 	storeKey storetypes.StoreKey,
 ) {
+	var mockTimeProvider *mocks.TimeProvider
 	ctx = initKeepers(t, func(
 		db *tmdb.MemDB,
 		registry codectypes.InterfaceRegistry,
@@ -51,7 +53,7 @@ func SendingKeepersWithSubaccountsKeeper(t testing.TB, saKeeper types.Subaccount
 	) []GenesisInitializer {
 		// Define necessary keepers here for unit tests
 		epochsKeeper, _ := createEpochsKeeper(stateStore, db, cdc)
-		pricesKeeper, _, _, _, _ = createPricesKeeper(stateStore, db, cdc, transientStoreKey)
+		pricesKeeper, _, _, _, mockTimeProvider = createPricesKeeper(stateStore, db, cdc, transientStoreKey)
 		perpetualsKeeper, _ = createPerpetualsKeeper(
 			stateStore,
 			db,
@@ -96,6 +98,9 @@ func SendingKeepersWithSubaccountsKeeper(t testing.TB, saKeeper types.Subaccount
 		return []GenesisInitializer{pricesKeeper, perpetualsKeeper, assetsKeeper, sendingKeeper}
 	})
 
+	// Mock time provider response for market creation.
+	mockTimeProvider.On("Now").Return(constants.TimeT)
+
 	return ctx,
 		sendingKeeper,
 		accountKeeper,

protocol/testutil/keeper/subaccounts.go

@@ -1,6 +1,7 @@
 package keeper
 
 import (
+	"github.com/dydxprotocol/v4-chain/protocol/testutil/constants"
 	"math/big"
 	"testing"
 
@@ -38,6 +39,7 @@ func SubaccountsKeepers(
 	assetsKeeper *asskeeper.Keeper,
 	storeKey storetypes.StoreKey,
 ) {
+	var mockTimeProvider *mocks.TimeProvider
 	ctx = initKeepers(t, func(
 		db *tmdb.MemDB,
 		registry codectypes.InterfaceRegistry,
@@ -46,7 +48,7 @@ func SubaccountsKeepers(
 		transientStoreKey storetypes.StoreKey,
 	) []GenesisInitializer {
 		// Define necessary keepers here for unit tests
-		pricesKeeper, _, _, _, _ = createPricesKeeper(stateStore, db, cdc, transientStoreKey)
+		pricesKeeper, _, _, _, mockTimeProvider = createPricesKeeper(stateStore, db, cdc, transientStoreKey)
 		epochsKeeper, _ := createEpochsKeeper(stateStore, db, cdc)
 		perpetualsKeeper, _ = createPerpetualsKeeper(stateStore, db, cdc, pricesKeeper, epochsKeeper, transientStoreKey)
 		assetsKeeper, _ = createAssetsKeeper(stateStore, db, cdc, pricesKeeper, transientStoreKey, msgSenderEnabled)
@@ -68,6 +70,9 @@ func SubaccountsKeepers(
 		return []GenesisInitializer{pricesKeeper, perpetualsKeeper, assetsKeeper, keeper}
 	})
 
+	// Mock time provider response for market creation.
+	mockTimeProvider.On("Now").Return(constants.TimeT)
+
 	return ctx, keeper, pricesKeeper, perpetualsKeeper, accountKeeper, bankKeeper, assetsKeeper, storeKey
 }
 

protocol/x/prices/genesis_test.go

@@ -12,7 +12,8 @@ import (
 func TestGenesis(t *testing.T) {
 	genesisState := constants.Prices_DefaultGenesisState
 
-	ctx, k, _, _, _, _ := keepertest.PricesKeepers(t)
+	ctx, k, _, _, _, mockTimeProvider := keepertest.PricesKeepers(t)
+	mockTimeProvider.On("Now").Return(constants.TimeT)
 	prices.InitGenesis(ctx, *k, genesisState)
 	got := prices.ExportGenesis(ctx, *k)
 	require.NotNil(t, got)
@@ -21,7 +22,8 @@ func TestGenesis(t *testing.T) {
 }
 
 func TestInitGenesisEmitsMarketUpdates(t *testing.T) {
-	ctx, k, _, _, _, _ := keepertest.PricesKeepers(t)
+	ctx, k, _, _, _, mockTimeProvider := keepertest.PricesKeepers(t)
+	mockTimeProvider.On("Now").Return(constants.TimeT)
 
 	prices.InitGenesis(ctx, *k, constants.Prices_DefaultGenesisState)
 

protocol/x/prices/keeper/grpc_query_market_test.go

@@ -1,6 +1,7 @@
 package keeper_test
 
 import (
+	"github.com/dydxprotocol/v4-chain/protocol/testutil/constants"
 	"testing"
 
 	sdk "github.com/cosmos/cosmos-sdk/types"
@@ -15,7 +16,8 @@ import (
 )
 
 func TestMarketPriceQuerySingle(t *testing.T) {
-	ctx, keeper, _, _, _, _ := keepertest.PricesKeepers(t)
+	ctx, keeper, _, _, _, mockTimeProvider := keepertest.PricesKeepers(t)
+	mockTimeProvider.On("Now").Return(constants.TimeT)
 	wctx := sdk.WrapSDKContext(ctx)
 	msgs := keepertest.CreateNMarkets(t, ctx, keeper, 2)
 	for _, tc := range []struct {
@@ -66,7 +68,8 @@ func TestMarketPriceQuerySingle(t *testing.T) {
 }
 
 func TestMarketPriceQueryPaginated(t *testing.T) {
-	ctx, keeper, _, _, _, _ := keepertest.PricesKeepers(t)
+	ctx, keeper, _, _, _, mockTimeProvider := keepertest.PricesKeepers(t)
+	mockTimeProvider.On("Now").Return(constants.TimeT)
 	wctx := sdk.WrapSDKContext(ctx)
 	msgs := keepertest.CreateNMarkets(t, ctx, keeper, 5)
 	prices := make([]types.MarketPrice, len(msgs))
@@ -126,7 +129,8 @@ func TestMarketPriceQueryPaginated(t *testing.T) {
 }
 
 func TestMarketParamQuerySingle(t *testing.T) {
-	ctx, keeper, _, _, _, _ := keepertest.PricesKeepers(t)
+	ctx, keeper, _, _, _, mockTimeProvider := keepertest.PricesKeepers(t)
+	mockTimeProvider.On("Now").Return(constants.TimeT)
 	wctx := sdk.WrapSDKContext(ctx)
 	msgs := keepertest.CreateNMarkets(t, ctx, keeper, 2)
 	for _, tc := range []struct {
@@ -177,7 +181,8 @@ func TestMarketParamQuerySingle(t *testing.T) {
 }
 
 func TestMarketParamQueryPaginated(t *testing.T) {
-	ctx, keeper, _, _, _, _ := keepertest.PricesKeepers(t)
+	ctx, keeper, _, _, _, mockTimeProvider := keepertest.PricesKeepers(t)
+	mockTimeProvider.On("Now").Return(constants.TimeT)
 	wctx := sdk.WrapSDKContext(ctx)
 	msgs := keepertest.CreateNMarkets(t, ctx, keeper, 5)
 	params := make([]types.MarketParam, len(msgs))

protocol/x/prices/keeper/keeper.go

@@ -2,6 +2,7 @@ package keeper
 
 import (
 	"fmt"
+	"time"
 
 	sdklog "cosmossdk.io/log"
 
@@ -23,6 +24,7 @@ type (
 		marketToSmoothedPrices types.MarketToSmoothedPrices
 		timeProvider           lib.TimeProvider
 		indexerEventManager    indexer_manager.IndexerEventManager
+		marketToCreatedAt      map[uint32]time.Time
 	}
 )
 
@@ -43,6 +45,7 @@ func NewKeeper(
 		marketToSmoothedPrices: marketToSmoothedPrices,
 		timeProvider:           timeProvider,
 		indexerEventManager:    indexerEventManager,
+		marketToCreatedAt:      map[uint32]time.Time{},
 	}
 }
 

protocol/x/prices/keeper/market.go

@@ -3,9 +3,8 @@ package keeper
 import (
 	errorsmod "cosmossdk.io/errors"
 	"fmt"
-	"github.com/dydxprotocol/v4-chain/protocol/daemons/pricefeed/metrics"
-
 	sdk "github.com/cosmos/cosmos-sdk/types"
+	"github.com/dydxprotocol/v4-chain/protocol/daemons/pricefeed/metrics"
 	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"
@@ -51,11 +50,25 @@ func (k Keeper) CreateMarket(
 		),
 	)
 
+	k.marketToCreatedAt[marketParam.Id] = k.timeProvider.Now()
 	metrics.AddMarketPairForTelemetry(marketParam.Id, marketParam.Pair)
 
 	return marketParam, nil
 }
 
+// IsRecentlyAdded returns true if the market was added recently. Since it takes a few seconds for
+// index prices to populate, we would not consider missing index prices for a recently added market
+// to be an error.
+func (k Keeper) IsRecentlyAdded(marketId uint32) bool {
+	createdAt, ok := k.marketToCreatedAt[marketId]
+
+	if !ok {
+		return false
+	}
+
+	return k.timeProvider.Now().Sub(createdAt) < types.MarketIsRecentDuration
+}
+
 // GetAllMarketParamPrices returns a slice of MarketParam, MarketPrice tuples for all markets.
 func (k Keeper) GetAllMarketParamPrices(ctx sdk.Context) ([]types.MarketParamPrice, error) {
 	marketParams := k.GetAllMarketParams(ctx)

protocol/x/prices/keeper/market_param_test.go

@@ -15,7 +15,8 @@ import (
 )
 
 func TestModifyMarketParam(t *testing.T) {
-	ctx, keeper, _, _, _, _ := keepertest.PricesKeepers(t)
+	ctx, keeper, _, _, _, mockTimeProvider := keepertest.PricesKeepers(t)
+	mockTimeProvider.On("Now").Return(constants.TimeT)
 	ctx = ctx.WithTxBytes(constants.TestTxBytes)
 	items := keepertest.CreateNMarkets(t, ctx, keeper, 10)
 	for i, item := range items {
@@ -111,7 +112,8 @@ func TestModifyMarketParam_Errors(t *testing.T) {
 	}
 	for name, tc := range tests {
 		t.Run(name, func(t *testing.T) {
-			ctx, keeper, _, _, _, _ := keepertest.PricesKeepers(t)
+			ctx, keeper, _, _, _, mockTimeKeeper := keepertest.PricesKeepers(t)
+			mockTimeKeeper.On("Now").Return(constants.TimeT)
 			ctx = ctx.WithTxBytes(constants.TestTxBytes)
 			keepertest.CreateNMarkets(t, ctx, keeper, 1)
 			_, err := keeper.ModifyMarketParam(
@@ -130,7 +132,8 @@ func TestModifyMarketParam_Errors(t *testing.T) {
 }
 
 func TestGetMarketParam(t *testing.T) {
-	ctx, keeper, _, _, _, _ := keepertest.PricesKeepers(t)
+	ctx, keeper, _, _, _, mockTimeProvider := keepertest.PricesKeepers(t)
+	mockTimeProvider.On("Now").Return(constants.TimeT)
 	items := keepertest.CreateNMarkets(t, ctx, keeper, 10)
 	for _, item := range items {
 		rst, err := keeper.GetMarketParam(ctx, item.Param.Id)
@@ -150,7 +153,8 @@ func TestGetMarketParam_NotFound(t *testing.T) {
 }
 
 func TestGetAllMarketParams(t *testing.T) {
-	ctx, keeper, _, _, _, _ := keepertest.PricesKeepers(t)
+	ctx, keeper, _, _, _, mockTimeProvider := keepertest.PricesKeepers(t)
+	mockTimeProvider.On("Now").Return(constants.TimeT)
 	items := keepertest.CreateNMarkets(t, ctx, keeper, 10)
 	params := make([]types.MarketParam, len(items))
 	for i, item := range items {