Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

database/sql: driver.Stmt.Close is called twice #16019

Closed
methane opened this issue Jun 9, 2016 · 9 comments
Closed

database/sql: driver.Stmt.Close is called twice #16019

methane opened this issue Jun 9, 2016 · 9 comments
Assignees
Milestone

Comments

@methane
Copy link
Contributor

@methane methane commented Jun 9, 2016

Please answer these questions before submitting your issue. Thanks!

  1. What version of Go are you using (go version)?

go1.7beta1

  1. What operating system and processor architecture are you using (go env)?
GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/inada-n/gopath"
GORACE=""
GOROOT="/usr/local/go"
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
CC="clang"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/11/3pzjxxcd7q53dbfsm95ms3d00000gn/T/go-build825338239=/tmp/go-build -gno-record-gcc-switches -fno-common"
CXX="clang++"
CGO_ENABLED="1"
  1. What did you do?

See go-sql-driver/mysql#450

reproducible example is here

  1. What did you expect to see?

No error log shown.

  1. What did you see instead?

go-sql-driver/mysql prints [mysql] 2016/04/24 13:56:27 statement.go:27: invalid connection.

It means Stmt.Close() is called twice. First stack trace is:

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 second is:

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

Possible solution is:

$ git diff
diff --git a/src/database/sql/sql.go b/src/database/sql/sql.go
index e7482a8..a14d416 100644
--- a/src/database/sql/sql.go
+++ b/src/database/sql/sql.go
@@ -1703,8 +1703,8 @@ func (s *Stmt) finalClose() error {
        defer s.mu.Unlock()
        if s.css != nil {
                for _, v := range s.css {
-                       s.db.noteUnusedDriverStatement(v.dc, v.si)
                        v.dc.removeOpenStmt(v.si)
+                       s.db.noteUnusedDriverStatement(v.dc, v.si)
                }
                s.css = nil
        }
@methane
Copy link
Contributor Author

@methane methane commented Jun 9, 2016

"Possible solution" I wrote above cause another race.

If dc.finelClose() is called between dc.removeOpenStmt() and db.noteUnusedDriverStatement(),
the si can be leaked. (never closed).

Another possible solution is:

diff --git a/src/database/sql/sql.go b/src/database/sql/sql.go
index e7482a8..ff476bf 100644
--- a/src/database/sql/sql.go
+++ b/src/database/sql/sql.go
@@ -850,11 +850,13 @@ func (db *DB) noteUnusedDriverStatement(c *driverConn, si driver.Stmt) {
        if c.inUse {
                c.onPut = append(c.onPut, func() {
                        si.Close()
+                       c.removeOpenStmt(si)
                })
        } else {
                c.Lock()
                defer c.Unlock()
                if !c.finalClosed {
+                       delete(c.openStmt, si)
                        si.Close()
                }
        }
@@ -1704,7 +1706,6 @@ func (s *Stmt) finalClose() error {
        if s.css != nil {
                for _, v := range s.css {
                        s.db.noteUnusedDriverStatement(v.dc, v.si)
-                       v.dc.removeOpenStmt(v.si)
                }
                s.css = nil
        }

(I haven't tested this because it's midnight in Japan)

@ianlancetaylor ianlancetaylor changed the title database/sql/driver.Stmt.Close() is called twice. database/sql: driver.Stmt.Close is called twice Jun 9, 2016
@ianlancetaylor ianlancetaylor added this to the Go1.8 milestone Jun 9, 2016
@quentinmit quentinmit added the NeedsFix label Oct 6, 2016
@bradfitz
Copy link
Contributor

@bradfitz bradfitz commented Nov 11, 2016

@kardianos, if you have time, can you take a look?

@kardianos
Copy link
Contributor

@kardianos kardianos commented Nov 11, 2016

I will try.

@methane
Copy link
Contributor Author

@methane methane commented Nov 14, 2016

I'm sorry about long time no update.
Now go-sql-driver/mysql stop print error log when Stmt.Close() is called twice.
Please revert this commit to reproduce the issue.

@kardianos
Copy link
Contributor

@kardianos kardianos commented Nov 16, 2016

I don't see anything in the current database/sql code that prevents driver.Stmt.Close from being closed more than once. It will prevent it from being called concurrently, but nothing prevents it from being called twice.

My recommendation is to document that driver.Stmt.Close may be called more than once and further calls should be idempotent.

Also, there is currently a code path where if driver.Stmt.Close panics the sql pool will lock up due to a held lock. This is in func (dc *driverConn) finalClose() error.

@methane
Copy link
Contributor Author

@methane methane commented Nov 16, 2016

I'm OK for your recommendation.
What should Stmt.Close return? nil? or errors.New("closing stmt already closed")?

@gopherbot
Copy link

@gopherbot gopherbot commented Nov 16, 2016

CL https://golang.org/cl/33329 mentions this issue.

@gopherbot
Copy link

@gopherbot gopherbot commented Nov 16, 2016

CL https://golang.org/cl/33328 mentions this issue.

gopherbot pushed a commit that referenced this issue Nov 16, 2016
Do not retain a lock when driver.Stmt.Close panic as the rest
of the sql package ensures.

Updates #16019

Change-Id: Idc7ea9258ae23f491e79cce3efc365684a708428
Reviewed-on: https://go-review.googlesource.com/33328
Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
@gopherbot
Copy link

@gopherbot gopherbot commented Nov 17, 2016

CL https://golang.org/cl/33352 mentions this issue.

@gopherbot gopherbot closed this in 90b8a0c Nov 17, 2016
@golang golang locked and limited conversation to collaborators Nov 17, 2017
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
6 participants
You can’t perform that action at this time.