Strange error on killed connection

[xaprb]

When I kill connections that have long-running queries, I get things like this:

[MySQL] 2013/12/05 22:17:19 packets.go:30: EOF
[MySQL] 2013/12/05 22:17:19 statement.go:24: Invalid Connection
[MySQL] 2013/12/05 22:17:27 packets.go:30: EOF
[MySQL] 2013/12/05 22:17:27 statement.go:24: Invalid Connection
[MySQL] 2013/12/05 22:17:39 packets.go:30: EOF
[MySQL] 2013/12/05 22:17:39 statement.go:24: Invalid Connection

I'm used to seeing this error:

2013 (HY000) at line 1: Lost connection to MySQL server during query

As far as I know, that error is actually sent across the network connection back to the client that got killed. Is this being masked in the driver or the database/sql, or is it not an error transmitted via the protocol as I think? Can we make it more clear what's happening, somehow?

[julienschmidt]

No, no error is transmitted. The error is actually that nothing can be recieved 😉
But it might be a good idea to print a more descriptive error message than EOF

[julienschmidt]

I guess the statement.go:24: Invalid Connection errors are a result of http://golang.org/issue/5718
Those errors should disappear when the auto-reconnect logic is fixed in the database/sql package.

EOF is just io.EOF, I'm not sure if we should filter and replace this. It is kind of an Go idiom to use it for cases like this (like e.g. in the net package, where this error originates from). But at least the meaning should be documented somewhere.

What's your opinion?

[xaprb]

I'd like to hear what @gkristic thinks of this too. He's been studying it.

[gkristic]

I followed the code at database/sql. The statement.go:24: Invalid Connection errors are not a result of http://golang.org/issue/5718, although I agree with @julienschmidt in that the package should attempt to retry. There are up to ten attempts for Query() and Exec() calls when run at the DB level, but none when you use a Stmt receiver.

The "Invalid Connection" @xaprb saw is due to the MySQL connection being no longer available when Close() is called for a prepared statement, i.e., stmt.mc.netConn is nil here. It's a harmless message, cause the connection at database/sql will be closed as soon as ErrBadConn is returned.

But that's not the only possibility I've seen; database/sql (Go 1.2) may have some concurrency issues that may end up with that message as well. If a (database/sql) statement is closed when a driver connection is using it, the driver statement is scheduled to be closed at the next putConn() by noteUnusedDriverStatement(). But putConn() could run before removeOpenStmt() is called (see (*Stmt) finalClose()). If, after calling pending onPut functions, the connection itself is closed due to the idle connection limit, then the package will try to close the statement again, resulting in the message. This is once again harmless, but nonetheless annoying.

IMHO Go's database/sql needs some careful revisiting...

[julienschmidt]

@gkristic do you suggest any changes in the driver?

The database/sql package has a few flaws, I hope to make a few improvements for Go 1.3. Revisiting the dependency management is one item on my list.

[julienschmidt]

If you discover issues like this, please report it at https://code.google.com/p/go/issues/list.

[gkristic]

Given that these conditions (namely, connection lost or double-close by database/sql) are harmless, I'd expect the driver to skip those silently, instead of printing the "Invalid Connection" message. In my opinion, the later can either be: scary, if you don't know it's harmless; annoying, once you do; but possibly misleading, if there's an identical message printed somewhere else (and there is, except for the line number), concealing a real warning you could easily skip. If either stmt.mc or stmt.mc.netConn are nil at the statement Close() function, I'd favor a return without further logging. Also, note that returning driver.ErrBadConn there (as introduced at 4d3764b) has absolutely no effect, cause database/sql does never check the return code for a statement close.

As a side note, I'd probably add a function to tweak the logger. Currently, errLog is initialized inside the package and is private. It prints to standard error that may, or may not be available; i.e., a process may choose to close the descriptor for other reasons. But even if it doesn't, the user may have a different idea about logging (think of files, syslog, whatever). The driver could provide this default logger, but maybe also allow the user to set another.

