From 190d0d7ac9314206db60e44bbf3b59eecf116dd8 Mon Sep 17 00:00:00 2001 From: Thomas E Lackey Date: Fri, 20 Jan 2023 19:39:26 -0600 Subject: [PATCH] Improved logging and metrics. (#227) 1. Improve logging to include API method, user ID, etc in the output. We do this by intercepting the request details in the "middleware" and adding them to the request context, as well as adding a wrapper to logrus that simplifies including the fields in the output. 2. Breakdown API metrics by method. This will allow us to differentiate call counts and durations by API method (eg, eth_call vs eth_getStorageAt). --- cmd/root.go | 36 +---- cmd/serve.go | 7 +- cmd/subscribe.go | 2 +- cmd/validate.go | 6 +- cmd/version.go | 2 +- main.go | 5 - pkg/eth/api.go | 25 ++- pkg/eth/backend.go | 2 +- pkg/eth/cid_retriever.go | 2 +- pkg/eth/eth_suite_test.go | 4 +- 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 | 4 +- pkg/graphql/service.go | 6 +- pkg/log/log.go | 246 ++++++++++++++++++++++++++++++ pkg/net/net_suite_test.go | 4 +- pkg/prom/middleware.go | 94 +++++++++++- 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 | 4 +- test_config/test_config.go | 7 +- 28 files changed, 392 insertions(+), 103 deletions(-) create mode 100644 pkg/log/log.go diff --git a/cmd/root.go b/cmd/root.go index e494ea80..4ee233f7 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() @@ -83,20 +65,6 @@ 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 -} - func init() { cobra.OnInitialize(initConfig) viper.SetEnvKeyReplacer(strings.NewReplacer(".", "_")) 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..58070814 100644 --- a/main.go +++ b/main.go @@ -16,14 +16,9 @@ package main import ( - "github.com/sirupsen/logrus" - "github.com/cerc-io/ipld-eth-server/v4/cmd" ) func main() { - logrus.SetFormatter(&logrus.TextFormatter{ - FullTimestamp: true, - }) cmd.Execute() } diff --git a/pkg/eth/api.go b/pkg/eth/api.go index b7da0051..9cdd3e20 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,6 @@ 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()) block, err := pea.B.BlockByNumber(ctx, number) if block != nil && err == nil { return pea.rpcMarshalBlock(block, true, fullTx) @@ -188,7 +188,6 @@ 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()) block, err := pea.B.BlockByHash(ctx, hash) if block != nil && err == nil { return pea.rpcMarshalBlock(block, true, fullTx) @@ -231,7 +230,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 +254,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 +751,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 +973,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 +1073,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 +1096,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 +1106,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..5a5782c7 100644 --- a/pkg/eth/eth_suite_test.go +++ b/pkg/eth/eth_suite_test.go @@ -20,9 +20,9 @@ import ( "io/ioutil" "testing" + "github.com/cerc-io/ipld-eth-server/v4/pkg/log" . "github.com/onsi/ginkgo" . "github.com/onsi/gomega" - "github.com/sirupsen/logrus" ) func TestETHSuite(t *testing.T) { @@ -31,5 +31,5 @@ func TestETHSuite(t *testing.T) { } var _ = BeforeSuite(func() { - logrus.SetOutput(ioutil.Discard) + log.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..e3e07262 100644 --- a/pkg/graphql/graphql_suite_test.go +++ b/pkg/graphql/graphql_suite_test.go @@ -20,9 +20,9 @@ import ( "io/ioutil" "testing" + "github.com/cerc-io/ipld-eth-server/v4/pkg/log" . "github.com/onsi/ginkgo" . "github.com/onsi/gomega" - "github.com/sirupsen/logrus" ) func TestGraphQL(t *testing.T) { @@ -31,5 +31,5 @@ func TestGraphQL(t *testing.T) { } var _ = BeforeSuite(func() { - logrus.SetOutput(ioutil.Discard) + log.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..5fe91c9d --- /dev/null +++ b/pkg/log/log.go @@ -0,0 +1,246 @@ +// Copyright © 2023 Cerc + +// This program is free software: you can redistribute it and/or modify +// it under the terms of the GNU Affero General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. + +// This program is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU Affero General Public License for more details. + +// You should have received a copy of the GNU Affero General Public License +// along with this program. If not, see . + +package log + +import ( + "context" + "fmt" + "io" + "os" + "runtime" + "strings" + + "github.com/sirupsen/logrus" + "github.com/spf13/viper" +) + +const ( + CtxKeyApiMethod = "api_method" + CtxKeyApiParams = "api_params" + CtxKeyApiReqId = "api_reqid" + CtxKeyBlockHash = "block_hash" + CtxKeyBlockNumber = "block_num" + CtxKeyConn = "conn" + CtxKeyDuration = "duration" + CtxKeyError = "err" + CtxKeyUniqId = "uuid" + CtxKeyUserId = "user_id" +) + +// TODO: Allow registering arbitrary keys. +var registeredKeys = []string{ + CtxKeyApiMethod, + CtxKeyApiParams, + CtxKeyApiReqId, + CtxKeyBlockHash, + CtxKeyBlockNumber, + CtxKeyConn, + CtxKeyDuration, + CtxKeyError, + CtxKeyUniqId, + CtxKeyUserId, +} + +const FatalLevel = logrus.FatalLevel +const ErrorLevel = logrus.ErrorLevel +const InfoLevel = logrus.InfoLevel +const DebugLevel = logrus.DebugLevel +const TraceLevel = logrus.TraceLevel + +type Entry = logrus.Entry +type Level = logrus.Level + +func WithFieldsFromContext(ctx context.Context) *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{}) { + WithFieldsFromContext(ctx).Fatal(args...) +} + +func Errorx(ctx context.Context, args ...interface{}) { + WithFieldsFromContext(ctx).Error(args...) +} + +func Warnx(ctx context.Context, args ...interface{}) { + WithFieldsFromContext(ctx).Warn(args...) +} + +func Infox(ctx context.Context, args ...interface{}) { + WithFieldsFromContext(ctx).Info(args...) +} + +func Debugx(ctx context.Context, args ...interface{}) { + WithFieldsFromContext(ctx).Debug(args...) +} + +func Tracex(ctx context.Context, args ...interface{}) { + WithFieldsFromContext(ctx).Trace(args...) +} + +func Errorxf(ctx context.Context, format string, args ...interface{}) { + WithFieldsFromContext(ctx).Errorf(format, args...) +} + +func Warnxf(ctx context.Context, format string, args ...interface{}) { + WithFieldsFromContext(ctx).Warnf(format, args...) +} + +func Infoxf(ctx context.Context, format string, args ...interface{}) { + WithFieldsFromContext(ctx).Infof(format, args...) +} + +func Debugxf(ctx context.Context, format string, args ...interface{}) { + WithFieldsFromContext(ctx).Debugf(format, args...) +} + +func Tracexf(ctx context.Context, format string, args ...interface{}) { + WithFieldsFromContext(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 SetOutput(out io.Writer) { + logrus.SetOutput(out) +} + +func SetLevel(lvl Level) { + logrus.SetLevel(lvl) +} + +func IsLevelEnabled(lvl Level) bool { + return logrus.IsLevelEnabled(lvl) +} + +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 { + Infof("Directing output to %s", logFile) + SetOutput(file) + } else { + SetOutput(os.Stdout) + Info("Failed to logrus.to file, using default stdout") + } + } else { + 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 + } + SetLevel(lvl) + + formatter := &logrus.TextFormatter{ + FullTimestamp: true, + } + // 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) + 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..a6c3f194 100644 --- a/pkg/net/net_suite_test.go +++ b/pkg/net/net_suite_test.go @@ -20,9 +20,9 @@ import ( "io/ioutil" "testing" + "github.com/cerc-io/ipld-eth-server/v4/pkg/log" . "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..b90c1c87 100644 --- a/pkg/prom/middleware.go +++ b/pkg/prom/middleware.go @@ -17,25 +17,105 @@ 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" ) -// HTTPMiddleware http connection metric reader -func HTTPMiddleware(next http.Handler) http.Handler { - if !metrics { - return next +const ( + jsonMethod = "method" + jsonParams = "params" + 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 preprocessRequest(r *http.Request) (*http.Request, error) { + // Generate a unique ID for this request. + uniqId, err := uuid.NewUUID() + if nil != err { + return nil, err } - return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - httpCount.Inc() + // Read the body so that we can peek inside. + body, err := io.ReadAll(r.Body) + if nil != 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 { + return nil, err + } + + // Pull out the method name, request ID, user ID, and address info. + reqId := fmt.Sprintf("%g", result[jsonReqId]) + reqMethod := fmt.Sprintf("%v", result[jsonMethod]) + reqParams := fmt.Sprintf("%v", result[jsonParams]) + // Truncate parameters unless trace logging is enabled. + if !log.IsLevelEnabled(log.TraceLevel) { + if len(reqParams) > 250 { + reqParams = reqParams[:250] + "..." + } + } + 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.CtxKeyApiParams, string(reqParams)) + ctx = context.WithValue(ctx, log.CtxKeyApiReqId, 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 { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { start := time.Now() + r, err := preprocessRequest(r) + if nil != err { + log.WithError(err).Error("Error preprocessing request") + w.WriteHeader(http.StatusBadRequest) + return + } + ctx := r.Context() + apiMethod := fmt.Sprintf("%s", ctx.Value(log.CtxKeyApiMethod)) + + if metrics { + 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") + + if metrics { + 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..e6307814 100644 --- a/test/integration_suite_test.go +++ b/test/integration_suite_test.go @@ -4,9 +4,9 @@ import ( "io/ioutil" "testing" + "github.com/cerc-io/ipld-eth-server/v4/pkg/log" . "github.com/onsi/ginkgo" . "github.com/onsi/gomega" - "github.com/sirupsen/logrus" ) func TestIntegration(t *testing.T) { @@ -15,5 +15,5 @@ func TestIntegration(t *testing.T) { } var _ = BeforeSuite(func() { - logrus.SetOutput(ioutil.Discard) + log.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")