feat: update go-redis to v8, support ctx in redis methods (zeromicro#…

…1507)

* feat: update go-redis to v8, support ctx in redis methods

* fix compile errors

* chore: remove unused const

* chore: add tracing log on redis

core/limit/periodlimit_test.go

@@ -23,10 +23,9 @@ func TestPeriodLimit_RedisUnavailable(t *testing.T) {
 
 	const (
 		seconds = 1
-		total   = 100
 		quota   = 5
 	)
-	l := NewPeriodLimit(seconds, quota, redis.NewRedis(s.Addr(), redis.NodeType), "periodlimit")
+	l := NewPeriodLimit(seconds, quota, redis.New(s.Addr()), "periodlimit")
 	s.Close()
 	val, err := l.Take("first")
 	assert.NotNil(t, err)

core/stores/redis/hook.go

@@ -0,0 +1,83 @@
+package redis
+
+import (
+	"context"
+	"strings"
+	"time"
+
+	red "github.com/go-redis/redis/v8"
+	"github.com/zeromicro/go-zero/core/logx"
+	"github.com/zeromicro/go-zero/core/mapping"
+	"github.com/zeromicro/go-zero/core/timex"
+)
+
+var (
+	startTimeKey = contextKey("startTime")
+	durationHook = hook{}
+)
+
+type (
+	contextKey string
+	hook       struct{}
+)
+
+func (h hook) BeforeProcess(ctx context.Context, _ red.Cmder) (context.Context, error) {
+	return context.WithValue(ctx, startTimeKey, timex.Now()), nil
+}
+
+func (h hook) AfterProcess(ctx context.Context, cmd red.Cmder) error {
+	val := ctx.Value(startTimeKey)
+	if val == nil {
+		return nil
+	}
+
+	start, ok := val.(time.Duration)
+	if !ok {
+		return nil
+	}
+
+	duration := timex.Since(start)
+	if duration > slowThreshold.Load() {
+		logDuration(ctx, cmd, duration)
+	}
+
+	return nil
+}
+
+func (h hook) BeforeProcessPipeline(ctx context.Context, _ []red.Cmder) (context.Context, error) {
+	return context.WithValue(ctx, startTimeKey, timex.Now()), nil
+}
+
+func (h hook) AfterProcessPipeline(ctx context.Context, cmds []red.Cmder) error {
+	if len(cmds) == 0 {
+		return nil
+	}
+
+	val := ctx.Value(startTimeKey)
+	if val == nil {
+		return nil
+	}
+
+	start, ok := val.(time.Duration)
+	if !ok {
+		return nil
+	}
+
+	duration := timex.Since(start)
+	if duration > slowThreshold.Load()*time.Duration(len(cmds)) {
+		logDuration(ctx, cmds[0], duration)
+	}
+
+	return nil
+}
+
+func logDuration(ctx context.Context, cmd red.Cmder, duration time.Duration) {
+	var buf strings.Builder
+	for i, arg := range cmd.Args() {
+		if i > 0 {
+			buf.WriteByte(' ')
+		}
+		buf.WriteString(mapping.Repr(arg))
+	}
+	logx.WithContext(ctx).WithDuration(duration).Slowf("[REDIS] slowcall on executing: %s", buf.String())
+}

core/stores/redis/hook_test.go

@@ -0,0 +1,138 @@
+package redis
+
+import (
+	"context"
+	"log"
+	"strings"
+	"testing"
+	"time"
+
+	red "github.com/go-redis/redis/v8"
+
+	"github.com/stretchr/testify/assert"
+)
+
+func TestHookProcessCase1(t *testing.T) {
+	writer := log.Writer()
+	var buf strings.Builder
+	log.SetOutput(&buf)
+	defer log.SetOutput(writer)
+
+	ctx, err := durationHook.BeforeProcess(context.Background(), nil)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	assert.Nil(t, durationHook.AfterProcess(ctx, red.NewCmd(context.Background())))
+	assert.False(t, strings.Contains(buf.String(), "slow"))
+}
+
+func TestHookProcessCase2(t *testing.T) {
+	writer := log.Writer()
+	var buf strings.Builder
+	log.SetOutput(&buf)
+	defer log.SetOutput(writer)
+
+	ctx, err := durationHook.BeforeProcess(context.Background(), nil)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	time.Sleep(slowThreshold.Load() + time.Millisecond)
+
+	assert.Nil(t, durationHook.AfterProcess(ctx, red.NewCmd(context.Background(), "foo", "bar")))
+	assert.True(t, strings.Contains(buf.String(), "slow"))
+}
+
+func TestHookProcessCase3(t *testing.T) {
+	writer := log.Writer()
+	var buf strings.Builder
+	log.SetOutput(&buf)
+	defer log.SetOutput(writer)
+
+	assert.Nil(t, durationHook.AfterProcess(context.Background(), red.NewCmd(context.Background())))
+	assert.True(t, buf.Len() == 0)
+}
+
+func TestHookProcessCase4(t *testing.T) {
+	writer := log.Writer()
+	var buf strings.Builder
+	log.SetOutput(&buf)
+	defer log.SetOutput(writer)
+
+	ctx := context.WithValue(context.Background(), startTimeKey, "foo")
+	assert.Nil(t, durationHook.AfterProcess(ctx, red.NewCmd(context.Background())))
+	assert.True(t, buf.Len() == 0)
+}
+
+func TestHookProcessPipelineCase1(t *testing.T) {
+	writer := log.Writer()
+	var buf strings.Builder
+	log.SetOutput(&buf)
+	defer log.SetOutput(writer)
+
+	ctx, err := durationHook.BeforeProcessPipeline(context.Background(), nil)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	assert.Nil(t, durationHook.AfterProcessPipeline(ctx, []red.Cmder{
+		red.NewCmd(context.Background()),
+	}))
+	assert.False(t, strings.Contains(buf.String(), "slow"))
+}
+
+func TestHookProcessPipelineCase2(t *testing.T) {
+	writer := log.Writer()
+	var buf strings.Builder
+	log.SetOutput(&buf)
+	defer log.SetOutput(writer)
+
+	ctx, err := durationHook.BeforeProcessPipeline(context.Background(), nil)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	time.Sleep(slowThreshold.Load() + time.Millisecond)
+
+	assert.Nil(t, durationHook.AfterProcessPipeline(ctx, []red.Cmder{
+		red.NewCmd(context.Background(), "foo", "bar"),
+	}))
+	assert.True(t, strings.Contains(buf.String(), "slow"))
+}
+
+func TestHookProcessPipelineCase3(t *testing.T) {
+	writer := log.Writer()
+	var buf strings.Builder
+	log.SetOutput(&buf)
+	defer log.SetOutput(writer)
+
+	assert.Nil(t, durationHook.AfterProcessPipeline(context.Background(), []red.Cmder{
+		red.NewCmd(context.Background()),
+	}))
+	assert.True(t, buf.Len() == 0)
+}
+
+func TestHookProcessPipelineCase4(t *testing.T) {
+	writer := log.Writer()
+	var buf strings.Builder
+	log.SetOutput(&buf)
+	defer log.SetOutput(writer)
+
+	ctx := context.WithValue(context.Background(), startTimeKey, "foo")
+	assert.Nil(t, durationHook.AfterProcessPipeline(ctx, []red.Cmder{
+		red.NewCmd(context.Background()),
+	}))
+	assert.True(t, buf.Len() == 0)
+}
+
+func TestHookProcessPipelineCase5(t *testing.T) {
+	writer := log.Writer()
+	var buf strings.Builder
+	log.SetOutput(&buf)
+	defer log.SetOutput(writer)
+
+	ctx := context.WithValue(context.Background(), startTimeKey, "foo")
+	assert.Nil(t, durationHook.AfterProcessPipeline(ctx, nil))
+	assert.True(t, buf.Len() == 0)
+}