packets.go:36: unexpected EOF (Invalid Connection)

[gentcys]

Issue description

Got a long time running query, and go routine exit, but executed show processlist; in mysql presented that the query was still running.

I have seted db.SetMaxIdleConns(0) and db.SetConnMaxLifetime(1000000000000), but that not works.

Example code

func CreateUserIdsMap(beginning int64, end int64) {
    trx, err := db.Begin()
    if err != nil {
        panic(err.Error())
    }
    defer trx.Commit()

    _, err = trx.Exec("DROP TABLE IF EXISTS user_ids_map;")
    if err != nil {
        panic(err.Error())
    }

    _, err = trx.Exec("CREATE TABLE user_ids_map (row_id INT NOT NULL PRIMARY KEY, user_id INT NOT NULL);")
    if err != nil {
        panic(err.Error())
    }

    _, err = trx.Exec("SET @row_id = 0;")
    if err != nil {
        panic(err.Error())
    }

    _, err = trx.Exec("INSERT INTO user_ids_map SELECT @row_id := @row_id + 1, user_id FROM users WHERE create_time BETWEEN ? AND ?;", beginning, end)
    if err != nil {
        fmt.Printf("db: %+v\n", db.Stats())
        panic(err.Error())
    }
}

func main() {
        ...
    CreateUserIdsMap(0, 1539747119) // line:147
        ...
}

Error log

[mysql] 2018/10/17 10:35:19 packets.go:36: unexpected EOF
panic: invalid connection

goroutine 1 [running]:
git.***/***/internal/pkg/dbutil.CreateUserIdsMap(0x0, 0x5b4a8e80)
        /Users/gentcys/Codes/gocode/src/git.***/***/internal/pkg/dbutil/dbutil.go:96 +0x38b
main.main()
        /Users/gentcys/Codes/gocode/src/git.***/***/cmd/***/main.go:147 +0xc7e
exit status 2

Configuration

*Driver version (or git SHA): 1.4

*Go version: go1.11.1 darwin/amd64

*Server version: MySQL 5.7

*Server OS: host is macOS and MySQL is on Docker container

[sintanial]

Similar problem. App open connection with mysql database, and if there are no query for some time (for example waiting 5 minute) then when create query, driver return [mysql] 2018/10/18 17:37:04 packets.go:36: unexpected EOF

[gentcys]

@sintanial yep, it's about 5 minutes.

[methane]

Upgrade your docker-for-mac https://github.com/docker/for-mac/issues/2442

[sintanial]

Hmm but I don’t use the docker, this problem is come on my Linux server with go1.11

[methane]

Someone kill idle TCP connection. I don't know who. Router, iptables, etc, etc...

[sintanial]

@methane I don't use router, iptables, etc... :) I tested case with "killing TCP connection". I open from my local machine a few connection with server where located mysql:

1. Raw tcp socket to net.Listen tcp server
2. /usr/local/bin/mysql client connection
3. This library connection

After about 5 minute, library connection is broken, but raw and client still alive !

[methane]

One possibility is interactive_timeout and wait_timeout. What is the output of SHOW global variables like "%_timeout" ?

Anyway, I don't know your environment. I don't have motivation to pay my time to debug your environment.

One clear thing is DB. SetConnMaxLifetime(time.Minute * 2) is the best solution for you.

Another clear thing is we can use connection more than 5 min. So it's very unlikely driver's bug. It's very likely your environment issue.

[sintanial]

SHOW global variables like "%_timeout"; +---------------------------------------+-------+ | Variable_name | Value | +---------------------------------------+-------+ | connect_timeout | 10 | | delayed_insert_timeout | 300 | | idle_readonly_transaction_timeout | 0 | | idle_transaction_timeout | 0 | | idle_write_transaction_timeout | 0 | | innodb_flush_log_at_timeout | 1 | | innodb_lock_wait_timeout | 50 | | innodb_rollback_on_timeout | OFF | | interactive_timeout | 28800 | | lock_wait_timeout | 86400 | | net_read_timeout | 30 | | net_write_timeout | 60 | | rpl_semi_sync_master_timeout | 10000 | | rpl_semi_sync_slave_kill_conn_timeout | 5 | | slave_net_timeout | 60 | | thread_pool_idle_timeout | 60 | | wait_timeout | 28800 | +---------------------------------------+-------+

