add optional logging, more test cases to cover corner cases (#51)

* add optional logging, more test cases to cover corner cases

* fix tests

Author: emmanuelm41

pkg/zcache/combined_cache.go

@@ -6,6 +6,7 @@ import (
 	"github.com/allegro/bigcache/v3"
 	"github.com/go-redis/redis/v8"
 	"github.com/zondax/golem/pkg/metrics"
+	"go.uber.org/zap"
 	"time"
 )
 
@@ -16,31 +17,55 @@ type CombinedCache interface {
 type combinedCache struct {
 	localCache         LocalCache
 	remoteCache        RemoteCache
+	logger             *zap.Logger
 	ttl                time.Duration
 	isRemoteBestEffort bool
 	metricsServer      *metrics.TaskMetrics
 	appName            string
 }
 
 func (c *combinedCache) Set(ctx context.Context, key string, value interface{}, _ time.Duration) error {
-	if err := c.remoteCache.Set(ctx, key, value, c.ttl); err != nil && !c.isRemoteBestEffort {
-		return err
+	c.logger.Sugar().Debugf("set key on combined cache, key: [%s]", key)
+
+	if err := c.remoteCache.Set(ctx, key, value, c.ttl); err != nil {
+		c.logger.Sugar().Errorf("error setting key on combined/remote cache, key: [%s], err: %s", key, err)
+		if !c.isRemoteBestEffort {
+			c.logger.Sugar().Debugf("emitting error as remote best effort is false, key: [%s]", key)
+			return err
+		}
 	}
 
 	// ttl is controlled by cache instantiation, so it does not matter here
 	if err := c.localCache.Set(ctx, key, value, c.ttl); err != nil {
+		c.logger.Sugar().Errorf("error setting key on combined/local cache, key: [%s], err: %s", key, err)
 		return err
 	}
 	return nil
 }
 
 func (c *combinedCache) Get(ctx context.Context, key string, data interface{}) error {
+	c.logger.Sugar().Debugf("get key on combined cache, key: [%s]", key)
+
 	err := c.localCache.Get(ctx, key, data)
 	if err != nil {
+		if c.localCache.IsNotFoundError(err) {
+			c.logger.Sugar().Debugf("key not found on combined/local cache, key: [%s]", key)
+		} else {
+			c.logger.Sugar().Debugf("error getting key on combined/local cache, key: [%s], err: %s", key, err)
+		}
+
 		if err := c.remoteCache.Get(ctx, key, data); err != nil {
+			if c.remoteCache.IsNotFoundError(err) {
+				c.logger.Sugar().Debugf("key not found on combined/remote cache, key: [%s]", key)
+			} else {
+				c.logger.Sugar().Debugf("error getting key on combined/remote cache, key: [%s], err: %s", key, err)
+			}
+
 			return err
 		}
 
+		c.logger.Sugar().Debugf("set value found on remote cache in the local cache, key: [%s]", key)
+
 		// Refresh data TTL on both caches
 		_ = c.localCache.Set(ctx, key, data, c.ttl)
 		_ = c.remoteCache.Set(ctx, key, data, c.ttl)
@@ -50,12 +75,18 @@ func (c *combinedCache) Get(ctx context.Context, key string, data interface{}) e
 }
 
 func (c *combinedCache) Delete(ctx context.Context, key string) error {
+	c.logger.Sugar().Debugf("delete key on combined cache, key: [%s]", key)
 	err2 := c.remoteCache.Delete(ctx, key)
-	if err2 != nil && !c.isRemoteBestEffort {
-		return err2
+	if err2 != nil {
+		c.logger.Sugar().Errorf("error deleting key on combined/remote cache, key: [%s], err: %s", key, err2)
+		if !c.isRemoteBestEffort {
+			c.logger.Sugar().Debugf("emitting error as remote best effort is false, key: [%s]")
+			return err2
+		}
 	}
 
 	if err1 := c.localCache.Delete(ctx, key); err1 != nil {
+		c.logger.Sugar().Errorf("error deleting key on combined/local cache, key: [%s], err: %s", key, err1)
 		return err1
 	}
 
@@ -73,6 +104,10 @@ func (c *combinedCache) GetStats() ZCacheStats {
 	}
 }
 
+func (c *combinedCache) IsNotFoundError(err error) bool {
+	return c.remoteCache.IsNotFoundError(err) || c.localCache.IsNotFoundError(err)
+}
+
 func (c *combinedCache) SetupAndMonitorMetrics(appName string, metricsServer metrics.TaskMetrics, updateInterval time.Duration) []error {
 	c.metricsServer = &metricsServer
 	c.appName = appName

pkg/zcache/combined_cache_test.go

@@ -3,6 +3,7 @@ package zcache
 import (
 	"context"
 	"github.com/stretchr/testify/suite"
+	"go.uber.org/zap"
 	"os"
 	"testing"
 	"time"
@@ -20,13 +21,17 @@ type CombinedCacheTestSuite struct {
 	cacheRemoteBrokenBestEffort    CombinedCache
 	cacheRemoteBrokenNotBestEffort CombinedCache
 	cacheOkNotBestEffort           CombinedCache
+	cacheRemote                    RemoteCache
 }
 
 func (suite *CombinedCacheTestSuite) SetupSuite() {
 	mr, err := miniredis.Run()
 	suite.Require().NoError(err)
 	suite.mr = mr
 
+	logger, err := zap.NewDevelopment()
+	suite.Require().NoError(err)
+
 	prefix := os.Getenv("PREFIX")
 	suite.cacheRemoteBrokenBestEffort, err = NewCombinedCache(
 		&CombinedConfig{
@@ -38,6 +43,7 @@ func (suite *CombinedCacheTestSuite) SetupSuite() {
 			},
 			IsRemoteBestEffort: true,
 			GlobalPrefix:       prefix,
+			GlobalLogger:       logger,
 		})
 	suite.Nil(err)
 
@@ -50,6 +56,7 @@ func (suite *CombinedCacheTestSuite) SetupSuite() {
 		},
 		IsRemoteBestEffort: false,
 		GlobalPrefix:       prefix,
+		GlobalLogger:       logger,
 	})
 	suite.Nil(err)
 
@@ -63,8 +70,16 @@ func (suite *CombinedCacheTestSuite) SetupSuite() {
 			},
 			IsRemoteBestEffort: false,
 			GlobalPrefix:       prefix,
+			GlobalLogger:       logger,
 		})
 	suite.Nil(err)
+
+	suite.cacheRemote, err = NewRemoteCache(&RemoteConfig{
+		Addr:   mr.Addr(),
+		Logger: logger,
+		Prefix: prefix,
+	})
+	suite.Nil(err)
 }
 
 func (suite *CombinedCacheTestSuite) TearDownSuite() {
@@ -99,6 +114,37 @@ func (suite *CombinedCacheTestSuite) TestSetAndGet() {
 	suite.Equal("", result3)
 }
 
+func (suite *CombinedCacheTestSuite) TestGetFromRemoteToLocal() {
+	ctx := context.Background()
+
+	// write value remotely directly
+	err := suite.cacheRemote.Set(ctx, "onlyOnRemote", "value_on_remote", -1)
+	suite.NoError(err)
+
+	// check value on combined cache, it should not find it locally or remotely (it should fail)
+	var result1 string
+	err = suite.cacheOkNotBestEffort.Get(ctx, "noFound", &result1)
+	suite.Error(err)
+	suite.Equal(suite.cacheOkNotBestEffort.IsNotFoundError(err), true)
+
+	// check value on combined cache, it should not find it locally, retrieve it remotely and write it back locally and remotely
+	err = suite.cacheOkNotBestEffort.Get(ctx, "onlyOnRemote", &result1)
+	suite.NoError(err)
+	suite.Equal("value_on_remote", result1)
+
+	// check value again on combined cache, it should find it now locally
+	var result2 string
+	err = suite.cacheOkNotBestEffort.Get(ctx, "onlyOnRemote", &result2)
+	suite.NoError(err)
+	suite.Equal("value_on_remote", result2)
+
+	// check value directly on remote cache
+	var result3 string
+	err = suite.cacheRemote.Get(ctx, "onlyOnRemote", &result3)
+	suite.NoError(err)
+	suite.Equal("value_on_remote", result3)
+}
+
 func (suite *CombinedCacheTestSuite) TestDelete() {
 	ctx := context.Background()
 

pkg/zcache/config.go

@@ -3,6 +3,7 @@ package zcache
 import (
 	"github.com/allegro/bigcache/v3"
 	"github.com/go-redis/redis/v8"
+	"go.uber.org/zap"
 	"math"
 	"time"
 )
@@ -22,11 +23,13 @@ type RemoteConfig struct {
 	IdleTimeout        time.Duration
 	IdleCheckFrequency time.Duration
 	Prefix             string
+	Logger             *zap.Logger
 }
 
 type LocalConfig struct {
 	EvictionInSeconds int
 	Prefix            string
+	Logger            *zap.Logger
 }
 
 func (c *RemoteConfig) ToRedisConfig() *redis.Options {
@@ -59,6 +62,7 @@ func (c *LocalConfig) ToBigCacheConfig() bigcache.Config {
 type CombinedConfig struct {
 	Local              *LocalConfig
 	Remote             *RemoteConfig
+	GlobalLogger       *zap.Logger
 	GlobalTtlSeconds   int
 	GlobalPrefix       string
 	IsRemoteBestEffort bool

pkg/zcache/local_cache.go

@@ -3,9 +3,11 @@ package zcache
 import (
 	"context"
 	"encoding/json"
+	"errors"
 	"fmt"
 	"github.com/allegro/bigcache/v3"
 	"github.com/zondax/golem/pkg/metrics"
+	"go.uber.org/zap"
 	"time"
 )
 
@@ -16,40 +18,64 @@ type LocalCache interface {
 type localCache struct {
 	client        *bigcache.BigCache
 	prefix        string
+	logger        *zap.Logger
 	metricsServer *metrics.TaskMetrics
 	appName       string
 }
 
 func (c *localCache) Set(_ context.Context, key string, value interface{}, _ time.Duration) error {
 	realKey := getKeyWithPrefix(c.prefix, key)
 
+	c.logger.Sugar().Debugf("set key on local cache, fullKey: [%s], value: [%v]", realKey, value)
 	val, err := json.Marshal(value)
 	if err != nil {
 		return err
 	}
-	return c.client.Set(realKey, val)
+
+	err = c.client.Set(realKey, val)
+	if err != nil {
+		c.logger.Sugar().Errorf("error setting new key on local cache, fullKey: [%s], err: [%s]", realKey, err)
+	}
+
+	return err
 }
 
 func (c *localCache) Get(_ context.Context, key string, data interface{}) error {
 	realKey := getKeyWithPrefix(c.prefix, key)
 
+	c.logger.Sugar().Debugf("get key on local cache, fullKey: [%s]", realKey)
+
 	val, err := c.client.Get(realKey)
 	if err != nil {
+		if c.IsNotFoundError(err) {
+			c.logger.Sugar().Debugf("key not found on local cache, fullKey: [%s]", realKey)
+		} else {
+			c.logger.Sugar().Errorf("error getting key on local cache, fullKey: [%s], err: [%s]", realKey, err)
+		}
+
 		return err
 	}
 	return json.Unmarshal(val, &data)
 }
 
 func (c *localCache) Delete(_ context.Context, key string) error {
 	realKey := getKeyWithPrefix(c.prefix, key)
+	c.logger.Sugar().Debugf("delete key on local cache, fullKey: [%s]", realKey)
+
 	return c.client.Delete(realKey)
 }
 
 func (c *localCache) GetStats() ZCacheStats {
 	stats := c.client.Stats()
+	c.logger.Sugar().Debugf("local cache stats: [%v]", stats)
+
 	return ZCacheStats{Local: &stats}
 }
 
+func (c *localCache) IsNotFoundError(err error) bool {
+	return errors.Is(err, bigcache.ErrEntryNotFound)
+}
+
 func (c *localCache) SetupAndMonitorMetrics(appName string, metricsServer metrics.TaskMetrics, updateInterval time.Duration) []error {
 	c.metricsServer = &metricsServer
 	c.appName = appName