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.

Sign up for GitHub

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

Jump to bottom

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
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Milestone
Go1.8

Comments

@methane
Copy link
Contributor

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
        }
This was referenced Jun 9, 2016
Closed
Closed
@methane
Copy link
Contributor Author

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 The path to resolution is known, but the work has not been done. label Oct 6, 2016
@bradfitz
Copy link
Contributor

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

@kardianos
Copy link
Contributor

I will try.

@methane
Copy link
Contributor Author

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

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 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
Contributor

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

@gopherbot
Copy link
Contributor

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

gopherbot pushed a commit that referenced this issue Nov 16, 2016
@kardianos @ianlancetaylor
database/sql: guard against driver.Stmt.Close panics
49b77a8 
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
Contributor

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

@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.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Projects
None yet
Milestone
Go1.8
Development

No branches or pull requests
6 participants
@bradfitz @quentinmit @methane @kardianos @ianlancetaylor @gopherbot