cmd/root.go

@@ -18,15 +18,14 @@ package cmd
 
 import (
 	"fmt"
-	"os"
 	"path/filepath"
 	"strings"
 
 	"github.com/joho/godotenv"
-	log "github.com/sirupsen/logrus"
 	"github.com/spf13/cobra"
 	"github.com/spf13/viper"
 
+	"github.com/cerc-io/ipld-eth-server/v4/pkg/log"
 	"github.com/cerc-io/ipld-eth-server/v4/pkg/prom"
 )
 
@@ -50,24 +49,7 @@ func Execute() {
 }
 
 func initFuncs(cmd *cobra.Command, args []string) {
-	viper.BindEnv("log.file", "LOGRUS_FILE")
+	log.Init()
-	logfile := viper.GetString("log.file")
-	if logfile != "" {
-		file, err := os.OpenFile(logfile,
-			os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0666)
-		if err == nil {
-			log.Infof("Directing output to %s", logfile)
-			log.SetOutput(file)
-		} else {
-			log.SetOutput(os.Stdout)
-			log.Info("Failed to log to file, using default stdout")
-		}
-	} else {
-		log.SetOutput(os.Stdout)
-	}
-	if err := logLevel(); err != nil {
-		log.Fatal("Could not set log level: ", err)
-	}
 
 	if viper.GetBool("metrics") {
 		prom.Init()
@@ -84,17 +66,7 @@ func initFuncs(cmd *cobra.Command, args []string) {
 }
 
 func logLevel() error {
-	viper.BindEnv("log.level", "LOGRUS_LEVEL")
+	return log.Init()
-	lvl, err := log.ParseLevel(viper.GetString("log.level"))
-	if err != nil {
-		return err
-	}
-	log.SetLevel(lvl)
-	if lvl > log.InfoLevel {
-		log.SetReportCaller(true)
-	}
-	log.Info("Log level set to ", lvl.String())
-	return nil
 }
 
 func init() {

cmd/serve.go

@@ -17,7 +17,6 @@ package cmd
 
 import (
 	"errors"
-	"github.com/mailgun/groupcache/v2"
 	"net/http"
 	"net/url"
 	"os"
@@ -26,8 +25,10 @@ import (
 	"sync"
 	"time"
 
+	"github.com/mailgun/groupcache/v2"
+
+	"github.com/cerc-io/ipld-eth-server/v4/pkg/log"
 	"github.com/ethereum/go-ethereum/rpc"
-	log "github.com/sirupsen/logrus"
 	"github.com/spf13/cobra"
 	"github.com/spf13/viper"
 	"github.com/vulcanize/gap-filler/pkg/mux"
@@ -255,7 +256,7 @@ func startStateTrieValidator(config *s.Config, server s.Server) {
 
 		block, err := backend.CurrentBlock()
 		if err != nil {
-			log.Errorln("Error fetching current block for state trie validator")
+			log.Error("Error fetching current block for state trie validator")
 			continue
 		}
 

cmd/subscribe.go

@@ -19,11 +19,11 @@ import (
 	"bytes"
 	"fmt"
 
+	"github.com/cerc-io/ipld-eth-server/v4/pkg/log"
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/core/types"
 	"github.com/ethereum/go-ethereum/rlp"
 	"github.com/ethereum/go-ethereum/rpc"
-	log "github.com/sirupsen/logrus"
 	"github.com/spf13/cobra"
 	"github.com/spf13/viper"
 

cmd/validate.go

@@ -20,8 +20,8 @@ import (
 
 	validator "github.com/cerc-io/eth-ipfs-state-validator/v4/pkg"
 	ipfsethdb "github.com/cerc-io/ipfs-ethdb/v4/postgres"
+	"github.com/cerc-io/ipld-eth-server/v4/pkg/log"
 	"github.com/ethereum/go-ethereum/common"
-	log "github.com/sirupsen/logrus"
 	"github.com/spf13/cobra"
 	"github.com/spf13/viper"
 
@@ -65,13 +65,13 @@ func validate() {
 
 	val := validator.NewValidator(nil, ethDB)
 	if err = val.ValidateTrie(stateRoot); err != nil {
-		log.Fatalln("Error validating state root")
+		log.Fatal("Error validating state root")
 	}
 
 	stats := ethDB.(*ipfsethdb.Database).GetCacheStats()
 	log.Debugf("groupcache stats %+v", stats)
 
-	log.Infoln("Successfully validated state root")
+	log.Info("Successfully validated state root")
 }
 
 func init() {

cmd/version.go

@@ -16,7 +16,7 @@
 package cmd
 
 import (
-	log "github.com/sirupsen/logrus"
+	"github.com/cerc-io/ipld-eth-server/v4/pkg/log"
 	"github.com/spf13/cobra"
 
 	v "github.com/cerc-io/ipld-eth-server/v4/version"

main.go

@@ -16,9 +16,8 @@
 package main
 
 import (
-	"github.com/sirupsen/logrus"
-
 	"github.com/cerc-io/ipld-eth-server/v4/cmd"
+	"github.com/sirupsen/logrus"
 )
 
 func main() {

pkg/eth/api.go

@@ -27,6 +27,8 @@ import (
 	"strconv"
 	"time"
 
+	"github.com/cerc-io/ipld-eth-server/v4/pkg/log"
+
 	"github.com/ethereum/go-ethereum/accounts/abi"
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/common/hexutil"
@@ -40,7 +42,6 @@ import (
 	"github.com/ethereum/go-ethereum/rlp"
 	"github.com/ethereum/go-ethereum/rpc"
 	"github.com/ethereum/go-ethereum/statediff"
-	"github.com/sirupsen/logrus"
 
 	"github.com/cerc-io/ipld-eth-server/v4/pkg/shared"
 )
@@ -169,7 +170,8 @@ func (pea *PublicEthAPI) BlockNumber() hexutil.Uint64 {
 // * When fullTx is true all transactions in the block are returned, otherwise
 //   only the transaction hash is returned.
 func (pea *PublicEthAPI) GetBlockByNumber(ctx context.Context, number rpc.BlockNumber, fullTx bool) (map[string]interface{}, error) {
-	logrus.Debug("Received getBlockByNumber request for number ", number.Int64())
+	ctx = context.WithValue(ctx, log.CtxKeyBlockNumber, number.Int64())
+	log.Debugx(ctx, "getBlockByNumber")
 	block, err := pea.B.BlockByNumber(ctx, number)
 	if block != nil && err == nil {
 		return pea.rpcMarshalBlock(block, true, fullTx)
@@ -188,7 +190,8 @@ func (pea *PublicEthAPI) GetBlockByNumber(ctx context.Context, number rpc.BlockN
 // GetBlockByHash returns the requested block. When fullTx is true all transactions in the block are returned in full
 // detail, otherwise only the transaction hash is returned.
 func (pea *PublicEthAPI) GetBlockByHash(ctx context.Context, hash common.Hash, fullTx bool) (map[string]interface{}, error) {
-	logrus.Debug("Received getBlockByHash request for hash ", hash.Hex())
+	ctx = context.WithValue(ctx, log.CtxKeyBlockHash, hash.Hex())
+	log.Debugx(ctx, "getBlockByHash")
 	block, err := pea.B.BlockByHash(ctx, hash)
 	if block != nil && err == nil {
 		return pea.rpcMarshalBlock(block, true, fullTx)
@@ -231,7 +234,7 @@ func (pea *PublicEthAPI) GetUncleByBlockNumberAndIndex(ctx context.Context, bloc
 	if block != nil && err == nil {
 		uncles := block.Uncles()
 		if index >= hexutil.Uint(len(uncles)) {
-			logrus.Debugf("uncle with index %s request at block number %d was not found", index.String(), blockNr.Int64())
+			log.Debugxf(ctx, "uncle with index %s request at block number %d was not found", index.String(), blockNr.Int64())
 			return nil, nil
 		}
 		block = types.NewBlockWithHeader(uncles[index])
@@ -255,7 +258,7 @@ func (pea *PublicEthAPI) GetUncleByBlockHashAndIndex(ctx context.Context, blockH
 	if block != nil {
 		uncles := block.Uncles()
 		if index >= hexutil.Uint(len(uncles)) {
-			logrus.Debugf("uncle with index %s request at block hash %s was not found", index.String(), blockHash.Hex())
+			log.Debugxf(ctx, "uncle with index %s request at block hash %s was not found", index.String(), blockHash.Hex())
 			return nil, nil
 		}
 		block = types.NewBlockWithHeader(uncles[index])
@@ -752,7 +755,7 @@ func (pea *PublicEthAPI) GetStorageAt(ctx context.Context, address common.Addres
 		return value[:], nil
 	}
 	if pea.config.ProxyOnError {
-		logrus.Warnf("Missing eth_getStorageAt(%s, %s, %s)", address.Hash().String(), key, blockNrOrHash.String())
+		log.Warnxf(ctx, "Missing eth_getStorageAt(%s, %s, %s)", address.Hash().String(), key, blockNrOrHash.String())
 		var res hexutil.Bytes
 		if err := pea.rpc.CallContext(ctx, &res, "eth_getStorageAt", address, key, blockNrOrHash); res != nil && err == nil {
 			return res, nil
@@ -974,7 +977,7 @@ func (pea *PublicEthAPI) Call(ctx context.Context, args CallArgs, blockNrOrHash
 
 func DoCall(ctx context.Context, b *Backend, args CallArgs, blockNrOrHash rpc.BlockNumberOrHash, overrides *StateOverride, timeout time.Duration, globalGasCap uint64) (*core.ExecutionResult, error) {
 	defer func(start time.Time) {
-		logrus.Debugf("Executing EVM call finished %s runtime %s", time.Now().String(), time.Since(start).String())
+		log.Debugxf(ctx, "Executing EVM call finished %s runtime %s", time.Now().String(), time.Since(start).String())
 	}(time.Now())
 
 	state, header, err := b.StateAndHeaderByNumberOrHash(ctx, blockNrOrHash)
@@ -1074,9 +1077,9 @@ func (pea *PublicEthAPI) writeStateDiffAt(height int64) {
 		IncludeTD:                true,
 		IncludeCode:              true,
 	}
-	logrus.Debugf("Calling statediff_writeStateDiffAt(%d)", height)
+	log.Debugf("Calling statediff_writeStateDiffAt(%d)", height)
 	if err := pea.rpc.CallContext(ctx, &data, "statediff_writeStateDiffAt", uint64(height), params); err != nil {
-		logrus.Errorf("writeStateDiffAt %d failed with err %s", height, err.Error())
+		log.Errorf("writeStateDiffAt %d failed with err %s", height, err.Error())
 	}
 }
 
@@ -1097,9 +1100,9 @@ func (pea *PublicEthAPI) writeStateDiffFor(blockHash common.Hash) {
 		IncludeTD:                true,
 		IncludeCode:              true,
 	}
-	logrus.Debugf("Calling statediff_writeStateDiffFor(%s)", blockHash.Hex())
+	log.Debugf("Calling statediff_writeStateDiffFor(%s)", blockHash.Hex())
 	if err := pea.rpc.CallContext(ctx, &data, "statediff_writeStateDiffFor", blockHash, params); err != nil {
-		logrus.Errorf("writeStateDiffFor %s failed with err %s", blockHash.Hex(), err.Error())
+		log.Errorf("writeStateDiffFor %s failed with err %s", blockHash.Hex(), err.Error())
 	}
 }
 
@@ -1107,13 +1110,13 @@ func (pea *PublicEthAPI) writeStateDiffFor(blockHash common.Hash) {
 func (pea *PublicEthAPI) rpcMarshalBlock(b *types.Block, inclTx bool, fullTx bool) (map[string]interface{}, error) {
 	fields, err := RPCMarshalBlock(b, inclTx, fullTx)
 	if err != nil {
-		logrus.Errorf("error RPC marshalling block with hash %s: %s", b.Hash().String(), err)
+		log.Errorf("error RPC marshalling block with hash %s: %s", b.Hash().String(), err)
 		return nil, err
 	}
 	if inclTx {
 		td, err := pea.B.GetTd(b.Hash())
 		if err != nil {
-			logrus.Errorf("error getting td for block with hash and number %s, %s: %s", b.Hash().String(), b.Number().String(), err)
+			log.Errorf("error getting td for block with hash and number %s, %s: %s", b.Hash().String(), b.Number().String(), err)
 			return nil, err
 		}
 		fields["totalDifficulty"] = (*hexutil.Big)(td)

pkg/eth/backend.go

@@ -28,6 +28,7 @@ import (
 
 	validator "github.com/cerc-io/eth-ipfs-state-validator/v4/pkg"
 	ipfsethdb "github.com/cerc-io/ipfs-ethdb/v4/postgres"
+	"github.com/cerc-io/ipld-eth-server/v4/pkg/log"
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/common/hexutil"
 	"github.com/ethereum/go-ethereum/consensus"
@@ -48,7 +49,6 @@ import (
 	sdtypes "github.com/ethereum/go-ethereum/statediff/types"
 	"github.com/ethereum/go-ethereum/trie"
 	"github.com/jmoiron/sqlx"
-	log "github.com/sirupsen/logrus"
 
 	"github.com/cerc-io/ipld-eth-server/v4/pkg/shared"
 )

pkg/eth/cid_retriever.go

@@ -21,12 +21,12 @@ import (
 	"math/big"
 	"strconv"
 
+	"github.com/cerc-io/ipld-eth-server/v4/pkg/log"
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/crypto"
 	"github.com/ethereum/go-ethereum/statediff/indexer/models"
 	"github.com/jmoiron/sqlx"
 	"github.com/lib/pq"
-	log "github.com/sirupsen/logrus"
 	"gorm.io/driver/postgres"
 	"gorm.io/gorm"
 

pkg/eth/eth_suite_test.go

@@ -17,12 +17,10 @@
 package eth_test
 
 import (
-	"io/ioutil"
 	"testing"
 
 	. "github.com/onsi/ginkgo"
 	. "github.com/onsi/gomega"
-	"github.com/sirupsen/logrus"
 )
 
 func TestETHSuite(t *testing.T) {
@@ -31,5 +29,4 @@ func TestETHSuite(t *testing.T) {
 }
 
 var _ = BeforeSuite(func() {
-	logrus.SetOutput(ioutil.Discard)
 })

pkg/eth/ipld_fetcher.go

@@ -22,11 +22,11 @@ import (
 	"math/big"
 	"strconv"
 
+	"github.com/cerc-io/ipld-eth-server/v4/pkg/log"
 	"github.com/cerc-io/ipld-eth-server/v4/pkg/shared"
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/statediff/indexer/models"
 	"github.com/jmoiron/sqlx"
-	log "github.com/sirupsen/logrus"
 )
 
 // Fetcher interface for substituting mocks in tests

pkg/eth/test_helpers/test_data.go

@@ -23,6 +23,7 @@ import (
 	"crypto/rand"
 	"math/big"
 
+	"github.com/cerc-io/ipld-eth-server/v4/pkg/log"
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/core/types"
 	"github.com/ethereum/go-ethereum/crypto"
@@ -36,7 +37,6 @@ import (
 	"github.com/ethereum/go-ethereum/trie"
 	blocks "github.com/ipfs/go-block-format"
 	"github.com/multiformats/go-multihash"
-	log "github.com/sirupsen/logrus"
 
 	"github.com/cerc-io/ipld-eth-server/v4/pkg/eth"
 )

pkg/eth/types.go

@@ -22,13 +22,13 @@ import (
 	"math/big"
 	"strconv"
 
+	"github.com/cerc-io/ipld-eth-server/v4/pkg/log"
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/common/hexutil"
 	"github.com/ethereum/go-ethereum/common/math"
 	"github.com/ethereum/go-ethereum/core/types"
 	"github.com/ethereum/go-ethereum/statediff/indexer/models"
 	sdtypes "github.com/ethereum/go-ethereum/statediff/types"
-	"github.com/sirupsen/logrus"
 )
 
 // RPCTransaction represents a transaction that will serialize to the RPC representation of a transaction
@@ -142,7 +142,7 @@ func (arg *CallArgs) ToMessage(globalGasCap uint64, baseFee *big.Int) (types.Mes
 		gas = uint64(*arg.Gas)
 	}
 	if globalGasCap != 0 && globalGasCap < gas {
-		logrus.Warn("Caller gas above allowance, capping", "requested", gas, "cap", globalGasCap)
+		log.Warn("Caller gas above allowance, capping", "requested", gas, "cap", globalGasCap)
 		gas = globalGasCap
 	}
 	var (

pkg/graphql/graphql_suite_test.go

@@ -17,12 +17,10 @@
 package graphql_test
 
 import (
-	"io/ioutil"
 	"testing"
 
 	. "github.com/onsi/ginkgo"
 	. "github.com/onsi/gomega"
-	"github.com/sirupsen/logrus"
 )
 
 func TestGraphQL(t *testing.T) {
@@ -31,5 +29,4 @@ func TestGraphQL(t *testing.T) {
 }
 
 var _ = BeforeSuite(func() {
-	logrus.SetOutput(ioutil.Discard)
 })

pkg/graphql/service.go

@@ -27,9 +27,9 @@ import (
 	"github.com/ethereum/go-ethereum/rpc"
 	"github.com/graph-gophers/graphql-go"
 	"github.com/graph-gophers/graphql-go/relay"
-	"github.com/sirupsen/logrus"
 
 	"github.com/cerc-io/ipld-eth-server/v4/pkg/eth"
+	"github.com/cerc-io/ipld-eth-server/v4/pkg/log"
 )
 
 // Service encapsulates a GraphQL service.
@@ -77,7 +77,7 @@ func (s *Service) Start(server *p2p.Server) error {
 		utils.Fatalf("Could not start RPC api: %v", err)
 	}
 	extapiURL := fmt.Sprintf("http://%v/", addr)
-	logrus.Infof("graphQL endpoint opened for url %s", extapiURL)
+	log.Infof("graphQL endpoint opened for url %s", extapiURL)
 	return nil
 }
 
@@ -105,7 +105,7 @@ func (s *Service) Stop() error {
 	if s.listener != nil {
 		s.listener.Close()
 		s.listener = nil
-		logrus.Debugf("graphQL endpoint closed for url %s", fmt.Sprintf("http://%s", s.endpoint))
+		log.Debugf("graphQL endpoint closed for url %s", fmt.Sprintf("http://%s", s.endpoint))
 	}
 	return nil
 }

pkg/log/log.go

@@ -0,0 +1,204 @@
+package log
+
+import (
+	"context"
+	"fmt"
+	"os"
+	"runtime"
+	"strings"
+
+	"github.com/sirupsen/logrus"
+	"github.com/spf13/viper"
+)
+
+const (
+	CtxKeyUniqId      = "id"
+	CtxKeyApiMethod   = "method"
+	CtxKeyReqId       = "reqid"
+	CtxKeyUserId      = "user_id"
+	CtxKeyConn        = "conn"
+	CtxKeyDuration    = "duration"
+	CtxKeyBlockNumber = "block_num"
+	CtxKeyBlockHash   = "block_hash"
+)
+
+// TODO: Allow registering arbitrary keys.
+var registeredKeys = []string{
+	CtxKeyApiMethod,
+	CtxKeyReqId,
+	CtxKeyUserId,
+	CtxKeyConn,
+	CtxKeyDuration,
+	CtxKeyUniqId,
+	CtxKeyBlockNumber,
+	CtxKeyBlockHash,
+}
+
+const FatalLevel = logrus.FatalLevel
+const ErrorLevel = logrus.ErrorLevel
+const InfoLevel = logrus.InfoLevel
+const DebugLevel = logrus.DebugLevel
+const TraceLevel = logrus.TraceLevel
+
+type Entry = logrus.Entry
+
+func GetLog(ctx context.Context) *logrus.Entry {
+	entry := logrus.WithContext(ctx)
+
+	for _, key := range registeredKeys {
+		if value := ctx.Value(key); value != nil {
+			entry = entry.WithField(key, value)
+		}
+	}
+	return entry
+}
+
+func Fatalx(ctx context.Context, args ...interface{}) {
+	GetLog(ctx).Fatal(args...)
+}
+
+func Errorx(ctx context.Context, args ...interface{}) {
+	GetLog(ctx).Error(args...)
+}
+
+func Warnx(ctx context.Context, args ...interface{}) {
+	GetLog(ctx).Warn(args...)
+}
+
+func Infox(ctx context.Context, args ...interface{}) {
+	GetLog(ctx).Info(args...)
+}
+
+func Debugx(ctx context.Context, args ...interface{}) {
+	GetLog(ctx).Debug(args...)
+}
+
+func Tracex(ctx context.Context, args ...interface{}) {
+	GetLog(ctx).Trace(args...)
+}
+
+func Errorxf(ctx context.Context, format string, args ...interface{}) {
+	GetLog(ctx).Errorf(format, args...)
+}
+
+func Warnxf(ctx context.Context, format string, args ...interface{}) {
+	GetLog(ctx).Warnf(format, args...)
+}
+
+func Infoxf(ctx context.Context, format string, args ...interface{}) {
+	GetLog(ctx).Infof(format, args...)
+}
+func Debugxf(ctx context.Context, format string, args ...interface{}) {
+	GetLog(ctx).Debugf(format, args...)
+}
+func Tracexf(ctx context.Context, format string, args ...interface{}) {
+	GetLog(ctx).Tracef(format, args...)
+}
+
+func Fatal(args ...interface{}) {
+	logrus.Fatal(args...)
+}
+func Error(args ...interface{}) {
+	logrus.Error(args...)
+}
+
+func Warn(args ...interface{}) {
+	logrus.Warn(args...)
+}
+
+func Info(args ...interface{}) {
+	logrus.Info(args...)
+}
+
+func Debug(args ...interface{}) {
+	logrus.Debug(args...)
+}
+
+func Trace(args ...interface{}) {
+	logrus.Trace(args...)
+}
+func Fatalf(format string, args ...interface{}) {
+	logrus.Fatalf(format, args...)
+}
+func Errorf(format string, args ...interface{}) {
+	logrus.Errorf(format, args...)
+}
+
+func Warnf(format string, args ...interface{}) {
+	logrus.Warnf(format, args...)
+}
+
+func Infof(format string, args ...interface{}) {
+	logrus.Infof(format, args...)
+}
+func Debugf(format string, args ...interface{}) {
+	logrus.Debugf(format, args...)
+}
+func Tracef(format string, args ...interface{}) {
+	logrus.Tracef(format, args...)
+}
+
+func WithError(err error) *Entry {
+	return logrus.WithError(err)
+}
+
+func WithField(field string, value interface{}) *Entry {
+	return logrus.WithField(field, value)
+}
+
+func Init() error {
+	// Set the output.
+	viper.BindEnv("logrus.file", "LOGRUS_FILE")
+	logFile := viper.GetString("logrus.file")
+	if logFile != "" {
+		file, err := os.OpenFile(logFile,
+			os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0640)
+		if err == nil {
+			logrus.Infof("Directing output to %s", logFile)
+			logrus.SetOutput(file)
+		} else {
+			logrus.SetOutput(os.Stdout)
+			logrus.Info("Failed to logrus.to file, using default stdout")
+		}
+	} else {
+		logrus.SetOutput(os.Stdout)
+	}
+
+	// Set the level.
+	viper.BindEnv("logrus.level", "LOGRUS_LEVEL")
+	lvl, err := logrus.ParseLevel(viper.GetString("logrus.level"))
+	if err != nil {
+		return err
+	}
+	logrus.SetLevel(lvl)
+
+	formatter := &logrus.TextFormatter{}
+	// Show file/line number only at Trace level.
+	if lvl >= TraceLevel {
+		logrus.SetReportCaller(true)
+
+		// We need to exclude this wrapper code, logrus.us itself, and the runtime from the stack to show anything useful.
+		// cf. https://github.com/sirupsen/logrus.us/pull/973
+		formatter.CallerPrettyfier = func(frame *runtime.Frame) (function string, file string) {
+			pcs := make([]uintptr, 50)
+			_ = runtime.Callers(0, pcs)
+			frames := runtime.CallersFrames(pcs)
+
+			// Filter logrus.wrapper / logrus.us / runtime frames.
+			for next, again := frames.Next(); again; next, again = frames.Next() {
+				if !strings.Contains(next.File, "sirupsen/logrus.us") &&
+					!strings.HasPrefix(next.Function, "runtime.") &&
+					!strings.Contains(next.File, "ipld-eth-server/pkg/logrus") {
+					return next.Function, fmt.Sprintf("%s:%d", next.File, next.Line)
+				}
+			}
+
+			// Fallback to the raw info.
+			return frame.Function, fmt.Sprintf("%s:%d", frame.File, frame.Line)
+		}
+	}
+
+	logrus.SetFormatter(formatter)
+	logrus.Info("Log level set to ", lvl.String())
+	return nil
+}

pkg/net/net_suite_test.go

@@ -18,11 +18,11 @@ package net_test
 
 import (
 	"io/ioutil"
+	"log"
 	"testing"
 
 	. "github.com/onsi/ginkgo"
 	. "github.com/onsi/gomega"
-	"github.com/sirupsen/logrus"
 )
 
 func TestNetSuite(t *testing.T) {
@@ -31,5 +31,5 @@ func TestNetSuite(t *testing.T) {
 }
 
 var _ = BeforeSuite(func() {
-	logrus.SetOutput(ioutil.Discard)
+	log.SetOutput(ioutil.Discard)
 })

pkg/prom/middleware.go

@@ -17,12 +17,74 @@
 package prom
 
 import (
+	"bytes"
+	"context"
+	"encoding/json"
+	"fmt"
+	"io"
 	"net/http"
 	"time"
 
+	"github.com/cerc-io/ipld-eth-server/v4/pkg/log"
+	"github.com/google/uuid"
+
 	"github.com/ethereum/go-ethereum/rpc"
 )
 
+const (
+	jsonMethod               = "method"
+	jsonReqId                = "id"
+	headerUserId             = "X-User-Id"
+	headerOriginalRemoteAddr = "X-Original-Remote-Addr"
+)
+
+// Peek at the request and update the Context accordingly (eg, API method, user ID, etc.)
+func prepareRequest(r *http.Request) (*http.Request, error) {
+	// Generate a unique ID for this request.
+	uniqId, err := uuid.NewUUID()
+	if nil != err {
+		log.Error("Error generating ID: ", err)
+		return nil, err
+	}
+
+	// Read the body so that we can peek inside.
+	body, err := io.ReadAll(r.Body)
+	if nil != err {
+		log.Error("Error reading request body: ", err)
+		return nil, err
+	}
+
+	// Replace it with a re-readable copy.
+	r.Body = io.NopCloser(bytes.NewBuffer(body))
+
+	// All API requests should be JSON.
+	var result map[string]interface{}
+	err = json.Unmarshal(body, &result)
+	if nil != err {
+		log.Error("Error parsing request body: ", err)
+		return nil, err
+	}
+
+	// Pull out the method name, request ID, user ID, and address info.
+	reqMethod := fmt.Sprintf("%v", result[jsonMethod])
+	reqId := fmt.Sprintf("%g", result[jsonReqId])
+	userId := r.Header.Get(headerUserId)
+	conn := r.Header.Get(headerOriginalRemoteAddr)
+	if len(conn) == 0 {
+		conn = r.RemoteAddr
+	}
+
+	// Add it all to the request context.
+	ctx := r.Context()
+	ctx = context.WithValue(ctx, log.CtxKeyUniqId, uniqId.String())
+	ctx = context.WithValue(ctx, log.CtxKeyApiMethod, reqMethod)
+	ctx = context.WithValue(ctx, log.CtxKeyReqId, reqId)
+	ctx = context.WithValue(ctx, log.CtxKeyUserId, userId)
+	ctx = context.WithValue(ctx, log.CtxKeyConn, conn)
+
+	return r.WithContext(ctx), nil
+}
+
 // HTTPMiddleware http connection metric reader
 func HTTPMiddleware(next http.Handler) http.Handler {
 	if !metrics {
@@ -30,12 +92,22 @@ func HTTPMiddleware(next http.Handler) http.Handler {
 	}
 
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		httpCount.Inc()
-
 		start := time.Now()
+		r, err := prepareRequest(r)
+		if nil != err {
+			w.WriteHeader(400)
+			return
+		}
+		ctx := r.Context()
+		apiMethod := fmt.Sprintf("%s", ctx.Value(log.CtxKeyApiMethod))
+		httpCount.WithLabelValues(apiMethod).Inc()
+		log.Debugx(ctx, "START")
+
 		next.ServeHTTP(w, r)
+
 		duration := time.Now().Sub(start)
-		httpDuration.Observe(float64(duration.Seconds()))
+		log.Debugxf(context.WithValue(ctx, log.CtxKeyDuration, duration.Milliseconds()), "END")
+		httpDuration.WithLabelValues(apiMethod).Observe(duration.Seconds())
 	})
 }
 

pkg/prom/prom.go

@@ -33,8 +33,8 @@ const (
 var (
 	metrics bool
 
-	httpCount    prometheus.Counter
+	httpCount    *prometheus.CounterVec
-	httpDuration prometheus.Histogram
+	httpDuration *prometheus.HistogramVec
 	wsCount      prometheus.Gauge
 	ipcCount     prometheus.Gauge
 )
@@ -43,18 +43,19 @@ var (
 func Init() {
 	metrics = true
 
-	httpCount = promauto.NewCounter(prometheus.CounterOpts{
+	httpCount = promauto.NewCounterVec(prometheus.CounterOpts{
 		Namespace: namespace,
 		Subsystem: subsystemHTTP,
 		Name:      "count",
 		Help:      "http request count",
-	})
+	}, []string{"method"})
-	httpDuration = promauto.NewHistogram(prometheus.HistogramOpts{
+
+	httpDuration = promauto.NewHistogramVec(prometheus.HistogramOpts{
 		Namespace: namespace,
 		Subsystem: subsystemHTTP,
 		Name:      "duration",
 		Help:      "http request duration",
-	})
+	}, []string{"method"})
 
 	wsCount = promauto.NewGauge(prometheus.GaugeOpts{
 		Namespace: namespace,

pkg/prom/serve.go

@@ -20,8 +20,8 @@ import (
 	"errors"
 	"net/http"
 
+	"github.com/cerc-io/ipld-eth-server/v4/pkg/log"
 	"github.com/prometheus/client_golang/prometheus/promhttp"
-	"github.com/sirupsen/logrus"
 )
 
 var errPromHTTP = errors.New("can't start http server for prometheus")
@@ -36,7 +36,7 @@ func Serve(addr string) *http.Server {
 	}
 	go func() {
 		if err := srv.ListenAndServe(); err != nil {
-			logrus.
+			log.
 				WithError(err).
 				WithField("module", "prom").
 				WithField("addr", addr).

pkg/rpc/http.go

@@ -19,10 +19,10 @@ package rpc
 import (
 	"fmt"
 
+	"github.com/cerc-io/ipld-eth-server/v4/pkg/log"
 	"github.com/ethereum/go-ethereum/cmd/utils"
 	"github.com/ethereum/go-ethereum/node"
 	"github.com/ethereum/go-ethereum/rpc"
-	log "github.com/sirupsen/logrus"
 
 	"github.com/cerc-io/ipld-eth-server/v4/pkg/prom"
 )

pkg/rpc/ipc.go

@@ -22,9 +22,9 @@ import (
 	"os"
 	"path/filepath"
 
+	"github.com/cerc-io/ipld-eth-server/v4/pkg/log"
 	"github.com/ethereum/go-ethereum/p2p/netutil"
 	"github.com/ethereum/go-ethereum/rpc"
-	log "github.com/sirupsen/logrus"
 
 	"github.com/cerc-io/ipld-eth-server/v4/pkg/prom"
 )

pkg/serve/api.go

@@ -19,9 +19,9 @@ package serve
 import (
 	"context"
 
+	"github.com/cerc-io/ipld-eth-server/v4/pkg/log"
 	"github.com/ethereum/go-ethereum/rpc"
 	"github.com/ethereum/go-ethereum/statediff/types"
-	log "github.com/sirupsen/logrus"
 
 	"github.com/cerc-io/ipld-eth-server/v4/pkg/eth"
 )

pkg/serve/helpers.go

@@ -16,7 +16,7 @@
 
 package serve
 
-import log "github.com/sirupsen/logrus"
+import "github.com/cerc-io/ipld-eth-server/v4/pkg/log"
 
 func sendNonBlockingErr(sub Subscription, err error) {
 	log.Error(err)

pkg/serve/service.go

@@ -22,6 +22,7 @@ import (
 	"sync"
 	"time"
 
+	"github.com/cerc-io/ipld-eth-server/v4/pkg/log"
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/core/vm"
 	"github.com/ethereum/go-ethereum/crypto"
@@ -31,7 +32,6 @@ import (
 	"github.com/ethereum/go-ethereum/rlp"
 	"github.com/ethereum/go-ethereum/rpc"
 	"github.com/jmoiron/sqlx"
-	log "github.com/sirupsen/logrus"
 
 	"github.com/cerc-io/ipld-eth-server/v4/pkg/debug"
 	"github.com/cerc-io/ipld-eth-server/v4/pkg/eth"

pkg/shared/functions.go

@@ -17,12 +17,12 @@
 package shared
 
 import (
+	"github.com/cerc-io/ipld-eth-server/v4/pkg/log"
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ipfs/go-cid"
 	blockstore "github.com/ipfs/go-ipfs-blockstore"
 	dshelp "github.com/ipfs/go-ipfs-ds-help"
 	"github.com/jmoiron/sqlx"
-	"github.com/sirupsen/logrus"
 )
 
 // HandleZeroAddrPointer will return an emtpy string for a nil address pointer
@@ -44,7 +44,7 @@ func HandleZeroAddr(to common.Address) string {
 // Rollback sql transaction and log any error
 func Rollback(tx *sqlx.Tx) {
 	if err := tx.Rollback(); err != nil {
-		logrus.Error(err)
+		log.Error(err)
 	}
 }
 

test/integration_suite_test.go

@@ -6,7 +6,6 @@ import (
 
 	. "github.com/onsi/ginkgo"
 	. "github.com/onsi/gomega"
-	"github.com/sirupsen/logrus"
 )
 
 func TestIntegration(t *testing.T) {
@@ -15,5 +14,4 @@ func TestIntegration(t *testing.T) {
 }
 
 var _ = BeforeSuite(func() {
-	logrus.SetOutput(ioutil.Discard)
 })

test_config/test_config.go

@@ -18,9 +18,8 @@ package test_config
 
 import (
 	"errors"
-
+	"github.com/cerc-io/ipld-eth-server/v4/pkg/log"
 	"github.com/ethereum/go-ethereum/statediff/indexer/database/sql/postgres"
-	"github.com/sirupsen/logrus"
 	"github.com/spf13/viper"
 )
 
@@ -35,7 +34,7 @@ func setTestConfig() {
 	vip.SetConfigName("testing")
 	vip.AddConfigPath("$GOPATH/src/github.com/cerc-io/ipld-eth-server/environments/")
 	if err := vip.ReadInConfig(); err != nil {
-		logrus.Fatal(err)
+		log.Fatal(err)
 	}
 	ipc := vip.GetString("client.ipcPath")
 
@@ -45,7 +44,7 @@ func setTestConfig() {
 		ipc = vip.GetString("url")
 	}
 	if ipc == "" {
-		logrus.Fatal(errors.New("testing.toml IPC path or $INFURA_URL env variable need to be set"))
+		log.Fatal(errors.New("testing.toml IPC path or $INFURA_URL env variable need to be set"))
 	}
 
 	hn := vip.GetString("database.hostname")