I tried many cases. I bought new raw dedicated server with ubuntu 18.04. Installed on server last mysql, and run simple golang code, and receiving same error.

And very important question: why i receive this error ? Why library don't reconnecting broken connection in background ?

[methane]

Is it really "last mysql"? When I google "thread_pool_idle_timeout", I found only MariaDB.

[sintanial]

Yep, it's MariaDB, you think this is a problem ?

[methane]

Why don't you think it's important to reproduce? How did you set MariaDB up? Did you reporduce it without docker, by only apt install mariadb-server?

[sintanial]

Why don't you think it's important to reproduce?

Because mariadb very similar to mysql. And for example the same test on rustlang worked fine, without break connections.

Did you reporduce it without docker, by only apt install mariadb-server?

I don't use docker, i use raw system. Yes maria installed from apt.

Ok, i receive this error but why library don't reconnecting broken connection in background ? All my requests failed with error, i think it's wrong behavior !?

[methane]

Ok, i receive this error but why library don't reconnecting broken connection in background ? All my requests failed with error, i think it's wrong behavior !?

That's the question I answered hundreds times...

SQL is not idempotant, and we can not know sent query is executed or not.

https://golang.org/pkg/database/sql/driver/ says:

ErrBadConn should be returned by a driver to signal to the sql package that a driver.Conn is in a bad state (such as the server having earlier closed the connection) and the sql package should retry on a new connection.

To prevent duplicate operations, ErrBadConn should NOT be returned if there's a possibility that the database server might have performed the operation. Even if the server sends back an error, you shouldn't return ErrBadConn.

So, if the connection is close by 5 min, you must use db.SetConnMaxLifetime() with duration shorter than 5 min. (e.g. time.Minute * 3).

[sintanial]

That's the question I answered hundreds times...

Excusme, thx for another answer )).

So, if the connection is close by 5 min, you must use db.SetConnMaxLifetime()

Ok I will try it

[methane]

@sintanial Can you reproduce UnexpectedEOF with this sample program? https://gist.github.com/methane/2d3ea01bfa88bfa275514146791817db

Or can you create simple snippet to reproduce?

[sintanial]

This is result of your code ` ./mysqltest 2018/11/30 16:19:24 wait_timeout=600

2018/11/30 16:20:24 60 - 2018/11/30 16:20:54 90 - 2018/11/30 16:21:24 120 - 2018/11/30 16:21:54 150 - 2018/11/30 16:22:24 180 - 2018/11/30 16:22:54 210 - 2018/11/30 16:23:24 240 - 2018/11/30 16:23:54 270 - 2018/11/30 16:24:24 300 - 2018/11/30 16:24:54 330 - 2018/11/30 16:25:24 360 - 2018/11/30 16:25:54 390 - 2018/11/30 16:26:24 420 - 2018/11/30 16:26:54 450 - 2018/11/30 16:27:24 480 - 2018/11/30 16:27:54 510 - 2018/11/30 16:28:24 540 - 2018/11/30 16:28:54 570 - 2018/11/30 16:29:24 600 - [mysql] 2018/11/30 16:29:54 packets.go:36: unexpected EOF 2018/11/30 16:29:54 630 - invalid connection [mysql] 2018/11/30 16:30:24 packets.go:36: unexpected EOF 2018/11/30 16:30:24 660 - invalid connection [mysql] 2018/11/30 16:30:54 packets.go:36: unexpected EOF 2018/11/30 16:30:54 690 - invalid connection [mysql] 2018/11/30 16:31:24 packets.go:36: unexpected EOF 2018/11/30 16:31:24 720 - invalid connection [mysql] 2018/11/30 16:31:54 packets.go:36: unexpected EOF 2018/11/30 16:31:54 750 - invalid connection [mysql] 2018/11/30 16:32:24 packets.go:36: unexpected EOF 2018/11/30 16:32:24 780 - invalid connection [mysql] 2018/11/30 16:32:54 packets.go:36: unexpected EOF 2018/11/30 16:32:54 810 - invalid connection [mysql] 2018/11/30 16:33:24 packets.go:36: unexpected EOF 2018/11/30 16:33:24 840 - invalid connection [mysql] 2018/11/30 16:33:54 packets.go:36: unexpected EOF 2018/11/30 16:33:54 870 - invalid connection [mysql] 2018/11/30 16:34:24 packets.go:36: unexpected EOF 2018/11/30 16:34:24 900 - invalid connection [mysql] 2018/11/30 16:34:54 packets.go:36: unexpected EOF 2018/11/30 16:34:54 930 - invalid connection [mysql] 2018/11/30 16:35:24 packets.go:36: unexpected EOF 2018/11/30 16:35:24 960 - invalid connection [mysql] 2018/11/30 16:35:54 packets.go:36: unexpected EOF 2018/11/30 16:35:54 990 - invalid connection [mysql] 2018/11/30 16:36:24 packets.go:36: unexpected EOF 2018/11/30 16:36:24 1020 - invalid connection `

