はじめに
先日、GitHub Blog にて Go の MySQL Driver に関する記事が掲載されました。
The GitHub Blog: 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 として起動しておきます。
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 を投げるためにテーブルを一つ作成しておきます。
mysql -h127.0.0.1 -P3306 -uuser -ppassword mydb -e "CREATE TABLE users (id int, name varchar(10))"
(*DB).Query
最初に wait_timeout に設定した値より少し大きい数のコネクションを張っておき、以後 1 秒間隔で Query を投げます。
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 のバージョンを変えて実行してみます。
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 が返却されます。
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 の修正により、パケットを送信する前に TCP レベルで接続確認を行い、切断時には driver.ErrBadConn が返却されるようになりました。
(*DB).QueryContext では driver.ErrBadConn 発生時に、 maxBadConnRetries (2回) リトライし、それでもダメなら新規コネクションを用いるような実装になっているため、(*DB).SetConnMaxLifetime が設定されていなくても問題なくなったわけです。
// 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
}
(*DB).Ping
次に、(*DB).Ping でも確認してみましょう。
先程のコードの db.Query を db.Ping に変更します。
for {
if err := db.Ping(); err != nil {
log.Fatal(err)
}
log.Print("OK")
time.Sleep(1 * time.Second)
}
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 が返却されています。
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 の実装を見てみると...
// 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)
}
一見すると、こちらも 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 の値を調整したほうがよさそうです。