GetContext never returns in case of TLS setting is ON for Redis Server

[vichauhan18]

I have setup local Redis Server and enabled redis.DialUseTLS(true) with its password using redis.DialPassword by mistake. This server doesn't support TLS. I am creating pool connection and everything was fine but while getting the connection value from from the pool using GetContext() method, it got stuck into infinite loop at Handshake() API. Ideally, API should return some error or atleast time out.

All my time out values setup properly like IdleTimeout, MaxIdle, DialConnectTimeout, DialReadTimeout and DialWriteTimeout.

[stevenh]

I'm not sure I understand as there no loop around HandShake()

Could you provide an example and resulting output?

[vichauhan18]

I am posting the sample code. Hope this helps

package main
import (
	"time"
	"github.com/gomodule/redigo/redis"
)

func main() {
	pool := &redis.Pool{
		MaxIdle:     10,
		IdleTimeout: 15 * time.Second,
		Dial: func() (redis.Conn, error) {
			c, err := redis.Dial("tcp", "localhost:6379",
				redis.DialConnectTimeout(time.Duration(15*time.Second)),
				redis.DialWriteTimeout(time.Duration(20*time.Second)),
				redis.DialPassword("Sgh27rV6D2bLRnF3339GGvGc22VSezGJUdP12"),
				redis.DialUseTLS(true),
			)
			return c, err
		},
	}
	wConn := pool.Get()   // This call goes into infinite loop, I tried GetContext() as well 
	defer wConn.Close()
}

[stevenh]

Some little cleanups you can make on that code, but looks sane otherwise:

package main

import (
	"time"
	"github.com/gomodule/redigo/redis"
)

func main() {
	pool := &redis.Pool{
		MaxIdle:     10,
		IdleTimeout: 15 * time.Second,
		Dial: func() (redis.Conn, error) {
			return redis.Dial("tcp", "localhost:6379",
				redis.DialConnectTimeout(15*time.Second),
				redis.DialWriteTimeout(20*time.Second),
				redis.DialPassword("Sgh27rV6D2bLRnF3339GGvGc22VSezGJUdP12"),
				redis.DialUseTLS(true),
                                redis.DialTLSSkipVerify(true), // You need either this or DialTLSConfig
			)
		},
	}
	c := pool.Get()   // This call goes into infinite loop, I tried GetContext() as well 
	defer c.Close()
}

You say it goes into an infinite loop, could you provide the stack traces which show that happening?

[razor-1]

This is trivial to reproduce - enable TLS when pointed to a redis instance that doesn't have TLS support. Handshake() blocks forever.

[stevenh]

That should result in the net package triggering the connection timeout. If this doesn't happen it could be a bug in the underlying net.Dialer.

A stack from a failing example might help confirm or deny that @razor-1

[stevenh]

I just found the following: golang/go#17708

This might be you don't have a read timeout, again a stack trace should help.

[razor-1]

Stack trace as requested:

SIGQUIT: quit
PC=0x7fff6b0eb882 m=0 sigcode=0

goroutine 0 [idle]:
runtime.pthread_cond_wait(0x277d628, 0x277d5e8, 0x0)
        /Users/jon/gocode/go1.14.3/src/runtime/sys_darwin.go:390 +0x39
runtime.semasleep(0xffffffffffffffff, 0x0)
        /Users/jon/gocode/go1.14.3/src/runtime/os_darwin.go:63 +0x85
runtime.notesleep(0x277d3e8)
        /Users/jon/gocode/go1.14.3/src/runtime/lock_sema.go:173 +0xe0
runtime.stopm()
        /Users/jon/gocode/go1.14.3/src/runtime/proc.go:1828 +0xc0
runtime.findrunnable(0xc00004b800, 0x0)
        /Users/jon/gocode/go1.14.3/src/runtime/proc.go:2360 +0xa0d
runtime.schedule()
        /Users/jon/gocode/go1.14.3/src/runtime/proc.go:2520 +0x2fc
