search

microsoft / go-mssqldb

Microsoft SQL server driver written in go language
BSD 3-Clause "New" or "Revised" License
280 stars 62 forks source link

tdsBuffer data race in transaction query with OUTPUT #171

Open pirm-in opened 8 months ago

pirm-in commented 8 months ago

Versions go 1.21 github.com/microsoft/go-mssqldb v1.6.0

Describe the bug Running $ go test ./... -race results in a data race. See stack trace below. The issue seems to happen when func (r *tdsBuffer) readNextPacket() is writing to a field of the tdsBuffer instance .

During the transaction there are two insert statements happening 

rows, err := tx.NamedQuery(`
        INSERT INTO Events (Type, Value, Description, ...)
        OUTPUT inserted.Uuid, inserted.Id
        VALUES (Type, :Value, :Description, ...)
    `, row)

and later this is called

func (h *EventHistory) TxStore(tx *sqlx.Tx) error {
    _, err := tx.Exec(`
          INSERT INTO EventHistory (EventId, Data) 
          VALUES (@event_id, @data)
        `,
        sql.Named("event_id", h.EventId),
        sql.Named("data", h.Data))

    return err
}

Edit: I just noticed the data race does not occur when there is no OUTPUT field in the NamedQuery. With the following query there is no data race:

rows, err := tx.NamedQuery(`
        INSERT INTO Events (Type, Value, Description, ...)
        VALUES (Type, :Value, :Description, ...)
    `, row)

Stack trace:

2024/01/26 11:56:53 INFO Database connection pool max_idle=40 max_open=40
==================
WARNING: DATA RACE
Write at 0x00c0000b6a60 by goroutine 60:
  github.com/microsoft/go-mssqldb.(*tdsBuffer).readNextPacket()
      /path/to/go/pkg/mod/github.com/microsoft/go-mssqldb@v1.6.0/buf.go:184 +0x4e4
  github.com/microsoft/go-mssqldb.(*tdsBuffer).BeginRead()
      /path/to/go/pkg/mod/github.com/microsoft/go-mssqldb@v1.6.0/buf.go:192 +0x16e
  github.com/microsoft/go-mssqldb.processSingleResponse()
      /path/to/go/pkg/mod/github.com/microsoft/go-mssqldb@v1.6.0/token.go:961 +0x148
  github.com/microsoft/go-mssqldb.startReading.func1()
      /path/to/go/pkg/mod/github.com/microsoft/go-mssqldb@v1.6.0/token.go:1145 +0x8f

Previous write at 0x00c0000b6a60 by goroutine 58:
  github.com/microsoft/go-mssqldb.(*tdsBuffer).ReadByte()
      /path/to/go/pkg/mod/github.com/microsoft/go-mssqldb@v1.6.0/buf.go:210 +0x126
  github.com/microsoft/go-mssqldb.(*tdsBuffer).byte()
      /path/to/go/pkg/mod/github.com/microsoft/go-mssqldb@v1.6.0/buf.go:215 +0x504
  github.com/microsoft/go-mssqldb.processSingleResponse()
      /path/to/go/pkg/mod/github.com/microsoft/go-mssqldb@v1.6.0/token.go:982 +0x4e3
  github.com/microsoft/go-mssqldb.startReading.func1()
      /path/to/go/pkg/mod/github.com/microsoft/go-mssqldb@v1.6.0/token.go:1145 +0x8f

Goroutine 60 (running) created at:
  github.com/microsoft/go-mssqldb.startReading()
      /path/to/go/pkg/mod/github.com/microsoft/go-mssqldb@v1.6.0/token.go:1145 +0x1da
  github.com/microsoft/go-mssqldb.(*Stmt).processExec()
      /path/to/go/pkg/mod/github.com/microsoft/go-mssqldb@v1.6.0/mssql.go:814 +0xd2
  github.com/microsoft/go-mssqldb.(*Stmt).exec()
      /path/to/go/pkg/mod/github.com/microsoft/go-mssqldb@v1.6.0/mssql.go:807 +0x1aa
  github.com/microsoft/go-mssqldb.(*Stmt).ExecContext()
      /path/to/go/pkg/mod/github.com/microsoft/go-mssqldb@v1.6.0/mssql.go:1181 +0x3a7
  database/sql.ctxDriverStmtExec()
      /usr/local/go/src/database/sql/ctxutil.go:65 +0xec
  database/sql.resultFromStatement()
      /usr/local/go/src/database/sql/sql.go:2642 +0x1b0
  database/sql.(*DB).execDC()
      /usr/local/go/src/database/sql/sql.go:1694 +0x4fc
  database/sql.(*Tx).ExecContext()
      /usr/local/go/src/database/sql/sql.go:2478 +0x128
  database/sql.(*Tx).Exec()
      /usr/local/go/src/database/sql/sql.go:2487 +0x214
  /path/to/vkdb-svc/pkg/eventhistory/repository/mssql.(*EventHistory).TxStore()
      /path/to/html/vke/vkdb-svc/pkg/eventhistory/repository/mssql/model.go:19 +0x160
  /path/to/vkdb-svc/pkg/events/repository/mssql.(*EventRepository).Create.func1()
     /path/to/html/vke/vkdb-svc/pkg/events/repository/mssql/create.go:77 +0x409
  /path/to/vkdb-svc/pkg/db/mssql.WithTx()
     /path/to//html/vke/vkdb-svc/pkg/db/mssql/transaction.go:34 +0xfa
  /path/to/vkdb-svc/pkg/events/repository/mssql.(*EventRepository).Create()
      /path/to/html/vke/vkdb-svc/pkg/events/repository/mssql/create.go:42 +0x4cc
  /path/to/vkdb-svc/pkg/events.(*EventService).Create()
      /path/to/html/vke/vkdb-svc/pkg/events/service.go:72 +0x7f1
  /path/to/vkdb-svc/pkg/events.TestCreateEvent.func1()
      /path/to/html/vke/vkdb-svc/pkg/events/service_test.go:183 +0x9e
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1595 +0x238
  testing.(*T).Run.func1()
      /usr/local/go/src/testing/testing.go:1648 +0x44

Goroutine 58 (finished) created at:
  github.com/microsoft/go-mssqldb.startReading()
      /path/to/go/pkg/mod/github.com/microsoft/go-mssqldb@v1.6.0/token.go:1145 +0x1da
  github.com/microsoft/go-mssqldb.(*Stmt).processQueryResponse()
     /path/to/go/pkg/mod/github.com/microsoft/go-mssqldb@v1.6.0/mssql.go:739 +0x11d
  github.com/microsoft/go-mssqldb.(*Stmt).queryContext()
     /path/to/go/pkg/mod/github.com/microsoft/go-mssqldb@v1.6.0/mssql.go:734 +0x23a
  github.com/microsoft/go-mssqldb.(*Stmt).QueryContext()
     /path/to/go/pkg/mod/github.com/microsoft/go-mssqldb@v1.6.0/mssql.go:1168 +0x3a7
  database/sql.ctxDriverStmtQuery()
      /usr/local/go/src/database/sql/ctxutil.go:82 +0xec
  database/sql.rowsiFromStatement()
      /usr/local/go/src/database/sql/sql.go:2808 +0x1f5
  database/sql.(*DB).queryDC()
      /usr/local/go/src/database/sql/sql.go:1778 +0x4d7
  database/sql.(*Tx).QueryContext()
      /usr/local/go/src/database/sql/sql.go:2497 +0x152
  database/sql.(*Tx).Query()
      /usr/local/go/src/database/sql/sql.go:2505 +0xaa
  github.com/jmoiron/sqlx.(*Tx).Queryx()
      /path/to/go/pkg/mod/github.com/jmoiron/sqlx@v1.3.5/sqlx.go:437 +0x54
  github.com/jmoiron/sqlx.NamedQuery()
      /path/to/go/pkg/mod/github.com/jmoiron/sqlx@v1.3.5/named.go:446 +0x162
  github.com/jmoiron/sqlx.(*Tx).NamedQuery()
      /path/to/go/pkg/mod/github.com/jmoiron/sqlx@v1.3.5/sqlx.go:419 +0x85
  /path/to/vkdb-svc/pkg/events/repository/mssql.(*EventRepository).Create.func1()
      /path/to/html/vke/vkdb-svc/pkg/events/repository/mssql/create.go:44 +0x5b
  /path/to/vkdb-svc/pkg/db/mssql.WithTx()
     /path/to/tml/vke/vkdb-svc/pkg/db/mssql/transaction.go:34 +0xfa
  /path/to/vkdb-svc/pkg/events/repository/mssql.(*EventRepository).Create()
     /path/to/html/vke/vkdb-svc/pkg/events/repository/mssql/create.go:42 +0x4cc
  /path/to/vkdb-svc/pkg/events.(*EventService).Create()
      /path/to/html/vke/vkdb-svc/pkg/events/service.go:72 +0x7f1
  /path/to/vkdb-svc/pkg/events.TestCreateEvent.func1()
      /path/to/html/vke/vkdb-svc/pkg/events/service_test.go:183 +0x9e
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1595 +0x238
  testing.(*T).Run.func1()
      /usr/local/go/src/testing/testing.go:1648 +0x44

Further technical details

The database is running in a docker container with base image from mcr.microsoft.com/mssql/server:2022-latest SELECT @@VERSION; shows

Microsoft SQL Server 2022 (RTM-CU5) (KB5026806) - 16.0.4045.3 (X64) 
        May 26 2023 12:52:08 
        Copyright (C) 2022 Microsoft Corporation
        Developer Edition (64-bit) on Linux (Ubuntu 20.04.6 LTS) <X64>

I cannot completely rule out that i am doing something wrong, but since I am not using go routines in my part of the code it seems more likely that it might indeed be an issue inside the go-mssqldb package.

shueybubbles commented 6 months ago

@pirm-in do you have a repro that doesn't use sqlx , just straight database/sql calls?