add debug logs

chain.json

@@ -12,5 +12,6 @@
   "testing-api-enabled": true,
   "load-from-snapshot-enabled": true,
   "snapshot-file-path": "/tmp/snapshot",
-  "makerbook-database-path": "/tmp/makerbook"
+  "makerbook-database-path": "/tmp/makerbook",
+  "log-level": "debug"
 }

network-configs/hubblenet/chain_validator_1.json

@@ -12,5 +12,6 @@
   "validator-private-key-file": "/var/avalanche/validator.pk",
   "feeRecipient": "0xa5e31FbE901362Cc93b6fdab99DB9741c673a942",
   "is-validator": true,
-  "snapshot-file-path": "/tmp/snapshot"
+  "snapshot-file-path": "/tmp/snapshot",
+  "log-level": "debug"
 }

plugin/evm/orderbook/matching_pipeline.go

@@ -88,6 +88,12 @@ func (pipeline *MatchingPipeline) Run(blockNumber *big.Int) bool {
 	orderMap := make(map[Market]*Orders)
 	for _, market := range markets {
 		orderMap[market] = pipeline.fetchOrders(market, hState.OraclePrices[market], cancellableOrderIds, blockNumber)
+		for i, order := range orderMap[market].longOrders {
+			log.Debug("long order", "i", i, "order", order)
+		}
+		for i, order := range orderMap[market].shortOrders {
+			log.Debug("short order", "i", i, "order", order)
+		}
 	}
 	pipeline.runLiquidations(liquidablePositions, orderMap, hState.OraclePrices, marginMap)
 	for _, market := range markets {
@@ -279,26 +285,31 @@ func (pipeline *MatchingPipeline) runMatchingEngine(lotp LimitOrderTxProcessor,
 
 func areMatchingOrders(longOrder, shortOrder Order, marginMap map[common.Address]*big.Int, minAllowableMargin, takerFee, upperBound *big.Int) *big.Int {
 	if longOrder.Price.Cmp(shortOrder.Price) == -1 {
+		log.Debug("long order price is less than short order price", "longOrder", longOrder, "shortOrder", shortOrder)
 		return nil
 	}
 	blockDiff := longOrder.BlockNumber.Cmp(shortOrder.BlockNumber)
 	if blockDiff == -1 && (longOrder.OrderType == IOC || shortOrder.isPostOnly()) ||
 		blockDiff == 1 && (shortOrder.OrderType == IOC || longOrder.isPostOnly()) {
+		log.Debug("post only or IOC order matched with a resting order", "longOrder", longOrder, "shortOrder", shortOrder)
 		return nil
 	}
 	fillAmount := utils.BigIntMinAbs(longOrder.GetUnFilledBaseAssetQuantity(), shortOrder.GetUnFilledBaseAssetQuantity())
 	if fillAmount.Sign() == 0 {
+		log.Debug("fillAmount is 0", "longOrder", longOrder, "shortOrder", shortOrder)
 		return nil
 	}
 
 	_isExecutable, longMargin := isExecutable(&longOrder, fillAmount, minAllowableMargin, takerFee, upperBound, marginMap[longOrder.Trader])
 	if !_isExecutable {
+		log.Debug("long order is not executable due to insufficient margin", "longOrder", longOrder, "shortOrder", shortOrder)
 		return nil
 	}
 
 	var shortMargin *big.Int = big.NewInt(0)
 	_isExecutable, shortMargin = isExecutable(&shortOrder, fillAmount, minAllowableMargin, takerFee, upperBound, marginMap[longOrder.Trader])
 	if !_isExecutable {
+		log.Debug("short order is not executable due to insufficient margin", "longOrder", longOrder, "shortOrder", shortOrder)
 		return nil
 	}
 	marginMap[longOrder.Trader].Sub(marginMap[longOrder.Trader], longMargin)
@@ -312,11 +323,19 @@ func isExecutable(order *Order, fillAmount, minAllowableMargin, takerFee, upperB
 	}
 	if order.OrderType == IOC {
 		requiredMargin := getRequiredMargin(order, fillAmount, minAllowableMargin, takerFee, upperBound)
-		return requiredMargin.Cmp(availableMargin) <= 0, requiredMargin
+		isExecutable := requiredMargin.Cmp(availableMargin) <= 0
+		if !isExecutable {
+			log.Debug("signed order is not executable due to insufficient margin", "order", order, "requiredMargin", requiredMargin, "availableMargin", availableMargin)
+		}
+		return isExecutable, requiredMargin
 	}
 	if order.OrderType == Signed {
 		requiredMargin := getRequiredMargin(order, fillAmount, minAllowableMargin, big.NewInt(0) /* signed orders are always maker */, upperBound)
-		return requiredMargin.Cmp(availableMargin) <= 0, requiredMargin
+		isExecutable := requiredMargin.Cmp(availableMargin) <= 0
+		if !isExecutable {
+			log.Debug("signed order is not executable due to insufficient margin", "order", order, "requiredMargin", requiredMargin, "availableMargin", availableMargin)
+		}
+		return isExecutable, requiredMargin
 	}
 	return false, big.NewInt(0)
 }

plugin/evm/orderbook/memory_database.go

@@ -998,6 +998,7 @@ func (db *InMemoryDatabase) GetNaughtyTraders(hState *hu.HubbleState) ([]Liquida
 				(posSize.Sign() > 0 && (totalReduceAmount.Sign() > 0 || (totalReduceAmount.Sign() < 0 && hu.Neg(totalReduceAmount).Cmp(posSize) > 0))) ||
 				(posSize.Sign() < 0 && (totalReduceAmount.Sign() < 0 || (totalReduceAmount.Sign() > 0 && totalReduceAmount.Cmp(hu.Neg(posSize)) > 0)))
 			if hasStaleReduceOnlyOrders {
+				log.Debug("hasStaleReduceOnlyOrders", "trader", addr.String(), "marketId", marketId, "posSize", posSize, "totalReduceAmount", totalReduceAmount)
 				marketsToCancelReduceOnlyOrdersIn[marketId] = true
 				shouldLookForOrdersToCancel = true
 			}

plugin/evm/orderbook/tx_processor.go

@@ -3,10 +3,8 @@ package orderbook
 import (
 	"context"
 	"crypto/ecdsa"
-	"encoding/hex"
 	"time"
 
-	// "encoding/hex"
 	"errors"
 	"fmt"
 	"math/big"
@@ -117,7 +115,6 @@ func (lotp *limitOrderTxProcessor) ExecuteLiquidation(trader common.Address, mat
 	}
 	txHash, err := lotp.executeLocalTx(lotp.orderBookContractAddress, lotp.orderBookABI, "liquidateAndExecuteOrder", trader, orderBytes, fillAmount)
 	log.Info("ExecuteLiquidation", "trader", trader, "matchedOrder", matchedOrder, "fillAmount", prettifyScaledBigInt(fillAmount, 18), "txHash", txHash.String(), "err", err)
-	// log.Info("ExecuteLiquidation", "trader", trader, "matchedOrder", matchedOrder, "fillAmount", prettifyScaledBigInt(fillAmount, 18), "orderBytes", hex.EncodeToString(orderBytes), "txHash", txHash.String(), "err", err)
 	return err
 }
 
@@ -151,8 +148,7 @@ func (lotp *limitOrderTxProcessor) ExecuteMatchedOrdersTx(longOrder Order, short
 		log.Error("EncodeLimitOrder failed for shortOrder", "order", shortOrder, "err", err)
 		return err
 	}
-	log.Info("ExecuteMatchedOrdersTx", "longOrder", hex.EncodeToString(orders[0]), "shortOrder", hex.EncodeToString(orders[1]), "fillAmount", prettifyScaledBigInt(fillAmount, 18), "err", err)
-
+	// log.Info("ExecuteMatchedOrdersTx", "longOrder", hex.EncodeToString(orders[0]), "shortOrder", hex.EncodeToString(orders[1]), "fillAmount", prettifyScaledBigInt(fillAmount, 18), "err", err)
 	txHash, err := lotp.executeLocalTx(lotp.orderBookContractAddress, lotp.orderBookABI, "executeMatchedOrders", orders, fillAmount)
 	log.Info("ExecuteMatchedOrdersTx", "LongOrder", longOrder, "ShortOrder", shortOrder, "fillAmount", prettifyScaledBigInt(fillAmount, 18), "txHash", txHash.String(), "err", err)
 	return err

precompile/contracts/jurorv2/matching_validation.go

@@ -411,7 +411,7 @@ func validateExecuteSignedOrder(bibliophile b.BibliophileClient, order *hu.Signe
 		return &Metadata{OrderHash: orderHash}, err
 	}
 
-	log.Info("validateExecuteSignedOrder", "trader", trader, "signer", signer, "orderHash", orderHash)
+	log.Debug("validateExecuteSignedOrder", "trader", trader, "signer", signer, "orderHash", orderHash)
 	if trader != signer && !bibliophile.IsTradingAuthority(trader, signer) {
 		return &Metadata{OrderHash: orderHash}, hu.ErrNoTradingAuthority
 	}