Repository: gomods/athens
Pull request #1817 (2023-01-26 15:26:38)

Pass Athens's logger to the Redis package
<!-- 
    Welcome, Athenian! Can you do us two quick favors before you submit your PR?
    
    1. Briefly fill out the sections below. It will make it easy for us to review your code
    2. Put "[WIP]" at the beginning of your PR title if you're not ready to have this merged yet (we have a bot that will tell everyone that it's a work in progress)
-->

## What is the problem I am trying to address?

The Redis package used by `pkg/stash/with_redis*` occasionally logs bits of information, such as when a Redis Sentinel is discovered or changes, but it uses its own logger by default. If Athens is configured to log in JSON but Redis is logging in plain text, this creates problems when parsing the log output.

## How is the fix applied?

Make an adapter struct around `pkg/log.Logger` to implement the interface that Redis v8 expects, then pass the logger to the `WithRedis*` functions to call `redis.SetLogger`.

## What GitHub issue(s) does this PR fix or close?

<!--
    If it doesn't fix any GitHub Issues, that's ok. Can you please delete the below "Fixes #" line for us? It would help us out a lot. Thanks!

    Your PR might fix one or more GitHub issues. If so, please use the below "Fixes #<issue number>" notation below. If your PR fixes multiple issues, please put multiple lines of "Fixes #<issue number>", one for each issue. If you do that, when this PR is merged, it'll automatically close the issue(s) you reference.
-->

Haven't found an Issue specifically for this.

r-ashish: Thanks for the fix!

The Changes LGTM, just wondering whether you've tested this already to make sure it's working as expected?
mikesep: Hi Ashish, thanks for reviewing!

> just wondering whether you've tested this already to make sure it's working as expected?

Yes, I've been running this change in my group's Athens instance for the last day or so, and Redis traces are definitely showing up as JSON rather than plain text. 😄 

