database/sql: Transaction was timeout and rollback but the query was executed on db

[namnd95]

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

go version go1.12 linux/amd64

Does this issue reproduce with the latest release?

Yes

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

go env Output

GOARCH="amd64"
GOBIN=""
GOCACHE="/home/nguyendn/.cache/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/nguyendn/go"
GOPROXY=""
GORACE=""
GOROOT="/usr/lib/go-1.12"
GOTMPDIR=""
GOTOOLDIR="/usr/lib/go-1.12/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build871815186=/tmp/go-build -gno-record-gcc-switches"

What did you do?

We begin a db transaction with a context timeout and exec a sql query after that.
If the db transaction is timeout, during extreme condition, the transaction was rollback because of timeout but the query was executed successfully and the data persists to db.

Code:

var err error
var tx *sql.Tx
ctx, cancelFunc := context.WithTimeout(context.Background(), time.Nanosecond*1000000)
defer cancelFunc()
tx, err = db.BeginTx(ctx, nil) // begin with a very short timeout to reproduce the error
_, err = tx.Exec("insert into test values()") // transaction timeout and auto rollback, but the query can be executed without errors
tx.Rollback() // err: sql: transaction has already been committed or rolled back

MySQL logs

279 Connect	root@localhost on test using TCP/IP
279 Query	START TRANSACTION
279 Query	ROLLBACK
279 Query	insert into test values()

What did you expect to see?

The query execution after rollback should return error

What did you see instead?

The query execution was committed to db

Cause

main go routine:

we have entered this function tx.Exec() -> tx.ExecContext() -> db.ExecDC() but haven't executed the query yet

	defer func() {
		release(err)
	}()
	execerCtx, ok := dc.ci.(driver.ExecerContext)
	var execer driver.Execer
	if !ok {
		execer, ok = dc.ci.(driver.Execer)
	}
	// WE ARE CURRENTLY AT THIS LINE
	if ok {
		var nvdargs []driver.NamedValue
		var resi driver.Result
		withLock(dc, func() {
			nvdargs, err = driverArgsConnLocked(dc.ci, nil, args)
			if err != nil {
				return
			}
			resi, err = ctxDriverExec(ctx, execerCtx, execer, query, nvdargs)
		})
		if err != driver.ErrSkip {
			if err != nil {
				return nil, err
			}
			return driverResult{dc, resi}, nil
		}
	}

awaitDone go routine:

we have entered tx.awaitDone() -> tx.rollback(true) -> tx.txi.Rollback()

	if !atomic.CompareAndSwapInt32(&tx.done, 0, 1) {
		return ErrTxDone
	}
	var err error
	withLock(tx.dc, func() {      
		err = tx.txi.Rollback()    // THIS CAN BE EXECUTED SUCCESSFULLY ALTHOUGH STILL HAVE ACTIVE QUERY
	})
	if err != driver.ErrBadConn {
		tx.closePrepared()
	}
	if discardConn {
		err = driver.ErrBadConn
	}
	tx.close(err) // We only check tx.closemu lock here
	return err

We have the lock tx.closemu to ensure there aren't any active queries in the transaction, but we already rollback the transaction before checking the availability of the lock.
I suggest checking this lock in tx.rollback and tx.Commit function directly instead of tx.Close

[methane]

Is this issue same to #34775?

[namnd95]

This issue should have the same cause with #34775

[gopherbot]

Change https://golang.org/cl/216240 mentions this issue: database/sql: prevent Tx statement from committing after rollback

[gopherbot]

Change https://golang.org/cl/242101 mentions this issue: [release-branch.go1.14] database/sql: backport 3 Tx rollback related CLs

[gopherbot]

Change https://golang.org/cl/242102 mentions this issue: [release-branch.go1.14] database/sql: backport 3 Tx rollback related CLs

[gopherbot]

Change https://golang.org/cl/242522 mentions this issue: [release-branch.go1.13] database/sql: backport 5 Tx rollback related CLs