runtime.park_m(0xc000000180)
        /Users/jon/gocode/go1.14.3/src/runtime/proc.go:2690 +0x9d
runtime.mcall(0x1066096)
        /Users/jon/gocode/go1.14.3/src/runtime/asm_amd64.s:318 +0x5b

goroutine 1 [IO wait]:
internal/poll.runtime_pollWait(0xa211518, 0x72, 0xffffffffffffffff)
        /Users/jon/gocode/go1.14.3/src/runtime/netpoll.go:203 +0x55
internal/poll.(*pollDesc).wait(0xc0003fe498, 0x72, 0x200, 0x205, 0xffffffffffffffff)
        /Users/jon/gocode/go1.14.3/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
        /Users/jon/gocode/go1.14.3/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc0003fe480, 0xc00052a000, 0x205, 0x205, 0x0, 0x0, 0x0)
        /Users/jon/gocode/go1.14.3/src/internal/poll/fd_unix.go:169 +0x201
net.(*netFD).Read(0xc0003fe480, 0xc00052a000, 0x205, 0x205, 0x203000, 0x277d2a0, 0x2b01560)
        /Users/jon/gocode/go1.14.3/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc000506008, 0xc00052a000, 0x205, 0x205, 0x0, 0x0, 0x0)
        /Users/jon/gocode/go1.14.3/src/net/net.go:184 +0x8e
crypto/tls.(*atLeastReader).Read(0xc000522020, 0xc00052a000, 0x205, 0x205, 0xc00052a000, 0x0, 0xc00041e248)
        /Users/jon/gocode/go1.14.3/src/crypto/tls/conn.go:760 +0x60
bytes.(*Buffer).ReadFrom(0xc00051a258, 0x203c2e0, 0xc000522020, 0x100c2f5, 0x1c77d20, 0x1d60400)
        /Users/jon/gocode/go1.14.3/src/bytes/buffer.go:204 +0xb1
crypto/tls.(*Conn).readFromUntil(0xc00051a000, 0xb800008, 0xc000506008, 0x5, 0xc000506008, 0xc00041e330)
        /Users/jon/gocode/go1.14.3/src/crypto/tls/conn.go:782 +0xec
crypto/tls.(*Conn).readRecordOrCCS(0xc00051a000, 0x0, 0xfc, 0x0)
        /Users/jon/gocode/go1.14.3/src/crypto/tls/conn.go:589 +0x115
crypto/tls.(*Conn).readRecord(...)
        /Users/jon/gocode/go1.14.3/src/crypto/tls/conn.go:557
crypto/tls.(*Conn).readHandshake(0xc00051a000, 0xc000526016, 0xc000526000, 0xfc, 0x180)
        /Users/jon/gocode/go1.14.3/src/crypto/tls/conn.go:973 +0x6d
crypto/tls.(*Conn).clientHandshake(0xc00051a000, 0x0, 0x0)
        /Users/jon/gocode/go1.14.3/src/crypto/tls/handshake_client.go:169 +0x279
crypto/tls.(*Conn).Handshake(0xc00051a000, 0x0, 0x0)
        /Users/jon/gocode/go1.14.3/src/crypto/tls/conn.go:1340 +0xcc
github.com/gomodule/redigo/redis.DialContext(0x20570c0, 0xc0001a0050, 0x1d969e9, 0x3, 0xc00020ffb0, 0xe, 0xc00041eb48, 0x8, 0x8, 0x39, ...)
        /Users/jon/gocode/pkg/mod/github.com/gomodule/redigo@v1.8.2/redis/conn.go:241 +0x255
github.com/gomodule/redigo/redis.Dial(...)
        /Users/jon/gocode/pkg/mod/github.com/gomodule/redigo@v1.8.2/redis/conn.go:201
hourglass/db.NewRedisPool.func1(0x30, 0x30, 0xc0004b2600, 0x0)
        /Users/jon/gocode/src/hourglass/db/db.go:123 +0x320
