golang version 1.6.2 invalid connection

[gzw13999]

Issue description

Tell us what should happen and what happens instead

Example code

If possible, please enter some example code here to reproduce the issue.

Error log

[mysql] 2016/04/24 13:56:27 statement.go:27: invalid connection
[mysql] 2016/04/24 13:56:27 statement.go:27: invalid connection
If you have an error log, please paste it here.

### Configuration
*Driver version (or git SHA):*

*Go version:* run `go version` in your console

*Server version:* E.g. MySQL 5.6, MariaDB 10.0.20

*Server OS:* E.g. Debian 8.1 (Jessie), Windows 10

[luca-moser]

Same on 1.6.1, for me it happens when I concurrently run queries with the same *sql.DB instance

[arnehormann]

Thanks for reporting this and for narrowing it down.
Can one of you please provide a sample program reliably producing this error (here, gist or http://play.golang.org)?

[arnehormann]

@gzw13999 @luca-moser any progress?

[luca-moser]

I can't reproduce the warning message anymore, maybe I had some statements which never got closed. For me the issue is resolved.

[lendico-seong]

Might be that I was misusing something, but I can reproduce the error with this gist:

https://gist.github.com/lendico-seong/662ea43126adc73de38b4b28b5b5b429

Additional information:

        {
            "importpath": "github.com/go-sql-driver/mysql",
            "repository": "https://github.com/go-sql-driver/mysql",
            "vcs": "git",
            "revision": "3654d25ec346ee8ce71a68431025458d52a38ac0",
            "branch": "master",
            "notests": true
        }

$ go version
go version go1.6 darwin/amd64

-- Server version   5.5.5-10.1.14-MariaDB-1~jessie

[methane]

@lendico-seong Thank you for complete information.

[arnehormann]

@methane are you taking this? If so, great, thanks a bunch!

[methane]

@arnehormann I'll investigate it. But I don't think I can determine how to fix.
The doc doesn't say Stmt.Close() is called only once.
So just removing this errorLog may be OK.

[methane]

I can reproduce it. Stack trace (go1.7beta1) is...

Stmt.Close() is called at first:

github.com/go-sql-driver/mysql.(*mysqlStmt).Close(0xc42011fe00, 0x5aae7, 0xc4200a4028)
    /Users/inada-n/gopath/src/github.com/go-sql-driver/mysql/statement.go:39 +0x2f4
database/sql.(*DB).noteUnusedDriverStatement.func1()
    /usr/local/go/src/database/sql/sql.go:852 +0x2f
database/sql.(*DB).putConn(0xc4200a4000, 0xc4200c8620, 0x0, 0x0)
    /usr/local/go/src/database/sql/sql.go:883 +0x78
database/sql.(*DB).prepare(0xc4200a4000, 0x1dad95, 0x1f, 0x6601, 0xc4200a41b8, 0x8, 0xc4200a4200)
    /usr/local/go/src/database/sql/sql.go:994 +0x26a
database/sql.(*DB).Prepare(0xc4200a4000, 0x1dad95, 0x1f, 0xc4200a41b8, 0x2963c0, 0xc420119d40)
    /usr/local/go/src/database/sql/sql.go:958 +0x60
main.insert(0xc4200a4000, 0x3e6)
    /Users/inada-n/tmp/sql/reproduce.go:75 +0x44
main.work(0xc4200a4000, 0xc42000cb80, 0xc4200a4160)
    /Users/inada-n/tmp/sql/reproduce.go:65 +0x91
created by main.main
    /Users/inada-n/tmp/sql/reproduce.go:46 +0x140

and then,

github.com/go-sql-driver/mysql.(*mysqlStmt).Close(0xc42011fe00, 0xc42028b680, 0xc4200e3c80)
    /Users/inada-n/gopath/src/github.com/go-sql-driver/mysql/statement.go:34 +0x19a
database/sql.(*driverConn).finalClose(0xc4200c8620, 0x2b6b80, 0x2b6b98)
    /usr/local/go/src/database/sql/sql.go:356 +0xac
database/sql.(finalCloser).(database/sql.finalClose)-fm(0xc4200a4028, 0x2945c0)
    /usr/local/go/src/database/sql/sql.go:449 +0x2f
database/sql.(*driverConn).Close(0xc4200c8620, 0xc4200c8620, 0x0)
    /usr/local/go/src/database/sql/sql.go:349 +0x14d
database/sql.(*DB).putConn(0xc4200a4000, 0xc4200c8620, 0x0, 0x0)
    /usr/local/go/src/database/sql/sql.go:904 +0x13c
database/sql.(*driverConn).releaseConn(0xc4200c8620, 0x0, 0x0)
    /usr/local/go/src/database/sql/sql.go:284 +0x47
database/sql.(*driverConn).(database/sql.releaseConn)-fm(0x0, 0x0)
    /usr/local/go/src/database/sql/sql.go:1073 +0x3e
database/sql.(*Stmt).Exec(0xc4203c4280, 0xc4200e3f30, 0x1, 0x1, 0x0, 0x0, 0x0, 0x0)
    /usr/local/go/src/database/sql/sql.go:1466 +0x278
main.insert(0xc4200a4000, 0x3e6)
    /Users/inada-n/tmp/sql/reproduce.go:85 +0x11e
main.work(0xc4200a4000, 0xc42000cb80, 0xc4200a4160)
    /Users/inada-n/tmp/sql/reproduce.go:65 +0x91

[arnehormann]

Hmmm... we could misuse an existing var for signaling.

type mysqlStmt struct {
    mc         *mysqlConn
    id         uint32
    paramCount int // <<<<<< misuse < 0 as "is closed"
    columns    []mysqlField // cached from the first query
}

func (stmt *mysqlStmt) Close() error {
    if stmt.mc == nil || stmt.mc.netConn == nil {
        errLog.Print(ErrInvalidConn) // <<<<<< only if stmt.paramCount >= 0
        return driver.ErrBadConn
    }

    err := stmt.mc.writeCommandPacketUint32(comStmtClose, stmt.id)
    stmt.mc = nil
    // <<<<<< stmt.paramCount = -1
    return err
}

[methane]

Scenario:

1. When stmt.Close() is called, the connection bound to prepared statement is used by other goroutine. So noteUnusedDriverStatement() put si.Close() in driverConn.onPut.

// noteUnusedDriverStatement notes that si is no longer used and should
// be closed whenever possible (when c is next not in use), unless c is
// already closed.
func (db *DB) noteUnusedDriverStatement(c *driverConn, si driver.Stmt) {
    db.mu.Lock()
    defer db.mu.Unlock()
    if c.inUse {
        c.onPut = append(c.onPut, func() {
            si.Close()
        })

1. DB.Prepare uses the connection (which contains Close()'ed Stmt), and put it to pool. When putting, registered si.Close() is called. And connection is put to free pool. While this close si, it doesn't remove from dc.openStmt.
2. After that, same connection is used by Exec of another Stmt. And when putting the connection to free pool, hit maxIdleConns. The connection is closed. Since driverConn.openStmt contains the si, it is closed.

[methane]

I can fix the issue by this patch for database/sql/sql.go. But I haven't checked this patch can cause deadlock or not. (I believe don't)

// noteUnusedDriverStatement notes that si is no longer used and should
// be closed whenever possible (when c is next not in use), unless c is
// already closed.
func (db *DB) noteUnusedDriverStatement(c *driverConn, si driver.Stmt) {
    db.mu.Lock()
    defer db.mu.Unlock()
    if c.inUse {
        c.onPut = append(c.onPut, func() {
+           c.removeOpenStmt(si)
            si.Close()
        })
    } else {

[methane]

I found better way to fix it and post it to golang/go#16019.