From b4828de6fa2d13a4cc152618861ca95aee3efacf Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Felix=20Geisend=C3=B6rfer?= Date: Mon, 29 Jan 2018 12:16:17 +0100 Subject: [PATCH] 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](https://github.com/golang/go/issues/23519), but the conclusion was that the [db drivers should fix it](https://github.com/golang/go/issues/23519#issuecomment-360572132). 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 ``` --- go18_test.go | 44 ++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 44 insertions(+) diff --git a/go18_test.go b/go18_test.go index 1d70fe7f3..b46808993 100644 --- a/go18_test.go +++ b/go18_test.go @@ -5,8 +5,10 @@ import ( "database/sql" "database/sql/driver" "errors" + "math/rand" "runtime" "strings" + "sync" "testing" "time" @@ -161,6 +163,48 @@ func TestContextCancelQuery(t *testing.T) { } } +// TestContextCancelQueryWhileScan checks for race conditions that arise when +// a query context is canceled while a user is calling rows.Scan(). The code +// is based on database/sql TestIssue18429. +// See https://github.com/golang/go/issues/23519 +func TestContextCancelQueryWhileScan(t *testing.T) { + db := openTestConn(t) + defer db.Close() + + const milliWait = 30 + sem := make(chan bool, 20) + + // This query seems to work well for triggering race conditions between + // the rows.Scan() call below, and the implicit rows.Close() call triggered + // by ctx timing out. + sql := `SELECT (g/10)::int, json_agg(g) FROM generate_series(1, 1000) g, pg_sleep($1) GROUP BY 1;` + var wg sync.WaitGroup + for i := 0; i < contextRaceIterations; i++ { + sem <- true + wg.Add(1) + go func() { + defer func() { + <-sem + wg.Done() + }() + qwait := float64(time.Duration(rand.Intn(milliWait))*time.Millisecond) / 1000 + + ctx, cancel := context.WithTimeout(context.Background(), time.Duration(rand.Intn(milliWait))*time.Millisecond) + defer cancel() + rows, _ := db.QueryContext(ctx, sql, qwait) + if rows != nil { + var d int + var n string + for rows.Next() { + rows.Scan(&d, &n) + } + rows.Close() + } + }() + } + wg.Wait() +} + // TestIssue617 tests that a failed query in QueryContext doesn't lead to a // goroutine leak. func TestIssue617(t *testing.T) {