Skip to content

test: show QueryContext cancel/Scan race condition #706

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

Open
wants to merge 1 commit into
base: master
Choose a base branch
from

Conversation

felixge
Copy link

@felixge felixge commented Jan 29, 2018

This test case shows a race condition we see in the test suite of our application. We already created an issue with the Go project, but the conclusion was that the db drivers should fix it.

I was able to reproduce this issue with the following go versions:

  • go version go1.9.3 darwin/amd64 (output shown below)
  • go version devel +5af1e7d78e Sun Jan 28 19:54:48 2018 +0000 darwin/amd64 (latest master)

Please let me know if I can provide more information and/or if you'd like me to attempt to create a patch to fix the issue.

$ while go test -v -race -run 'TestContextCancelQueryWhileScan'; do :; done
=== RUN   TestContextCancelQueryWhileScan
--- PASS: TestContextCancelQueryWhileScan (0.13s)
PASS
ok  	github.com/lib/pq	1.160s
=== RUN   TestContextCancelQueryWhileScan
==================
WARNING: DATA RACE
Read at 0x00c4201ae5ae by goroutine 23:
  runtime.slicebytetostring()
      /usr/local/Cellar/go/1.9.3/libexec/src/runtime/string.go:72 +0x0
  database/sql.convertAssign()
      /usr/local/Cellar/go/1.9.3/libexec/src/database/sql/convert.go:244 +0x2333
  database/sql.(*Rows).Scan()
      /usr/local/Cellar/go/1.9.3/libexec/src/database/sql/sql.go:2727 +0x295
  github.com/lib/pq.TestContextCancelQueryWhileScan.func1()
      /Users/felixge/code/go/src/github.com/lib/pq/go18_test.go:188 +0x38a

Previous write at 0x00c4201ae5a8 by goroutine 50:
  runtime.slicecopy()
      /usr/local/Cellar/go/1.9.3/libexec/src/runtime/slice.go:160 +0x0
  bufio.(*Reader).Read()
      /usr/local/Cellar/go/1.9.3/libexec/src/bufio/bufio.go:224 +0x240
  io.ReadAtLeast()
      /usr/local/Cellar/go/1.9.3/libexec/src/io/io.go:309 +0x93
  io.ReadFull()
      /usr/local/Cellar/go/1.9.3/libexec/src/io/io.go:327 +0x72
  github.com/lib/pq.(*conn).recvMessage()
      /Users/felixge/code/go/src/github.com/lib/pq/conn.go:971 +0x38a
  github.com/lib/pq.(*conn).recv1Buf()
      /Users/felixge/code/go/src/github.com/lib/pq/conn.go:1007 +0x46
  github.com/lib/pq.(*rows).Next()
      /Users/felixge/code/go/src/github.com/lib/pq/conn.go:1399 +0x13b
  github.com/lib/pq.(*rows).Close()
      /Users/felixge/code/go/src/github.com/lib/pq/conn.go:1356 +0x8f
  database/sql.(*Rows).close.func1()
      /usr/local/Cellar/go/1.9.3/libexec/src/database/sql/sql.go:2761 +0x6e
  database/sql.withLock()
      /usr/local/Cellar/go/1.9.3/libexec/src/database/sql/sql.go:2873 +0x76
  database/sql.(*Rows).close()
      /usr/local/Cellar/go/1.9.3/libexec/src/database/sql/sql.go:2760 +0x1ca
  database/sql.(*Rows).awaitDone()
      /usr/local/Cellar/go/1.9.3/libexec/src/database/sql/sql.go:2436 +0x14c

Goroutine 23 (running) created at:
  github.com/lib/pq.TestContextCancelQueryWhileScan()
      /Users/felixge/code/go/src/github.com/lib/pq/go18_test.go:174 +0x163
  testing.tRunner()
      /usr/local/Cellar/go/1.9.3/libexec/src/testing/testing.go:746 +0x16c

Goroutine 50 (running) created at:
  database/sql.(*Rows).initContextClose()
      /usr/local/Cellar/go/1.9.3/libexec/src/database/sql/sql.go:2420 +0xdd
  database/sql.(*DB).queryDC()
      /usr/local/Cellar/go/1.9.3/libexec/src/database/sql/sql.go:1334 +0xb7f
  database/sql.(*DB).query()
      /usr/local/Cellar/go/1.9.3/libexec/src/database/sql/sql.go:1304 +0x193
  database/sql.(*DB).QueryContext()
      /usr/local/Cellar/go/1.9.3/libexec/src/database/sql/sql.go:1281 +0xe2
  github.com/lib/pq.TestContextCancelQueryWhileScan.func1()
      /Users/felixge/code/go/src/github.com/lib/pq/go18_test.go:183 +0x22f
==================
--- FAIL: TestContextCancelQueryWhileScan (0.12s)
	testing.go:699: race detected during execution of test
FAIL
exit status 1
FAIL	github.com/lib/pq	0.153s

