From 966c9e8fbf19bb5f5f0c86c72bee7632357b2a54 Mon Sep 17 00:00:00 2001 From: Thomas E Lackey Date: Fri, 20 Jan 2023 12:31:47 -0600 Subject: [PATCH 01/11] 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") -- 2.45.2 From 2cfc53bc4f2d0b9d905792c4f1fd80aa566c68e9 Mon Sep 17 00:00:00 2001 From: Thomas E Lackey Date: Fri, 20 Jan 2023 12:35:22 -0600 Subject: [PATCH 02/11] Remove unused method. --- cmd/root.go | 4 ---- 1 file changed, 4 deletions(-) diff --git a/cmd/root.go b/cmd/root.go index 221ff4f0..4ee233f7 100644 --- a/cmd/root.go +++ b/cmd/root.go @@ -65,10 +65,6 @@ func initFuncs(cmd *cobra.Command, args []string) { } } -func logLevel() error { - return log.Init() -} - func init() { cobra.OnInitialize(initConfig) viper.SetEnvKeyReplacer(strings.NewReplacer(".", "_")) -- 2.45.2 From 2155a2e176f3bd4a3fd1a153d13ff49729f606fd Mon Sep 17 00:00:00 2001 From: Thomas E Lackey Date: Fri, 20 Jan 2023 12:41:51 -0600 Subject: [PATCH 03/11] Refactor --- pkg/log/log.go | 26 +++++++++++++------------- 1 file changed, 13 insertions(+), 13 deletions(-) diff --git a/pkg/log/log.go b/pkg/log/log.go index 12a65c65..aeec5421 100644 --- a/pkg/log/log.go +++ b/pkg/log/log.go @@ -42,8 +42,8 @@ const TraceLevel = logrus.TraceLevel type Entry = logrus.Entry -func GetLog(ctx context.Context) *logrus.Entry { - entry := logrus.WithContext(ctx) +func FieldsFromContext(ctx context.Context) *logrus.Entry { + entry := logrus.FieldsFromContext(ctx) for _, key := range registeredKeys { if value := ctx.Value(key); value != nil { @@ -54,45 +54,45 @@ func GetLog(ctx context.Context) *logrus.Entry { } func Fatalx(ctx context.Context, args ...interface{}) { - GetLog(ctx).Fatal(args...) + FieldsFromContext(ctx).Fatal(args...) } func Errorx(ctx context.Context, args ...interface{}) { - GetLog(ctx).Error(args...) + FieldsFromContext(ctx).Error(args...) } func Warnx(ctx context.Context, args ...interface{}) { - GetLog(ctx).Warn(args...) + FieldsFromContext(ctx).Warn(args...) } func Infox(ctx context.Context, args ...interface{}) { - GetLog(ctx).Info(args...) + FieldsFromContext(ctx).Info(args...) } func Debugx(ctx context.Context, args ...interface{}) { - GetLog(ctx).Debug(args...) + FieldsFromContext(ctx).Debug(args...) } func Tracex(ctx context.Context, args ...interface{}) { - GetLog(ctx).Trace(args...) + FieldsFromContext(ctx).Trace(args...) } func Errorxf(ctx context.Context, format string, args ...interface{}) { - GetLog(ctx).Errorf(format, args...) + FieldsFromContext(ctx).Errorf(format, args...) } func Warnxf(ctx context.Context, format string, args ...interface{}) { - GetLog(ctx).Warnf(format, args...) + FieldsFromContext(ctx).Warnf(format, args...) } func Infoxf(ctx context.Context, format string, args ...interface{}) { - GetLog(ctx).Infof(format, args...) + FieldsFromContext(ctx).Infof(format, args...) } func Debugxf(ctx context.Context, format string, args ...interface{}) { - GetLog(ctx).Debugf(format, args...) + FieldsFromContext(ctx).Debugf(format, args...) } func Tracexf(ctx context.Context, format string, args ...interface{}) { - GetLog(ctx).Tracef(format, args...) + FieldsFromContext(ctx).Tracef(format, args...) } func Fatal(args ...interface{}) { -- 2.45.2 From 0324ce86029cdbadd1d85e62c3b10926aa97e1d8 Mon Sep 17 00:00:00 2001 From: Thomas E Lackey Date: Fri, 20 Jan 2023 12:42:16 -0600 Subject: [PATCH 04/11] Refactor --- pkg/log/log.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pkg/log/log.go b/pkg/log/log.go index aeec5421..70b6cd4f 100644 --- a/pkg/log/log.go +++ b/pkg/log/log.go @@ -43,7 +43,7 @@ const TraceLevel = logrus.TraceLevel type Entry = logrus.Entry func FieldsFromContext(ctx context.Context) *logrus.Entry { - entry := logrus.FieldsFromContext(ctx) + entry := logrus.WithContext(ctx) for _, key := range registeredKeys { if value := ctx.Value(key); value != nil { -- 2.45.2 From 903b855508e340e424b955e13ee6791c2fff9f70 Mon Sep 17 00:00:00 2001 From: Thomas E Lackey Date: Fri, 20 Jan 2023 12:43:43 -0600 Subject: [PATCH 05/11] Refactor --- pkg/log/log.go | 24 ++++++++++++------------ 1 file changed, 12 insertions(+), 12 deletions(-) diff --git a/pkg/log/log.go b/pkg/log/log.go index 70b6cd4f..d9ff4d8b 100644 --- a/pkg/log/log.go +++ b/pkg/log/log.go @@ -42,7 +42,7 @@ const TraceLevel = logrus.TraceLevel type Entry = logrus.Entry -func FieldsFromContext(ctx context.Context) *logrus.Entry { +func WithFieldsFromContext(ctx context.Context) *logrus.Entry { entry := logrus.WithContext(ctx) for _, key := range registeredKeys { @@ -54,45 +54,45 @@ func FieldsFromContext(ctx context.Context) *logrus.Entry { } func Fatalx(ctx context.Context, args ...interface{}) { - FieldsFromContext(ctx).Fatal(args...) + WithFieldsFromContext(ctx).Fatal(args...) } func Errorx(ctx context.Context, args ...interface{}) { - FieldsFromContext(ctx).Error(args...) + WithFieldsFromContext(ctx).Error(args...) } func Warnx(ctx context.Context, args ...interface{}) { - FieldsFromContext(ctx).Warn(args...) + WithFieldsFromContext(ctx).Warn(args...) } func Infox(ctx context.Context, args ...interface{}) { - FieldsFromContext(ctx).Info(args...) + WithFieldsFromContext(ctx).Info(args...) } func Debugx(ctx context.Context, args ...interface{}) { - FieldsFromContext(ctx).Debug(args...) + WithFieldsFromContext(ctx).Debug(args...) } func Tracex(ctx context.Context, args ...interface{}) { - FieldsFromContext(ctx).Trace(args...) + WithFieldsFromContext(ctx).Trace(args...) } func Errorxf(ctx context.Context, format string, args ...interface{}) { - FieldsFromContext(ctx).Errorf(format, args...) + WithFieldsFromContext(ctx).Errorf(format, args...) } func Warnxf(ctx context.Context, format string, args ...interface{}) { - FieldsFromContext(ctx).Warnf(format, args...) + WithFieldsFromContext(ctx).Warnf(format, args...) } func Infoxf(ctx context.Context, format string, args ...interface{}) { - FieldsFromContext(ctx).Infof(format, args...) + WithFieldsFromContext(ctx).Infof(format, args...) } func Debugxf(ctx context.Context, format string, args ...interface{}) { - FieldsFromContext(ctx).Debugf(format, args...) + WithFieldsFromContext(ctx).Debugf(format, args...) } func Tracexf(ctx context.Context, format string, args ...interface{}) { - FieldsFromContext(ctx).Tracef(format, args...) + WithFieldsFromContext(ctx).Tracef(format, args...) } func Fatal(args ...interface{}) { -- 2.45.2 From c2a5b012cfd4c55fe8aaf3de2229de67fb28c316 Mon Sep 17 00:00:00 2001 From: Thomas E Lackey Date: Fri, 20 Jan 2023 13:21:43 -0600 Subject: [PATCH 06/11] More log refactoring --- main.go | 4 --- pkg/eth/eth_suite_test.go | 3 ++ pkg/graphql/graphql_suite_test.go | 3 ++ pkg/log/log.go | 48 +++++++++++++++++++++---------- pkg/net/net_suite_test.go | 2 +- pkg/prom/middleware.go | 13 +++++++-- test/integration_suite_test.go | 2 ++ 7 files changed, 53 insertions(+), 22 deletions(-) diff --git a/main.go b/main.go index 787cd8e1..58070814 100644 --- a/main.go +++ b/main.go @@ -17,12 +17,8 @@ package main import ( "github.com/cerc-io/ipld-eth-server/v4/cmd" - "github.com/sirupsen/logrus" ) func main() { - logrus.SetFormatter(&logrus.TextFormatter{ - FullTimestamp: true, - }) cmd.Execute() } diff --git a/pkg/eth/eth_suite_test.go b/pkg/eth/eth_suite_test.go index 98bcaac3..5a5782c7 100644 --- a/pkg/eth/eth_suite_test.go +++ b/pkg/eth/eth_suite_test.go @@ -17,8 +17,10 @@ package eth_test import ( + "io/ioutil" "testing" + "github.com/cerc-io/ipld-eth-server/v4/pkg/log" . "github.com/onsi/ginkgo" . "github.com/onsi/gomega" ) @@ -29,4 +31,5 @@ func TestETHSuite(t *testing.T) { } var _ = BeforeSuite(func() { + log.SetOutput(ioutil.Discard) }) diff --git a/pkg/graphql/graphql_suite_test.go b/pkg/graphql/graphql_suite_test.go index b6dc5df3..e3e07262 100644 --- a/pkg/graphql/graphql_suite_test.go +++ b/pkg/graphql/graphql_suite_test.go @@ -17,8 +17,10 @@ package graphql_test import ( + "io/ioutil" "testing" + "github.com/cerc-io/ipld-eth-server/v4/pkg/log" . "github.com/onsi/ginkgo" . "github.com/onsi/gomega" ) @@ -29,4 +31,5 @@ func TestGraphQL(t *testing.T) { } var _ = BeforeSuite(func() { + log.SetOutput(ioutil.Discard) }) diff --git a/pkg/log/log.go b/pkg/log/log.go index d9ff4d8b..90d60be5 100644 --- a/pkg/log/log.go +++ b/pkg/log/log.go @@ -3,6 +3,7 @@ package log import ( "context" "fmt" + "io" "os" "runtime" "strings" @@ -13,8 +14,9 @@ import ( const ( CtxKeyUniqId = "id" - CtxKeyApiMethod = "method" - CtxKeyReqId = "reqid" + CtxKeyApiMethod = "api_method" + CtxKeyApiParams = "api_params" + CtxKeyApiReqId = "api_reqid" CtxKeyUserId = "user_id" CtxKeyConn = "conn" CtxKeyDuration = "duration" @@ -25,13 +27,14 @@ const ( // TODO: Allow registering arbitrary keys. var registeredKeys = []string{ CtxKeyApiMethod, - CtxKeyReqId, - CtxKeyUserId, + CtxKeyApiParams, + CtxKeyApiReqId, + CtxKeyBlockHash, + CtxKeyBlockNumber, CtxKeyConn, CtxKeyDuration, CtxKeyUniqId, - CtxKeyBlockNumber, - CtxKeyBlockHash, + CtxKeyUserId, } const FatalLevel = logrus.FatalLevel @@ -41,8 +44,9 @@ const DebugLevel = logrus.DebugLevel const TraceLevel = logrus.TraceLevel type Entry = logrus.Entry +type Level = logrus.Level -func WithFieldsFromContext(ctx context.Context) *logrus.Entry { +func WithFieldsFromContext(ctx context.Context) *Entry { entry := logrus.WithContext(ctx) for _, key := range registeredKeys { @@ -138,6 +142,18 @@ 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) } @@ -154,14 +170,14 @@ func Init() error { 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) + Infof("Directing output to %s", logFile) + SetOutput(file) } else { - logrus.SetOutput(os.Stdout) - logrus.Info("Failed to logrus.to file, using default stdout") + SetOutput(os.Stdout) + Info("Failed to logrus.to file, using default stdout") } } else { - logrus.SetOutput(os.Stdout) + SetOutput(os.Stdout) } // Set the level. @@ -170,9 +186,11 @@ func Init() error { if err != nil { return err } - logrus.SetLevel(lvl) + SetLevel(lvl) - formatter := &logrus.TextFormatter{} + formatter := &logrus.TextFormatter{ + FullTimestamp: true, + } // Show file/line number only at Trace level. if lvl >= TraceLevel { logrus.SetReportCaller(true) @@ -199,6 +217,6 @@ func Init() error { } logrus.SetFormatter(formatter) - logrus.Info("Log level set to ", lvl.String()) + 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 f3dfc32d..a6c3f194 100644 --- a/pkg/net/net_suite_test.go +++ b/pkg/net/net_suite_test.go @@ -18,9 +18,9 @@ package net_test import ( "io/ioutil" - "log" "testing" + "github.com/cerc-io/ipld-eth-server/v4/pkg/log" . "github.com/onsi/ginkgo" . "github.com/onsi/gomega" ) diff --git a/pkg/prom/middleware.go b/pkg/prom/middleware.go index 9137e313..bbefb2d9 100644 --- a/pkg/prom/middleware.go +++ b/pkg/prom/middleware.go @@ -33,6 +33,7 @@ import ( const ( jsonMethod = "method" + jsonParams = "params" jsonReqId = "id" headerUserId = "X-User-Id" headerOriginalRemoteAddr = "X-Original-Remote-Addr" @@ -66,8 +67,15 @@ func prepareRequest(r *http.Request) (*http.Request, error) { } // Pull out the method name, request ID, user ID, and address info. - reqMethod := fmt.Sprintf("%v", result[jsonMethod]) reqId := fmt.Sprintf("%g", result[jsonReqId]) + reqMethod := fmt.Sprintf("%v", result[jsonMethod]) + reqParams, _ := json.Marshal(result[jsonParams]) + // Truncate parameters unless trace logging is enabled. + if !log.IsLevelEnabled(log.TraceLevel) { + if len(reqParams) > 100 { + reqParams = reqParams[:100] + } + } userId := r.Header.Get(headerUserId) conn := r.Header.Get(headerOriginalRemoteAddr) if len(conn) == 0 { @@ -78,7 +86,8 @@ func prepareRequest(r *http.Request) (*http.Request, error) { 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.CtxKeyApiMethod, reqParams) + ctx = context.WithValue(ctx, log.CtxKeyApiReqId, reqId) ctx = context.WithValue(ctx, log.CtxKeyUserId, userId) ctx = context.WithValue(ctx, log.CtxKeyConn, conn) diff --git a/test/integration_suite_test.go b/test/integration_suite_test.go index 9856687f..f8c7c979 100644 --- a/test/integration_suite_test.go +++ b/test/integration_suite_test.go @@ -6,6 +6,7 @@ import ( . "github.com/onsi/ginkgo" . "github.com/onsi/gomega" + "github.com/sirupsen/logrus" ) func TestIntegration(t *testing.T) { @@ -14,4 +15,5 @@ func TestIntegration(t *testing.T) { } var _ = BeforeSuite(func() { + logrus.SetOutput(ioutil.Discard) }) -- 2.45.2 From bb39cac1eb208f937a4df13ef92c99d4183283e3 Mon Sep 17 00:00:00 2001 From: Thomas E Lackey Date: Fri, 20 Jan 2023 14:27:12 -0600 Subject: [PATCH 07/11] Params --- pkg/eth/api.go | 4 ---- pkg/log/log.go | 10 ++++++---- pkg/prom/middleware.go | 8 ++++---- test/integration_suite_test.go | 4 ++-- 4 files changed, 12 insertions(+), 14 deletions(-) diff --git a/pkg/eth/api.go b/pkg/eth/api.go index 6df2fe29..9cdd3e20 100644 --- a/pkg/eth/api.go +++ b/pkg/eth/api.go @@ -170,8 +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) { - 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) @@ -190,8 +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) { - 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) diff --git a/pkg/log/log.go b/pkg/log/log.go index 90d60be5..47e6136f 100644 --- a/pkg/log/log.go +++ b/pkg/log/log.go @@ -13,15 +13,16 @@ import ( ) const ( - CtxKeyUniqId = "id" CtxKeyApiMethod = "api_method" CtxKeyApiParams = "api_params" CtxKeyApiReqId = "api_reqid" - CtxKeyUserId = "user_id" + CtxKeyBlockHash = "block_hash" + CtxKeyBlockNumber = "block_num" CtxKeyConn = "conn" CtxKeyDuration = "duration" - CtxKeyBlockNumber = "block_num" - CtxKeyBlockHash = "block_hash" + CtxKeyError = "err" + CtxKeyUniqId = "uuid" + CtxKeyUserId = "user_id" ) // TODO: Allow registering arbitrary keys. @@ -33,6 +34,7 @@ var registeredKeys = []string{ CtxKeyBlockNumber, CtxKeyConn, CtxKeyDuration, + CtxKeyError, CtxKeyUniqId, CtxKeyUserId, } diff --git a/pkg/prom/middleware.go b/pkg/prom/middleware.go index bbefb2d9..0fcdb430 100644 --- a/pkg/prom/middleware.go +++ b/pkg/prom/middleware.go @@ -69,11 +69,11 @@ func prepareRequest(r *http.Request) (*http.Request, error) { // 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, _ := json.Marshal(result[jsonParams]) + reqParams := fmt.Sprintf("%v", result[jsonParams]) // Truncate parameters unless trace logging is enabled. if !log.IsLevelEnabled(log.TraceLevel) { - if len(reqParams) > 100 { - reqParams = reqParams[:100] + if len(reqParams) > 250 { + reqParams = reqParams[:250] + "..." } } userId := r.Header.Get(headerUserId) @@ -86,7 +86,7 @@ func prepareRequest(r *http.Request) (*http.Request, error) { ctx := r.Context() ctx = context.WithValue(ctx, log.CtxKeyUniqId, uniqId.String()) ctx = context.WithValue(ctx, log.CtxKeyApiMethod, reqMethod) - ctx = context.WithValue(ctx, log.CtxKeyApiMethod, reqParams) + 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) 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) }) -- 2.45.2 From 04639982a779b2573602166ce6a970d710594f5f Mon Sep 17 00:00:00 2001 From: Thomas E Lackey Date: Fri, 20 Jan 2023 14:34:12 -0600 Subject: [PATCH 08/11] Copyright --- pkg/log/log.go | 15 +++++++++++++++ 1 file changed, 15 insertions(+) diff --git a/pkg/log/log.go b/pkg/log/log.go index 47e6136f..152b07ae 100644 --- a/pkg/log/log.go +++ b/pkg/log/log.go @@ -1,3 +1,18 @@ +// 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 ( -- 2.45.2 From eff0d2c4aead4718b927024ed974fa14dee79bac Mon Sep 17 00:00:00 2001 From: Thomas E Lackey Date: Fri, 20 Jan 2023 14:36:59 -0600 Subject: [PATCH 09/11] fmt --- pkg/log/log.go | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/pkg/log/log.go b/pkg/log/log.go index 152b07ae..5fe91c9d 100644 --- a/pkg/log/log.go +++ b/pkg/log/log.go @@ -109,9 +109,11 @@ func Warnxf(ctx context.Context, format string, args ...interface{}) { 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...) } @@ -119,6 +121,7 @@ func Tracexf(ctx context.Context, format string, args ...interface{}) { func Fatal(args ...interface{}) { logrus.Fatal(args...) } + func Error(args ...interface{}) { logrus.Error(args...) } @@ -138,9 +141,11 @@ func Debug(args ...interface{}) { 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...) } @@ -152,9 +157,11 @@ func Warnf(format string, args ...interface{}) { 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...) } -- 2.45.2 From 1986fee75191649682dc7e30ec35605f498efc97 Mon Sep 17 00:00:00 2001 From: Thomas E Lackey Date: Fri, 20 Jan 2023 17:31:51 -0600 Subject: [PATCH 10/11] Always enable the logging. --- pkg/prom/middleware.go | 17 +++++++++-------- 1 file changed, 9 insertions(+), 8 deletions(-) diff --git a/pkg/prom/middleware.go b/pkg/prom/middleware.go index 0fcdb430..65bec802 100644 --- a/pkg/prom/middleware.go +++ b/pkg/prom/middleware.go @@ -96,10 +96,6 @@ func prepareRequest(r *http.Request) (*http.Request, error) { // HTTPMiddleware http connection metric reader func HTTPMiddleware(next http.Handler) http.Handler { - if !metrics { - return next - } - return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { start := time.Now() r, err := prepareRequest(r) @@ -109,14 +105,19 @@ func HTTPMiddleware(next http.Handler) http.Handler { } ctx := r.Context() apiMethod := fmt.Sprintf("%s", ctx.Value(log.CtxKeyApiMethod)) - httpCount.WithLabelValues(apiMethod).Inc() + + if metrics { + httpCount.WithLabelValues(apiMethod).Inc() + } + log.Debugx(ctx, "START") - next.ServeHTTP(w, r) - duration := time.Now().Sub(start) log.Debugxf(context.WithValue(ctx, log.CtxKeyDuration, duration.Milliseconds()), "END") - httpDuration.WithLabelValues(apiMethod).Observe(duration.Seconds()) + + if metrics { + httpDuration.WithLabelValues(apiMethod).Observe(duration.Seconds()) + } }) } -- 2.45.2 From da926007067e84a5dbdf1717cce04cc5ba87fbcc Mon Sep 17 00:00:00 2001 From: Thomas E Lackey Date: Fri, 20 Jan 2023 17:42:09 -0600 Subject: [PATCH 11/11] Simplify error logging --- pkg/prom/middleware.go | 10 ++++------ 1 file changed, 4 insertions(+), 6 deletions(-) diff --git a/pkg/prom/middleware.go b/pkg/prom/middleware.go index 65bec802..b90c1c87 100644 --- a/pkg/prom/middleware.go +++ b/pkg/prom/middleware.go @@ -40,18 +40,16 @@ const ( ) // Peek at the request and update the Context accordingly (eg, API method, user ID, etc.) -func prepareRequest(r *http.Request) (*http.Request, error) { +func preprocessRequest(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 } @@ -62,7 +60,6 @@ func prepareRequest(r *http.Request) (*http.Request, error) { var result map[string]interface{} err = json.Unmarshal(body, &result) if nil != err { - log.Error("Error parsing request body: ", err) return nil, err } @@ -98,9 +95,10 @@ func prepareRequest(r *http.Request) (*http.Request, error) { func HTTPMiddleware(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { start := time.Now() - r, err := prepareRequest(r) + r, err := preprocessRequest(r) if nil != err { - w.WriteHeader(400) + log.WithError(err).Error("Error preprocessing request") + w.WriteHeader(http.StatusBadRequest) return } ctx := r.Context() -- 2.45.2