Patch:
diff --git a/cmd/proxy/actions/app_proxy.go b/cmd/proxy/actions/app_proxy.go
index fc562713..e0f1f6bc 100644
--- a/cmd/proxy/actions/app_proxy.go
+++ b/cmd/proxy/actions/app_proxy.go
@@ -1,6 +1,7 @@
 package actions
 
 import (
+	"context"
 	"fmt"
 	"net/http"
 	"net/url"
@@ -99,7 +100,7 @@ func addProxyRoutes(
 
 	lister := module.NewVCSLister(c.GoBinary, c.GoBinaryEnvVars, fs)
 	checker := storage.WithChecker(s)
-	withSingleFlight, err := getSingleFlight(c, checker)
+	withSingleFlight, err := getSingleFlight(l, c, checker)
 	if err != nil {
 		return err
 	}
@@ -126,7 +127,16 @@ func addProxyRoutes(
 	return nil
 }
 
-func getSingleFlight(c *config.Config, checker storage.Checker) (stash.Wrapper, error) {
+// athensLoggerForRedis implements pkg/stash.RedisLogger.
+type athensLoggerForRedis struct {
+	logger *log.Logger
+}
+
+func (l *athensLoggerForRedis) Printf(ctx context.Context, format string, v ...interface{}) {
+	l.logger.WithContext(ctx).Printf(format, v...)
+}
+
+func getSingleFlight(l *log.Logger, c *config.Config, checker storage.Checker) (stash.Wrapper, error) {
 	switch c.SingleFlightType {
 	case "", "memory":
 		return stash.WithSingleflight, nil
@@ -140,12 +150,18 @@ func getSingleFlight(c *config.Config, checker storage.Checker) (stash.Wrapper,
 		if c.SingleFlight == nil || c.SingleFlight.Redis == nil {
 			return nil, fmt.Errorf("Redis config must be present")
 		}
-		return stash.WithRedisLock(c.SingleFlight.Redis.Endpoint, c.SingleFlight.Redis.Password, checker, c.SingleFlight.Redis.LockConfig)
+		return stash.WithRedisLock(
+			&athensLoggerForRedis{logger: l},
+			c.SingleFlight.Redis.Endpoint,
+			c.SingleFlight.Redis.Password,
+			checker,
+			c.SingleFlight.Redis.LockConfig)
 	case "redis-sentinel":
 		if c.SingleFlight == nil || c.SingleFlight.RedisSentinel == nil {
 			return nil, fmt.Errorf("Redis config must be present")
 		}
 		return stash.WithRedisSentinelLock(
+			&athensLoggerForRedis{logger: l},
 			c.SingleFlight.RedisSentinel.Endpoints,
 			c.SingleFlight.RedisSentinel.MasterName,
 			c.SingleFlight.RedisSentinel.SentinelPassword,
diff --git a/pkg/stash/with_redis.go b/pkg/stash/with_redis.go
index 7332c7ed..35bf7936 100644
--- a/pkg/stash/with_redis.go
+++ b/pkg/stash/with_redis.go
@@ -13,9 +13,16 @@ import (
 	"github.com/gomods/athens/pkg/storage"
 )
 
+// RedisLogger mirrors github.com/go-redis/redis/v8/internal.Logging
+type RedisLogger interface {
+	Printf(ctx context.Context, format string, v ...interface{})
+}
+
 // WithRedisLock returns a distributed singleflight
 // using a redis cluster. If it cannot connect, it will return an error.
-func WithRedisLock(endpoint string, password string, checker storage.Checker, lockConfig *config.RedisLockConfig) (Wrapper, error) {
+func WithRedisLock(l RedisLogger, endpoint string, password string, checker storage.Checker, lockConfig *config.RedisLockConfig) (Wrapper, error) {
+	redis.SetLogger(l)
+
 	const op errors.Op = "stash.WithRedisLock"
 	client := redis.NewClient(&redis.Options{
 		Network:  "tcp",
diff --git a/pkg/stash/with_redis_sentinel.go b/pkg/stash/with_redis_sentinel.go
index 5922a64d..3eb4aa59 100644
--- a/pkg/stash/with_redis_sentinel.go
+++ b/pkg/stash/with_redis_sentinel.go
@@ -2,6 +2,7 @@ package stash
 
 import (
 	"context"
+
 	"github.com/go-redis/redis/v8"
 	"github.com/gomods/athens/pkg/config"
 	"github.com/gomods/athens/pkg/errors"
@@ -10,7 +11,9 @@ import (
 
 // WithRedisSentinelLock returns a distributed singleflight
 // with a redis cluster that utilizes sentinel for quorum and failover
-func WithRedisSentinelLock(endpoints []string, master, password string, checker storage.Checker, lockConfig *config.RedisLockConfig) (Wrapper, error) {
+func WithRedisSentinelLock(l RedisLogger, endpoints []string, master, password string, checker storage.Checker, lockConfig *config.RedisLockConfig) (Wrapper, error) {
+	redis.SetLogger(l)
+
 	const op errors.Op = "stash.WithRedisSentinelLock"
 	// The redis client constructor does not return an error when no endpoints
 	// are provided, so we check for ourselves.


Test patch:
diff --git a/pkg/stash/with_redis_sentinel_test.go b/pkg/stash/with_redis_sentinel_test.go
index 9f347f26..ec2ee29d 100644
--- a/pkg/stash/with_redis_sentinel_test.go
+++ b/pkg/stash/with_redis_sentinel_test.go
@@ -27,8 +27,9 @@ func TestWithRedisSentinelLock(t *testing.T) {
 		t.Fatal(err)
 	}
 	ms := &mockRedisStasher{strg: strg}
+	l := &testingRedisLogger{t: t}
 
-	wrapper, err := WithRedisSentinelLock([]string{endpoint}, masterName, password, storage.WithChecker(strg), config.DefaultRedisLockConfig())
+	wrapper, err := WithRedisSentinelLock(l, []string{endpoint}, masterName, password, storage.WithChecker(strg), config.DefaultRedisLockConfig())
 	if err != nil {
 		t.Fatal(err)
 	}
diff --git a/pkg/stash/with_redis_test.go b/pkg/stash/with_redis_test.go
index 9f1dac9b..c4cab31d 100644
--- a/pkg/stash/with_redis_test.go
+++ b/pkg/stash/with_redis_test.go
@@ -15,6 +15,15 @@ import (
 	"golang.org/x/sync/errgroup"
 )
 
+// testingRedisLogger implements pkg/stash.RedisLogger.
+type testingRedisLogger struct {
+	t *testing.T
+}
+
+func (l *testingRedisLogger) Printf(ctx context.Context, format string, v ...interface{}) {
+	l.t.Logf(format, v...)
+}
+
 // WithRedisLock will ensure that 5 concurrent requests will all get the first request's
 // response. We can ensure that because only the first response does not return an error
 // and therefore all 5 responses should have no error.
@@ -29,7 +38,8 @@ func TestWithRedisLock(t *testing.T) {
 		t.Fatal(err)
 	}
 	ms := &mockRedisStasher{strg: strg}
-	wrapper, err := WithRedisLock(endpoint, password, storage.WithChecker(strg), config.DefaultRedisLockConfig())
+	l := &testingRedisLogger{t: t}
+	wrapper, err := WithRedisLock(l, endpoint, password, storage.WithChecker(strg), config.DefaultRedisLockConfig())
 	if err != nil {
 		t.Fatal(err)
 	}
@@ -64,7 +74,8 @@ func TestWithRedisLockWithPassword(t *testing.T) {
 		t.Fatal(err)
 	}
 	ms := &mockRedisStasher{strg: strg}
-	wrapper, err := WithRedisLock(endpoint, password, storage.WithChecker(strg), config.DefaultRedisLockConfig())
+	l := &testingRedisLogger{t: t}
+	wrapper, err := WithRedisLock(l, endpoint, password, storage.WithChecker(strg), config.DefaultRedisLockConfig())
 	if err != nil {
 		t.Fatal(err)
 	}
@@ -98,7 +109,8 @@ func TestWithRedisLockWithWrongPassword(t *testing.T) {
 	if err != nil {
 		t.Fatal(err)
 	}
-	_, err = WithRedisLock(endpoint, password, storage.WithChecker(strg), config.DefaultRedisLockConfig())
+	l := &testingRedisLogger{t: t}
+	_, err = WithRedisLock(l, endpoint, password, storage.WithChecker(strg), config.DefaultRedisLockConfig())
 	if err == nil {
 		t.Fatal("Expected Connection Error")
 	}