fix rollup limiter & improve "slow query" logging (#1551)

* fix rollup limiter.
Improve "slow query" logging

* add fix for empty rollups

* add fix for empty rollups

go/enclave/components/rollup_compression.go

@@ -161,7 +161,7 @@ func (rc *RollupCompression) createRollupHeader(batches []*core.Batch) (*common.
 
 	isReorg := false
 	for i, batch := range batches {
-		rc.logger.Info("Add batch to rollup", log.BatchSeqNoKey, batch.SeqNo(), log.BatchHeightKey, batch.Number(), log.BatchHashKey, batch.Hash())
+		rc.logger.Debug("Compressing batch to rollup", log.BatchSeqNoKey, batch.SeqNo(), log.BatchHeightKey, batch.Number(), log.BatchHashKey, batch.Hash())
 		// determine whether the batch is canonical
 		can, err := rc.storage.FetchBatchByHeight(batch.NumberU64())
 		if err != nil {

go/enclave/limiters/interfaces.go

@@ -3,6 +3,8 @@ package limiters
 import (
 	"errors"
 
+	"github.com/obscuronet/go-obscuro/go/enclave/core"
+
 	"github.com/ethereum/go-ethereum/core/types"
 )
 
@@ -14,5 +16,5 @@ type BatchSizeLimiter interface {
 var ErrInsufficientSpace = errors.New("insufficient space in BatchSizeLimiter")
 
 type RollupLimiter interface {
-	AcceptBatch(encodable interface{}) (bool, error)
+	AcceptBatch(batch *core.Batch) (bool, error)
 }

go/enclave/limiters/rolluplimiter.go

@@ -1,20 +1,19 @@
 package limiters
 
 import (
-	"errors"
 	"fmt"
 
+	"github.com/obscuronet/go-obscuro/go/enclave/core"
+
 	"github.com/ethereum/go-ethereum/rlp"
 )
 
-var ErrFailedToEncode = errors.New("failed to encode data")
-
-// MaxTransactionSizeLimiter - configured to be close to what the ethereum clients
-// have configured as the maximum size a transaction can have. Note that this isn't
-// a protocol limit, but a miner imposed limit and it might be hard to find someone
-// to include a transaction if it goes above it
-// todo - figure out the best number, optimism uses 132KB
-const MaxTransactionSize = 64 * 1024
+const (
+	// 85% is a very conservative number. It will most likely be 66% in practice.
+	// We can lower it, once we have a mechanism in place to handle batches that don't actually compress to that.
+	txCompressionFactor  = 0.85
+	compressedHeaderSize = 1
+)
 
 type rollupLimiter struct {
 	remainingSize uint64
@@ -27,13 +26,14 @@ func NewRollupLimiter(size uint64) RollupLimiter {
 }
 
 // todo (@stefan) figure out how to optimize the serialization out of the limiter
-func (rl *rollupLimiter) AcceptBatch(encodable interface{}) (bool, error) {
-	encodedData, err := rlp.EncodeToBytes(encodable)
+func (rl *rollupLimiter) AcceptBatch(batch *core.Batch) (bool, error) {
+	encodedData, err := rlp.EncodeToBytes(batch.Transactions)
 	if err != nil {
-		return false, fmt.Errorf("%w: %s", ErrFailedToEncode, err.Error())
+		return false, fmt.Errorf("failed to encode data. Cause: %w", err)
 	}
 
-	encodedSize := uint64(len(encodedData))
+	// adjust with a compression factor and add the size of a compressed batch header
+	encodedSize := uint64(float64(len(encodedData))*txCompressionFactor) + compressedHeaderSize
 	if encodedSize > rl.remainingSize {
 		return false, nil
 	}

go/enclave/storage/storage.go

@@ -40,8 +40,11 @@ import (
 
 // todo - this will require a dedicated table when updates are implemented
 const (
-	masterSeedCfg            = "MASTER_SEED"
-	_slowCallThresholdMillis = 50 // requests that take longer than this will be logged
+	masterSeedCfg                 = "MASTER_SEED"
+	_slowCallDebugThresholdMillis = 50  // requests that take longer than this will be logged with DEBUG
+	_slowCallInfoThresholdMillis  = 100 // requests that take longer than this will be logged with INFO
+	_slowCallWarnThresholdMillis  = 200 // requests that take longer than this will be logged with WARN
+	_slowCallErrorThresholdMillis = 500 // requests that take longer than this will be logged with ERROR
 )
 
 type storageImpl struct {
@@ -551,8 +554,16 @@ func (s *storageImpl) GetPublicTransactionCount() (uint64, error) {
 
 func (s *storageImpl) logDuration(method string, callStart time.Time) {
 	durationMillis := time.Since(callStart).Milliseconds()
+	msg := fmt.Sprintf("Storage::%s completed", method)
 	// we only log 'slow' calls to reduce noise
-	if durationMillis > _slowCallThresholdMillis {
-		s.logger.Info(fmt.Sprintf("Storage::%s completed", method), log.DurationMilliKey, durationMillis)
+	switch {
+	case durationMillis > _slowCallErrorThresholdMillis:
+		s.logger.Error(msg, log.DurationMilliKey, durationMillis)
+	case durationMillis > _slowCallWarnThresholdMillis:
+		s.logger.Warn(msg, log.DurationMilliKey, durationMillis)
+	case durationMillis > _slowCallInfoThresholdMillis:
+		s.logger.Info(msg, log.DurationMilliKey, durationMillis)
+	case durationMillis > _slowCallDebugThresholdMillis:
+		s.logger.Debug(msg, log.DurationMilliKey, durationMillis)
 	}
 }

integration/simulation/validate_chain.go

@@ -127,32 +127,44 @@ func checkObscuroBlockchainValidity(t *testing.T, s *Simulation, maxL1Height uin
 	}
 }
 
-func checkCollectedL1Fees(t *testing.T, node ethadapter.EthClient, s *Simulation, nodeIdx int, rollupReceipts types.Receipts) {
-	costOfRollups := big.NewInt(0)
+// the cost of an empty rollup - adjust if the management contract changes. This is the rollup overhead.
+const emptyRollupGas = 110_000
 
-	if !s.Params.IsInMem {
-		for _, receipt := range rollupReceipts {
-			block, err := node.EthClient().BlockByHash(context.Background(), receipt.BlockHash)
-			if err != nil {
-				panic(err)
-			}
+func checkCollectedL1Fees(t *testing.T, node ethadapter.EthClient, s *Simulation, nodeIdx int, rollupReceipts types.Receipts) {
+	costOfRollupsWithTransactions := big.NewInt(0)
+	costOfEmptyRollups := big.NewInt(0)
 
-			txCost := big.NewInt(0).Mul(block.BaseFee(), big.NewInt(0).SetUint64(receipt.GasUsed))
-			costOfRollups.Add(costOfRollups, txCost)
-		}
+	if s.Params.IsInMem {
+		// not supported for in memory tests
+		return
+	}
 
-		l2FeesWallet := s.Params.Wallets.L2FeesWallet
-		obsClients := network.CreateAuthClients(s.RPCHandles.RPCClients, l2FeesWallet)
-		feeBalance, err := obsClients[nodeIdx].BalanceAt(context.Background(), nil)
+	for _, receipt := range rollupReceipts {
+		block, err := node.EthClient().BlockByHash(context.Background(), receipt.BlockHash)
 		if err != nil {
-			panic(fmt.Errorf("failed getting balance for bridge transfer receiver. Cause: %w", err))
+			panic(err)
 		}
 
-		// if balance of collected fees is less than cost of published rollups fail
-		if feeBalance.Cmp(costOfRollups) == -1 {
-			t.Errorf("Node %d: Sequencer has collected insufficient fees. Has: %d, needs: %d", nodeIdx, feeBalance, costOfRollups)
+		txCost := big.NewInt(0).Mul(block.BaseFee(), big.NewInt(0).SetUint64(receipt.GasUsed))
+		// only calculate the fees collected for non-empty rollups, because the empty ones are subsidized
+		if receipt.GasUsed > emptyRollupGas {
+			costOfRollupsWithTransactions.Add(costOfRollupsWithTransactions, txCost)
+		} else {
+			costOfEmptyRollups.Add(costOfEmptyRollups, txCost)
 		}
 	}
+
+	l2FeesWallet := s.Params.Wallets.L2FeesWallet
+	obsClients := network.CreateAuthClients(s.RPCHandles.RPCClients, l2FeesWallet)
+	feeBalance, err := obsClients[nodeIdx].BalanceAt(context.Background(), nil)
+	if err != nil {
+		panic(fmt.Errorf("failed getting balance for bridge transfer receiver. Cause: %w", err))
+	}
+
+	// if balance of collected fees is less than cost of published rollups fail
+	if feeBalance.Cmp(costOfRollupsWithTransactions) == -1 {
+		t.Errorf("Node %d: Sequencer has collected insufficient fees. Has: %d, needs: %d", nodeIdx, feeBalance, costOfRollupsWithTransactions)
+	}
 }
 
 func checkBlockchainOfEthereumNode(t *testing.T, node ethadapter.EthClient, minHeight uint64, s *Simulation, nodeIdx int) uint64 {