From 289f588d99788cbcd39beee2c78cfacb24ca1ff6 Mon Sep 17 00:00:00 2001 From: Tim Zhu Date: Fri, 14 Mar 2025 11:08:35 -0400 Subject: [PATCH 1/7] test logger --- osscluster.go | 1 + 1 file changed, 1 insertion(+) diff --git a/osscluster.go b/osscluster.go index 1e9ee7de4..a18543eef 100644 --- a/osscluster.go +++ b/osscluster.go @@ -1396,6 +1396,7 @@ func (c *ClusterClient) pipelineReadCmds( cmds []Cmder, failedCmds *cmdsMap, ) error { + internal.Logger.Printf(ctx, "------------------pipelineReadCmds-----------------------") for i, cmd := range cmds { err := cmd.readReply(rd) cmd.SetErr(err) From da2445b4c931b0acf3aaf119aa1173399a391fa8 Mon Sep 17 00:00:00 2001 From: Tim Zhu Date: Fri, 14 Mar 2025 11:39:08 -0400 Subject: [PATCH 2/7] try this --- error.go | 9 +++++++-- osscluster.go | 6 ++++-- pubsub.go | 2 +- redis.go | 2 +- 4 files changed, 13 insertions(+), 6 deletions(-) diff --git a/error.go b/error.go index a7bf159c2..009d4e7ca 100644 --- a/error.go +++ b/error.go @@ -87,30 +87,35 @@ func isRedisError(err error) bool { return ok } -func isBadConn(err error, allowTimeout bool, addr string) bool { +func isBadConn(ctx context.Context, err error, allowTimeout bool, addr string, shouldLog bool) bool { switch err { case nil: + internal.Logger.Printf(ctx, "go-redis:nil error: %s", err) return false case context.Canceled, context.DeadlineExceeded: + internal.Logger.Printf(ctx, "go-redis: context error: %s", err) return true } if isRedisError(err) { switch { case isReadOnlyError(err): + internal.Logger.Printf(ctx, "go-redis: is read-only error: %s", err) // Close connections in read only state in case domain addr is used // and domain resolves to a different Redis Server. See #790. return true case isMovedSameConnAddr(err, addr): + internal.Logger.Printf(ctx, "go-redis: is isMovedSameConnAddr error: %s", err) // Close connections when we are asked to move to the same addr // of the connection. Force a DNS resolution when all connections // of the pool are recycled return true default: + internal.Logger.Printf(ctx, "go-redis:other redis error: %s", err) return false } } - + internal.Logger.Printf(ctx, "go-redis:other error: %s", err) if allowTimeout { if netErr, ok := err.(net.Error); ok && netErr.Timeout() { return false diff --git a/osscluster.go b/osscluster.go index a18543eef..12fd4c605 100644 --- a/osscluster.go +++ b/osscluster.go @@ -1374,7 +1374,7 @@ func (c *ClusterClient) processPipelineNodeConn( if err := cn.WithWriter(c.context(ctx), c.opt.WriteTimeout, func(wr *proto.Writer) error { return writeCmds(wr, cmds) }); err != nil { - if isBadConn(err, false, node.Client.getAddr()) { + if isBadConn(ctx, err, false, node.Client.getAddr(), false) { node.MarkAsFailing() } if shouldRetry(err, true) { @@ -1409,7 +1409,9 @@ func (c *ClusterClient) pipelineReadCmds( continue } - if c.opt.ReadOnly && isBadConn(err, false, node.Client.getAddr()) { + // we may get >1k errors per second, lower the log volume to 1% + shouldLog := rand.Intn(100) == 0 + if c.opt.ReadOnly && isBadConn(ctx, err, false, node.Client.getAddr(), shouldLog) { node.MarkAsFailing() } diff --git a/pubsub.go b/pubsub.go index 72b18f49a..5c2e7e08e 100644 --- a/pubsub.go +++ b/pubsub.go @@ -150,7 +150,7 @@ func (c *PubSub) releaseConn(ctx context.Context, cn *pool.Conn, err error, allo if c.cn != cn { return } - if isBadConn(err, allowTimeout, c.opt.Addr) { + if isBadConn(ctx, err, allowTimeout, c.opt.Addr, false) { c.reconnect(ctx, err) } } diff --git a/redis.go b/redis.go index ec3ff616a..df5d58d1a 100644 --- a/redis.go +++ b/redis.go @@ -373,7 +373,7 @@ func (c *baseClient) releaseConn(ctx context.Context, cn *pool.Conn, err error) c.opt.Limiter.ReportResult(err) } - if isBadConn(err, false, c.opt.Addr) { + if isBadConn(ctx, err, false, c.opt.Addr, false) { c.connPool.Remove(ctx, cn, err) } else { c.connPool.Put(ctx, cn) From 7d4e158079ad23a629d5a4cf203727152ce12484 Mon Sep 17 00:00:00 2001 From: Tim Zhu Date: Fri, 14 Mar 2025 11:59:05 -0400 Subject: [PATCH 3/7] is this a bug --- osscluster.go | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/osscluster.go b/osscluster.go index 12fd4c605..799a39c36 100644 --- a/osscluster.go +++ b/osscluster.go @@ -1396,9 +1396,10 @@ func (c *ClusterClient) pipelineReadCmds( cmds []Cmder, failedCmds *cmdsMap, ) error { - internal.Logger.Printf(ctx, "------------------pipelineReadCmds-----------------------") for i, cmd := range cmds { err := cmd.readReply(rd) + shouldLog := rand.Intn(10) == 0 + internal.Logger.Printf(ctx, "--------------err before %s--------------", err) cmd.SetErr(err) if err == nil { @@ -1408,9 +1409,9 @@ func (c *ClusterClient) pipelineReadCmds( if c.checkMovedErr(ctx, cmd, err, failedCmds) { continue } - + internal.Logger.Printf(ctx, "--------------err after %s--------------", err) // we may get >1k errors per second, lower the log volume to 1% - shouldLog := rand.Intn(100) == 0 + if c.opt.ReadOnly && isBadConn(ctx, err, false, node.Client.getAddr(), shouldLog) { node.MarkAsFailing() } From 2b158929b139dbac94f929ea3f74798de7e98a5a Mon Sep 17 00:00:00 2001 From: Tim Zhu Date: Fri, 14 Mar 2025 12:13:31 -0400 Subject: [PATCH 4/7] log better --- osscluster.go | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/osscluster.go b/osscluster.go index 799a39c36..eb772047a 100644 --- a/osscluster.go +++ b/osscluster.go @@ -1398,18 +1398,19 @@ func (c *ClusterClient) pipelineReadCmds( ) error { for i, cmd := range cmds { err := cmd.readReply(rd) - shouldLog := rand.Intn(10) == 0 - internal.Logger.Printf(ctx, "--------------err before %s--------------", err) cmd.SetErr(err) if err == nil { continue } + shouldLog := rand.Intn(10) == 0 + internal.Logger.Printf(ctx, "--------------err before %s--------------", err) if c.checkMovedErr(ctx, cmd, err, failedCmds) { + internal.Logger.Printf(ctx, "--------------err after %s--------------", err) continue } - internal.Logger.Printf(ctx, "--------------err after %s--------------", err) + internal.Logger.Printf(ctx, "--------------err after continue %s--------------", err) // we may get >1k errors per second, lower the log volume to 1% if c.opt.ReadOnly && isBadConn(ctx, err, false, node.Client.getAddr(), shouldLog) { From f2d67881881fcaf3d0cee36b7ae3268389eb953c Mon Sep 17 00:00:00 2001 From: Tim Zhu Date: Fri, 14 Mar 2025 12:30:37 -0400 Subject: [PATCH 5/7] print better --- error.go | 12 ++++++------ osscluster.go | 6 +++--- 2 files changed, 9 insertions(+), 9 deletions(-) diff --git a/error.go b/error.go index 009d4e7ca..2615d2c1e 100644 --- a/error.go +++ b/error.go @@ -90,32 +90,32 @@ func isRedisError(err error) bool { func isBadConn(ctx context.Context, err error, allowTimeout bool, addr string, shouldLog bool) bool { switch err { case nil: - internal.Logger.Printf(ctx, "go-redis:nil error: %s", err) + internal.Logger.Printf(ctx, "go-redis:nil error: %v", err) return false case context.Canceled, context.DeadlineExceeded: - internal.Logger.Printf(ctx, "go-redis: context error: %s", err) + internal.Logger.Printf(ctx, "go-redis: context error: %v", err) return true } if isRedisError(err) { switch { case isReadOnlyError(err): - internal.Logger.Printf(ctx, "go-redis: is read-only error: %s", err) + internal.Logger.Printf(ctx, "go-redis: is read-only error: %v", err) // Close connections in read only state in case domain addr is used // and domain resolves to a different Redis Server. See #790. return true case isMovedSameConnAddr(err, addr): - internal.Logger.Printf(ctx, "go-redis: is isMovedSameConnAddr error: %s", err) + internal.Logger.Printf(ctx, "go-redis: is isMovedSameConnAddr error: %v", err) // Close connections when we are asked to move to the same addr // of the connection. Force a DNS resolution when all connections // of the pool are recycled return true default: - internal.Logger.Printf(ctx, "go-redis:other redis error: %s", err) + internal.Logger.Printf(ctx, "go-redis:other redis error: %v", err) return false } } - internal.Logger.Printf(ctx, "go-redis:other error: %s", err) + internal.Logger.Printf(ctx, "go-redis:other error: %v", err) if allowTimeout { if netErr, ok := err.(net.Error); ok && netErr.Timeout() { return false diff --git a/osscluster.go b/osscluster.go index eb772047a..eae79f05f 100644 --- a/osscluster.go +++ b/osscluster.go @@ -1405,12 +1405,12 @@ func (c *ClusterClient) pipelineReadCmds( } shouldLog := rand.Intn(10) == 0 - internal.Logger.Printf(ctx, "--------------err before %s--------------", err) + internal.Logger.Printf(ctx, "--------------err before isNil:%v err: %v string: %s------------", err == nil, err, err.Error()) if c.checkMovedErr(ctx, cmd, err, failedCmds) { - internal.Logger.Printf(ctx, "--------------err after %s--------------", err) + internal.Logger.Printf(ctx, "--------------err after isNil:%v err: %v------------", err == nil, err) continue } - internal.Logger.Printf(ctx, "--------------err after continue %s--------------", err) + internal.Logger.Printf(ctx, "--------------err after continueisNil:%v err: %v------------", err == nil, err) // we may get >1k errors per second, lower the log volume to 1% if c.opt.ReadOnly && isBadConn(ctx, err, false, node.Client.getAddr(), shouldLog) { From f97b8dcf177d6af562df54384b02187592a6c4f1 Mon Sep 17 00:00:00 2001 From: Tim Zhu Date: Fri, 14 Mar 2025 12:56:36 -0400 Subject: [PATCH 6/7] sample log correctly --- error.go | 21 ++++++++++++++++----- osscluster.go | 7 +------ 2 files changed, 17 insertions(+), 11 deletions(-) diff --git a/error.go b/error.go index 2615d2c1e..6448da08d 100644 --- a/error.go +++ b/error.go @@ -10,6 +10,7 @@ import ( "github.com/redis/go-redis/v9/internal" "github.com/redis/go-redis/v9/internal/pool" "github.com/redis/go-redis/v9/internal/proto" + "github.com/redis/go-redis/v9/internal/rand" ) // ErrClosed performs any operation on the closed client will return this error. @@ -88,30 +89,40 @@ func isRedisError(err error) bool { } func isBadConn(ctx context.Context, err error, allowTimeout bool, addr string, shouldLog bool) bool { + // sample logging the error as it could get up to 1k errors per second + shouldLog = shouldLog && rand.Intn(100) == 0 switch err { case nil: - internal.Logger.Printf(ctx, "go-redis:nil error: %v", err) + if shouldLog { + internal.Logger.Printf(ctx, "isBadConn: nil error: %v", err) + } return false case context.Canceled, context.DeadlineExceeded: - internal.Logger.Printf(ctx, "go-redis: context error: %v", err) + internal.Logger.Printf(ctx, "isBadConn: context error: %v", err) return true } if isRedisError(err) { switch { case isReadOnlyError(err): - internal.Logger.Printf(ctx, "go-redis: is read-only error: %v", err) + if shouldLog { + internal.Logger.Printf(ctx, "isBadConn: is read-only error: %v", err) + } // Close connections in read only state in case domain addr is used // and domain resolves to a different Redis Server. See #790. return true case isMovedSameConnAddr(err, addr): - internal.Logger.Printf(ctx, "go-redis: is isMovedSameConnAddr error: %v", err) + if shouldLog { + internal.Logger.Printf(ctx, "isBadConn: is isMovedSameConnAddr error: %v", err) + } // Close connections when we are asked to move to the same addr // of the connection. Force a DNS resolution when all connections // of the pool are recycled return true default: - internal.Logger.Printf(ctx, "go-redis:other redis error: %v", err) + if shouldLog { + internal.Logger.Printf(ctx, "isBadConn:other redis error: %v", err) + } return false } } diff --git a/osscluster.go b/osscluster.go index eae79f05f..f410747d9 100644 --- a/osscluster.go +++ b/osscluster.go @@ -1404,16 +1404,11 @@ func (c *ClusterClient) pipelineReadCmds( continue } - shouldLog := rand.Intn(10) == 0 - internal.Logger.Printf(ctx, "--------------err before isNil:%v err: %v string: %s------------", err == nil, err, err.Error()) if c.checkMovedErr(ctx, cmd, err, failedCmds) { - internal.Logger.Printf(ctx, "--------------err after isNil:%v err: %v------------", err == nil, err) continue } - internal.Logger.Printf(ctx, "--------------err after continueisNil:%v err: %v------------", err == nil, err) - // we may get >1k errors per second, lower the log volume to 1% - if c.opt.ReadOnly && isBadConn(ctx, err, false, node.Client.getAddr(), shouldLog) { + if c.opt.ReadOnly && isBadConn(ctx, err, false, node.Client.getAddr(), true) { node.MarkAsFailing() } From 1c00572289a512996dc8e19c9592c5c1b6efe668 Mon Sep 17 00:00:00 2001 From: Tim Zhu Date: Fri, 14 Mar 2025 13:35:24 -0400 Subject: [PATCH 7/7] wrap one more --- error.go | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/error.go b/error.go index 6448da08d..82ad46d52 100644 --- a/error.go +++ b/error.go @@ -126,7 +126,9 @@ func isBadConn(ctx context.Context, err error, allowTimeout bool, addr string, s return false } } - internal.Logger.Printf(ctx, "go-redis:other error: %v", err) + if shouldLog { + internal.Logger.Printf(ctx, "go-redis:other error: %v", err) + } if allowTimeout { if netErr, ok := err.(net.Error); ok && netErr.Timeout() { return false