From 966c9e8fbf19bb5f5f0c86c72bee7632357b2a54 Mon Sep 17 00:00:00 2001 From: Thomas E Lackey Date: Fri, 20 Jan 2023 12:31:47 -0600 Subject: [PATCH] Improved logging and metrics. --- cmd/root.go | 34 +---- cmd/serve.go | 7 +- cmd/subscribe.go | 2 +- cmd/validate.go | 6 +- cmd/version.go | 2 +- main.go | 3 +- pkg/eth/api.go | 29 +++-- pkg/eth/backend.go | 2 +- pkg/eth/cid_retriever.go | 2 +- pkg/eth/eth_suite_test.go | 3 - pkg/eth/ipld_fetcher.go | 2 +- pkg/eth/test_helpers/test_data.go | 2 +- pkg/eth/types.go | 4 +- pkg/graphql/graphql_suite_test.go | 3 - pkg/graphql/service.go | 6 +- pkg/log/log.go | 204 ++++++++++++++++++++++++++++++ pkg/net/net_suite_test.go | 4 +- pkg/prom/middleware.go | 78 +++++++++++- pkg/prom/prom.go | 13 +- pkg/prom/serve.go | 4 +- pkg/rpc/http.go | 2 +- pkg/rpc/ipc.go | 2 +- pkg/serve/api.go | 2 +- pkg/serve/helpers.go | 2 +- pkg/serve/service.go | 2 +- pkg/shared/functions.go | 4 +- test/integration_suite_test.go | 2 - test_config/test_config.go | 7 +- 28 files changed, 338 insertions(+), 95 deletions(-) create mode 100644 pkg/log/log.go diff --git a/cmd/root.go b/cmd/root.go index e494ea80..221ff4f0 100644 --- a/cmd/root.go +++ b/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") - 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) - } + log.Init() 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") - 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 + return log.Init() } func init() { diff --git a/cmd/serve.go b/cmd/serve.go index 14c744f8..45aff289 100644 --- a/cmd/serve.go +++ b/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 } diff --git a/cmd/subscribe.go b/cmd/subscribe.go index d99e3e4f..155aebbc 100644 --- a/cmd/subscribe.go +++ b/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" diff --git a/cmd/validate.go b/cmd/validate.go index c514f8c2..f1d9f41f 100644 --- a/cmd/validate.go +++ b/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() { diff --git a/cmd/version.go b/cmd/version.go index 2cf2317d..e95bde18 100644 --- a/cmd/version.go +++ b/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" diff --git a/main.go b/main.go index 2e1bb119..787cd8e1 100644 --- a/main.go +++ b/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() { diff --git a/pkg/eth/api.go b/pkg/eth/api.go index b7da0051..6df2fe29 100644 --- a/pkg/eth/api.go +++ b/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) diff --git a/pkg/eth/backend.go b/pkg/eth/backend.go index 1123a875..03c9f2cc 100644 --- a/pkg/eth/backend.go +++ b/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" ) diff --git a/pkg/eth/cid_retriever.go b/pkg/eth/cid_retriever.go index 1ef56aae..59198697 100644 --- a/pkg/eth/cid_retriever.go +++ b/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" diff --git a/pkg/eth/eth_suite_test.go b/pkg/eth/eth_suite_test.go index 73dabe49..98bcaac3 100644 --- a/pkg/eth/eth_suite_test.go +++ b/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) }) diff --git a/pkg/eth/ipld_fetcher.go b/pkg/eth/ipld_fetcher.go index 9a686695..f734f012 100644 --- a/pkg/eth/ipld_fetcher.go +++ b/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 diff --git a/pkg/eth/test_helpers/test_data.go b/pkg/eth/test_helpers/test_data.go index 2efea8c3..78e7bac8 100644 --- a/pkg/eth/test_helpers/test_data.go +++ b/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" ) diff --git a/pkg/eth/types.go b/pkg/eth/types.go index a1f1e9c8..1efa9084 100644 --- a/pkg/eth/types.go +++ b/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 ( diff --git a/pkg/graphql/graphql_suite_test.go b/pkg/graphql/graphql_suite_test.go index cdfd5329..b6dc5df3 100644 --- a/pkg/graphql/graphql_suite_test.go +++ b/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) }) diff --git a/pkg/graphql/service.go b/pkg/graphql/service.go index 498e221d..95211d7a 100644 --- a/pkg/graphql/service.go +++ b/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 } diff --git a/pkg/log/log.go b/pkg/log/log.go new file mode 100644 index 00000000..12a65c65 --- /dev/null +++ b/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 +} diff --git a/pkg/net/net_suite_test.go b/pkg/net/net_suite_test.go index aa2b5b8b..f3dfc32d 100644 --- a/pkg/net/net_suite_test.go +++ b/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) }) diff --git a/pkg/prom/middleware.go b/pkg/prom/middleware.go index 9397576f..9137e313 100644 --- a/pkg/prom/middleware.go +++ b/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()) }) } diff --git a/pkg/prom/prom.go b/pkg/prom/prom.go index f2bd5792..96eb82d6 100644 --- a/pkg/prom/prom.go +++ b/pkg/prom/prom.go @@ -33,8 +33,8 @@ const ( var ( metrics bool - httpCount prometheus.Counter - httpDuration prometheus.Histogram + httpCount *prometheus.CounterVec + 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", - }) - httpDuration = promauto.NewHistogram(prometheus.HistogramOpts{ + }, []string{"method"}) + + httpDuration = promauto.NewHistogramVec(prometheus.HistogramOpts{ Namespace: namespace, Subsystem: subsystemHTTP, Name: "duration", Help: "http request duration", - }) + }, []string{"method"}) wsCount = promauto.NewGauge(prometheus.GaugeOpts{ Namespace: namespace, diff --git a/pkg/prom/serve.go b/pkg/prom/serve.go index 12257d51..7e621bb3 100644 --- a/pkg/prom/serve.go +++ b/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). diff --git a/pkg/rpc/http.go b/pkg/rpc/http.go index 6cac14c1..9c2efa84 100644 --- a/pkg/rpc/http.go +++ b/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" ) diff --git a/pkg/rpc/ipc.go b/pkg/rpc/ipc.go index 5a09f5af..20767ce2 100644 --- a/pkg/rpc/ipc.go +++ b/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" ) diff --git a/pkg/serve/api.go b/pkg/serve/api.go index aa2d6c3e..d8397041 100644 --- a/pkg/serve/api.go +++ b/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" ) diff --git a/pkg/serve/helpers.go b/pkg/serve/helpers.go index a4571197..358568a3 100644 --- a/pkg/serve/helpers.go +++ b/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) diff --git a/pkg/serve/service.go b/pkg/serve/service.go index a0e54189..d6c6feae 100644 --- a/pkg/serve/service.go +++ b/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" diff --git a/pkg/shared/functions.go b/pkg/shared/functions.go index 748e1f13..f5eac06c 100644 --- a/pkg/shared/functions.go +++ b/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) } } diff --git a/test/integration_suite_test.go b/test/integration_suite_test.go index f8c7c979..9856687f 100644 --- a/test/integration_suite_test.go +++ b/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) }) diff --git a/test_config/test_config.go b/test_config/test_config.go index db0d36c2..982f9b44 100644 --- a/test_config/test_config.go +++ b/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")