github.com/gomodule/redigo/redis.(*Pool).dial(0xc000316ea0, 0x20570c0, 0xc0001a0050, 0x0, 0x0, 0x0, 0x2)
        /Users/jon/gocode/pkg/mod/github.com/gomodule/redigo@v1.8.2/redis/pool.go:412 +0x40
github.com/gomodule/redigo/redis.(*Pool).GetContext(0xc000316ea0, 0x20570c0, 0xc0001a0050, 0x32, 0xc00041f000, 0x1, 0x1)
        /Users/jon/gocode/pkg/mod/github.com/gomodule/redigo@v1.8.2/redis/pool.go:257 +0x69d
github.com/gomodule/redigo/redis.(*Pool).Get(...)
        /Users/jon/gocode/pkg/mod/github.com/gomodule/redigo@v1.8.2/redis/pool.go:189
hourglass/db.checkRedis(0xc000316ea0, 0x1d9c893, 0x9)
        /Users/jon/gocode/src/hourglass/db/db.go:145 +0xf1
hourglass/db.NewDB(0x1da9c3a, 0x16, 0x258, 0xc0000381cd, 0x5, 0xc00003802e, 0xf, 0xc00020fea0, 0xf, 0x10, ...)
        /Users/jon/gocode/src/hourglass/db/db.go:94 +0x5ad
main.main()
        /Users/jon/gocode/src/hourglass/cmd/main.go:26 +0x17a

goroutine 20 [select]:
database/sql.(*DB).connectionOpener(0xc0002f0900, 0x2057080, 0xc0004b6480)
        /Users/jon/gocode/go1.14.3/src/database/sql/sql.go:1052 +0xe8
created by database/sql.OpenDB
        /Users/jon/gocode/go1.14.3/src/database/sql/sql.go:722 +0x15d

goroutine 21 [select]:
database/sql.(*DB).connectionResetter(0xc0002f0900, 0x2057080, 0xc0004b6480)
        /Users/jon/gocode/go1.14.3/src/database/sql/sql.go:1065 +0xfb
created by database/sql.OpenDB
        /Users/jon/gocode/go1.14.3/src/database/sql/sql.go:723 +0x193

goroutine 34 [select]:
github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher.func1(0xc000502060, 0xc0004aac60, 0xc00050a000)
        /Users/jon/gocode/pkg/mod/github.com/go-sql-driver/mysql@v1.5.0/connection.go:621 +0xbf
created by github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher
        /Users/jon/gocode/pkg/mod/github.com/go-sql-driver/mysql@v1.5.0/connection.go:618 +0xbe

rax    0x104
rbx    0x2
rcx    0x7ffeefbff238
rdx    0x1c00
rdi    0x277d628
rsi    0x1c0100001d00
rbp    0x7ffeefbff2d0
rsp    0x7ffeefbff238
r8     0x0
r9     0xa0
r10    0x0
r11    0x202
r12    0x277d628
r13    0x16
r14    0x1c0100001d00
r15    0xfb5adc0
rip    0x7fff6b0eb882
rflags 0x203
cs     0x7
fs     0x0
gs     0x0

Process finished with exit code 2

[stevenh]

So that's waiting for a read try adding a read timeout to you dialer:

redis.DialReadTimeout(20*time.Second),

[razor-1]

There is one, that is set. I will provide a full code sample with all details and another stack trace from that code shortly.

[razor-1]

package main

import (
	"crypto/tls"
	"fmt"
	"time"

	log "github.com/sirupsen/logrus"

	"github.com/gomodule/redigo/redis"
)

func main() {
	const redisAddr = "localhost"
	pool := NewRedisPool(redisAddr)
	checkRedis(pool, redisAddr)
}


func NewRedisPool(redisAddr string) *redis.Pool {
	redisTLSConfig := &tls.Config{
		ServerName:         redisAddr,
		InsecureSkipVerify: false,
		MinVersion:         tls.VersionTLS12,
	}
	pool := &redis.Pool{
		Dial: func() (redis.Conn, error) {
			oneSec := 1 * time.Second
			return redis.Dial("tcp", fmt.Sprintf("%s:%d", redisAddr, 6379),
				redis.DialConnectTimeout(oneSec),
				redis.DialReadTimeout(oneSec),
				redis.DialWriteTimeout(oneSec),
				redis.DialUseTLS(true),
				redis.DialTLSSkipVerify(false),
				redis.DialTLSConfig(redisTLSConfig),
			)
		},
		MaxIdle:     300,
		MaxActive:   20000,
		IdleTimeout: 240 * time.Second,
	}

	return pool
}

//checkRedis just does a ping to make sure we can talk to redis. we want to fail starting up if we can't
func checkRedis(pool *redis.Pool, addr string) {
	log.Infof("redis is enabled. verifying connectivity to %s ...", addr)
	conn := pool.Get()
	defer conn.Close()

	_, err := conn.Do("PING")
	if err != nil {
		log.Fatalf("cannot connect to redis: %v", err)
	}

	log.Info("redis connectivity verified!")
}

the above, when run against a redis:5.0.6 container listening on localhost:6379, yields the following stack trace after waiting > 10s

INFO[0000] redis is enabled. verifying connectivity to localhost ... 
SIGQUIT: quit
PC=0x7fff6b0eb882 m=0 sigcode=0

goroutine 0 [idle]:
runtime.pthread_cond_wait(0x14133a8, 0x1413368, 0x0)
	/usr/local/Cellar/go/1.14.5/libexec/src/runtime/sys_darwin.go:390 +0x39
runtime.semasleep(0xffffffffffffffff, 0x0)
	/usr/local/Cellar/go/1.14.5/libexec/src/runtime/os_darwin.go:63 +0x85
runtime.notesleep(0x1413168)
	/usr/local/Cellar/go/1.14.5/libexec/src/runtime/lock_sema.go:173 +0xe0
runtime.stopm()
	/usr/local/Cellar/go/1.14.5/libexec/src/runtime/proc.go:1834 +0xc0
runtime.findrunnable(0xc000026800, 0x0)
	/usr/local/Cellar/go/1.14.5/libexec/src/runtime/proc.go:2366 +0xa0d
runtime.schedule()
	/usr/local/Cellar/go/1.14.5/libexec/src/runtime/proc.go:2526 +0x2fc
runtime.park_m(0xc000000180)
	/usr/local/Cellar/go/1.14.5/libexec/src/runtime/proc.go:2696 +0x9d
runtime.mcall(0x105f806)
	/usr/local/Cellar/go/1.14.5/libexec/src/runtime/asm_amd64.s:318 +0x5b

goroutine 1 [IO wait]:
internal/poll.runtime_pollWait(0x9cc5f18, 0x72, 0xffffffffffffffff)
	/usr/local/Cellar/go/1.14.5/libexec/src/runtime/netpoll.go:203 +0x55
internal/poll.(*pollDesc).wait(0xc00013c098, 0x72, 0x200, 0x205, 0xffffffffffffffff)
	/usr/local/Cellar/go/1.14.5/libexec/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/Cellar/go/1.14.5/libexec/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc00013c080, 0xc0000b0000, 0x205, 0x205, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.14.5/libexec/src/internal/poll/fd_unix.go:169 +0x201
net.(*netFD).Read(0xc00013c080, 0xc0000b0000, 0x205, 0x205, 0x203000, 0x1413020, 0x30007d0)
	/usr/local/Cellar/go/1.14.5/libexec/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc000094000, 0xc0000b0000, 0x205, 0x205, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.14.5/libexec/src/net/net.go:184 +0x8e
crypto/tls.(*atLeastReader).Read(0xc0000a6020, 0xc0000b0000, 0x205, 0x205, 0xc0000b0000, 0x0, 0xc000131488)
	/usr/local/Cellar/go/1.14.5/libexec/src/crypto/tls/conn.go:760 +0x60
bytes.(*Buffer).ReadFrom(0xc0000a0258, 0x12a49c0, 0xc0000a6020, 0x100ba55, 0x1220ec0, 0x124b820)
	/usr/local/Cellar/go/1.14.5/libexec/src/bytes/buffer.go:204 +0xb1
