From 32091fc8cd3827bb5e188131f331d72a8547d5ab Mon Sep 17 00:00:00 2001 From: Lukasz Raczylo Date: Tue, 20 Dec 2022 10:26:05 +0000 Subject: [PATCH] Add cache per query. --- README.md | 17 ++ pkg/logging/logging.go | 61 +++--- pkg/logging/logging_test.go | 373 ++++++++++++++++++++++++++++++++++++ query.go | 6 + query_test.go | 63 ++++++ 5 files changed, 492 insertions(+), 28 deletions(-) create mode 100644 pkg/logging/logging_test.go diff --git a/README.md b/README.md index 1897f1d..e83ef27 100644 --- a/README.md +++ b/README.md @@ -9,6 +9,7 @@ Ps. It's Hasura friendly. - [Features](#features) - [Usage example](#usage-example) - [Environment variables](#environment-variables) + - [Cache](#cache) - [Example reader code](#example-reader-code) - [Working with results](#working-with-results) @@ -37,6 +38,22 @@ Therefore, I present you the simple client to which you can copy & paste your gr * `RETRIES_NUMBER` - Number of retries: Default: `1` * `RETRIES_DELAY` - Delay in retries in milliseconds. Default: `250` +### Cache + +You have two options to enable the cache: + +* Use `GRAPHQL_CACHE` environment variable which will enable the cache globally. It may be desired if you want to use the cache for all queries. +* Add `gqlcache: true` header for your query which will enable the cache for this query only with `GRAPHQL_CACHE_TTL` TTL. + +Example: + +```go +headers := map[string]interface{}{ + ... + "gqlcache": true, +} +``` + ### Example reader code diff --git a/pkg/logging/logging.go b/pkg/logging/logging.go index 0a14da3..3dd3d40 100644 --- a/pkg/logging/logging.go +++ b/pkg/logging/logging.go @@ -6,6 +6,7 @@ import ( "os" "time" + "github.com/lukaszraczylo/pandati" "github.com/rs/zerolog" ) @@ -16,14 +17,14 @@ type LogConfig struct { func NewLogger() *LogConfig { log := new(LogConfig) - dll := os.Getenv("LOG_LEVEL") - if dll == "debug" { + switch dll := os.Getenv("LOG_LEVEL"); dll { + case "debug": zerolog.SetGlobalLevel(zerolog.DebugLevel) - } else if dll == "warn" { + case "warn": zerolog.SetGlobalLevel(zerolog.WarnLevel) - } else if dll == "error" { + case "error": zerolog.SetGlobalLevel(zerolog.ErrorLevel) - } else { + default: zerolog.SetGlobalLevel(zerolog.InfoLevel) } zerolog.TimeFieldFormat = time.RFC3339 @@ -36,12 +37,36 @@ func NewLogger() *LogConfig { return log } -func (l *LogConfig) Log(level zerolog.Level, message string, v ...map[string]interface{}) { - contextLog := l.Logger.WithLevel(level) +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{}) { if len(v) > 0 { for _, m := range v { for k, v := range m { - if v != nil && k != "" { + if !pandati.IsZero(v) && !pandati.IsZero(k) { contextLog.Str(k, fmt.Sprintf("%v", v)) } } @@ -50,23 +75,3 @@ func (l *LogConfig) Log(level zerolog.Level, message string, v ...map[string]int // 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 new file mode 100644 index 0000000..159e118 --- /dev/null +++ b/pkg/logging/logging_test.go @@ -0,0 +1,373 @@ +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.go b/query.go index 7f1deaf..60c0750 100644 --- a/query.go +++ b/query.go @@ -50,6 +50,12 @@ func (g *GraphQL) Query(queryContent string, queryVariables interface{}, queryHe var queryResult *queryResults queryHash := fmt.Sprintf("%x", md5.Sum(query)) + // If header 'gqlcache' is set to true, we will enforce the cache for the query + if !pandati.IsZero(queryHeaders) && !pandati.IsZero(queryHeaders["gqlcache"]) && queryHeaders["gqlcache"].(bool) { + g.Log.Debug("Forced cache for query", map[string]interface{}{"_query": queryContent, "_headers": queryHeaders}) + g.Cache = true + } + if g.Cache { g.Log.Debug("Checking the cache for the query", map[string]interface{}{"_query": queryHash}) if entry, entryInfo, err := g.CacheStore.GetWithInfo(queryHash); err == nil { diff --git a/query_test.go b/query_test.go index e7775b4..24144dc 100644 --- a/query_test.go +++ b/query_test.go @@ -125,6 +125,69 @@ func (suite *TestSuite) Test_GraphQL_Query() { wantResult: `{"sub_group_packages_aggregate":{"aggregate":{"count":4}}}`, wantErr: false, }, + { + name: "Valid query, with cache per query empty", + endpoint: "https://telegram-bot.app/v1/graphql", + isLocal: true, + cache_enabled: false, + args: args{ + queryContent: `query packages_prices_no_inlinecache { + sub_group_packages_aggregate(where: {enabled: {_eq: true}}) { + aggregate { + count + } + } + }`, + queryVariables: nil, + queryHeaders: map[string]interface{}{ + "gqlcache": false, + }, + }, + wantResult: `{"sub_group_packages_aggregate":{"aggregate":{"count":4}}}`, + wantErr: false, + }, + { + name: "Valid query, with cache per query", + endpoint: "https://telegram-bot.app/v1/graphql", + isLocal: true, + cache_enabled: false, + args: args{ + queryContent: `query packages_prices_inlinecache { + sub_group_packages_aggregate(where: {enabled: {_eq: true}}) { + aggregate { + count + } + } + }`, + queryVariables: nil, + queryHeaders: map[string]interface{}{ + "gqlcache": true, + }, + }, + wantResult: `{"sub_group_packages_aggregate":{"aggregate":{"count":4}}}`, + wantErr: false, + }, + { + name: "Valid query, with cache per query [verify]", + endpoint: "https://telegram-bot.app/v1/graphql", + isLocal: true, + cache_enabled: false, + args: args{ + queryContent: `query packages_prices_inlinecache { + sub_group_packages_aggregate(where: {enabled: {_eq: true}}) { + aggregate { + count + } + } + }`, + queryVariables: nil, + queryHeaders: map[string]interface{}{ + "gqlcache": true, + }, + }, + wantResult: `{"sub_group_packages_aggregate":{"aggregate":{"count":4}}}`, + wantErr: false, + }, { name: "Valid query, with cache filled", endpoint: "https://telegram-bot.app/v1/graphql",