From bd0c5ec3739d42c27c98c441e7390fe55ded0fa1 Mon Sep 17 00:00:00 2001 From: Lukasz Raczylo Date: Mon, 19 Dec 2022 11:22:58 +0000 Subject: [PATCH] Update logging package to bring a bit of a speed improvement. --- gql.go | 2 +- pkg/logging/logging.go | 61 +++--- pkg/logging/logging_test.go | 373 ------------------------------------ query_test.go | 18 ++ 4 files changed, 47 insertions(+), 407 deletions(-) delete mode 100644 pkg/logging/logging_test.go diff --git a/gql.go b/gql.go index 9235389..a54d781 100644 --- a/gql.go +++ b/gql.go @@ -20,7 +20,7 @@ import ( "strconv" "time" - "github.com/allegro/bigcache/v3" + bigcache "github.com/allegro/bigcache/v3" jsoniter "github.com/json-iterator/go" "github.com/lukaszraczylo/go-simple-graphql/pkg/logging" retry "github.com/sethvargo/go-retry" diff --git a/pkg/logging/logging.go b/pkg/logging/logging.go index 3dd3d40..0a14da3 100644 --- a/pkg/logging/logging.go +++ b/pkg/logging/logging.go @@ -6,7 +6,6 @@ import ( "os" "time" - "github.com/lukaszraczylo/pandati" "github.com/rs/zerolog" ) @@ -17,14 +16,14 @@ type LogConfig struct { func NewLogger() *LogConfig { log := new(LogConfig) - switch dll := os.Getenv("LOG_LEVEL"); dll { - case "debug": + dll := os.Getenv("LOG_LEVEL") + if dll == "debug" { zerolog.SetGlobalLevel(zerolog.DebugLevel) - case "warn": + } else if dll == "warn" { zerolog.SetGlobalLevel(zerolog.WarnLevel) - case "error": + } else if dll == "error" { zerolog.SetGlobalLevel(zerolog.ErrorLevel) - default: + } else { zerolog.SetGlobalLevel(zerolog.InfoLevel) } zerolog.TimeFieldFormat = time.RFC3339 @@ -37,36 +36,12 @@ func NewLogger() *LogConfig { return log } -func (l *LogConfig) Critical(message string, v ...map[string]interface{}) { - w := l.Logger.Output(os.Stderr) - log(w.Fatal(), message, v...) -} - -func (l *LogConfig) Error(message string, v ...map[string]interface{}) { - w := l.Logger.Output(os.Stderr) - log(w.Error(), message, v...) -} - -func (l *LogConfig) Warning(message string, v ...map[string]interface{}) { - w := l.Logger.Output(os.Stdout) - log(w.Warn(), message, v...) -} - -func (l *LogConfig) Info(message string, v ...map[string]interface{}) { - w := l.Logger.Output(os.Stdout) - log(w.Info(), message, v...) -} - -func (l *LogConfig) Debug(message string, v ...map[string]interface{}) { - w := l.Logger.Output(os.Stdout) - log(w.Debug(), message, v...) -} - -func log(contextLog *zerolog.Event, message string, v ...map[string]interface{}) { +func (l *LogConfig) Log(level zerolog.Level, message string, v ...map[string]interface{}) { + contextLog := l.Logger.WithLevel(level) if len(v) > 0 { for _, m := range v { for k, v := range m { - if !pandati.IsZero(v) && !pandati.IsZero(k) { + if v != nil && k != "" { contextLog.Str(k, fmt.Sprintf("%v", v)) } } @@ -75,3 +50,23 @@ func log(contextLog *zerolog.Event, message string, v ...map[string]interface{}) // contextLog.Str("_stack_trace", pandati.Trace()) contextLog.Msg(message) } + +func (l *LogConfig) Critical(message string, v ...map[string]interface{}) { + l.Log(zerolog.FatalLevel, message, v...) +} + +func (l *LogConfig) Error(message string, v ...map[string]interface{}) { + l.Log(zerolog.ErrorLevel, message, v...) +} + +func (l *LogConfig) Warning(message string, v ...map[string]interface{}) { + l.Log(zerolog.WarnLevel, message, v...) +} + +func (l *LogConfig) Info(message string, v ...map[string]interface{}) { + l.Log(zerolog.InfoLevel, message, v...) +} + +func (l *LogConfig) Debug(message string, v ...map[string]interface{}) { + l.Log(zerolog.DebugLevel, message, v...) +} diff --git a/pkg/logging/logging_test.go b/pkg/logging/logging_test.go deleted file mode 100644 index 159e118..0000000 --- a/pkg/logging/logging_test.go +++ /dev/null @@ -1,373 +0,0 @@ -package logging - -import ( - "errors" - "io/ioutil" - "os" - "reflect" - "testing" - - "github.com/buger/jsonparser" - "github.com/stretchr/testify/suite" -) - -type LoggingTestSuite struct { - suite.Suite -} - -var ( - testsLogger *LogConfig -) - -type stdoutCapture struct { - oldStdout *os.File - readPipe *os.File -} - -func (sc *stdoutCapture) StartCapture() { - sc.oldStdout = os.Stdout - sc.readPipe, os.Stdout, _ = os.Pipe() -} - -func (sc *stdoutCapture) StopCapture() (string, error) { - if sc.oldStdout == nil || sc.readPipe == nil { - return "", errors.New("StartCapture not called before StopCapture on Stdout") - } - os.Stdout.Close() - os.Stdout = sc.oldStdout - bytes, err := ioutil.ReadAll(sc.readPipe) - if err != nil { - return "", err - } - return string(bytes), nil -} - -type stderrCapture struct { - oldStderr *os.File - readPipe *os.File -} - -func (sc *stderrCapture) StartCapture() { - sc.oldStderr = os.Stderr - sc.readPipe, os.Stderr, _ = os.Pipe() -} - -func (sc *stderrCapture) StopCapture() (string, error) { - if sc.oldStderr == nil || sc.readPipe == nil { - return "", errors.New("StartCapture not called before StopCapture on Stderr") - } - os.Stderr.Close() - os.Stderr = sc.oldStderr - bytes, err := ioutil.ReadAll(sc.readPipe) - if err != nil { - return "", err - } - return string(bytes), nil -} - -func (suite *LoggingTestSuite) SetupTest() { -} - -func TestLoggingTestSuite(t *testing.T) { - suite.Run(t, new(LoggingTestSuite)) -} - -func (suite *LoggingTestSuite) TestLogConfig_AllHandlers() { - type args struct { - message string - } - tests := []struct { - name string - args args - wantLevel string - wantMessage string - envMinLogLevel string - stdOutExpect bool - stdErrExpect bool - loggerType string - }{ - { - name: "Test log: Error", - loggerType: "Error", - args: args{ - message: "This is a error message", - }, - wantLevel: "error", - wantMessage: "This is a error message", - stdErrExpect: true, - stdOutExpect: false, - }, - { - name: "Test log: Warning", - loggerType: "Warning", - args: args{ - message: "This is a warning message", - }, - wantLevel: "warn", - wantMessage: "This is a warning message", - stdErrExpect: false, - stdOutExpect: true, - envMinLogLevel: "info", - }, - { - name: "Test log: Warning | Min level: Debug", - loggerType: "Warning", - args: args{ - message: "This is a warning message", - }, - wantLevel: "warn", - wantMessage: "This is a warning message", - stdErrExpect: false, - stdOutExpect: true, - envMinLogLevel: "debug", - }, - { - name: "Test log: Info", - loggerType: "Info", - args: args{ - message: "This is a info message", - }, - wantLevel: "info", - wantMessage: "This is a info message", - stdErrExpect: false, - stdOutExpect: true, - }, - { - name: "Test log: Info | Min level: Warn", - loggerType: "Info", - args: args{ - message: "This is a info message", - }, - wantLevel: "", - wantMessage: "", - stdErrExpect: false, - stdOutExpect: false, - envMinLogLevel: "warn", - }, - { - name: "Test log: Warning | Min level: Warn", - loggerType: "Warning", - args: args{ - message: "This is a warning message", - }, - wantLevel: "warn", - wantMessage: "This is a warning message", - stdErrExpect: false, - stdOutExpect: true, - envMinLogLevel: "warn", - }, - { - name: "Test log: Warning | Min level: Error", - loggerType: "Warning", - args: args{ - message: "This is an error message", - }, - wantLevel: "", - wantMessage: "", - stdErrExpect: false, - stdOutExpect: false, - envMinLogLevel: "error", - }, - { - name: "Test log: Debug | Min level: Debug", - loggerType: "Debug", - args: args{ - message: "This is a debug message", - }, - wantLevel: "debug", - wantMessage: "This is a debug message", - stdErrExpect: false, - stdOutExpect: true, - envMinLogLevel: "debug", - }, - } - - for _, tt := range tests { - suite.T().Run(tt.name, func(t *testing.T) { - if tt.envMinLogLevel != "" { - os.Setenv("LOG_LEVEL", tt.envMinLogLevel) - defer os.Unsetenv("LOG_LEVEL") - } - testsLogger = NewLogger() - - captureStdout := stdoutCapture{} - captureStdout.StartCapture() - captureStderr := stderrCapture{} - captureStderr.StartCapture() - - reflect.ValueOf(testsLogger).MethodByName(tt.loggerType).Call([]reflect.Value{reflect.ValueOf(tt.args.message)}) - - stdoutOut, err := captureStdout.StopCapture() - if err != nil { - suite.T().Fatal(err) - } - - stderrOut, err := captureStderr.StopCapture() - if err != nil { - suite.T().Fatal(err) - } - - if tt.stdErrExpect && !tt.stdOutExpect { - gotLvl, gotMsg, err := getResponseValues(stderrOut, "short_message") - suite.NoError(err, "Failed in [STDERR]: "+tt.name) - suite.Equal(tt.wantLevel, gotLvl, "Failed in [STDERR]: "+tt.name) - suite.Equal(tt.wantMessage, gotMsg, "Failed in [STDERR]: "+tt.name) - suite.Equal("", stdoutOut, "Failed in [STDERR]: "+tt.name) - } - if tt.stdOutExpect && !tt.stdErrExpect { - gotLvl, gotMsg, err := getResponseValues(stdoutOut, "short_message") - suite.NoError(err, "Failed in [STDOUT]: "+tt.name) - suite.Equal(tt.wantLevel, gotLvl, "Failed in [STDOUT]: "+tt.name) - suite.Equal(tt.wantMessage, gotMsg, "Failed in [STDOUT]: "+tt.name) - suite.Equal("", stderrOut, "Failed in [STDOUT]: "+tt.name) - } - if !tt.stdErrExpect && !tt.stdOutExpect { - suite.Equal("", stderrOut, "Failed in [NEITHER]: "+tt.name) - suite.Equal("", stdoutOut, "Failed in [NEITHER]: "+tt.name) - } - os.Unsetenv("LOG_LEVEL") - }) - } -} - -func (suite *LoggingTestSuite) TestFullMessage() { - type args struct { - message string - extraFields map[string]interface{} - } - extraFields := make(map[string]interface{}) - extraFields["_full_message"] = "full message" - - tests := []struct { - name string - args args - wantLevel string - wantMessage string - envMinLogLevel string - stdOutExpect bool - stdErrExpect bool - loggerType string - }{ - { - name: "Test log: Error", - loggerType: "Error", - args: args{ - message: "This is a error message", - extraFields: extraFields, - }, - wantLevel: "error", - wantMessage: extraFields["_full_message"].(string), - stdErrExpect: true, - stdOutExpect: false, - }, - { - name: "Test log: Info", - loggerType: "Info", - args: args{ - message: "This is a info message", - extraFields: extraFields, - }, - wantMessage: extraFields["_full_message"].(string), - stdErrExpect: false, - stdOutExpect: true, - }, - } - - for _, tt := range tests { - suite.T().Run(tt.name, func(t *testing.T) { - if tt.envMinLogLevel != "" { - os.Setenv("LOG_LEVEL", tt.envMinLogLevel) - defer os.Unsetenv("LOG_LEVEL") - } - testsLogger = NewLogger() - - captureStdout := stdoutCapture{} - captureStdout.StartCapture() - captureStderr := stderrCapture{} - captureStderr.StartCapture() - - reflect.ValueOf(testsLogger).MethodByName(tt.loggerType).Call([]reflect.Value{ - reflect.ValueOf(tt.args.message), - reflect.ValueOf(tt.args.extraFields), - }) - - stdoutOut, err := captureStdout.StopCapture() - if err != nil { - suite.T().Fatal(err) - } - - stderrOut, err := captureStderr.StopCapture() - if err != nil { - suite.T().Fatal(err) - } - - if tt.stdErrExpect && !tt.stdOutExpect { - _, gotMsg, err := getResponseValues(stderrOut, "_full_message") - suite.NoError(err, "Failed in [STDERR]: "+tt.name) - suite.Equal(tt.wantMessage, gotMsg, "Failed in [STDERR]: "+tt.name) - } - if tt.stdOutExpect && !tt.stdErrExpect { - _, gotMsg, err := getResponseValues(stdoutOut, "_full_message") - suite.NoError(err, "Failed in [STDOUT]: "+tt.name) - suite.Equal(tt.wantMessage, gotMsg, "Failed in [STDOUT]: "+tt.name) - } - os.Unsetenv("LOG_LEVEL") - }) - } -} - -func Test_getResponseValues(t *testing.T) { - type args struct { - sourceJson string - } - tests := []struct { - name string - args args - wantGotLvl string - wantGotMsg string - wantErr bool - }{ - { - name: "Test with json", - args: args{ - sourceJson: `{"level": "debug", "short_message": "hello world"`, - }, - wantGotLvl: "debug", - wantGotMsg: "hello world", - wantErr: false, - }, - { - name: "Test with json, wrong message field", - args: args{ - sourceJson: `{"level": "debug", "message": "hello world"`, - }, - wantGotLvl: "debug", - wantGotMsg: "", - wantErr: true, - }, - } - for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - gotGotLvl, gotGotMsg, err := getResponseValues(tt.args.sourceJson, "short_message") - if (err != nil) != tt.wantErr { - t.Errorf("getResponseValues() error = %v, wantErr %v", err, tt.wantErr) - return - } - if gotGotLvl != tt.wantGotLvl { - t.Errorf("getResponseValues() gotGotLvl = %v, want %v", gotGotLvl, tt.wantGotLvl) - } - if gotGotMsg != tt.wantGotMsg { - t.Errorf("getResponseValues() gotGotMsg = %v, want %v", gotGotMsg, tt.wantGotMsg) - } - }) - } -} - -func getResponseValues(sourceJson string, key string) (gotLvl, gotMsg string, err error) { - gotLvl, err = jsonparser.GetString([]byte(sourceJson), "level") - if err != nil { - return - } - gotMsg, err = jsonparser.GetString([]byte(sourceJson), key) - return -} diff --git a/query_test.go b/query_test.go index 97a8aaf..e7775b4 100644 --- a/query_test.go +++ b/query_test.go @@ -89,6 +89,24 @@ func (suite *TestSuite) Test_GraphQL_Query() { wantResult: `{"sub_group_packages_aggregate":{"aggregate":{"count":4}}}`, wantErr: false, }, + { + name: "Valid query, no cache #2", + endpoint: "https://telegram-bot.app/v1/graphql", + isLocal: true, + cache_enabled: false, + args: args{ + queryContent: `query packages_prices { + sub_group_packages_aggregate(where: {enabled: {_eq: true}}) { + aggregate { + count + } + } + }`, + queryVariables: nil, + }, + wantResult: `{"sub_group_packages_aggregate":{"aggregate":{"count":4}}}`, + wantErr: false, + }, { name: "Valid query, with cache empty", endpoint: "https://telegram-bot.app/v1/graphql",