As soon as I have some spare time I'll prepare a small example for the issue I mentioned before and write a report.

Thanks!

[arnehormann]

@gkristic concerning the logger - you mean something like #182 (merged into master a week ago)?

[gkristic]

@arnehormann Oh, man... exactly that. I've been working with v1.1. I checked the other stuff at master too before posting, but forgot to check logging. Sorry and thanks!

[arnehormann]

@gkristic not a problem at all 😀

[julienschmidt]

Any changes which should be done before the next release? PRs welcome :)

[rmulley]

Hey guys, new user of go-sql-driver here. I'm noticing similar issues, but was wondering if someone could help me confirm the cause is the same? In long running crons that utilize goroutines I'm routinely receiving the following.

[MySQL] 2014/05/14 20:33:05 packets.go:356: Busy buffer
[MySQL] 2014/05/14 20:33:05 packets.go:73: EOF
[MySQL] 2014/05/14 20:33:05 statement.go:24: Invalid Connection
[MySQL] 2014/05/14 20:33:05 connection.go:206: Invalid Connection

I'm more than willing to get my hands dirty here, just looking for some guidance on how to approach the problem. Is this "Invalid Connection" error safe to ignore in certain circumstances? Is there a way to automatically grab another connection if this is detected?

[gkristic]

Uh, oh... now that I see, I missed the comment by @julienschmidt from last Friday. (I apologize Julien.) @rmulley, it looks like you've hit the same problem I was describing above. Look at this comment. The "Invalid Connection" at statement.go:24 is harmless. The driver should do the appropriate thing by choosing a different connection. I'm not sure about the "Busy buffer" though; I don't recall having seen that. It's been quite a while since I checked this code. I'll set some time apart to have a look at it again and see whether I can help. Unfortunately, that can't happen before the end of next week. But I'll get back to you by then.

[julienschmidt]

@rmulley: To me this seems unrelated to this issue.
Please try to reproduce this error with the current git master version in case you used a version installed by go get (which is an older version).
Please open a new issue then. A minimal code sample triggering this error would definitely help.

It seems like (b *buffer) takeBuffer returns nil. This seems to happen only when b.length > 0. This would mean that for some reason there is unread data in the buffer.
I have never seen this error before and I only implemented these extra checks for extra safety. I never would have believed to this this error in the wild.

[carbocation]

According to #206 this error actually goes away when go is run from tip. Is that not actually the case?

[rmulley]

First off, sorry for the late response I was on vacation and then forgot to follow up. I ensured I have the newest version of the MySQL Driver and am now testing with Go 1.3. It does look like I am seeing more detail in the error message now.

[MySQL] 2014/06/23 11:46:04 packets.go:356: Busy buffer
[MySQL] 2014/06/23 11:46:04 packets.go:73: read tcp xxx.xxx.xxx.xx:3306: connection reset by peer

Is this a MySQL issue on my end? (I haven't found anything useful online on how to resolve this issue)
Or is this something I can check for and then reconnect in my code somehow?

[zelda81]

i've encountered the same problem as rmulley described. what was different is that the "busy buffer" appeared in extremely short query (as short as 1 Query + 2 Exec's).

i feel the problem is related to prepared statements. i found that if i have prepared a statement in a transaction, like

 stmt, err = tx.Prepare("SELECT ...")

i must close this stmt before i prepare another statement, or i will encounter "busy buffer" each time. if i don't use prepared statements, for example doing directly to tx like

 tx.Query("...")

or

tx.Exec("...")

, it was fine.

and, if i prepare a statement and then executing other Query or Exec other stuffs, it is fine too... just don't prepare another statement without closing the previous one, and it looks fine.

hope it is really where the problem is.

thanks.

[julienschmidt]

Can you maybe create a small Go program with which the error can be reproduced?
It seems to be definitely a bug in the driver, but not related to the original issue reported here.
Please create a new issue then.

[arnehormann]

I think this is the problem:

package main

