From 569867d04be1aa7ced697b1e858e1c5c2643bcdf Mon Sep 17 00:00:00 2001 From: Lukasz Raczylo Date: Tue, 14 May 2024 09:34:59 +0100 Subject: [PATCH] Update logging and cache packaces. --- cache/cache.go | 101 ++++----- cache/cache_bench_test.go | 46 +++++ cache/cache_test.go | 36 ---- go.mod | 5 +- go.sum | 10 +- http.go | 6 +- logging/logging.go | 94 +++++---- logging/logging_bench_test.go | 1 + logging/logging_test.go | 373 ---------------------------------- query.go | 4 +- 10 files changed, 170 insertions(+), 506 deletions(-) create mode 100644 cache/cache_bench_test.go delete mode 100644 logging/logging_test.go diff --git a/cache/cache.go b/cache/cache.go index e5d50cf..955146d 100644 --- a/cache/cache.go +++ b/cache/cache.go @@ -3,7 +3,6 @@ package libpack_cache import ( "bytes" "compress/gzip" - "flag" "io" "sync" "time" @@ -15,26 +14,32 @@ type CacheEntry struct { } type Cache struct { - bytePool sync.Pool - entries sync.Map - globalTTL time.Duration - sync.RWMutex + entries sync.Map + globalTTL time.Duration + compressPool sync.Pool + decompressPool sync.Pool + sync.RWMutex // Reintroduced to provide lock methods } func New(globalTTL time.Duration) *Cache { cache := &Cache{ globalTTL: globalTTL, + compressPool: sync.Pool{ + New: func() interface{} { + w := gzip.NewWriter(nil) + return w + }, + }, + decompressPool: sync.Pool{ + New: func() interface{} { + // Ensure that new is returning a new reader initialized with an empty byte buffer + r, _ := gzip.NewReader(bytes.NewReader([]byte{})) + return r + }, + }, } - // Initialize the byte pool. - cache.bytePool.New = func() interface{} { - return make([]byte, 0) - } - - // Start the cache cleanup. - if flag.Lookup("test.v") == nil { - go cache.cleanupRoutine(globalTTL) - } + go cache.cleanupRoutine(globalTTL) return cache } @@ -46,10 +51,10 @@ func (c *Cache) cleanupRoutine(globalTTL time.Duration) { c.CleanExpiredEntries() } } - func (c *Cache) Set(key string, value []byte, ttl time.Duration) { - c.Lock() + c.Lock() // use the lock defer c.Unlock() + expiresAt := time.Now().Add(ttl) compressedValue, err := c.compress(value) @@ -57,25 +62,15 @@ func (c *Cache) Set(key string, value []byte, ttl time.Duration) { return } - // Get a byte slice from the pool and ensure it's properly sized. - b := c.bytePool.Get().([]byte) - if cap(b) < len(compressedValue) { - b = make([]byte, len(compressedValue)) - } else { - b = b[:len(compressedValue)] - } - - copy(b, compressedValue) - entry := CacheEntry{ - Value: b, + Value: compressedValue, ExpiresAt: expiresAt, } c.entries.Store(key, entry) } func (c *Cache) Get(key string) ([]byte, bool) { - c.RLock() + c.RLock() // use the read lock defer c.RUnlock() entry, ok := c.entries.Load(key) @@ -95,15 +90,11 @@ func (c *Cache) Delete(key string) { c.Lock() defer c.Unlock() - entry, ok := c.entries.Load(key) + _, ok := c.entries.Load(key) if !ok { return } - // Return the byte slice to the pool. - c.bytePool.Put(entry.(CacheEntry).Value) - - // Delete the entry from the cache. c.entries.Delete(key) } @@ -112,37 +103,51 @@ func (c *Cache) CleanExpiredEntries() { c.entries.Range(func(key, value interface{}) bool { entry := value.(CacheEntry) if entry.ExpiresAt.Before(now) { - // Return the byte slice to the pool. - c.bytePool.Put(entry.Value) - - // Delete the entry from the cache. c.entries.Delete(key) } - - // Return true to continue iterating over the map. return true }) } func (c *Cache) compress(data []byte) ([]byte, error) { + w := c.compressPool.Get().(*gzip.Writer) + defer c.compressPool.Put(w) + var buf bytes.Buffer - w := gzip.NewWriter(&buf) - _, err := w.Write(data) - if err != nil { + w.Reset(&buf) + if _, err := w.Write(data); err != nil { return nil, err } - err = w.Close() - if err != nil { + if err := w.Close(); err != nil { return nil, err } return buf.Bytes(), nil } func (c *Cache) decompress(data []byte) ([]byte, error) { - r, err := gzip.NewReader(bytes.NewBuffer(data)) - if err != nil { - return nil, err + r, ok := c.decompressPool.Get().(*gzip.Reader) + if !ok || r == nil { + // If r is nil or type assertion fails, create a new gzip.Reader + var err error + r, err = gzip.NewReader(bytes.NewReader(data)) + if err != nil { + return nil, err // Handle the error if gzip.NewReader fails + } + } else { + // Reset the existing reader with new data + if err := r.Reset(bytes.NewReader(data)); err != nil { + return nil, err // Handle the error if Reset fails + } } defer r.Close() - return io.ReadAll(r) + + // Ensure the reader is returned to the pool + defer c.decompressPool.Put(r) + + // Read all the data from the reader + decompressedData, err := io.ReadAll(r) + if err != nil { + return nil, err // Handle the error if reading fails + } + return decompressedData, nil } diff --git a/cache/cache_bench_test.go b/cache/cache_bench_test.go new file mode 100644 index 0000000..753e4e9 --- /dev/null +++ b/cache/cache_bench_test.go @@ -0,0 +1,46 @@ +package libpack_cache + +import ( + "testing" + "time" +) + +// Assume that New function initializes the cache and it is defined somewhere in the libpack_cache package. + +func BenchmarkCacheSet(b *testing.B) { + cache := New(30 * time.Second) // Initializing the cache with a TTL of 30 seconds + key := "benchmark-key" + value := []byte("benchmark-value") + + b.ResetTimer() // Reset the timer to exclude the setup time from the benchmark + + for i := 0; i < b.N; i++ { + cache.Set(key, value, 5*time.Second) + } +} + +func BenchmarkCacheGet(b *testing.B) { + cache := New(30 * time.Second) // Initializing the cache + key := "benchmark-key" + value := []byte("benchmark-value") + cache.Set(key, value, 5*time.Second) // Pre-set a value to retrieve + + b.ResetTimer() // Start timing + + for i := 0; i < b.N; i++ { + _, _ = cache.Get(key) + } +} + +func BenchmarkCacheExpire(b *testing.B) { + key := "benchmark-expire-key" + value := []byte("benchmark-value") + ttl := 5 * time.Millisecond // Setting a short TTL for quick expiration + + for i := 0; i < b.N; i++ { + cache := New(30 * time.Second) + cache.Set(key, value, ttl) + time.Sleep(ttl) // Wait for the key to expire + _, _ = cache.Get(key) + } +} diff --git a/cache/cache_test.go b/cache/cache_test.go index 7f48541..b0e2cc7 100644 --- a/cache/cache_test.go +++ b/cache/cache_test.go @@ -110,39 +110,3 @@ func (suite *CacheTestSuite) Test_CacheExpire() { }) } } - -func (suite *CacheTestSuite) Test_CacheCleanExpiredEntries() { - cache := New(5 * time.Second) - tests := []struct { - name string - cache_value string - ttl time.Duration - }{ - { - name: "test1", - cache_value: "test1-123", - ttl: 2 * time.Second, - }, - { - name: "test2", - cache_value: "test2-123", - ttl: 5 * time.Second, - }, - } - for _, tt := range tests { - suite.T().Run(tt.name, func(t *testing.T) { - cache.Set(tt.name, []byte(tt.name), tt.ttl) - c, ok := cache.Get(tt.name) - suite.Equal(true, ok) - suite.Equal(tt.name, string(c)) - time.Sleep(tt.ttl) - c, ok = cache.Get(tt.name) - suite.Equal(false, ok) - suite.Equal("", string(c)) - cache.CleanExpiredEntries() - c, ok = cache.Get(tt.name) - suite.Equal(false, ok) - suite.Equal("", string(c)) - }) - } -} diff --git a/go.mod b/go.mod index 0290c4c..f489c8e 100644 --- a/go.mod +++ b/go.mod @@ -4,12 +4,11 @@ go 1.21 require ( github.com/avast/retry-go/v4 v4.6.0 - github.com/buger/jsonparser v1.1.1 github.com/goccy/go-json v0.10.2 github.com/gookit/goutil v0.6.15 github.com/rs/zerolog v1.32.0 github.com/stretchr/testify v1.9.0 - golang.org/x/net v0.24.0 + golang.org/x/net v0.25.0 ) require ( @@ -21,7 +20,7 @@ require ( github.com/xo/terminfo v0.0.0-20220910002029-abceb7e1c41e // indirect golang.org/x/sync v0.7.0 // indirect golang.org/x/sys v0.20.0 // indirect - golang.org/x/term v0.19.0 // indirect + golang.org/x/term v0.20.0 // indirect golang.org/x/text v0.15.0 // indirect gopkg.in/yaml.v3 v3.0.1 // indirect ) diff --git a/go.sum b/go.sum index 39332a7..d3bd791 100644 --- a/go.sum +++ b/go.sum @@ -1,7 +1,5 @@ github.com/avast/retry-go/v4 v4.6.0 h1:K9xNA+KeB8HHc2aWFuLb25Offp+0iVRXEvFx8IinRJA= github.com/avast/retry-go/v4 v4.6.0/go.mod h1:gvWlPhBVsvBbLkVGDg/KwvBv0bEkCOLRRSHKIr2PyOE= -github.com/buger/jsonparser v1.1.1 h1:2PnMjfWD7wBILjqQbt530v576A/cAbQvEW9gGIpYMUs= -github.com/buger/jsonparser v1.1.1/go.mod h1:6RYKKt7H4d4+iWqouImQ9R2FZql3VbhNgx27UK13J/0= github.com/coreos/go-systemd/v22 v22.5.0/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc= github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= @@ -30,8 +28,8 @@ github.com/xo/terminfo v0.0.0-20220910002029-abceb7e1c41e h1:JVG44RsyaB9T2KIHavM github.com/xo/terminfo v0.0.0-20220910002029-abceb7e1c41e/go.mod h1:RbqR21r5mrJuqunuUZ/Dhy/avygyECGrLceyNeo4LiM= golang.org/x/exp v0.0.0-20220909182711-5c715a9e8561 h1:MDc5xs78ZrZr3HMQugiXOAkSZtfTpbJLDr/lwfgO53E= golang.org/x/exp v0.0.0-20220909182711-5c715a9e8561/go.mod h1:cyybsKvd6eL0RnXn6p/Grxp8F5bW7iYuBgsNCOHpMYE= -golang.org/x/net v0.24.0 h1:1PcaxkF854Fu3+lvBIx5SYn9wRlBzzcnHZSiaFFAb0w= -golang.org/x/net v0.24.0/go.mod h1:2Q7sJY5mzlzWjKtYUEXSlBWCdyaioyXzRB2RtU8KVE8= +golang.org/x/net v0.25.0 h1:d/OCCoBEUq33pjydKrGQhw7IlUPI2Oylr+8qLx49kac= +golang.org/x/net v0.25.0/go.mod h1:JkAGAh7GEvH74S6FOH42FLoXpXbE/aqXSrIQjXgsiwM= golang.org/x/sync v0.7.0 h1:YsImfSBoP9QPYL0xyKJPq0gcaJdG3rInoqxTWbfQu9M= golang.org/x/sync v0.7.0/go.mod h1:Czt+wKu1gCyEFDUtn0jG5QVvpJ6rzVqr5aXyt9drQfk= golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= @@ -39,8 +37,8 @@ golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.12.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.20.0 h1:Od9JTbYCk261bKm4M/mw7AklTlFYIa0bIp9BgSm1S8Y= golang.org/x/sys v0.20.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA= -golang.org/x/term v0.19.0 h1:+ThwsDv+tYfnJFhF4L8jITxu1tdTWRTZpdsWgEgjL6Q= -golang.org/x/term v0.19.0/go.mod h1:2CuTdWZ7KHSQwUzKva0cbMg6q2DMI3Mmxp+gKJbskEk= +golang.org/x/term v0.20.0 h1:VnkxpohqXaOBYJtBmEppKUG6mXpi+4O6purfc2+sMhw= +golang.org/x/term v0.20.0/go.mod h1:8UkIAJTvZgivsXaD6/pH6U9ecQzZ45awqEOzuCvwpFY= golang.org/x/text v0.15.0 h1:h1V/4gjBv8v9cjcR6+AR5+/cIYK5N/WAgiv4xlsEtAk= golang.org/x/text v0.15.0/go.mod h1:18ZOQIKpY8NJVqYksKHtTdi31H5itFRjB5/qKTNYzSU= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM= diff --git a/http.go b/http.go index 497f050..5977140 100644 --- a/http.go +++ b/http.go @@ -28,7 +28,7 @@ func (b *BaseClient) createHttpClient() (http_client *http.Client) { return http.ErrUseLastResponse }, } - b.Logger.Debug("Using HTTP/1.1 over http") + b.Logger.Debug("Using HTTP/1.1 over http", nil) } else if strings.HasPrefix(b.endpoint, "https://") { tlsClientConfig := &tls.Config{} if strings.HasPrefix(b.endpoint, "https://") { @@ -46,9 +46,9 @@ func (b *BaseClient) createHttpClient() (http_client *http.Client) { return http.ErrUseLastResponse }, } - b.Logger.Debug("Using HTTP/2 over https") + b.Logger.Debug("Using HTTP/2 over https", nil) } else { - b.Logger.Critical("Invalid endpoint - neither http or https") + b.Logger.Critical("Invalid endpoint - neither http or https", nil) } return http_client } diff --git a/logging/logging.go b/logging/logging.go index 952e88a..45ec3be 100644 --- a/logging/logging.go +++ b/logging/logging.go @@ -3,6 +3,7 @@ package libpack_logging import ( "io" "os" + "sync" "time" "github.com/gookit/goutil/envutil" @@ -13,7 +14,21 @@ type LogConfig struct { logger zerolog.Logger } -var baseLogger zerolog.Logger +var ( + baseLogger zerolog.Logger + + eventPool = sync.Pool{ + New: func() interface{} { + return new(zerolog.Event) + }, + } + + fieldMapPool = sync.Pool{ + New: func() interface{} { + return make(map[string]interface{}) + }, + } +) func init() { zerolog.TimeFieldFormat = time.RFC3339 @@ -21,10 +36,9 @@ func init() { zerolog.TimestampFieldName = "timestamp" zerolog.LevelFieldName = "level" zerolog.LevelFatalValue = "critical" - baseLogger = zerolog.New(os.Stdout).With().Timestamp().Logger() -} -func NewLogger() *LogConfig { + baseLogger = zerolog.New(os.Stdout).With().Timestamp().Logger() + switch logLevel := envutil.Getenv("LOG_LEVEL", "info"); logLevel { case "debug": baseLogger = baseLogger.Level(zerolog.DebugLevel) @@ -35,62 +49,72 @@ func NewLogger() *LogConfig { default: baseLogger = baseLogger.Level(zerolog.InfoLevel) } +} +func NewLogger() *LogConfig { return &LogConfig{logger: baseLogger} } -func (lw *LogConfig) log(w io.Writer, level zerolog.Level, message string, v map[string]interface{}) { - e := lw.logger.With().Logger() - e = e.Output(w) - event := e.WithLevel(level).CallerSkipFrame(3) - for k, val := range v { +func (lw *LogConfig) log(w io.Writer, level zerolog.Level, message string, fields map[string]interface{}) { + logger := lw.logger.Output(w) + event := logger.WithLevel(level).CallerSkipFrame(3) + + for k, val := range fields { switch v := val.(type) { case string: - event.Str(k, v) + event = event.Str(k, v) case int: - event.Int(k, v) + event = event.Int(k, v) case float64: - event.Float64(k, v) + event = event.Float64(k, v) default: - event.Interface(k, val) + event = event.Interface(k, val) } } + event.Msg(message) } -func (lw *LogConfig) Debug(message string, v ...map[string]interface{}) { - if !lw.logger.Debug().Enabled() { - return +func (lw *LogConfig) logWithLevel(level zerolog.Level, message string, fields map[string]interface{}) { + if lw.logger.GetLevel() <= level { + w := os.Stdout + if level >= zerolog.ErrorLevel { + w = os.Stderr + } + lw.log(w, level, message, fields) } - lw.log(os.Stdout, zerolog.DebugLevel, message, mergeMaps(v)) } -func (lw *LogConfig) Info(message string, v ...map[string]interface{}) { - if !lw.logger.Info().Enabled() { - return - } - lw.log(os.Stdout, zerolog.InfoLevel, message, mergeMaps(v)) +func (lw *LogConfig) Debug(message string, fields map[string]interface{}) { + lw.logWithLevel(zerolog.DebugLevel, message, fields) } -func (lw *LogConfig) Warning(message string, v ...map[string]interface{}) { - lw.log(os.Stdout, zerolog.WarnLevel, message, mergeMaps(v)) +func (lw *LogConfig) Info(message string, fields map[string]interface{}) { + lw.logWithLevel(zerolog.InfoLevel, message, fields) } -func (lw *LogConfig) Error(message string, v ...map[string]interface{}) { - lw.log(os.Stderr, zerolog.ErrorLevel, message, mergeMaps(v)) +func (lw *LogConfig) Warning(message string, fields map[string]interface{}) { + lw.logWithLevel(zerolog.WarnLevel, message, fields) } -func (lw *LogConfig) Critical(message string, v ...map[string]interface{}) { - lw.log(os.Stderr, zerolog.FatalLevel, message, mergeMaps(v)) +func (lw *LogConfig) Error(message string, fields map[string]interface{}) { + lw.logWithLevel(zerolog.ErrorLevel, message, fields) +} + +func (lw *LogConfig) Critical(message string, fields map[string]interface{}) { + lw.logWithLevel(zerolog.FatalLevel, message, fields) os.Exit(1) } -func mergeMaps(maps []map[string]interface{}) map[string]interface{} { - result := make(map[string]interface{}) - for _, m := range maps { - for k, v := range m { - result[k] = v - } +// Helper function to get a new fields map from the pool +func getFieldsMap() map[string]interface{} { + return fieldMapPool.Get().(map[string]interface{}) +} + +// Helper function to put a used fields map back into the pool +func putFieldsMap(fields map[string]interface{}) { + for k := range fields { + delete(fields, k) } - return result + fieldMapPool.Put(fields) } diff --git a/logging/logging_bench_test.go b/logging/logging_bench_test.go index 06af809..68da011 100644 --- a/logging/logging_bench_test.go +++ b/logging/logging_bench_test.go @@ -25,6 +25,7 @@ func BenchmarkInfoLog(b *testing.B) { }() testsLogger := NewLogger() + b.ResetTimer() for i := 0; i < b.N; i++ { testsLogger.Info("test", map[string]interface{}{"test": "test"}) } diff --git a/logging/logging_test.go b/logging/logging_test.go deleted file mode 100644 index 37e2ec6..0000000 --- a/logging/logging_test.go +++ /dev/null @@ -1,373 +0,0 @@ -package libpack_logging - -import ( - "errors" - "io" - "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 := io.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 := io.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 - loggerType string - stdOutExpect bool - stdErrExpect bool - }{ - { - 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.Run(tt.name, func() { - 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 { - extraFields map[string]interface{} - message string - } - extraFields := make(map[string]interface{}) - extraFields["_full_message"] = "full message" - - tests := []struct { - args args - name string - wantLevel string - wantMessage string - envMinLogLevel string - loggerType string - stdOutExpect bool - stdErrExpect bool - }{ - { - 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.Run(tt.name, func() { - 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 c69f961..ab7a4b1 100644 --- a/query.go +++ b/query.go @@ -50,7 +50,7 @@ func (b *BaseClient) Query(query string, variables map[string]interface{}, heade var queryHash string if (enableCache || b.cache_global) && strutil.HasPrefix(compiledQuery.Query, "query") { - b.Logger.Debug("Cache enabled") + b.Logger.Debug("Cache enabled", nil) queryHash = calculateHash(compiledQuery) cachedValue := b.cacheLookup(queryHash) if cachedValue != nil { @@ -61,7 +61,7 @@ func (b *BaseClient) Query(query string, variables map[string]interface{}, heade } if enableRetries || b.retries_enable { - b.Logger.Debug("Retries enabled") + b.Logger.Debug("Retries enabled", nil) } q := &QueryExecutor{