database/sql: SetConnMaxIdleTime, SetConnMaxLifetime order impacts close time

[eqinox76]

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

$ go version
go version go1.16.3 linux/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
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/carsten/.cache/go-build"
GOENV="/home/carsten/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/carsten/go/pkg/mod"
GONOPROXY="dev.azure.com/xtp"
GONOSUMDB="dev.azure.com/xtp"
GOOS="linux"
GOPATH="/home/carsten/go"
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/snap/go/7360"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/snap/go/7360/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.16.3"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/dev/null"
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 -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build3305456222=/tmp/go-build -gno-record-gcc-switches"
GOROOT/bin/go version: go version go1.16.3 linux/amd64
GOROOT/bin/go tool compile -V: compile version go1.16.3
uname -sr: Linux 5.8.0-50-generic
Distributor ID:	Ubuntu
Description:	Ubuntu 20.04.2 LTS
Release:	20.04
Codename:	focal
/lib/x86_64-linux-gnu/libc.so.6: GNU C Library (Ubuntu GLIBC 2.31-0ubuntu9.2) stable release version 2.31.
gdb --version: GNU gdb (Ubuntu 9.2-0ubuntu1~20.04) 9.2

What did you do?

When using

db.SetConnMaxIdleTime(5 * time.Second)
db.SetConnMaxLifetime(5 * time.Hour)

idle connections get closed after 5 hours. While setting the parameters in reverse order works fine.

db.SetConnMaxLifetime(5 * time.Hour)
db.SetConnMaxIdleTime(5 * time.Second)

What did you expect to see?

Closing idle connections after ~5s.

What did you see instead?

Closing connections after ~5h

I think this is due to sql.go#L1041 only checking if maxIdleTime has been reduced and not also if its smaller than maxLifetime.

[seankhliao]

@Equinox76 both lines look the same?

[eqinox76]

Thanks! Copy paste error which i corrected.

[seankhliao]

cc @bradfitz @kardianos @kevinburke

[latentflip]

I re-discovered this today and can add a little more context on how to reproduce it.

I believe @eqinox76's examples are actually backwards. Setting SetConnMaxIdleTime before SetConnMaxLifetime gives the correct behaviour, while setting SetConnMaxLifetime first gives the incorrect behavior.

Reproducing the bug

To trigger this bug, the following order of operations is required:

1. We have an open connection
2. We set SetConnMaxLifetime to something higher than our desired SetConnMaxIdleTime
3. We set SetConnMaxIdleTime

If this is the order of operations, then no idle connections will be closed until one SetConnMaxLifetime time has passed. After that we will cleanup connections every SetConnMaxIdleTime seconds as expected

Example code that triggers the bug:

package main

// Import go-sql-driver and connect to a mysqL server and make a basic query
import (
	"database/sql"
	"fmt"
	"time"

	_ "github.com/go-sql-driver/mysql"
)

func main() {
	db, _ := sql.Open("mysql", "root:@tcp(localhost:3306)/dbname")

        // Create a connection
	db.Ping()

	db.SetConnMaxLifetime(1000 * time.Second)
	db.SetConnMaxIdleTime(3 * time.Second)

	stats := db.Stats()
	fmt.Println("Open connections", stats.OpenConnections, "Idle connections", stats.Idle)

	fmt.Println("Sleep")
	// Should be long enough to clear idle connection
	time.Sleep(5 * time.Second)

	stats = db.Stats()
	fmt.Println("Open connections", stats.OpenConnections, "Idle connections", stats.Idle)
}

Expected output:

Open connections 1 Idle connections 1
Sleep
Open connections 0 Idle connections 0

Actual Output:

Open connections 1 Idle connections 1
Sleep
Open connections 1 Idle connections 1

Workarounds

To avoid the bug currently, either of the following changes will fix it:

1. Call SetConnMaxIdleTime before SetConnMaxLifetime:

	db.SetConnMaxLifetime(1000 * time.Second)
	db.SetConnMaxIdleTime(3 * time.Second)

2. Ensure that no active connections are setup when calling SetConnMaxLifetime and SetConnMaxIdleTime

Cause

When a connection exists and SetConnMaxLifetime is called, we will start the connectionCleaner with the interval set to our value of SetConnMaxLifetime.

https://github.com/golang/go/blob/master/src/database/sql/sql.go#L1046

Afterwards when we call SetConnMaxIdleTime we will not wake the cleaner because the existing logic only does so if we've reduced maxIdleTime, which we haven't. As suggested by @eqinox76 we probably should check additionally if if maxIdleTime has been set to less than maxLifetime and wake up the cleaner in that case too.

https://github.com/golang/go/blob/master/src/database/sql/sql.go#L1034

Why the workarounds work:

If there is no connection when we call these functions, then the cleaner is not started at all, and is only started after the first connection is allocated here, at which point it will use the lower maxIdleTime as expected.

https://github.com/golang/go/blob/master/src/database/sql/sql.go#L1521-L1523

Alternatively, calling SetConnMaxIdleTime before SetConnMaxLifetime ensures that the cleaner is setup with the shorter interval initially.

[gopherbot]

Change https://go.dev/cl/467655 mentions this issue: database/sql: wake cleaner if maxIdleTime set to less than maxLifetime