Skip to content

Commit

Permalink
Disable logging in go routine
Browse files Browse the repository at this point in the history
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
  • Loading branch information
denisenkom committed Nov 3, 2020
1 parent 2f2a555 commit d64bfdb
Showing 1 changed file with 8 additions and 4 deletions.
12 changes: 8 additions & 4 deletions token.go
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down

0 comments on commit d64bfdb

Please sign in to comment.