go-sql-driver/mysql を用いる際に (*DB).SetConnMaxLifetime は不要なのか


# はじめに

先日、GitHub Blog にて Go の MySQL Driver に関する記事が掲載されました。
[The GitHub Blog: Three bugs in the Go MySQL Driver](https://github.blog/2020-05-20-three-bugs-in-the-go-mysql-driver/)

ここでは Three bugs のうち、最初に挙げられている `The crash` について話します。

`The crash` は、切断されたコネクションをコネクションプールから引き当てて用いた際に `unexpected EOF` が発生する問題です。 
この問題に対して、今までは `(*DB).SetConnMaxLifetime` を設定することで、切断されたコネクションを再利用しないよう対処してきました。

go-sql-driver/mysql v1.5.0 では著者による修正がマージされており、記事中では `(*DB).SetConnMaxLifetime` が不要とされています。 

> If your MySQL server uses idle timeouts, or is actively pruning connections, you don’t need to call (*DB).SetConnMaxLifetime in your production services. It’s no longer needed as the driver can now gracefully detect and retry stale connections. Setting a max lifetime for connections simply causes unnecessary churn by killing and re-opening healthy connections.

しかし、時折コネクション周りのエラーログを見かけることがあり、挙動が気になったため簡単に検証してみました。

# 結論

記事にある通り、TCP コネクションが切断されていてもリトライ処理が行われるため、`(*DB).SetConnMaxLifetime` は必須ではなくなりました。
ただし、`(*DB).Ping` についてはリトライすることなく `driver.ErrBadConn` が返却されるため注意が必要です。

# 挙動を確認してみる

## 準備

まず、MySQL を `--wait-timeout=3` として起動しておきます。

```bash
docker run --rm -d --name the-crash-mysql -p 3306:3306 \
  -e MYSQL_ROOT_PASSWORD=password -e MYSQL_USER=user -e MYSQL_PASSWORD=password \
  -e MYSQL_DATABASE=mydb \
  mysql/mysql-server:8.0 --wait-timeout=3
```

Query を投げるためにテーブルを一つ作成しておきます。

```bash
mysql -h127.0.0.1 -P3306 -uuser -ppassword mydb -e "CREATE TABLE users (id int, name varchar(10))"
```

## (*DB).Query

最初に `wait_timeout` に設定した値より少し大きい数のコネクションを張っておき、以後 1 秒間隔で Query を投げます。

```go:main.go
package main

import (
	"database/sql"
	"log"
	"sync"
	"time"

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

func main() {
	db, err := sql.Open("mysql", "user:password@tcp(localhost:3306)/mydb")
	if err != nil {
		log.Fatal(err)
	}
	defer db.Close()

	const numOfConns = 10
	db.SetMaxIdleConns(numOfConns)
	db.SetMaxOpenConns(numOfConns)
	// db.SetConnMaxLifetime は設定しない

	var wg sync.WaitGroup
	for i := 0; i < numOfConns; i++ {
		wg.Add(1)
		go func() {
			rows, err := db.Query("SELECT * from users")
			if err != nil {
				log.Fatal(err)
			}
			if err := rows.Close(); err != nil {
				log.Fatal(err)
			}
			wg.Done()
		}()
	}
	wg.Wait()
	log.Printf("idle conns: %d", db.Stats().Idle)

	for {
		rows, err := db.Query("SELECT * from users")
		if err != nil {
			log.Fatal(err)
		}
		if err := rows.Close(); err != nil {
			log.Fatal(err)
		}
		log.Print("OK")
		time.Sleep(1 * time.Second)
	}
}
```

go-sql-driver/mysql のバージョンを変えて実行してみます。

```:v1.4.0
2020/05/26 01:50:16 idle conns: 10
2020/05/26 01:50:16 OK
2020/05/26 01:50:17 OK
2020/05/26 01:50:18 OK
[mysql] 2020/05/26 01:50:19 packets.go:36: unexpected EOF
2020/05/26 01:50:19 invalid connection
```

v1.4.0 の場合は `unexpected EOF` が発生し、`mysql.ErrInvalidConn` が返却されます。

```:v1.5.0
2020/05/26 01:50:34 idle conns: 10
2020/05/26 01:50:34 OK
2020/05/26 01:50:35 OK
2020/05/26 01:50:36 OK
[mysql] 2020/05/26 01:50:37 packets.go:122: closing bad idle connection: EOF
[mysql] 2020/05/26 01:50:37 packets.go:122: closing bad idle connection: EOF
2020/05/26 01:50:37 OK
[mysql] 2020/05/26 01:50:38 packets.go:122: closing bad idle connection: EOF
[mysql] 2020/05/26 01:50:38 packets.go:122: closing bad idle connection: EOF
2020/05/26 01:50:38 OK
[mysql] 2020/05/26 01:50:39 packets.go:122: closing bad idle connection: EOF
[mysql] 2020/05/26 01:50:39 packets.go:122: closing bad idle connection: EOF
2020/05/26 01:50:39 OK
```

v1.5.0 の場合は `closing bad idle connection: EOF` が2回発生した後、`OK`のログが出力されています。

[go-sql-driver/mysql#934](https://github.com/go-sql-driver/mysql/pull/934) の修正により、パケットを送信する前に TCP レベルで接続確認を行い、切断時には `driver.ErrBadConn` が返却されるようになりました。
[(*DB).QueryContext](https://github.com/golang/go/blob/f65ad0dda7ffef9397d1aaa47259ad4d4f12474f/src/database/sql/sql.go#L1592-L1607) では `driver.ErrBadConn` 発生時に、 `maxBadConnRetries` (2回) リトライし、それでもダメなら新規コネクションを用いるような実装になっているため、`(*DB).SetConnMaxLifetime` が設定されていなくても問題なくなったわけです。

```go:(*DB).QueryContext
// QueryContext executes a query that returns rows, typically a SELECT.
// The args are for any placeholder parameters in the query.
func (db *DB) QueryContext(ctx context.Context, query string, args ...interface{}) (*Rows, error) {
	var rows *Rows
	var err error
	for i := 0; i < maxBadConnRetries; i++ {
		rows, err = db.query(ctx, query, args, cachedOrNewConn)
		if err != driver.ErrBadConn {
			break
		}
	}
	if err == driver.ErrBadConn {
		return db.query(ctx, query, args, alwaysNewConn)
	}
	return rows, err
}
```
ref.) https://github.com/golang/go/blob/f65ad0dda7ffef9397d1aaa47259ad4d4f12474f/src/database/sql/sql.go#L1592-L1607

## (*DB).Ping

次に、(*DB).Ping でも確認してみましょう。
先程のコードの `db.Query` を `db.Ping` に変更します。

```go:main.go
	for {
		if err := db.Ping(); err != nil {
			log.Fatal(err)
		}
		log.Print("OK")
		time.Sleep(1 * time.Second)
	}
```

```:v1.4.0
2020/05/26 01:51:02 idle conns: 10
2020/05/26 01:51:02 OK
2020/05/26 01:51:03 OK
2020/05/26 01:51:04 OK
[mysql] 2020/05/26 01:51:05 packets.go:36: unexpected EOF
2020/05/26 01:51:05 invalid connection
```

v1.4.0 ではやはり `unexpected EOF` 発生からの `mysql.ErrInvalidConn` が返却されています。

```:v1.5.0
2020/05/26 01:51:18 idle conns: 10
2020/05/26 01:51:18 OK
2020/05/26 01:51:19 OK
2020/05/26 01:51:20 OK
[mysql] 2020/05/26 01:51:21 packets.go:122: closing bad idle connection: EOF
2020/05/26 01:51:21 driver: bad connection
```

一方、v1.5.0 では修正されているんだよね！と思いきや、`driver.ErrBadConn` が返ってきます。
[(*DB).PingContext](https://github.com/golang/go/blob/f65ad0dda7ffef9397d1aaa47259ad4d4f12474f/src/database/sql/sql.go#L792-L812) の実装を見てみると...

```go:(*DB).PingContext
// PingContext verifies a connection to the database is still alive,
// establishing a connection if necessary.
func (db *DB) PingContext(ctx context.Context) error {
	var dc *driverConn
	var err error

	for i := 0; i < maxBadConnRetries; i++ {
		dc, err = db.conn(ctx, cachedOrNewConn)
		if err != driver.ErrBadConn {
			break
		}
	}
	if err == driver.ErrBadConn {
		dc, err = db.conn(ctx, alwaysNewConn)
	}
	if err != nil {
		return err
	}

	return db.pingDC(ctx, dc, dc.releaseConn)
}
```
ref.) https://github.com/golang/go/blob/f65ad0dda7ffef9397d1aaa47259ad4d4f12474f/src/database/sql/sql.go#L792-L812

一見すると、こちらも `driver.ErrBadConn` 発生時にリトライしているように見えますが、`(*DB).conn` はコネクションプールからコネクションを取り出すだけ。
この時点ではコネクションが切断されたかを知ることは出来ません。
`(*DB.pingDC)` が呼ばれて初めて、 `(*mysqlConn).writePacket` にてコネクションの確認が行われるため、リトライされることなく `driver.ErrBadConn` が返却されてしまうのです。

Query 実行時はリトライして処理を継続できるケースなのに、Ping の場合にエラー扱いになるのは少し違和感がありますね。

# おわりに

`(*DB).SetConnMaxLifetime` を設定しなくても、多くの場合、リトライして処理が継続されるため必須ではなくなりました。
ただし、`(*DB).Ping` についてはリトライすることなく `driver.ErrBadConn` が返却されます。
Pod の Readiness Probe Endpoint などに `(*DB).Ping` を活用している場合は、即時失敗とみなさずリトライ処理を行うか、failureThreshold の値を調整したほうがよさそうです。