redis: discarding bad PubSub connection: redis: ping timeout 이슈

https://github.com/redis-go/redis

 

상황

- Docker Log 에서 아래와 같은 로그가 계속해서 찍혔다.

redis: 2022/06/13 08:42:40 pubsub.go:159: redis: discarding bad PubSub connection: redis: ping timeout

- 해당 로그를 확인해보니 pubsub.go 159 line 에서 발생한 것임을 알 수 있다.

  이는 go-redis 부분에서 발생하는 로그로 오픈소스 이슈일 가능성을 시사한다.

 

- 오픈소스 이슈일 때는 현재 프로젝트의 해당 오픈소스 버전이 몇인지를 먼저 확인하는 것이 중요하다.

github.com/go-redis/redis v6.15.9+incompatible

 

 

discarding bad PubSub connection 오류

• go-redis 의 pubsub.go 의 159line

func (c *PubSub) _closeTheCn(reason error) error {
	if c.cn == nil {
		return nil
	}
	if !c.closed {
		internal.Logf("redis: discarding bad PubSub connection: %s", reason)
	}
	err := c.closeConn(c.cn)
	c.cn = nil
	return err
}

• Ping Timeout , Redis 의 PubSub 연결이 시간지연으로 원활하게 이루어지지 않아 해당 세션을 삭제한다는 로그

 

해당 pubsub.go 가 어떻게 호출되는지를 알아봤다.

• main.go 139line 에서 Redis Sentinel 접속 세션 부분

// redis setting
	client := redis.NewFailoverClient(&redis.FailoverOptions{
		MasterName:    conf.RedisMasters,
		SentinelAddrs: []string{conf.RedisSentinelHost + ":" + conf.RedisSentinelPort},
	})
	defer client.Close()

→ NewFailoverClient() → failover.Pool() → dial → MasterAddr() → masterAddr() → c.setSentinel(sentinel) → c.listen(c.pubsub) → Channel() → initChannel() → ping → …

즉, Sentinel 세션을 생성하고자 할 때 기본적으로 pubsub 접속을 실행한다는 의미이다.

그러나 ping timeout 으로 인해 위와 같은 로그를 찍었다.

 

 

 

• Sentinel, discarding bad PubSub connection: redis: ping timeout #1518

https://github.com/go-redis/redis/issues/1518

go func() {
		timer := time.NewTimer(timeout)
		timer.Stop()

		healthy := true
		for {
			timer.Reset(timeout)
			select {
			case <-c.ping:
				healthy = true
				if !timer.Stop() {
					<-timer.C
				}
			case <-timer.C:
				pingErr := c.Ping()
				if healthy {
					healthy = false
				} else {
					if pingErr == nil {
						pingErr = errPingTimeout
					}
					c.mu.Lock()
					c._reconnect(pingErr)
					c.mu.Unlock()
				}
			case <-c.exit:
				return
			}
		}
	}()

• if the pubsub was previously healthy, it is changed to not healthy, which will trigger again a ping later
• if the pubsub was previously not healty, it is ALWAYS disconnected/reconnected, and an error is logged (even if the ping command didn't fail)
• even if pingErr is nil, it will be defined with errPingTimeout

 

시간 지연으로 인해 Health 가 False가 되면, pingErr 가 nil 임에도 불구하고 앞으로 Health 는 무조건 False 값으로 Reconnect 를 계속 하는상황

 

 

func (c *PubSub) initPing() error {
	//....
	go func() {
		timer := time.NewTimer(time.Minute)
		timer.Stop()

		healthy := true
		timeout := pingTimeout // 1 * time.Second
		for {
			timer.Reset(timeout)
			select {
			case <-c.ping:
				healthy = true
				timeout = pingTimeout
				if !timer.Stop() {
					<-timer.C
				}
			case <-timer.C:
				var healthyErr error

				if healthy {
					healthyErr = c.Ping(ctx)
					healthy = false
				} else {
					healthyErr = errPingTimeout
				}

				if healthyErr != nil {
					c.mu.Lock()
					c.reconnect(ctx, pingErr)
					c.mu.Unlock()

					healthy = true
					timeout = pingTimeout
				} else {
					timeout = c.healthTimeout
				}
			case <-c.exit:
				return
			}
		}
	}()
}

• Ping Timeout 이 발생하면 Healthy 값을 false 로 바꿔주고, Ping 으로 Error 를 검사함.
• 이후 Error 가 존재하면 Reconnect 를 진행하고, Health 를 다시 True 로 변환해줌
• 만일 HealthyError 가 없을 시에는 Reconnect 를 진행하지 않음

 

이는 go-redis v7 부터 반영되어 있다.

https://github.com/go-redis/redis/blob/v7/pubsub.go

GitHub - go-redis/redis: Type-safe Redis client for Golang

 

 

Go-redis 의 v6 오픈소스에서 발생한 이슈이며, 이는 Go-Redis 버전을 올리면 없어지는 이슈이다.

 

Go-Redis 오픈소스에서는 기존 Redis 6 버전을 사용자는 8로 업데이트하라며 권장하고 있다.