[methane]

2018/11/30 16:19:24 wait_timeout=600

You configured server kill connection by 600 sec.

[methane]

When I google "wait_timeout 600", I found similar issue: https://github.com/docker-library/mariadb/issues/113

[sintanial]

Oh you are absolutely right, my bad :(. Thank you so much for helping with my problem.

I hope people with a similar problem will find a solution in this post, and will not annoy you with questions, as I did :)!

[johncoleman83]

I just wanted to add to this convo since I spent a few days debugging this same thing and in case someone else runs into my issue. My app was throwing an error at the same line of code as this issue title, to be exact the error was:

[mysql] 2018/12/27 21:04:13 packets.go:36: unexpected EOF
driver: bad connection

The circumstances were that my golang app started a docker container from image, mysql:latest and then attempted to connect to it through database/sql and go-sql-driver/mysql package or gorm a popular golang orm. A snippet of the code I used to start the container was:

args := []string{
  "run", "--name", "foobar",
  "--env", "MYSQL_ALLOW_EMPTY_PASSWORD=yes",
  "--env", "MYSQL_DATABASE=foobar_db",
  "--env", "MYSQL_USER=foobar_user",
  "--env", "MYSQL_PASSWORD=foobar_pass",
  "-p", "54016:3306", "mysql:latest",
  "mysqld", "--default-authentication-plugin=mysql_native_password",
}
cmd := exec.Command("docker", args...)
err := cmd.Start()
// more code here to loop 2 actions
// (1) establish connection to container with `sql` package or `gorm`
// (2) pinging the db

Then, the app would ping the db until it could connect to mysql. No matter how long I pinged the DB or how much I adjusted the mysql timeouts or other settings, this error persisted. I could not for the life of me get this to function. The odd things were that when starting the container with exec.Command() as mentioned above, I could successfully login to mysql from my terminal in bash. Also, if I started a container with the same exact above commands from bash, my app using the same code to ping the db was able to connect to ping successfully and execute mysql queries.

My solution to resolve this was to use docker API to work with docker containers in my app instead of exec.Command(). Instead of rebuilding this, I just used the ory implementation which is working great for me now: https://github.com/ory/dockertest . I used their function pool.RunWithOptions() instead of Run() so I could control the docker command arguments a bit more. Ory uses docker api from here: https://github.com/docker/go-connections and it does have some big package dependencies, and I have not researched why yet but I think it's related to docker (https://github.com/fsouza/go-dockerclient/issues/599 ), but I was not worried about that considering how good the solution is for me.

p.s. I just discovered ory in this process, and have no affiliation, so this is not an ory promotion.

[john35]

good

[john35]

My Error Log: packets.go:36: unexpected EOF [mysql] packets.go:423: busy buffer panic: runtime error: slice bounds out of range

[mattbonnell]

Having this same issue. Tried all of the above, no luck :(

[nik-hil]

Faced the same issue. I m updating/inserting over 250k records in 4 min. These values worked for me.

    sqlDB.SetMaxIdleConns(50)
    sqlDB.SetMaxOpenConns(50)
    sqlDB.SetConnMaxLifetime(time.Minute * 2)