Merge pull request #262 from onflow/gregor/improve-logging

Improve logging

api/api.go

@@ -165,7 +165,6 @@ func (b *BlockChainAPI) GetBalance(
 
 	balance, err := b.evm.GetBalance(ctx, address, cadenceHeight)
 	if err != nil {
-		b.logger.Error().Err(err).Msg("failed to get balance")
 		return handleError[*hexutil.Big](b.logger, err)
 	}
 
@@ -427,6 +426,7 @@ func (b *BlockChainAPI) Call(
 
 	res, err := b.evm.Call(ctx, tx, from, cadenceHeight)
 	if err != nil {
+		// we debug output this error because the execution error is related to user input
 		b.logger.Debug().Err(err).Msg("failed to execute call")
 		return nil, err
 	}

bootstrap/bootstrap.go

@@ -57,10 +57,33 @@ func Start(ctx context.Context, cfg *config.Config) error {
 		}
 	}
 
+	// create access client with cross-spork capabilities
+	currentSporkClient, err := grpc.NewClient(cfg.AccessNodeHost)
+	if err != nil {
+		return fmt.Errorf("failed to create client connection for host: %s, with error: %w", cfg.AccessNodeHost, err)
+	}
+
+	// if we provided access node previous spork hosts add them to the client
+	pastSporkClients := make([]access.Client, len(cfg.AccessNodePreviousSporkHosts))
+	for i, host := range cfg.AccessNodePreviousSporkHosts {
+		grpcClient, err := grpc.NewClient(host)
+		if err != nil {
+			return fmt.Errorf("failed to create client connection for host: %s, with error: %w", host, err)
+		}
+
+		pastSporkClients[i] = grpcClient
+	}
+
+	client, err := requester.NewCrossSporkClient(currentSporkClient, pastSporkClients, logger)
+	if err != nil {
+		return err
+	}
+
 	go func() {
 		err := startServer(
 			ctx,
 			cfg,
+			client,
 			blocks,
 			transactions,
 			receipts,
@@ -79,6 +102,7 @@ func Start(ctx context.Context, cfg *config.Config) error {
 	err = startIngestion(
 		ctx,
 		cfg,
+		client,
 		blocks,
 		transactions,
 		receipts,
@@ -98,6 +122,7 @@ func Start(ctx context.Context, cfg *config.Config) error {
 func startIngestion(
 	ctx context.Context,
 	cfg *config.Config,
+	client *requester.CrossSporkClient,
 	blocks storage.BlockIndexer,
 	transactions storage.TransactionIndexer,
 	receipts storage.ReceiptIndexer,
@@ -109,27 +134,6 @@ func startIngestion(
 ) error {
 	logger.Info().Msg("starting up event ingestion")
 
-	currentSporkClient, err := grpc.NewClient(cfg.AccessNodeHost)
-	if err != nil {
-		return fmt.Errorf("failed to create client connection for host: %s, with error: %w", cfg.AccessNodeHost, err)
-	}
-
-	// if we provided access node previous spork hosts add them to the client
-	pastSporkClients := make([]access.Client, len(cfg.AccessNodePreviousSporkHosts))
-	for i, host := range cfg.AccessNodePreviousSporkHosts {
-		grpcClient, err := grpc.NewClient(host)
-		if err != nil {
-			return fmt.Errorf("failed to create client connection for host: %s, with error: %w", host, err)
-		}
-
-		pastSporkClients[i] = grpcClient
-	}
-
-	client, err := requester.NewCrossSporkClient(currentSporkClient, pastSporkClients, logger)
-	if err != nil {
-		return err
-	}
-
 	blk, err := client.GetLatestBlock(context.Background(), false)
 	if err != nil {
 		return fmt.Errorf("failed to get latest cadence block: %w", err)
@@ -147,8 +151,8 @@ func startIngestion(
 	}
 
 	logger.Info().
-		Uint64("start-height", latestCadenceHeight).
-		Uint64("latest-network-height", blk.Height).
+		Uint64("start-cadence-height", latestCadenceHeight).
+		Uint64("latest-cadence-height", blk.Height).
 		Uint64("missed-heights", blk.Height-latestCadenceHeight).
 		Msg("indexing cadence height information")
 
@@ -184,6 +188,7 @@ func startIngestion(
 func startServer(
 	ctx context.Context,
 	cfg *config.Config,
+	client access.Client,
 	blocks storage.BlockIndexer,
 	transactions storage.TransactionIndexer,
 	receipts storage.ReceiptIndexer,
@@ -198,14 +203,10 @@ func startServer(
 
 	srv := api.NewHTTPServer(l, rpc.DefaultHTTPTimeouts)
 
-	client, err := grpc.NewClient(cfg.AccessNodeHost)
-	if err != nil {
-		return err
-	}
-
 	// create the signer based on either a single coa key being provided and using a simple in-memory
 	// signer, or multiple keys being provided and using signer with key-rotation mechanism.
 	var signer crypto.Signer
+	var err error
 	switch {
 	case cfg.COAKey != nil:
 		signer, err = crypto.NewInMemorySigner(cfg.COAKey, crypto.SHA3_256)

services/ingestion/engine.go

@@ -4,12 +4,13 @@ import (
 	"context"
 	"fmt"
 
-	"github.com/onflow/flow-evm-gateway/models"
-	"github.com/onflow/flow-evm-gateway/storage"
 	"github.com/onflow/flow-go/engine"
 	"github.com/onflow/flow-go/fvm/evm/types"
 	gethTypes "github.com/onflow/go-ethereum/core/types"
 	"github.com/rs/zerolog"
+
+	"github.com/onflow/flow-evm-gateway/models"
+	"github.com/onflow/flow-evm-gateway/storage"
 )
 
 var _ models.Engine = &Engine{}
@@ -124,7 +125,7 @@ func (e *Engine) Run(ctx context.Context) error {
 //
 // Any error is unexpected and fatal.
 func (e *Engine) processEvents(events *models.CadenceEvents) error {
-	e.log.Debug().
+	e.log.Info().
 		Uint64("cadence-height", events.CadenceHeight()).
 		Int("cadence-event-length", events.Length()).
 		Msg("received new cadence evm events")
@@ -175,12 +176,17 @@ func (e *Engine) indexBlock(cadenceHeight uint64, block *types.Block) error {
 		return fmt.Errorf("invalid block height, expected %d, got %d: %w", e.evmLastHeight.Load(), block.Height, err)
 	}
 
-	h, _ := block.Hash()
+	blockHash, _ := block.Hash()
+	txHashes := make([]string, len(block.TransactionHashes))
+	for i, t := range block.TransactionHashes {
+		txHashes[i] = t.Hex()
+	}
 	e.log.Info().
-		Str("hash", h.Hex()).
+		Str("hash", blockHash.Hex()).
 		Uint64("evm-height", block.Height).
+		Uint64("cadence-height", cadenceHeight).
 		Str("parent-hash", block.ParentBlockHash.String()).
-		Str("tx-hash", block.TransactionHashes[0].Hex()). // now we only have 1 tx per block
+		Strs("tx-hashes", txHashes).
 		Msg("new evm block executed event")
 
 	// todo should probably be batch in the same as bellow tx
@@ -207,7 +213,6 @@ func (e *Engine) indexTransaction(tx models.Transaction, receipt *gethTypes.Rece
 		Int("log-count", len(receipt.Logs)).
 		Uint64("evm-height", receipt.BlockNumber.Uint64()).
 		Uint("tx-index", receipt.TransactionIndex).
-		Str("receipt-tx-hash", receipt.TxHash.String()).
 		Str("tx-hash", txHash.String()).
 		Msg("ingesting new transaction executed event")
 

services/requester/requester.go

@@ -275,11 +275,14 @@ func (e *EVM) GetBalance(
 		[]cadence.Value{hexEncodedAddress},
 	)
 	if err != nil {
-		return nil, err
+		e.logger.Error().
+			Err(err).
+			Str("address", address.String()).
+			Uint64("cadence-height", height).
+			Msg("failed to get get balance")
+		return nil, fmt.Errorf("failed to get balance: %w", err)
 	}
 
-	e.logger.Info().Str("address", address.String()).Msg("get balance")
-
 	// sanity check, should never occur
 	if _, ok := val.(cadence.UInt); !ok {
 		e.logger.Panic().Msg(fmt.Sprintf("failed to convert balance %v to UInt", val))
@@ -305,11 +308,13 @@ func (e *EVM) GetNonce(
 		[]cadence.Value{hexEncodedAddress},
 	)
 	if err != nil {
-		return 0, err
+		e.logger.Error().Err(err).
+			Str("address", address.String()).
+			Uint64("cadence-height", height).
+			Msg("failed to get nonce")
+		return 0, fmt.Errorf("failed to get nonce: %w", err)
 	}
 
-	e.logger.Info().Str("address", address.String()).Msg("get nonce")
-
 	// sanity check, should never occur
 	if _, ok := val.(cadence.UInt64); !ok {
 		e.logger.Panic().Msg(fmt.Sprintf("failed to convert balance %v to UInt64", val))
@@ -324,10 +329,6 @@ func (e *EVM) Call(
 	from common.Address,
 	height uint64,
 ) ([]byte, error) {
-	e.logger.Debug().
-		Str("data", fmt.Sprintf("%x", data)).
-		Msg("call")
-
 	hexEncodedTx, err := cadence.NewString(hex.EncodeToString(data))
 	if err != nil {
 		return nil, err
@@ -345,6 +346,12 @@ func (e *EVM) Call(
 		[]cadence.Value{hexEncodedTx, hexEncodedAddress},
 	)
 	if err != nil {
+		e.logger.Error().
+			Err(err).
+			Uint64("cadence-height", height).
+			Str("from", from.String()).
+			Str("data", string(data)).
+			Msg("failed to execute call")
 		return nil, fmt.Errorf("failed to execute script: %w", err)
 	}
 
@@ -358,8 +365,7 @@ func (e *EVM) Call(
 
 	result := evmResult.ReturnedValue
 
-	e.logger.Info().
-		Str("data", fmt.Sprintf("%x", data)).
+	e.logger.Debug().
 		Str("result", hex.EncodeToString(result)).
 		Msg("call executed")