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?