import (
    "database/sql"

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

func main() {
    db, _ := sql.Open("mysql", "/")
    defer db.Close()
    tx, err := db.Begin()
    if err != nil {
        panic(err)
    }
    defer tx.Commit()
    stmt1, err := tx.Prepare("SELECT 1")
    if err != nil {
        panic(err)
    }
    rows1, err := stmt1.Query()
    if err != nil {
        panic(err)
    }
    stmt2, err := tx.Prepare("SELECT 2")
    if err != nil {
        // rows1 is not closed -> triggers busy buffer because transaction is on one connection
        // and stmt1, stmt2 use the same one.
        // Move rows1.Close() in front of tx.Prepare and it disappears
        panic(err)
    }
    rows2, err := stmt2.Query()
    if err != nil {
        panic(err)
    }
    rows1.Close()
    rows2.Close()
    stmt1.Close()
    stmt2.Close()
}

[rmulley]

I just ran into a similar busy buffer issue and can confirm that @arnehormann seems to be correct. The issue happens when attempting to use the same transaction for multiple queries while a rows object is still open

[salmagnone]

Hi guys, I don't know if this was resolved in any way. I'm seeing this issue in short inserts performed with "Exec" ->

var sql = "insert into table (f1,f2 ... f25) values (?,?, ... ?)"
_,err := db.Exec(sql, ...)

After about 4000, sometimes 5000 inserts I get "Unexpected EOF" and "Busy Buffer".
The inserts are tight (in a for loop) but there is a REST request between each, so, not so rapid fire; same connection reference. This is Go 1.3.

Thanks,
Sal

[carbocation]

@sal - what happens when you use go 1.4?

On Wed, Dec 31, 2014 at 10:11 PM, Sal A. Magnone notifications@github.com
wrote:

Hi guys, I don't know if this was resolved in any way. I'm seeing this
issue in short inserts performed with "Exec" ->

var sql = "insert into table (f1,f2 ... f25) values (?,?, ... ?)"
_,err := db.Exec(sql, ...)

After about 4000, sometimes 5000 inserts I get "Unexpected EOF" and "Busy
Buffer".
The inserts are tight (in a for loop) but there is a REST request between
each, so, not so rapid fire; same connection reference. This is Go 1.3.

Thanks,
Sal

—
Reply to this email directly or view it on GitHub
#185 (comment).

[salmagnone]

Thanks for your reply.

1.4 – same error. Died at 4205 inserts in about 50 minutes (there is net and screen i/o between each insert).

I’ve refactored the code to optionally pick up where it left off the previous time. So not critical for this app, but will be could be critical for other apps in this project if this a cumulative request problem.

-Sal

From: carbocation [mailto:notifications@github.com]
Sent: Sunday, January 4, 2015 9:50 AM
To: go-sql-driver/mysql
Cc: Sal A. Magnone
Subject: Re: [mysql] Strange error on killed connection (#185)

@sal - what happens when you use go 1.4?

On Wed, Dec 31, 2014 at 10:11 PM, Sal A. Magnone <notifications@github.com mailto:notifications@github.com >
wrote:

Hi guys, I don't know if this was resolved in any way. I'm seeing this
issue in short inserts performed with "Exec" ->

var sql = "insert into table (f1,f2 ... f25) values (?,?, ... ?)"
_,err := db.Exec(sql, ...)

After about 4000, sometimes 5000 inserts I get "Unexpected EOF" and "Busy
Buffer".
The inserts are tight (in a for loop) but there is a REST request between
each, so, not so rapid fire; same connection reference. This is Go 1.3.

Thanks,
Sal

—
Reply to this email directly or view it on GitHub
#185 (comment).

—
Reply to this email directly or view it on GitHub #185 (comment) . https://github.com/notifications/beacon/AA4DdvfCFMdiqPlTZITEs9VrxyyJqqFQks5neUqigaJpZM4BSM1b.gif

[xaprb]

Is this thread turning into a few threads now? Should the most recent comments be put into a new issue and this one closed?

[rmulley]

@xaprb I agree, I think there are a few threads going on now. We can probably close this one and take from #185 (comment) into a new issue.