This test case shows a race condition we see in the test suite of our
application. We already created an issue with the [Go
project](golang/go#23519), but the conclusion was
that the [db drivers should fix
it](golang/go#23519 (comment)).

I was able to reproduce this issue with the following go versions:

- `go version go1.9.3 darwin/amd64` (output shown below)
- `go version devel +5af1e7d78e Sun Jan 28 19:54:48 2018 +0000 darwin/amd64` (latest master)

Please let me know if I can provide more information and/or if you'd
like me to attempt to create a patch to fix the issue.

```
$ while go test -v -race -run 'TestContextCancelQueryWhileScan'; do :; done
=== RUN   TestContextCancelQueryWhileScan
--- PASS: TestContextCancelQueryWhileScan (0.13s)
PASS
ok  	github.com/lib/pq	1.160s
=== RUN   TestContextCancelQueryWhileScan
==================
WARNING: DATA RACE
Read at 0x00c4201ae5ae by goroutine 23:
  runtime.slicebytetostring()
      /usr/local/Cellar/go/1.9.3/libexec/src/runtime/string.go:72 +0x0
  database/sql.convertAssign()
      /usr/local/Cellar/go/1.9.3/libexec/src/database/sql/convert.go:244 +0x2333
  database/sql.(*Rows).Scan()
      /usr/local/Cellar/go/1.9.3/libexec/src/database/sql/sql.go:2727 +0x295
  github.com/lib/pq.TestContextCancelQueryWhileScan.func1()
      /Users/felixge/code/go/src/github.com/lib/pq/go18_test.go:188 +0x38a

Previous write at 0x00c4201ae5a8 by goroutine 50:
  runtime.slicecopy()
      /usr/local/Cellar/go/1.9.3/libexec/src/runtime/slice.go:160 +0x0
  bufio.(*Reader).Read()
      /usr/local/Cellar/go/1.9.3/libexec/src/bufio/bufio.go:224 +0x240
  io.ReadAtLeast()
      /usr/local/Cellar/go/1.9.3/libexec/src/io/io.go:309 +0x93
  io.ReadFull()
      /usr/local/Cellar/go/1.9.3/libexec/src/io/io.go:327 +0x72
  github.com/lib/pq.(*conn).recvMessage()
      /Users/felixge/code/go/src/github.com/lib/pq/conn.go:971 +0x38a
  github.com/lib/pq.(*conn).recv1Buf()
      /Users/felixge/code/go/src/github.com/lib/pq/conn.go:1007 +0x46
  github.com/lib/pq.(*rows).Next()
      /Users/felixge/code/go/src/github.com/lib/pq/conn.go:1399 +0x13b
  github.com/lib/pq.(*rows).Close()
      /Users/felixge/code/go/src/github.com/lib/pq/conn.go:1356 +0x8f
  database/sql.(*Rows).close.func1()
      /usr/local/Cellar/go/1.9.3/libexec/src/database/sql/sql.go:2761 +0x6e
  database/sql.withLock()
      /usr/local/Cellar/go/1.9.3/libexec/src/database/sql/sql.go:2873 +0x76
  database/sql.(*Rows).close()
      /usr/local/Cellar/go/1.9.3/libexec/src/database/sql/sql.go:2760 +0x1ca
  database/sql.(*Rows).awaitDone()
      /usr/local/Cellar/go/1.9.3/libexec/src/database/sql/sql.go:2436 +0x14c

Goroutine 23 (running) created at:
  github.com/lib/pq.TestContextCancelQueryWhileScan()
      /Users/felixge/code/go/src/github.com/lib/pq/go18_test.go:174 +0x163
  testing.tRunner()
      /usr/local/Cellar/go/1.9.3/libexec/src/testing/testing.go:746 +0x16c

Goroutine 50 (running) created at:
  database/sql.(*Rows).initContextClose()
      /usr/local/Cellar/go/1.9.3/libexec/src/database/sql/sql.go:2420 +0xdd
  database/sql.(*DB).queryDC()
      /usr/local/Cellar/go/1.9.3/libexec/src/database/sql/sql.go:1334 +0xb7f
  database/sql.(*DB).query()
      /usr/local/Cellar/go/1.9.3/libexec/src/database/sql/sql.go:1304 +0x193
  database/sql.(*DB).QueryContext()
      /usr/local/Cellar/go/1.9.3/libexec/src/database/sql/sql.go:1281 +0xe2
  github.com/lib/pq.TestContextCancelQueryWhileScan.func1()
      /Users/felixge/code/go/src/github.com/lib/pq/go18_test.go:183 +0x22f
==================
--- FAIL: TestContextCancelQueryWhileScan (0.12s)
	testing.go:699: race detected during execution of test
FAIL
exit status 1
FAIL	github.com/lib/pq	0.153s
```
@felixge
Copy link
Author

felixge commented Feb 13, 2018

Is there any additional information I could provide to help this along?

@jbowens
Copy link

jbowens commented Feb 20, 2018

Should this be filed as an issue? Then any resolving pull request will include the test case from this pull request?

@felixge
Copy link
Author

felixge commented Feb 22, 2018

@jbowens I'm happy to create a separate issue for this, but I suspect this is currently stuck because none of the maintainers has time to look at it? (Which is fine, I'm grateful for all the work that went into this project)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants