Skip to content

Data race between mysqlConn watcher and okHandler during context cancellation #1559

Closed

Description

@bobvawter

Issue description

I have one goroutine running database transactions in a loop and another goroutine cancels the context being used. This leads to the data race shown below.

Example code

Execute with go test -v -race . -test.count 1000 -test.failfast -test.run 'TestRace'

func TestRace(t *testing.T) {
	r := require.New(t)

	driver := mysql.MySQLDriver{}
	connector, err := driver.OpenConnector("root:SoupOrSecret@/mysql")
	r.NoError(err)
	db := sql.OpenDB(connector)

	ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second)
	defer cancel()

	triggerCancel := make(chan struct{})
	done := make(chan struct{})

	go func() {
		defer close(done)

		didTrigger := false
		for ctx.Err() == nil {
			tx, err := db.BeginTx(ctx, nil)
			if errors.Is(err, context.Canceled) {
				return
			}
			r.NoError(err)

			var one int
			err = tx.QueryRowContext(ctx, "SELECT 1").Scan(&one)
			if errors.Is(err, context.Canceled) {
				return
			}
			r.NoError(err)

			_ = tx.Rollback()
			if !didTrigger {
				didTrigger = true
				close(triggerCancel)
			}
		}
	}()

	<-triggerCancel
	time.Sleep(10 * time.Millisecond)
	cancel()
	<-done
}

Error log

WARNING: DATA RACE
Write at 0x00c000392458 by goroutine 28578:
  github.com/go-sql-driver/mysql.(*mysqlConn).clearResult()
      /home/runner/go/pkg/mod/github.com/go-sql-driver/mysql@v1.8.0/packets.go:630 +0x1c4
  github.com/go-sql-driver/mysql.(*mysqlConn).cleanup()
      /home/runner/go/pkg/mod/github.com/go-sql-driver/mysql@v1.8.0/connection.go:156 +0x1a4
  github.com/go-sql-driver/mysql.(*mysqlConn).cancel()
      /home/runner/go/pkg/mod/github.com/go-sql-driver/mysql@v1.8.0/connection.go:441 +0x84
  github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher.func1()
      /home/runner/go/pkg/mod/github.com/go-sql-driver/mysql@v1.8.0/connection.go:628 +0x234

Previous read at 0x00c000392458 by goroutine 30352:
  github.com/go-sql-driver/mysql.(*okHandler).handleOkPacket()
      /home/runner/go/pkg/mod/github.com/go-sql-driver/mysql@v1.8.0/packets.go:650 +0xfd
  github.com/go-sql-driver/mysql.(*okHandler).readResultSetHeaderPacket()
      /home/runner/go/pkg/mod/github.com/go-sql-driver/mysql@v1.8.0/packets.go:536 +0x36f
  github.com/go-sql-driver/mysql.(*mysqlConn).exec()
      /home/runner/go/pkg/mod/github.com/go-sql-driver/mysql@v1.8.0/connection.go:336 +0x18d
  github.com/go-sql-driver/mysql.(*mysqlConn).begin()
      /home/runner/go/pkg/mod/github.com/go-sql-driver/mysql@v1.8.0/connection.go:121 +0x8a
  github.com/go-sql-driver/mysql.(*mysqlConn).BeginTx()
      /home/runner/go/pkg/mod/github.com/go-sql-driver/mysql@v1.8.0/connection.go:498 +0x156
  database/sql.ctxDriverBegin()
      /opt/hostedtoolcache/go/1.20.14/x64/src/database/sql/ctxutil.go:104 +0x105
  database/sql.(*DB).beginDC.func1()
      /opt/hostedtoolcache/go/1.20.14/x64/src/database/sql/sql.go:1868 +0x156
  database/sql.withLock()
      /opt/hostedtoolcache/go/1.20.14/x64/src/database/sql/sql.go:3405 +0xa2
  database/sql.(*DB).beginDC()
      /opt/hostedtoolcache/go/1.20.14/x64/src/database/sql/sql.go:1864 +0x113
  database/sql.(*DB).begin()
      /opt/hostedtoolcache/go/1.20.14/x64/src/database/sql/sql.go:1857 +0x104
  database/sql.(*DB).BeginTx.func1()

Configuration

Driver version (or git SHA): 1.8.0

Go version: 1.20.7 & 1.22.1

Server version: mysql-v8 & mariadb-v10

Server OS: Ubuntu 22.04 (an ubuntu-latest GitHub actions runner)

Activity

  1. miparnisari commented on Mar 16, 2024

    @miparnisari

    I am seeing something similar: https://github.com/openfga/openfga/actions/runs/8271747091/job/22632184961

    ==================
    WARNING: DATA RACE
    Write at 0x00c0007cb718 by goroutine 8005:
      github.com/go-sql-driver/mysql.(*mysqlConn).clearResult()
          /home/runner/go/pkg/mod/github.com/go-sql-driver/mysql@v1.8.0/packets.go:630 +0x1c5
      github.com/go-sql-driver/mysql.(*mysqlConn).cleanup()
          /home/runner/go/pkg/mod/github.com/go-sql-driver/mysql@v1.8.0/connection.go:156 +0x1b8
      github.com/go-sql-driver/mysql.(*mysqlConn).cancel()
          /home/runner/go/pkg/mod/github.com/go-sql-driver/mysql@v1.8.0/connection.go:441 +0x77
      github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher.func1()
          /home/runner/go/pkg/mod/github.com/go-sql-driver/mysql@v1.8.0/connection.go:628 +0x21e
    
    Previous write at 0x00c0007cb718 by goroutine 8178:
      github.com/go-sql-driver/mysql.(*okHandler).readResultSetHeaderPacket()
          /home/runner/go/pkg/mod/github.com/go-sql-driver/mysql@v1.8.0/packets.go:528 +0xdc
      github.com/go-sql-driver/mysql.(*mysqlStmt).query()
          /home/runner/go/pkg/mod/github.com/go-sql-driver/mysql@v1.8.0/statement.go:111 +0x388
      github.com/go-sql-driver/mysql.(*mysqlStmt).QueryContext()
          /home/runner/go/pkg/mod/github.com/go-sql-driver/mysql@v1.8.0/connection.go:564 +0x26a
      database/sql.ctxDriverStmtQuery()
          /opt/hostedtoolcache/go/1.21.8/x64/src/database/sql/ctxutil.go:82 +0xec
      database/sql.rowsiFromStatement()
          /opt/hostedtoolcache/go/1.21.8/x64/src/database/sql/sql.go:1721 +0x8d
      database/sql.(*DB).QueryContext.func1()
          /opt/hostedtoolcache/go/1.21.8/x64/src/database/sql/sql.go:1704 +0xcf
      database/sql.(*DB).retry()
          /opt/hostedtoolcache/go/1.21.8/x64/src/database/sql/sql.go:1538 +0x4a
      database/sql.(*DB).QueryContext()
          /opt/hostedtoolcache/go/1.21.8/x64/src/database/sql/sql.go:1703 +0x186
      database/sql.(*DB).QueryRowContext()
          /opt/hostedtoolcache/go/1.21.8/x64/src/database/sql/sql.go:1804 +0x9a
      github.com/Masterminds/squirrel.(*stdsqlCtxRunner).QueryRowContext()
          /home/runner/go/pkg/mod/github.com/!masterminds/squirrel@v1.5.4/squirrel_ctx.go:68 +0x99
      github.com/Masterminds/squirrel.QueryRowContextWith()
          /home/runner/go/pkg/mod/github.com/!masterminds/squirrel@v1.5.4/squirrel_ctx.go:92 +0xa3
      github.com/Masterminds/squirrel.(*selectData).QueryRowContext()
          /home/runner/go/pkg/mod/github.com/!masterminds/squirrel@v1.5.4/select_ctx.go:45 +0x29c
      github.com/Masterminds/squirrel.SelectBuilder.QueryRowContext()
          /home/runner/go/pkg/mod/github.com/!masterminds/squirrel@v1.5.4/select_ctx.go:63 +0x18e
      github.com/openfga/openfga/pkg/storage/mysql.(*MySQL).ReadUserTuple()
          /home/runner/work/openfga/openfga/pkg/storage/mysql/mysql.go:[243](https://github.com/openfga/openfga/actions/runs/8271747091/job/22632184961#step:4:244) +0x9f2
      github.com/openfga/openfga/pkg/storage/storagewrappers.(*boundedConcurrencyTupleReader).ReadUserTuple()
          /home/runner/work/openfga/openfga/pkg/storage/storagewrappers/boundedconcurrency.go:61 +0x193
      github.com/openfga/openfga/pkg/storage/storagewrappers.(*combinedTupleReader).ReadUserTuple()
          /home/runner/work/openfga/openfga/pkg/storage/storagewrappers/combinedtuplereader.go:87 +0x677
      github.com/openfga/openfga/internal/graph.(*LocalChecker).checkRewrite.(*LocalChecker).checkDirect.func1.1()
          /home/runner/work/openfga/openfga/internal/graph/check.go:598 +0x4af
      github.com/openfga/openfga/internal/graph.resolver.func1.2()
          /home/runner/work/openfga/openfga/internal/graph/check.go:216 +0x69
    
    Goroutine 8178 (finished) created at:
      github.com/sourcegraph/conc.(*WaitGroup).Go()
          /home/runner/go/pkg/mod/github.com/sourcegraph/conc@v0.3.0/waitgroup.go:30 +0xe4
      github.com/sourcegraph/conc/pool.(*Pool).Go()
          /home/runner/go/pkg/mod/github.com/sourcegraph/conc@v0.3.0/pool/pool.go:58 +0x207
      github.com/sourcegraph/conc/pool.(*ErrorPool).Go()
          /home/runner/go/pkg/mod/github.com/sourcegraph/conc@v0.3.0/pool/error_pool.go:29 +0x187
      github.com/sourcegraph/conc/pool.(*ContextPool).Go()
          /home/runner/go/pkg/mod/github.com/sourcegraph/conc@v0.3.0/pool/context_pool.go:25 +0x26
      github.com/openfga/openfga/pkg/server/commands/reverseexpand.(*ReverseExpandQuery).execute()
          /home/runner/work/openfga/openfga/pkg/server/commands/reverseexpand/reverse_expand.go:[317](https://github.com/openfga/openfga/actions/runs/8271747091/job/22632184961#step:4:318) +0x2b64
      github.com/openfga/openfga/pkg/server/commands/reverseexpand.(*ReverseExpandQuery).readTuplesAndExecute.func2()
          /home/runner/work/openfga/openfga/pkg/server/commands/reverseexpand/reverse_expand.go:534 +0x544
      github.com/sourcegraph/conc/pool.(*ContextPool).Go.func1()
          /home/runner/go/pkg/mod/github.com/sourcegraph/conc@v0.3.0/pool/context_pool.go:38 +0xf2
      github.com/sourcegraph/conc/pool.(*ContextPool).Go.(*ErrorPool).Go.func2()
          /home/runner/go/pkg/mod/github.com/sourcegraph/conc@v0.3.0/pool/error_pool.go:30 +0x33
      github.com/sourcegraph/conc/pool.(*Pool).worker()
          /home/runner/go/pkg/mod/github.com/sourcegraph/conc@v0.3.0/pool/pool.go:154 +0xf0
      github.com/sourcegraph/conc/pool.(*Pool).worker-fm()
          <autogenerated>:1 +0x33
      github.com/sourcegraph/conc/panics.(*Catcher).Try()
          /home/runner/go/pkg/mod/github.com/sourcegraph/conc@v0.3.0/panics/panics.go:23 +0x77
      github.com/sourcegraph/conc.(*WaitGroup).Go.func1()
          /home/runner/go/pkg/mod/github.com/sourcegraph/conc@v0.3.0/waitgroup.go:32 +0x96
    ==================
    
  2. added 4 commits that reference this issue on Mar 17, 2024
    d86c452
    8a24bdf
    be8468e
    65395d8
  3. methane commented on Mar 17, 2024

    @methane
    Member

    I merged the fix to 1.8 branch.
    Please try go get -u github.com/go-sql-driver/mysql@1.8.

  4. bobvawter commented on Mar 17, 2024

    @bobvawter
    Author

    That fix is working for me. Thank you for the quick response.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions