database/sql: reuses expired connections with strategy= alwaysNewConn

[gwax]

What version of Go are you using (go version)?

$ go version
go version go1.11.5 darwin/amd64

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/georgeleslie-waksman/Library/Caches/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/georgeleslie-waksman/co/backend/go"
GOPROXY=""
GORACE=""
GOROOT="/Users/georgeleslie-waksman/co/backend/opt/go1.11.5"
GOTMPDIR=""
GOTOOLDIR="/Users/georgeleslie-waksman/co/backend/opt/go1.11.5/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/41/19kt662x72n9nfj8hzb8t1q00000gq/T/go-build118274996=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

When connections are released, they may bypass the pool and be used to fulfill requests made with strategy=alwaysNewConn even if they are "expired" according to SetConnMaxLifetime, which allows the connections to fail on BeginTx with ErrBadConn despite passing through putConn with err == nil

The following testcase (for database/sql_test.go) exhibits the failure case:

func TestPutConnExpiredOrBadReset(t *testing.T) {
	execCases := []struct{
		expired bool
		badReset bool
	}{
		{false, false},
		{true, false},
		{false, true},
	}

	t0 := time.Unix(1000000, 0)
	offset := time.Duration(0)

	nowFunc = func() time.Time { return t0.Add(offset) }
	defer func() { nowFunc = time.Now}()

	ctx, cancel := context.WithCancel(context.Background())
	defer cancel()

	db := newTestDB(t, "magicquery")
	defer closeDB(t, db)

	db.SetMaxOpenConns(1)

	for _, ec := range execCases {
		ec := ec
		name := fmt.Sprintf("expired=%t,badReset=%t", ec.expired, ec.badReset)
		t.Run(name, func(t *testing.T) {
			db.clearAllConns(t)

			db.SetMaxIdleConns(1)
			db.SetConnMaxLifetime(10 * time.Second)

			conn, err := db.conn(ctx, alwaysNewConn)
			if err != nil {
				t.Fatal(err)
			}

			var wg sync.WaitGroup
			wg.Add(1)
			go func() {
				defer wg.Done()
				conn, err := db.conn(ctx, alwaysNewConn)
				if err != nil {
					t.Fatal(err)
				}
				db.putConn(conn, err, false)
			}()

			// Wait for pending request
			for len(db.connRequests) < 1 {}

			if ec.expired {
				offset = 11 * time.Second
			} else {
				offset = time.Duration(0)
			}

			if ec.badReset {
				conn.ci.(*fakeConn).stickyBad = true
			}
			db.putConn(conn, err, true)

			wg.Wait()
		})
	}
}

with output:

--- FAIL: TestPutConnExpiredOrBadReset (0.00s)
    --- FAIL: TestPutConnExpiredOrBadReset/expired=true,badReset=false (0.00s)
        sql_test.go:2226: driver: bad connection
    --- FAIL: TestPutConnExpiredOrBadReset/expired=false,badReset=true (0.00s)
        sql_test.go:2226: driver: bad connection
FAIL
FAIL	_/Users/georgeleslie-waksman/co/go/src/database/sql	1.337s

What did you expect to see?

BeginTx's third attempt with strategy=alwaysNewConn should not reuse an existing connection and should definitely not reuse an expired connection.

What did you see instead?

BeginTx's third attempt fails with ErrBadConn due to connection expiration.

[gwax]

To the best of my understanding, we can resolve the issue by modifying putConnDbLocked so that only new connections may only be directly used to fulfill requests and reused connections must pass through the idle pool.

[gwax]

This issue also occurs and is seriously exacerbated if the session resetter channel db.resetterCh becomes blocked, in which case connections will be released back with err = driver.ErrBadConn and sent for reuse.

[ianlancetaylor]

CC @kardianos

[gwax]

I have updated the issue with a more minimal failure case that can be dropped directly into database/sql_test.go

[gwax]

I have put together a fix and submitted a PR: #32656

[gopherbot]

Change https://golang.org/cl/182599 mentions this issue: database/sql: prevent conn reuse on new conn request

[kardianos]

@gwax Let's ignore the session resetter issue for now, I will resolve that in the next release.

Can you explain when you encounter this issue, and what it looks like for your application when you do? Thanks.

[gwax]

In our application, with SetConnMaxLifetime, we experience a small but steady rate of driver.ErrBadConn being returned by DB.BeginTx.

In debugging and tracing the issue, we found the code path is as follows:

1. DB.BeginTx tries twice with strategy == cachedOrNewConn, getting driver.ErrBadConn both times: https://github.com/golang/go/blob/master/src/database/sql/sql.go#L1676
2. DB.BeginTx calls DB.begin with strategy == alwaysNewConn: https://github.com/golang/go/blob/master/src/database/sql/sql.go#L1682
3. DB.begin calls DB.conn with strategy == alwaysNewConn: https://github.com/golang/go/blob/master/src/database/sql/sql.go#L1694
4. We have the maximum number of connections open so we push a request to db.connRequests: https://github.com/golang/go/blob/master/src/database/sql/sql.go#L1176
5. (thread2) Concurrently to this, another thread finishes execution with a connection that has gone (or is just about to go over its lifetime) and attempts to put the connection back: https://github.com/golang/go/blob/master/src/database/sql/sql.go#L1322
6. (thread2) The released connection is then used to satisfy the pending request (reused connection for a new alwaysNewConn request): https://github.com/golang/go/blob/master/src/database/sql/sql.go#L1371
7. DB.conn checks if the connection has expired (it has) and we return driver.ErrBadConn: https://github.com/golang/go/blob/master/src/database/sql/sql.go#L1207

Adding an expiry check to the putConn codepath decreased the rate of errors (smaller concurrency race window) but did not eliminate them.

Enabling session resetter hits the same race condition but spikes our error rate. In this case, the resetter was overloaded and we were having dc.lastErr set concurrently to the connection release (step 6): https://github.com/golang/go/blob/master/src/database/sql/sql.go#L1339

[gwax]

The PR that I have submitted is fairly large and is, perhaps, clearer to understand as two separate changes (I can resubmit as two PRs, if that makes it easier).

The first change is quite large, and refactors db.freeConn from []*driverConn to chan *driverConn. This change is necessary so that while we are at max connections and waiting for a request to be filled, we can use a case statement to unblock on either a direct request or on a connection going to the pool: 6baa77b

The second change is quite small and makes sure that reused sessions always go to the connection pool, not connRequests: 9816712