Skip to content

Commit f9df137

Browse files
committed
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 19c8e9a commit f9df137

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 @@ package pq
55
import (
66
"context"
77
"database/sql"
8+
"math/rand"
89
"runtime"
910
"strings"
11+
"sync"
1012
"testing"
1113
"time"
1214
)
@@ -157,6 +159,48 @@ func TestContextCancelQuery(t *testing.T) {
157159
}
158160
}
159161

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

0 commit comments

Comments
 (0)