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: panic: double close #18429

Closed
opennota opened this issue Dec 25, 2016 · 8 comments
Closed

database/sql: panic: double close #18429

opennota opened this issue Dec 25, 2016 · 8 comments
Assignees
Milestone

Comments

@opennota
Copy link

@opennota opennota commented Dec 25, 2016

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

go version go1.8beta2 linux/amd64

What operating system and processor architecture are you using (go env)?

linux/amd64

What did you do?

I open an sqlite3 database (using mattn/go-sqlite3) and in an HTTP handler do roughly the following:

tx, err := db.BeginTx(req.Context(), nil)
...
_, err = tx.ExecContext(req.Context(), "...")
...
_, err = tx.ExecContext(req.Context(), "...")
...
_, err = tx.Commit()
...

Unfortunately, I don't yet have a simple program that reproduces the issue.

What did you expect to see?

No panics.

What did you see instead?

panic: double close
goroutine 36 [running]:
database/sql.(*Tx).close(0xc4201102a0, 0xbc2d60, 0xc420014f90)
        /home/opennota/go/src/database/sql/sql.go:1426 +0x12b
database/sql.(*Tx).rollback(0xc4201102a0, 0xc420110201, 0x0, 0x0)
        /home/opennota/go/src/database/sql/sql.go:1487 +0xf8
database/sql.(*DB).begin.func2(0xc4201102a0)
        /home/opennota/go/src/database/sql/sql.go:1366 +0x94
created by database/sql.(*DB).begin
        /home/opennota/go/src/database/sql/sql.go:1369 +0x255

and, more often

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x28 pc=0x6ac7be]

goroutine 127 [running]:
database/sql.(*Tx).rollback.func1()
        /home/opennota/go/src/database/sql/sql.go:1479 +0x2e
database/sql.withLock(0xbc46a0, 0xc42001c2a0, 0xc4202b2780)
        /home/opennota/go/src/database/sql/sql.go:2442 +0x65
database/sql.(*Tx).rollback(0xc42006fda0, 0xc42006fd01, 0x0, 0x7f81d39cc1c0)
        /home/opennota/go/src/database/sql/sql.go:1480 +0x91
database/sql.(*DB).begin.func2(0xc42006fda0)
        /home/opennota/go/src/database/sql/sql.go:1366 +0x94
created by database/sql.(*DB).begin
        /home/opennota/go/src/database/sql/sql.go:1369 +0x255

If non-context method versions are used, there's no panic.

Might be a problem with go-sqlite3, for all I know.

@opennota
Copy link
Author

@opennota opennota commented Dec 25, 2016

Okay, here is a reproducible test case:

package main

import (
	"database/sql"
	"log"
	"net/http"

	_ "github.com/mattn/go-sqlite3"
)

var db *sql.DB

func index(w http.ResponseWriter, r *http.Request) {
	ctx := r.Context()

	tx, err := db.BeginTx(ctx, nil)
	if err != nil {
		log.Print(err)
		return
	}

	_, err = tx.ExecContext(ctx, "INSERT INTO t (text) VALUES ('')")
	if err != nil {
		log.Print(err)
		return
	}

	err = tx.Commit()
	if err != nil {
		log.Print(err)
		return
	}
}

func main() {
	var err error
	db, err = sql.Open("sqlite3", "test.sqlite")
	if err != nil {
		log.Print(err)
		return
	}

	_, err = db.Exec("CREATE TABLE IF NOT EXISTS t ( text TEXT );")
	if err != nil {
		log.Print(err)
		return
	}

	http.HandleFunc("/", index)
	log.Fatal(http.ListenAndServe(":8080", nil))
}

Open http://localhost:8080 in a browser, press F5 and do not release it for 1-3 seconds until the program crashes.

@opennota
Copy link
Author

@opennota opennota commented Dec 25, 2016

/cc @mattn

@bradfitz
Copy link
Contributor

@bradfitz bradfitz commented Dec 25, 2016

Seems like an sqlite driver problem?

/cc @kardianos

@mattn
Copy link
Member

@mattn mattn commented Dec 26, 2016

When transaction is closed, Tx.txi is set nil. So I guess the goroutine in database/sql should check whether the txi is already closed (is nil).

@kardianos
Copy link
Contributor

@kardianos kardianos commented Dec 26, 2016

I'm looking into this now.
For ref, here is a stack from the above program:

2016/12/26 09:35:07 context canceled
2016/12/26 09:35:07 context canceled
2016/12/26 09:35:08 context canceled
fatal error: unexpected signal during runtime execution
[signal SIGSEGV: segmentation violation code=0x1 addr=0x150 pc=0x6a1850]

runtime stack:
runtime.throw(0x7e8495, 0x2a)
	/home/daniel/code/go-cl/src/runtime/panic.go:596 +0x95
runtime.sigpanic()
	/home/daniel/code/go-cl/src/runtime/signal_unix.go:274 +0x2db
runtime.asmcgocall(0x438438, 0xc420021900)
	/home/daniel/code/go-cl/src/runtime/asm_amd64.s:620 +0x70

goroutine 84 [syscall, locked to thread]:
runtime.cgocall(0x69cbf0, 0xc42012f6d0, 0x30)
	/home/daniel/code/go-cl/src/runtime/cgocall.go:131 +0xe2 fp=0xc42012f6a0 sp=0xc42012f660
github.com/mattn/go-sqlite3._Cfunc_sqlite3_interrupt(0x0)
	github.com/mattn/go-sqlite3/_obj/_cgo_gotypes.go:679 +0x41 fp=0xc42012f6d0 sp=0xc42012f6a0
github.com/mattn/go-sqlite3.(*SQLiteStmt).exec.func3.1(0x0)
	/home/daniel/src/github.com/mattn/go-sqlite3/sqlite3.go:814 +0x60 fp=0xc42012f708 sp=0xc42012f6d0
github.com/mattn/go-sqlite3.(*SQLiteStmt).exec.func3(0x7f7202a29028, 0xc420014bc0, 0xc420126120, 0xc420124180)
	/home/daniel/src/github.com/mattn/go-sqlite3/sqlite3.go:814 +0xce fp=0xc42012f7c0 sp=0xc42012f708
runtime.goexit()
	/home/daniel/code/go-cl/src/runtime/asm_amd64.s:2184 +0x1 fp=0xc42012f7c8 sp=0xc42012f7c0
created by github.com/mattn/go-sqlite3.(*SQLiteStmt).exec
	/home/daniel/src/github.com/mattn/go-sqlite3/sqlite3.go:817 +0x145

goroutine 1 [IO wait]:
net.runtime_pollWait(0x7f7202ad9000, 0x72, 0xb5e620)
	/home/daniel/code/go-cl/src/runtime/netpoll.go:164 +0x59
net.(*pollDesc).wait(0xc4200561b8, 0x72, 0xb5b1f0, 0xc4200babe0)
	/home/daniel/code/go-cl/src/net/fd_poll_runtime.go:75 +0x38
net.(*pollDesc).waitRead(0xc4200561b8, 0xffffffffffffffff, 0x0)
	/home/daniel/code/go-cl/src/net/fd_poll_runtime.go:80 +0x34
net.(*netFD).accept(0xc420056150, 0x0, 0xb5d420, 0xc4200babe0)
	/home/daniel/code/go-cl/src/net/fd_unix.go:430 +0x1e5
net.(*TCPListener).accept(0xc42000e058, 0xc420088c60, 0x780040, 0xffffffffffffffff)
	/home/daniel/code/go-cl/src/net/tcpsock_posix.go:136 +0x2e
net.(*TCPListener).AcceptTCP(0xc42000e058, 0xc42004bdc8, 0xc42004bdd0, 0xc42004bdc0)
	/home/daniel/code/go-cl/src/net/tcpsock.go:215 +0x49
net/http.tcpKeepAliveListener.Accept(0xc42000e058, 0x7edda0, 0xc420088be0, 0xb61760, 0xc420016fc0)
	/home/daniel/code/go-cl/src/net/http/server.go:3032 +0x2f
net/http.(*Server).Serve(0xc420094370, 0xb612e0, 0xc42000e058, 0x0, 0x0)
	/home/daniel/code/go-cl/src/net/http/server.go:2631 +0x228
net/http.(*Server).ListenAndServe(0xc420094370, 0xc420094370, 0x1)
	/home/daniel/code/go-cl/src/net/http/server.go:2573 +0xb0
net/http.ListenAndServe(0x7dbef9, 0x5, 0x0, 0x0, 0x0, 0x0)
	/home/daniel/code/go-cl/src/net/http/server.go:2775 +0x7f
main.main()
	/home/daniel/src/test/test-sqlite2/main.go:50 +0x1e7

goroutine 17 [syscall, locked to thread]:
runtime.goexit()
	/home/daniel/code/go-cl/src/runtime/asm_amd64.s:2184 +0x1

goroutine 5 [chan receive]:
database/sql.(*DB).connectionOpener(0xc4200942c0)
	/home/daniel/code/go-cl/src/database/sql/sql.go:835 +0x4a
created by database/sql.Open
	/home/daniel/code/go-cl/src/database/sql/sql.go:580 +0x1c8

goroutine 7 [IO wait]:
net.runtime_pollWait(0x7f7202ad8f40, 0x72, 0x6)
	/home/daniel/code/go-cl/src/runtime/netpoll.go:164 +0x59
net.(*pollDesc).wait(0xc420056228, 0x72, 0xb5e620, 0xb5b1f0)
	/home/daniel/code/go-cl/src/net/fd_poll_runtime.go:75 +0x38
net.(*pollDesc).waitRead(0xc420056228, 0xc420085000, 0x1000)
	/home/daniel/code/go-cl/src/net/fd_poll_runtime.go:80 +0x34
net.(*netFD).Read(0xc4200561c0, 0xc420085000, 0x1000, 0x1000, 0x0, 0xb5e620, 0xb5b1f0)
	/home/daniel/code/go-cl/src/net/fd_unix.go:250 +0x1b7
net.(*conn).Read(0xc42000e060, 0xc420085000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/home/daniel/code/go-cl/src/net/net.go:181 +0x70
net/http.(*connReader).Read(0xc4200145c0, 0xc420085000, 0x1000, 0x1000, 0x46f372, 0x1, 0xc4200ce000)
	/home/daniel/code/go-cl/src/net/http/server.go:742 +0x140
bufio.(*Reader).fill(0xc420060300)
	/home/daniel/code/go-cl/src/bufio/bufio.go:97 +0x117
bufio.(*Reader).ReadSlice(0xc420060300, 0xa, 0x0, 0x0, 0xc4200e40a0, 0x0, 0x51f5d7)
	/home/daniel/code/go-cl/src/bufio/bufio.go:338 +0xbb
bufio.(*Reader).ReadLine(0xc420060300, 0xc420110800, 0x100, 0xf8, 0x7d2c20, 0x0, 0x46f372)
	/home/daniel/code/go-cl/src/bufio/bufio.go:367 +0x37
net/textproto.(*Reader).readLineSlice(0xc4200172c0, 0xc420036ac8, 0xc420036ac8, 0x417628, 0x100, 0x7d2c20)
	/home/daniel/code/go-cl/src/net/textproto/reader.go:55 +0x5f
net/textproto.(*Reader).ReadLine(0xc4200172c0, 0xc420110800, 0x72, 0x8000000000000000, 0x0)
	/home/daniel/code/go-cl/src/net/textproto/reader.go:36 +0x2f
net/http.readRequest(0xc420060300, 0x0, 0xc420110800, 0x0, 0x0)
	/home/daniel/code/go-cl/src/net/http/request.go:894 +0xa5
net/http.(*conn).readRequest(0xc420088820, 0xb616a0, 0xc420014580, 0x0, 0x0, 0x0)
	/home/daniel/code/go-cl/src/net/http/server.go:922 +0x213
net/http.(*conn).serve(0xc420088820, 0xb616a0, 0xc420014580)
	/home/daniel/code/go-cl/src/net/http/server.go:1751 +0x49a
created by net/http.(*Server).Serve
	/home/daniel/code/go-cl/src/net/http/server.go:2656 +0x2ce

goroutine 83 [IO wait]:
net.runtime_pollWait(0x7f7202ad8c40, 0x72, 0xe)
	/home/daniel/code/go-cl/src/runtime/netpoll.go:164 +0x59
net.(*pollDesc).wait(0xc420056848, 0x72, 0xb5e620, 0xb5b1f0)
	/home/daniel/code/go-cl/src/net/fd_poll_runtime.go:75 +0x38
net.(*pollDesc).waitRead(0xc420056848, 0xc420014ed1, 0x1)
	/home/daniel/code/go-cl/src/net/fd_poll_runtime.go:80 +0x34
net.(*netFD).Read(0xc4200567e0, 0xc420014ed1, 0x1, 0x1, 0x0, 0xb5e620, 0xb5b1f0)
	/home/daniel/code/go-cl/src/net/fd_unix.go:250 +0x1b7
net.(*conn).Read(0xc42000e158, 0xc420014ed1, 0x1, 0x1, 0x0, 0x0, 0x0)
	/home/daniel/code/go-cl/src/net/net.go:181 +0x70
net/http.(*connReader).backgroundRead(0xc420014ec0)
	/home/daniel/code/go-cl/src/net/http/server.go:644 +0x58
created by net/http.(*connReader).startBackgroundRead
	/home/daniel/code/go-cl/src/net/http/server.go:640 +0x87

goroutine 102 [chan receive]:
database/sql.(*DB).begin.func2(0xc4200e9080)
	/home/daniel/code/go-cl/src/database/sql/sql.go:1362 +0x60
created by database/sql.(*DB).begin
	/home/daniel/code/go-cl/src/database/sql/sql.go:1369 +0x255

goroutine 60 [syscall, locked to thread]:
github.com/mattn/go-sqlite3._Cfunc_sqlite3_prepare_v2(0x20a8b98, 0x20aa570, 0xc4ffffffff, 0xc4200f41a0, 0xc4200f41a8, 0x0)
	github.com/mattn/go-sqlite3/_obj/_cgo_gotypes.go:732 +0x4d
github.com/mattn/go-sqlite3.(*SQLiteConn).prepare.func2(0x20a8b98, 0x20aa570, 0xffffffff, 0xc4200f41a0, 0xc4200f41a8, 0x0)
	/home/daniel/src/github.com/mattn/go-sqlite3/sqlite3.go:648 +0x1aa
github.com/mattn/go-sqlite3.(*SQLiteConn).prepare(0xc4200cc3c0, 0x7f7202a29028, 0xc420116240, 0x7e4c0b, 0x20, 0x0, 0x0, 0x0, 0x0)
	/home/daniel/src/github.com/mattn/go-sqlite3/sqlite3.go:648 +0x123
github.com/mattn/go-sqlite3.(*SQLiteConn).exec(0xc4200cc3c0, 0x7f7202a29028, 0xc420116240, 0x7e4c0b, 0x20, 0xba19a8, 0x0, 0x0, 0x0, 0x0, ...)
	/home/daniel/src/github.com/mattn/go-sqlite3/sqlite3.go:424 +0xab
github.com/mattn/go-sqlite3.(*SQLiteConn).ExecContext(0xc4200cc3c0, 0xb616a0, 0xc420116240, 0x7e4c0b, 0x20, 0xba19a8, 0x0, 0x0, 0x10, 0x10, ...)
	/home/daniel/src/github.com/mattn/go-sqlite3/sqlite3_go18.go:40 +0x25b
database/sql.ctxDriverExec(0xb616a0, 0xc420116240, 0x7f7202ad8070, 0xc4200cc3c0, 0x7e4c0b, 0x20, 0xba19a8, 0x0, 0x0, 0x42f60e, ...)
	/home/daniel/code/go-cl/src/database/sql/ctxutil.go:31 +0x2b7
database/sql.(*Tx).ExecContext.func1()
	/home/daniel/code/go-cl/src/database/sql/sql.go:1634 +0x99
database/sql.withLock(0xb5f020, 0xc4200de700, 0xc420119b80)
	/home/daniel/code/go-cl/src/database/sql/sql.go:2442 +0x65
database/sql.(*Tx).ExecContext(0xc4200e9080, 0xb616a0, 0xc420116240, 0x7e4c0b, 0x20, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/home/daniel/code/go-cl/src/database/sql/sql.go:1635 +0x4a4
main.index(0xb611a0, 0xc420190000, 0xc42000b000)
	/home/daniel/src/test/test-sqlite2/main.go:22 +0x142
net/http.HandlerFunc.ServeHTTP(0x7edba8, 0xb611a0, 0xc420190000, 0xc42000b000)
	/home/daniel/code/go-cl/src/net/http/server.go:1930 +0x44
net/http.(*ServeMux).ServeHTTP(0xb84900, 0xb611a0, 0xc420190000, 0xc42000b000)
	/home/daniel/code/go-cl/src/net/http/server.go:2226 +0x130
net/http.serverHandler.ServeHTTP(0xc420094370, 0xb611a0, 0xc420190000, 0xc42000b000)
	/home/daniel/code/go-cl/src/net/http/server.go:2556 +0x92
net/http.(*conn).serve(0xc420088be0, 0xb616a0, 0xc420014e80)
	/home/daniel/code/go-cl/src/net/http/server.go:1813 +0x612
created by net/http.(*Server).Serve
	/home/daniel/code/go-cl/src/net/http/server.go:2656 +0x2ce
@kardianos
Copy link
Contributor

@kardianos kardianos commented Dec 26, 2016

This is caused by Tx.close racing with Tx.rollback(true) when the context times out. It is compounded by close nilling the locker used to guard against races (tx.dc) which makes it difficult guard against this.

I'm working on a solution now.

@kardianos kardianos added this to the Go1.8 milestone Dec 26, 2016
@kardianos kardianos self-assigned this Dec 26, 2016
@kardianos
Copy link
Contributor

@kardianos kardianos commented Dec 26, 2016

On a side note, sqlite3 might also have a data race where sqliteConn.Close doesn't check if the sqliteStmt.exec is still running the goroutine.

WARNING: DATA RACE
Read at 0x00c420095810 by goroutine 2118:
  github.com/mattn/go-sqlite3.(*SQLiteStmt).exec.func3()
      /home/daniel/src/github.com/mattn/go-sqlite3/sqlite3.go:814 +0xef

Previous write at 0x00c420095810 by goroutine 312:
  github.com/mattn/go-sqlite3.(*SQLiteConn).Close()
      /home/daniel/src/github.com/mattn/go-sqlite3/sqlite3.go:633 +0x7b
  database/sql.(*driverConn).finalClose.func2()
      /home/daniel/code/go-cl/src/database/sql/sql.go:439 +0x8c
  database/sql.withLock()
      /home/daniel/code/go-cl/src/database/sql/sql.go:2452 +0x76
  database/sql.(*driverConn).finalClose()
      /home/daniel/code/go-cl/src/database/sql/sql.go:441 +0x1d0
  database/sql.(finalCloser).(database/sql.finalClose)-fm()
      /home/daniel/code/go-cl/src/database/sql/sql.go:536 +0x46
  database/sql.(*driverConn).Close()
      /home/daniel/code/go-cl/src/database/sql/sql.go:418 +0x1ee
  database/sql.(*DB).putConn()
      /home/daniel/code/go-cl/src/database/sql/sql.go:1016 +0x2d0
  database/sql.(*Tx).close()
      /home/daniel/code/go-cl/src/database/sql/sql.go:1428 +0xb7
  database/sql.(*Tx).rollback()
      /home/daniel/code/go-cl/src/database/sql/sql.go:1497 +0x14d
  database/sql.(*DB).begin.func2()
      /home/daniel/code/go-cl/src/database/sql/sql.go:1366 +0xb8
@gopherbot
Copy link

@gopherbot gopherbot commented Dec 26, 2016

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

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
5 participants
You can’t perform that action at this time.