Connections stuck with "busy buffer" after ErrPktSync

[owbone]

Issue description

In #1393, I described a situation that can frequently cause ErrPktSync errors in very busy services, when the local timeout is greater than the wait_timeout.

In one service, we saw this triggering huge bursts of "busy buffer" log messages and "invalid connection" errors. This is because:

1. When we get an ErrPktSync error here, the connection is not closed and the buffer is left filled.
2. The connection is then returned to the pool, because IsValid() returns true (because the connection is not closed).
3. When the connection is taken from the pool, ResetSession() doesn't reset the buffer.
4. If the buffer isn't empty, interpolateParams() returns ErrInvalidConn without closing the connection, which brings us back to step 2.

Almost 100% of our queries were using interpolateParams, so we'd essentially get stuck in this cycle until the connection timed out.

It seems like one of the simplest things to do might be to clear the buffer in ResetSession(), since it's only at that point we know that any previous queries are no longer relevant.

Example code

Use https://github.com/lukaszlach/docker-tc to apply a network delay to the MySQL container:

docker run -d \
    --name docker-tc \
    --network host \
    --cap-add NET_ADMIN \
    --restart always \
    -v /var/run/docker.sock:/var/run/docker.sock \
    -v /var/docker-tc:/var/docker-tc \
    lukaszlach/docker-tc

Start the MySQL container in a network, with a 1 second network delay applied:

docker network create test-net
docker run \
    -e MYSQL_ROOT_PASSWORD=password \
    --label "com.docker-tc.enabled=1" \
    --label "com.docker-tc.delay=1000ms" \
    -p 3306:3306 \
    --net test-net \
    mysql:8.0.24

package main

import (
	"database/sql"
	"fmt"
	"time"

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

func main() {
	mysql.SetLogger(logger{})

	cfg := mysql.NewConfig()
	cfg.User = "root"
	cfg.Passwd = "password"
	cfg.Net = "tcp"
	cfg.Addr = "127.0.0.1"
	cfg.DBName = "mysql"
	cfg.InterpolateParams = true

	db, err := sql.Open("mysql", cfg.FormatDSN())
	if err != nil {
		panic(err)
	}
	defer db.Close()

	db.SetMaxOpenConns(1)

	if _, err := db.Exec("SET GLOBAL wait_timeout = 2"); err != nil {
		panic(err)
	}

	time.Sleep(1500 * time.Millisecond)

	// Trigger the "commands out of sync error".
	rows, err := db.Query("SHOW TABLES")
	if err != nil {
		fmt.Println("query failed:", err)
	} else {
		rows.Close()
	}

	// Repeatedly trigger the "busy buffer" / "invalid connection" error.
	for i := 0; i < 10; i++ {
		rows, err = db.Query("SHOW TABLES WHERE 1=?", 1)
		if err != nil {
			fmt.Println("query failed:", err)
		} else {
			rows.Close()
		}
	}
}

type logger struct{}

func (logger) Print(v ...interface{}) {
	fmt.Println(append([]interface{}{"mysql: "}, v...)...)
}

Error log

query failed: commands out of sync. You can't run this command now
mysql:  busy buffer
query failed: invalid connection
mysql:  busy buffer
query failed: invalid connection
mysql:  busy buffer
query failed: invalid connection
mysql:  busy buffer
query failed: invalid connection
mysql:  busy buffer
query failed: invalid connection
mysql:  busy buffer
query failed: invalid connection
mysql:  busy buffer
query failed: invalid connection
mysql:  busy buffer
query failed: invalid connection
mysql:  busy buffer
query failed: invalid connection
mysql:  busy buffer
query failed: invalid connection
mysql:  busy buffer

Configuration

Driver version (or git SHA): 1.7.0

Go version: 1.19.5

Server version: MySQL 8.0.24

Server OS: Ubuntu 18.04.1