From d64bfdbad13a5c4c18490e7742a7043aa2503dfd Mon Sep 17 00:00:00 2001 From: denisenk Date: Mon, 2 Nov 2020 22:44:50 -0500 Subject: [PATCH] Disable logging in go routine Logging was causing data race error. Here is one example of such error (from https://ci.appveyor.com/project/denisenkom/go-mssqldb/builds/36105319/job/qrymmer7mnvkbv2p): ``` 2020/11/03 03:32:09 initiating response reading 2020/11/03 03:32:09 got token tokenLoginAck 2020/11/03 03:32:09 got token tokenEnvChange 2020/11/03 03:32:09 got token tokenDone 2020/11/03 03:32:09 got DONE or DONEPROC status=0 2020/11/03 03:32:09 response finished 2020/11/03 03:32:09 SET XACT_ABORT ON; -- 16384 SET ANSI_NULLS ON; -- 32 SET ARITHIGNORE ON; -- 128 2020/11/03 03:32:09 initiating response reading 2020/11/03 03:32:09 got token tokenEnvChange 2020/11/03 03:32:09 got token tokenDone 2020/11/03 03:32:09 got DONE or DONEPROC status=1 2020/11/03 03:32:09 got token tokenDone 2020/11/03 03:32:09 got DONE or DONEPROC status=1 2020/11/03 03:32:09 got token tokenDone 2020/11/03 03:32:09 got DONE or DONEPROC status=0 2020/11/03 03:32:09 response finished 2020/11/03 03:32:09 select Options = @@OPTIONS; 2020/11/03 03:32:09 initiating response reading 2020/11/03 03:32:09 got token tokenColMetadata 2020/11/03 03:32:09 got token tokenRow 2020/11/03 03:32:09 got token tokenDone 2020/11/03 03:32:09 got DONE or DONEPROC status=16 2020/11/03 03:32:09 (1 row(s) affected) 2020/11/03 03:32:09 response finished 2020/11/03 03:32:09 SET XACT_ABORT ON; -- 16384 SET ANSI_NULLS ON; -- 32 SET ARITHIGNORE ON; -- 128 2020/11/03 03:32:09 initiating response reading 2020/11/03 03:32:09 got token tokenEnvChange 2020/11/03 03:32:09 got token tokenDone 2020/11/03 03:32:09 got DONE or DONEPROC status=1 2020/11/03 03:32:09 got token tokenDone 2020/11/03 03:32:09 got DONE or DONEPROC status=1 2020/11/03 03:32:09 got token tokenDone 2020/11/03 03:32:09 got DONE or DONEPROC status=0 2020/11/03 03:32:09 response finished ================== WARNING: DATA RACE Read at 0x00c00033a043 by goroutine 55: testing.(*common).logDepth() c:/go113/src/testing/testing.go:665 +0xa8 testing.(*common).Log() c:/go113/src/testing/testing.go:658 +0x7e github.com/denisenkom/go-mssqldb.testLogger.Println() C:/gopath/src/github.com/denisenkom/go-mssqldb/tds_test.go:224 +0x5f github.com/denisenkom/go-mssqldb.optionalLogger.Println() C:/gopath/src/github.com/denisenkom/go-mssqldb/log.go:26 +0xa1 github.com/denisenkom/go-mssqldb.(*parseResp).dlog() C:/gopath/src/github.com/denisenkom/go-mssqldb/token.go:708 +0x176 github.com/denisenkom/go-mssqldb.(*parseResp).iter() C:/gopath/src/github.com/denisenkom/go-mssqldb/token.go:725 +0xcc6 github.com/denisenkom/go-mssqldb.processResponse() C:/gopath/src/github.com/denisenkom/go-mssqldb/token.go:813 +0x17c Previous write at 0x00c00033a043 by goroutine 40: testing.tRunner.func1() c:/go113/src/testing/testing.go:900 +0x35a testing.tRunner() c:/go113/src/testing/testing.go:913 +0x1c2 Goroutine 55 (running) created at: github.com/denisenkom/go-mssqldb.(*Stmt).processQueryResponse() C:/gopath/src/github.com/denisenkom/go-mssqldb/mssql.go:600 +0x1a5 github.com/denisenkom/go-mssqldb.(*Stmt).queryContext() C:/gopath/src/github.com/denisenkom/go-mssqldb/mssql.go:594 +0x1c2 github.com/denisenkom/go-mssqldb.(*Stmt).Query() C:/gopath/src/github.com/denisenkom/go-mssqldb/mssql.go:584 +0xbe github.com/denisenkom/go-mssqldb.TestQueryCancelLowLevel() C:/gopath/src/github.com/denisenkom/go-mssqldb/queries_test.go:1805 +0x54c testing.tRunner() c:/go113/src/testing/testing.go:909 +0x1a0 Goroutine 40 (running) created at: testing.(*T).Run() c:/go113/src/testing/testing.go:960 +0x658 testing.runTests.func1() c:/go113/src/testing/testing.go:1202 +0xad testing.tRunner() c:/go113/src/testing/testing.go:909 +0x1a0 testing.runTests() c:/go113/src/testing/testing.go:1200 +0x528 testing.(*M).Run() c:/go113/src/testing/testing.go:1117 +0x306 main.main() _testmain.go:362 +0x33e ================== 2020/11/03 03:32:18 [{Hello} {World} {TVP}] FAIL coverage: 78.2% of statements exit status 1 ``` Testing data race Testing data race Testing data race Testing data race Testing data race add comment --- token.go | 12 ++++++++---- 1 file changed, 8 insertions(+), 4 deletions(-) diff --git a/token.go b/token.go index 25385e89..6aa99aa9 100644 --- a/token.go +++ b/token.go @@ -704,14 +704,18 @@ func (ts *parseResp) sendAttention(ch chan tokenStruct) parseRespIter { } func (ts *parseResp) dlog(msg string) { - if ts.sess.logFlags&logDebug != 0 { + // logging from goroutine is disabled to prevent + // data race detection from firing + // The race is probably happening when + // test logger changes between tests. + /*if ts.sess.logFlags&logDebug != 0 { ts.sess.log.Println(msg) - } + }*/ } func (ts *parseResp) dlogf(f string, v ...interface{}) { - if ts.sess.logFlags&logDebug != 0 { + /*if ts.sess.logFlags&logDebug != 0 { ts.sess.log.Printf(f, v...) - } + }*/ } func (ts *parseResp) iter(ctx context.Context, ch chan tokenStruct, tokChan chan tokenStruct) parseRespIter {