[TT- 1545] lower the amount of WARN and ERROR logs (#1124)

seth/README.md

@@ -34,6 +34,7 @@ Reliable and debug-friendly Ethereum client
 13. [Block Stats](#block-stats)
 14. [Single transaction tracing](#single-transaction-tracing)
 15. [Bulk transaction tracing](#bulk-transaction-tracing)
+16. [RPC traffic logging](#rpc-traffic-logging)
 
 ## Goals
 
@@ -786,3 +787,6 @@ You need to pass a file with a list of transaction hashes to trace. The file sho
 ```
 
 (Note that currently Seth automatically creates `reverted_transactions_<network>_<date>.json` with all reverted transactions, so you can use this file as input for the `trace` command.)
+
+### RPC Traffic logging
+With `SETH_LOG_LEVEL=trace` we will also log to console all traffic between Seth and RPC node. This can be useful for debugging as you can see all the requests and responses.

seth/client.go

@@ -307,7 +307,7 @@ func NewClientRaw(
 
 	if cfg.CheckRpcHealthOnStart {
 		if c.NonceManager == nil {
-			L.Warn().Msg("Nonce manager is not set, RPC health check will be skipped. Client will most probably fail on first transaction")
+			L.Debug().Msg("Nonce manager is not set, RPC health check will be skipped. Client will most probably fail on first transaction")
 		} else {
 			if err := c.checkRPCHealth(); err != nil {
 				return nil, err
@@ -500,14 +500,13 @@ func (m *Client) WaitMined(ctx context.Context, l zerolog.Logger, b bind.DeployB
 				Str("TX", tx.Hash().String()).
 				Msg("Awaiting transaction")
 		} else {
-			l.Warn().
-				Err(err).
+			l.Debug().
 				Str("TX", tx.Hash().String()).
-				Msg("Failed to get receipt")
+				Msgf("Failed to get receipt due to: %s", err)
 		}
 		select {
 		case <-ctx.Done():
-			l.Error().Err(err).Msg("Transaction context is done")
+			l.Error().Err(err).Str("Tx hash", tx.Hash().Hex()).Msg("Timed out, while waiting for transaction to be mined")
 			return nil, ctx.Err()
 		case <-queryTicker.C:
 		}
@@ -727,7 +726,7 @@ func (m *Client) getNonceStatus(address common.Address) (NonceStatus, error) {
 	defer cancel()
 	pendingNonce, err := m.Client.PendingNonceAt(ctx, address)
 	if err != nil {
-		L.Error().Err(err).Msg("Failed to get pending nonce")
+		L.Error().Err(err).Msg("Failed to get pending nonce from RPC node")
 		return NonceStatus{}, err
 	}
 
@@ -848,7 +847,7 @@ func (m *Client) CalculateGasEstimations(request GasEstimationRequest) GasEstima
 		gasPrice, err := m.GetSuggestedLegacyFees(ctx, request.Priority)
 		if err != nil {
 			disableEstimationsIfNeeded(err)
-			L.Warn().Err(err).Msg("Failed to get suggested Legacy fees. Using hardcoded values")
+			L.Debug().Err(err).Msg("Failed to get suggested Legacy fees. Using hardcoded values")
 			estimations.GasPrice = big.NewInt(request.FallbackGasPrice)
 		} else {
 			estimations.GasPrice = gasPrice
@@ -858,7 +857,7 @@ func (m *Client) CalculateGasEstimations(request GasEstimationRequest) GasEstima
 	if m.Cfg.Network.EIP1559DynamicFees {
 		maxFee, priorityFee, err := m.GetSuggestedEIP1559Fees(ctx, request.Priority)
 		if err != nil {
-			L.Warn().Err(err).Msg("Failed to get suggested EIP1559 fees. Using hardcoded values")
+			L.Debug().Err(err).Msg("Failed to get suggested EIP1559 fees. Using hardcoded values")
 			estimations.GasFeeCap = big.NewInt(request.FallbackGasFeeCap)
 			estimations.GasTipCap = big.NewInt(request.FallbackGasTipCap)
 
@@ -893,7 +892,7 @@ func (m *Client) EstimateGasLimitForFundTransfer(from, to common.Address, amount
 		Value: amount,
 	})
 	if err != nil {
-		L.Warn().Err(err).Msg("Failed to estimate gas for fund transfer.")
+		L.Debug().Msgf("Failed to estimate gas for fund transfer due to: %s", err.Error())
 		return 0, errors.Wrapf(err, "failed to estimate gas for fund transfer")
 	}
 	return gasLimit, nil

seth/config.go

@@ -168,7 +168,7 @@ func ReadConfig() (*Config, error) {
 				cfg.Network.URLs = []string{url}
 
 				if selectedNetwork == "" {
-					L.Warn().Msg("No network name provided, using default network")
+					L.Debug().Msg("No network name provided, using default network")
 					cfg.Network.Name = DefaultNetworkName
 				}
 

seth/contract_store.go

@@ -174,7 +174,7 @@ func (c *ContractStore) loadGethWrappers(gethWrappersPaths []string) error {
 					if !strings.Contains(err.Error(), ErrNoABIInFile) {
 						return err
 					}
-					L.Debug().Err(err).Msg("ABI not found in file. Skipping")
+					L.Debug().Msgf("ABI not found in file due to: %s. Skipping", err.Error())
 
 					return nil
 				}

seth/decode.go

@@ -27,7 +27,7 @@ const (
 	ErrDecodeLog            = "failed to decode log"
 	ErrDecodedLogNonIndexed = "failed to decode non-indexed log data"
 	ErrDecodeILogIndexed    = "failed to decode indexed log data"
-	ErrNoTxData             = "no tx data or it's less than 4 bytes"
+	ErrTooShortTxData       = "tx data is less than 4 bytes, can't decode"
 	ErrRPCJSONCastError     = "failed to cast CallMsg error as rpc.DataError"
 
 	WarnNoContractStore = "ContractStore is nil, use seth.NewContractStore(...) to decode transactions"
@@ -204,7 +204,7 @@ func (m *Client) waitUntilMined(l zerolog.Logger, tx *types.Transaction) (*types
 		}, retry.OnRetry(func(i uint, retryErr error) {
 			replacementTx, replacementErr := prepareReplacementTransaction(m, tx)
 			if replacementErr != nil {
-				L.Debug().Str("Replacement error", replacementErr.Error()).Str("Current error", retryErr.Error()).Uint("Attempt", i).Msg("Failed to prepare replacement transaction. Retrying without the original one")
+				L.Debug().Str("Replacement error", replacementErr.Error()).Str("Current error", retryErr.Error()).Uint("Attempt", i).Msg("Failed to prepare replacement transaction. Retrying with the original one")
 				return
 			}
 			l.Debug().Str("Current error", retryErr.Error()).Uint("Attempt", i).Msg("Waiting for transaction to be confirmed after gas bump")
@@ -279,12 +279,12 @@ func (m *Client) handleTracingError(l zerolog.Logger, decoded DecodedTransaction
 	}
 
 	if strings.Contains(traceErr.Error(), "debug_traceTransaction does not exist") {
-		l.Warn().
+		l.Debug().
 			Msg("Debug API is either disabled or not available on the node. Disabling tracing")
 
 		l.Error().
 			Err(revertErr).
-			Msg("Transaction was reverted, but we couldn't trace the transaction.")
+			Msg("Transaction was reverted, but we couldn't trace it, because debug API on the node is disabled")
 
 		m.Cfg.TracingLevel = TracingLevel_None
 	}
@@ -378,19 +378,25 @@ func (m *Client) decodeTransaction(l zerolog.Logger, tx *types.Transaction, rece
 		Protected:   tx.Protected(),
 		Hash:        tx.Hash().String(),
 	}
-	// if there is no tx data we have no inputs/outputs/logs
-	if len(txData) == 0 || len(txData) < 4 {
-		l.Err(errors.New(ErrNoTxData)).Send()
+
+	if len(txData) == 0 && tx.Value() != nil && tx.Value().Cmp(big.NewInt(0)) > 0 {
+		l.Debug().Msg("Transaction has no data. It looks like a simple ETH transfer and there is nothing to decode")
+		return defaultTxn, nil
+	}
+
+	// this might indicate a malformed tx, but we can't be sure, so we just log it and continue
+	if len(txData) < 4 {
+		l.Debug().Msgf("Transaction data is too short to decode. Expected at last 4 bytes, but got %d. Skipping decoding", len(txData))
 		return defaultTxn, nil
 	}
 	if m.ContractStore == nil {
-		L.Warn().Msg(WarnNoContractStore)
+		l.Warn().Msg(WarnNoContractStore)
 		return defaultTxn, nil
 	}
 
 	sig := txData[:4]
 	if m.ABIFinder == nil {
-		L.Err(errors.New("ABIFInder is nil")).Msg("ABIFinder is required for transaction decoding")
+		l.Err(errors.New("ABIFInder is nil")).Msg("ABIFinder is required for transaction decoding")
 		return defaultTxn, nil
 	}
 
@@ -493,7 +499,7 @@ func (m *Client) DecodeCustomABIErr(txErr error) (string, error) {
 			}
 		}
 	} else {
-		L.Warn().Msg("No error data in tx submission error")
+		L.Debug().Msg("Transaction submission error doesn't contain any data. Impossible to decode the revert reason")
 	}
 	return "", nil
 }
@@ -503,8 +509,7 @@ func (m *Client) CallMsgFromTx(tx *types.Transaction) (ethereum.CallMsg, error)
 	signer := types.LatestSignerForChainID(tx.ChainId())
 	sender, err := types.Sender(signer, tx)
 	if err != nil {
-		L.Warn().Err(err).Msg("Failed to get sender from tx")
-		return ethereum.CallMsg{}, err
+		return ethereum.CallMsg{}, errors.Wrapf(err, "failed to get sender from transaction")
 	}
 
 	if tx.Type() == types.LegacyTxType {
@@ -552,7 +557,7 @@ func (m *Client) callAndGetRevertReason(tx *types.Transaction, rc *types.Receipt
 	// if there is no match we print the error from CallMsg call
 	msg, err := m.CallMsgFromTx(tx)
 	if err != nil {
-		L.Warn().Err(err).Msg("Failed to get call msg from tx. We won't be able to decode revert reason.")
+		L.Debug().Msgf("Failed to extract required data from transaction due to: %s, We won't be able to decode revert reason.", err.Error())
 		return nil
 	}
 	_, plainStringErr := m.Client.CallContract(context.Background(), msg, rc.BlockNumber)
@@ -566,22 +571,22 @@ func (m *Client) callAndGetRevertReason(tx *types.Transaction, rc *types.Receipt
 	}
 
 	if plainStringErr != nil {
-		L.Warn().Msg("Failed to decode revert reason")
+		L.Debug().Msg("Failed to decode revert reason")
 
 		if plainStringErr.Error() == "execution reverted" && tx != nil && rc != nil {
 			if tx.To() != nil {
 				pragma, err := m.DownloadContractAndGetPragma(*tx.To(), rc.BlockNumber)
 				if err == nil {
 					if DoesPragmaSupportCustomRevert(pragma) {
-						L.Warn().Str("Pragma", fmt.Sprint(pragma)).Msg("Custom revert reason is supported by pragma, but we could not decode it. This might be a bug in Seth. Please contact the Test Tooling team.")
+						L.Warn().Str("Pragma", fmt.Sprint(pragma)).Msg("Custom revert reason is supported by pragma, but we could not decode it. If you are sure that this contract has custom revert reasons this might indicate a bug in Seth. Please contact the Test Tooling team.")
 					} else {
 						L.Info().Str("Pragma", fmt.Sprint(pragma)).Msg("Custom revert reason is not supported by pragma version (must be >= 0.8.4). There's nothing more we can do to get custom revert reason.")
 					}
 				} else {
-					L.Warn().Err(err).Msg("Failed to decode pragma version. Contract either uses very old version or was compiled without metadata. We won't be able to decode revert reason.")
+					L.Debug().Msgf("Failed to decode pragma version due to: %s. Contract either uses very old version or was compiled without metadata. We won't be able to decode revert reason.", err.Error())
 				}
 			} else {
-				L.Warn().Msg("Transaction has no recipient address. Most likely it's a contract creation transaction. We don't support decoding revert reasons for contract creation transactions yet.")
+				L.Debug().Msg("Transaction has no recipient address. Most likely it's a contract creation transaction. We don't support decoding revert reasons for contract creation transactions yet.")
 			}
 		}
 
@@ -594,7 +599,7 @@ func (m *Client) callAndGetRevertReason(tx *types.Transaction, rc *types.Receipt
 func decodeTxInputs(l zerolog.Logger, txData []byte, method *abi.Method) (map[string]interface{}, error) {
 	l.Trace().Msg("Parsing tx inputs")
 	if (len(txData)) < 4 {
-		return nil, errors.New(ErrNoTxData)
+		return nil, errors.New(ErrTooShortTxData)
 	}
 
 	inputMap := make(map[string]interface{})

seth/dot_graph.go

@@ -119,7 +119,7 @@ func (t *Tracer) generateDotGraph(txHash string, calls []*DecodedCall, revertErr
 		_, exists := callHashToID[hash]
 		if exists {
 			// This could be also valid if the same call is present twice in the trace, but in typical scenarios that should not happen
-			L.Warn().Msg("The same call was present twice. This should not happen and might indicate a bug in the tracer. Check debug log for details")
+			L.Warn().Msg("The same call was present twice. This should not happen and might indicate a bug in the tracer. Check debug log for details and contact the Test Tooling team")
 			marshalled, err := json.Marshal(call)
 			if err == nil {
 				L.Debug().Msgf("Call: %v", marshalled)

seth/gas_adjuster.go

@@ -11,7 +11,6 @@ import (
 	"time"
 
 	"github.com/ethereum/go-ethereum/core/types"
-	"github.com/pkg/errors"
 )
 
 const (
@@ -110,7 +109,7 @@ func (m *Client) CalculateNetworkCongestionMetric(blocksNumber uint64, strategy
 		go func(bn *big.Int) {
 			header, err := getHeaderData(bn)
 			if err != nil {
-				L.Error().Err(err).Msgf("Failed to get block %d header", bn.Int64())
+				L.Debug().Msgf("Failed to get block %d header due to: %s", bn.Int64(), err.Error())
 				wg.Done()
 				return
 			}
@@ -235,19 +234,20 @@ func (m *Client) GetSuggestedEIP1559Fees(ctx context.Context, priority string) (
 	}
 
 	if baseFee64 == 0.0 {
-		err = errors.New(ZeroGasSuggestedErr)
-
-		L.Error().
-			Err(err).
+		L.Debug().
 			Float64("BaseFee", baseFee64).
 			Int64("SuggestedTip", currentGasTip.Int64()).
-			Msg("Incorrect gas data received from node. Skipping automation gas estimation")
+			Msgf("Incorrect gas data received from node: historical base fee was 0. Skipping automation gas estimation")
 		return
 	}
 
 	if currentGasTip.Int64() == 0 {
-		L.Warn().
-			Msg("Suggested tip is 0.0. Although not strictly incorrect, it is unusual. Transaction might take much longer to confirm.")
+		L.Debug().
+			Int64("SuggestedTip", currentGasTip.Int64()).
+			Str("Fallback gas tip", fmt.Sprintf("%d wei / %s ether", m.Cfg.Network.GasTipCap, WeiToEther(big.NewInt(m.Cfg.Network.GasTipCap)).Text('f', -1))).
+			Msg("Suggested tip is 0.0. Although not strictly incorrect, it is unusual. Will use fallback value instead")
+
+		currentGasTip = big.NewInt(m.Cfg.Network.GasTipCap)
 	}
 
 	// between 0.8 and 1.5
@@ -299,9 +299,8 @@ func (m *Client) GetSuggestedEIP1559Fees(ctx context.Context, priority string) (
 		} else if !strings.Contains(err.Error(), BlockFetchingErr) {
 			return
 		} else {
-			L.Warn().
-				Err(err).
-				Msg("Failed to calculate congestion metric. Skipping congestion buffer adjustment")
+			L.Debug().
+				Msgf("Failed to calculate congestion metric due to: %s. Skipping congestion buffer adjustment", err.Error())
 
 			// set error to nil, as we can still calculate the fees, but without congestion buffer
 			// we don't want to return an error in this case
@@ -354,9 +353,8 @@ func (m *Client) GetSuggestedLegacyFees(ctx context.Context, priority string) (a
 
 	if suggestedGasPrice.Int64() == 0 {
 		err = fmt.Errorf("suggested gas price is 0")
-		L.Error().
-			Err(err).
-			Msg("Incorrect gas data received from node. Skipping automation gas estimation")
+		L.Debug().
+			Msg("Incorrect gas data received from node: suggested gas price was 0. Skipping automation gas estimation")
 		return
 	}
 
@@ -399,9 +397,8 @@ func (m *Client) GetSuggestedLegacyFees(ctx context.Context, priority string) (a
 		} else if !strings.Contains(err.Error(), BlockFetchingErr) {
 			return
 		} else {
-			L.Warn().
-				Err(err).
-				Msg("Failed to calculate congestion metric. Skipping congestion buffer adjustment")
+			L.Debug().
+				Msgf("Failed to calculate congestion metric due to: %s. Skipping congestion buffer adjustment", err.Error())
 
 			// set error to nil, as we can still calculate the fees, but without congestion buffer
 			// we don't want to return an error in this case
@@ -469,9 +466,8 @@ func (m *Client) HistoricalFeeData(priority string) (baseFee float64, historical
 	estimator := NewGasEstimator(m)
 	stats, err := estimator.Stats(m.Cfg.Network.GasPriceEstimationBlocks, 99)
 	if err != nil {
-		L.Error().
-			Err(err).
-			Msg("Failed to get fee history. Skipping automation gas estimation")
+		L.Debug().
+			Msgf("Failed to get fee history due to: %s. Skipping automation gas estimation", err.Error())
 
 		return
 	}
@@ -491,15 +487,15 @@ func (m *Client) HistoricalFeeData(priority string) (baseFee float64, historical
 		historicalGasTipCap = stats.TipCap.Perc25
 	default:
 		err = fmt.Errorf("unknown priority: %s", priority)
-		L.Error().
+		L.Debug().
 			Str("Priority", priority).
-			Msg("Unknown priority. Skipping automation gas estimation")
+			Msgf("Unknown priority: %s. Skipping automation gas estimation", err.Error())
 
 		return
 
 	}
 
-	return baseFee, historicalGasTipCap, err
+	return
 }
 
 // calculateGasUsedRatio averages the gas used ratio for a sense of how full blocks are

seth/http_logging_transport.go

@@ -6,6 +6,7 @@ import (
 	"net/http"
 	"net/http/httputil"
 	"os"
+	"strings"
 	"time"
 )
 
@@ -20,7 +21,7 @@ func (t *LoggingTransport) RoundTrip(req *http.Request) (*http.Response, error)
 
 	reqDump, err := httputil.DumpRequestOut(req, true)
 	if err != nil {
-		L.Error().Err(err).Msg("Error dumping request")
+		L.Warn().Err(err).Msg("Error dumping request")
 	} else {
 		fmt.Printf("Request:\n%s\n", string(reqDump))
 	}
@@ -37,7 +38,7 @@ func (t *LoggingTransport) RoundTrip(req *http.Request) (*http.Response, error)
 
 	respDump, err := httputil.DumpResponse(resp, true)
 	if err != nil {
-		L.Error().Err(err).Msg("Error dumping response")
+		L.Warn().Err(err).Msg("Error dumping response")
 	} else {
 		fmt.Printf("Response:\n%s\n", string(respDump))
 	}
@@ -49,7 +50,7 @@ func (t *LoggingTransport) RoundTrip(req *http.Request) (*http.Response, error)
 // NewLoggingTransport creates a new logging transport for GAP or default transport
 // controlled by SETH_LOG_LEVEL
 func NewLoggingTransport() http.RoundTripper {
-	if os.Getenv(LogLevelEnvVar) == "debug" {
+	if strings.EqualFold(os.Getenv(LogLevelEnvVar), "trace") {
 		return &LoggingTransport{
 			// TODO: GAP, add proper certificates
 			Transport: &http.Transport{