Add cache per query.

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
 
 

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")
+	switch dll := os.Getenv("LOG_LEVEL"); dll {
-	if dll == "debug" {
+	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{}) {
+func (l *LogConfig) Critical(message string, v ...map[string]interface{}) {
-	contextLog := l.Logger.WithLevel(level)
+	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...)
-}

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
+}

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 {

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",