crypto/tls.(*Conn).readFromUntil(0xc0000a0000, 0x9c85008, 0xc000094000, 0x5, 0xc000094000, 0xc000131570)
	/usr/local/Cellar/go/1.14.5/libexec/src/crypto/tls/conn.go:782 +0xec
crypto/tls.(*Conn).readRecordOrCCS(0xc0000a0000, 0x0, 0xfc, 0x0)
	/usr/local/Cellar/go/1.14.5/libexec/src/crypto/tls/conn.go:589 +0x115
crypto/tls.(*Conn).readRecord(...)
	/usr/local/Cellar/go/1.14.5/libexec/src/crypto/tls/conn.go:557
crypto/tls.(*Conn).readHandshake(0xc0000a0000, 0xc0000ac016, 0xc0000ac000, 0xfc, 0x180)
	/usr/local/Cellar/go/1.14.5/libexec/src/crypto/tls/conn.go:973 +0x6d
crypto/tls.(*Conn).clientHandshake(0xc0000a0000, 0x0, 0x0)
	/usr/local/Cellar/go/1.14.5/libexec/src/crypto/tls/handshake_client.go:169 +0x279
crypto/tls.(*Conn).Handshake(0xc0000a0000, 0x0, 0x0)
	/usr/local/Cellar/go/1.14.5/libexec/src/crypto/tls/conn.go:1340 +0xcc
github.com/gomodule/redigo/redis.DialContext(0x12a7c80, 0xc0000180f8, 0x1258afc, 0x3, 0xc0000183d0, 0xe, 0xc000131d68, 0x6, 0x6, 0xc000126380, ...)
	/Users/jon/gocode/pkg/mod/github.com/gomodule/redigo@v1.8.2/redis/conn.go:241 +0x255
github.com/gomodule/redigo/redis.Dial(...)
	/Users/jon/gocode/pkg/mod/github.com/gomodule/redigo@v1.8.2/redis/conn.go:201
main.NewRedisPool.func1(0x30, 0x30, 0xc00007c8a0, 0x0)
	/Users/jon/gocode/src/awesomeProject2/main.go:29 +0x24b
github.com/gomodule/redigo/redis.(*Pool).dial(0xc000122120, 0x12a7c80, 0xc0000180f8, 0x0, 0x0, 0x0, 0x0)
	/Users/jon/gocode/pkg/mod/github.com/gomodule/redigo@v1.8.2/redis/pool.go:412 +0x40
github.com/gomodule/redigo/redis.(*Pool).GetContext(0xc000122120, 0x12a7c80, 0xc0000180f8, 0x32, 0xc000131f30, 0x1, 0x1)
	/Users/jon/gocode/pkg/mod/github.com/gomodule/redigo@v1.8.2/redis/pool.go:257 +0x69d
github.com/gomodule/redigo/redis.(*Pool).Get(...)
	/Users/jon/gocode/pkg/mod/github.com/gomodule/redigo@v1.8.2/redis/pool.go:189
main.checkRedis(0xc000122120, 0x1259999, 0x9)
	/Users/jon/gocode/src/awesomeProject2/main.go:49 +0xf1
main.main()
	/Users/jon/gocode/src/awesomeProject2/main.go:16 +0x59

rax    0x104
rbx    0x2
rcx    0x7ffeefbff498
rdx    0x200
rdi    0x14133a8
rsi    0x20100000300
rbp    0x7ffeefbff530
rsp    0x7ffeefbff498
r8     0x0
r9     0xa0
r10    0x0
r11    0x202
r12    0x14133a8
r13    0x16
r14    0x20100000300
r15    0xaf3cdc0
rip    0x7fff6b0eb882
rflags 0x203
cs     0x7
fs     0x0
gs     0x0

[stevenh]

Thanks @razor-1 that really helped.

Can you test #530 with a configured DialTLSHandshakeTimeout to see if that fixes it for you?