Skip to content

Commit b4828de

Browse files
felixgearp242
authored andcommitted
test: show QueryContext cancel/Scan race condition
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 ```
1 parent 6696a19 commit b4828de

1 file changed

Lines changed: 44 additions & 0 deletions

File tree

go18_test.go

Lines changed: 44 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -5,8 +5,10 @@ import (
55
"database/sql"
66
"database/sql/driver"
77
"errors"
8+
"math/rand"
89
"runtime"
910
"strings"
11+
"sync"
1012
"testing"
1113
"time"
1214

@@ -161,6 +163,48 @@ func TestContextCancelQuery(t *testing.T) {
161163
}
162164
}
163165

166+
// TestContextCancelQueryWhileScan checks for race conditions that arise when
167+
// a query context is canceled while a user is calling rows.Scan(). The code
168+
// is based on database/sql TestIssue18429.
169+
// See https://github.com/golang/go/issues/23519
170+
func TestContextCancelQueryWhileScan(t *testing.T) {
171+
db := openTestConn(t)
172+
defer db.Close()
173+
174+
const milliWait = 30
175+
sem := make(chan bool, 20)
176+
177+
// This query seems to work well for triggering race conditions between
178+
// the rows.Scan() call below, and the implicit rows.Close() call triggered
179+
// by ctx timing out.
180+
sql := `SELECT (g/10)::int, json_agg(g) FROM generate_series(1, 1000) g, pg_sleep($1) GROUP BY 1;`
181+
var wg sync.WaitGroup
182+
for i := 0; i < contextRaceIterations; i++ {
183+
sem <- true
184+
wg.Add(1)
185+
go func() {
186+
defer func() {
187+
<-sem
188+
wg.Done()
189+
}()
190+
qwait := float64(time.Duration(rand.Intn(milliWait))*time.Millisecond) / 1000
191+
192+
ctx, cancel := context.WithTimeout(context.Background(), time.Duration(rand.Intn(milliWait))*time.Millisecond)
193+
defer cancel()
194+
rows, _ := db.QueryContext(ctx, sql, qwait)
195+
if rows != nil {
196+
var d int
197+
var n string
198+
for rows.Next() {
199+
rows.Scan(&d, &n)
200+
}
201+
rows.Close()
202+
}
203+
}()
204+
}
205+
wg.Wait()
206+
}
207+
164208
// TestIssue617 tests that a failed query in QueryContext doesn't lead to a
165209
// goroutine leak.
166210
func TestIssue617(t *testing.T) {

0 commit comments

Comments
 (0)