Context cancellation rolls transaction back (MySQL)

[ryantking]

It looks like I have found some unexpected behavior with this library when it comes to how context and transactions interact.

Description

When using a context that has a cancel function with db.QueryContext and similar functions, sometimes, when that cancel function is called, the transaction is rolled back, returning sql: transaction has already been committed or rolled back on subsequent calls.

Reproduction

This code reproduces the issue about 20% of times that it runs. After the aux function countUsers returns and dispatches the cancel function, the next call will return the above transaction error.

func main() {
	txdb.Register("mysqltx", "mysql", "root@/txdb_test")
	db, err := sql.Open("mysqltx", fmt.Sprintf("connection_%d", time.Now().UnixNano()))
	if err != nil {
		log.Fatalf("could not open DB tx: %s", err.Error())
	}
	n, err := countUsers(db)
	if err != nil {
		log.Fatalf("error doing query: %s", err.Error())
	}
	log.Printf("Found %d users", n)
	if err := db.Close(); err != nil {
                // error here
		log.Fatalf("could not close DB tx: %s", err.Error())
	}
}

func countUsers(db *sql.DB) (int, error) {
	ctx, cancel := context.WithTimeout(context.Background(), 100*time.Millisecond)
	defer cancel()
	var n int
	if err := db.QueryRowContext(ctx, "SELECT COUNT(*) FROM user").Scan(&n); err != nil {
		return 0, err
	}

	return n, nil
}

Notes

• Go version: go version go1.13.5 linux/amd64
• MySQL version mysql:5.7.12 Docker image
• Not able to reproduce this in my example, but on my project that I've found this issue, I'm also seeing series of these errors:

[mysql] 2020/01/12 20:17:11 packets.go:412: busy buffer
[mysql] 2020/01/12 20:17:11 packets.go:433: busy buffer
[mysql] 2020/01/12 20:17:11 packets.go:393: busy buffer
[mysql] 2020/01/12 20:17:11 packets.go:412: busy buffer
[mysql] 2020/01/12 20:17:11 packets.go:433: busy buffer
[mysql] 2020/01/12 20:17:11 packets.go:393: busy buffer

Let me know if I'm doing anything improperly or if you need any more information.

Thanks!

[l3pp4rd]

Hi, if you see busy buffer errors, it means that most likely you are not closing sql.Rows before calling another exec or anything on that transaction.

In transaction you acquire a single connection, if you query rows and do not close it before calling any other exec or query on that tx, then you definitely will endup with timeout of tx or context, whichever happens first. It will simply block.

The best practice is in any case, just to release rows when you read it, do not defer the close if you happen to issue another call. If not within transaction, it would use more connections to db than needed or block if you run out of connections.

[samsondav]

We are encountering this issue on postgres. It's still a problem and has nothing to do with not closing sql.Rows.

I opened a new issue here to track: #43