[BUG] false positive races found, only half of a race is reported (previous access stack trace not available) #17
Description
Two problems can be seen in the log that follows.
a) We suspect that false positive races are detected. The standard Go race
detector does not identify a race on the returned err error value in the first "race"
detected below.
b) The other half (previous read) of the supposed write/read race is missing. I don't
think a race detector can be considered production ready if it does not report
both stack traces that participated in the race.
On linux/amd64
go install racedetector @latest was installed, which should be v0.7.0 but I also see
things like this in the stack trace, which strangely refers to v0.4.10.
/home/jaten/go/pkg/mod/github.com/kolkov/racedetector@v0.4.10/race/api.go:96
Note that the zygomys repo is pure Go, so should be testable without cgo issues.
$ go version
go version go1.25.3 linux/amd64
$ git clone https://github.com/glycerine/zygomys
$ cd zygomys/zygo
$ racedetector test -v
Instrumented: address.go
- 0 writes, 1 reads instrumented
Instrumented: arrayutils.go
- 9 writes, 22 reads instrumented
Instrumented: basetypes.go
Instrumented: blake2.go
- 0 writes, 1 reads instrumented
Instrumented: bsave.go
- 6 writes, 21 reads instrumented
Instrumented: builders.go
- 47 writes, 145 reads instrumented
Instrumented: calendar.go
- 1 writes, 2 reads instrumented
Instrumented: callgo.go
- 25 writes, 51 reads instrumented
Instrumented: callgo2_test.go
- 1 writes, 7 reads instrumented
Instrumented: callgo_test.go
- 8 writes, 44 reads instrumented
Instrumented: cfg.go
Instrumented: channels.go
- 2 writes, 2 reads instrumented
Instrumented: check.go
- 3 writes, 17 reads instrumented
Instrumented: closing.go
Instrumented: comment.go
- 3 writes, 13 reads instrumented
Instrumented: comparisons.go
- 15 writes, 53 reads instrumented
Instrumented: coroutines.go
- 0 writes, 3 reads instrumented
Instrumented: datastack.go
- 3 writes, 8 reads instrumented
Instrumented: dates.go
- 22 writes, 95 reads instrumented
Instrumented: demo_go_structs.go
- 2 writes, 1 reads instrumented
Instrumented: demo_go_structs_gen.go
- 236 writes, 109 reads instrumented
Instrumented: demo_go_structs_gen_test.go
- 50 writes, 75 reads instrumented
Instrumented: doc.go
Instrumented: environment.go
- 32 writes, 95 reads instrumented
Instrumented: environment_test.go
- 0 writes, 5 reads instrumented
Instrumented: exists.go
- 0 writes, 2 reads instrumented
Instrumented: expressions.go
- 34 writes, 61 reads instrumented
Instrumented: func.go
- 28 writes, 72 reads instrumented
Instrumented: functions.go
- 103 writes, 221 reads instrumented
Instrumented: generator.go
- 85 writes, 196 reads instrumented
Instrumented: gitcommit.go
Instrumented: gob.go
- 1 writes, 7 reads instrumented
Instrumented: gotypereg.go
- 8 writes, 41 reads instrumented
Instrumented: hashutils.go
- 57 writes, 223 reads instrumented
Instrumented: import.go
- 6 writes, 10 reads instrumented
Instrumented: import_test.go
- 1 writes, 2 reads instrumented
Instrumented: jsonmsgp.go
- 47 writes, 182 reads instrumented
Instrumented: jsonmsgp_test.go
- 6 writes, 30 reads instrumented
Instrumented: lexer.go
- 14 writes, 35 reads instrumented
Instrumented: lexer_test.go
- 43 writes, 10 reads instrumented
Instrumented: liner.go
- 15 writes, 27 reads instrumented
Instrumented: listutils.go
- 9 writes, 15 reads instrumented
Instrumented: makego.go
Instrumented: msgpackmap.go
- 0 writes, 1 reads instrumented
Instrumented: numerictower.go
- 17 writes, 22 reads instrumented
Instrumented: panicon.go
Instrumented: parser.go
- 45 writes, 57 reads instrumented
Instrumented: pratt.go
- 16 writes, 77 reads instrumented
Instrumented: printstate.go
- 0 writes, 1 reads instrumented
Instrumented: printstate_test.go
Instrumented: ptrcheck.go
Instrumented: random.go
Instrumented: rawutils.go
- 40 writes, 83 reads instrumented
Instrumented: regexp.go
- 3 writes, 12 reads instrumented
Instrumented: repl.go
- 46 writes, 47 reads instrumented
Instrumented: reuse_test.go
- 1 writes, 6 reads instrumented
Instrumented: scopes.go
- 13 writes, 34 reads instrumented
Instrumented: slurp.go
- 14 writes, 32 reads instrumented
Instrumented: source.go
- 7 writes, 14 reads instrumented
Instrumented: stack.go
- 13 writes, 31 reads instrumented
Instrumented: stack_test.go
- 0 writes, 2 reads instrumented
Instrumented: strutils.go
- 2 writes, 5 reads instrumented
Instrumented: system.go
- 9 writes, 20 reads instrumented
Instrumented: time.go
- 12 writes, 18 reads instrumented
Instrumented: typeutils.go
- 23 writes, 5 reads instrumented
Instrumented: unsafe.go
- 0 writes, 4 reads instrumented
Instrumented: version.go
Instrumented: vm.go
- 20 writes, 49 reads instrumented
Instrumented: vprint.go
- 4 writes, 10 reads instrumented
go: finding module for package github.com/glycerine/greenpack/msgp
go: finding module for package github.com/glycerine/liner
go: finding module for package github.com/glycerine/goconvey/convey
go: finding module for package github.com/tinylib/msgp/msgp
go: finding module for package github.com/ugorji/go/codec
go: finding module for package github.com/glycerine/blake2b
go: finding module for package github.com/shurcooL/go-goon
go: found github.com/glycerine/blake2b in github.com/glycerine/blake2b v0.0.0-20151022103502-3c8c640cd7be
go: found github.com/glycerine/greenpack/msgp in github.com/glycerine/greenpack v0.540.0
go: found github.com/glycerine/liner in github.com/glycerine/liner v0.0.0-20160121172638-72909af234e0
go: found github.com/shurcooL/go-goon in github.com/shurcooL/go-goon v1.0.0
go: found github.com/tinylib/msgp/msgp in github.com/tinylib/msgp v1.6.1
go: found github.com/ugorji/go/codec in github.com/ugorji/go/codec v1.3.1
go: found github.com/glycerine/goconvey/convey in github.com/glycerine/goconvey v0.0.0-20190410193231-58a59202ab31
=== RUN Test019_ScriptCreatesData_GoReadsIt
==================
WARNING: DATA RACE
Write at 0x000000c0000dcc70 by goroutine 3:
github.com/kolkov/racedetector/internal/race/detector.(*Detector).reportRaceV2()
/home/jaten/go/pkg/mod/github.com/kolkov/racedetector@v0.4.10/internal/race/detector/report.go:519 +0xab1
github.com/kolkov/racedetector/internal/race/api.racewrite()
/home/jaten/go/pkg/mod/github.com/kolkov/racedetector@v0.4.10/internal/race/api/race.go:186 +0xf44
github.com/kolkov/racedetector/internal/race/api.RaceWrite()
/home/jaten/go/pkg/mod/github.com/kolkov/racedetector@v0.4.10/internal/race/api/race.go:1120 +0x344
github.com/kolkov/racedetector/race.RaceWrite()
/home/jaten/go/pkg/mod/github.com/kolkov/racedetector@v0.4.10/race/api.go:96 +0x33c
instrumented/src.(*Lexer).GetNextToken()
/tmp/racedetector-build-4194930721/src/lexer.go:885 +0x337
instrumented/src.(*Parser).ParseExpression()
/tmp/racedetector-build-4194930721/src/parser.go:284 +0xda
instrumented/src.(*Parser).ParseTokens.(*Parser).ParsingIter.func1()
/tmp/racedetector-build-4194930721/src/parser.go:656 +0xb10
iter.Pull[...].func1()
/mnt/oldrog/usr/local/go1.25.3/src/iter/iter.go:299 +0xb44
[epoch: 4@3]
Previous Read at 0x000000c0000dcc70 by goroutine 1:
(previous access stack trace not available)
(future enhancement: store stack traces in shadow memory)
[epoch: 131@1]
==================
==================
WARNING: DATA RACE
Read at 0x000000c0000dcac0 by goroutine 3:
github.com/kolkov/racedetector/internal/race/detector.(*Detector).reportRaceV2()
/home/jaten/go/pkg/mod/github.com/kolkov/racedetector@v0.4.10/internal/race/detector/report.go:519 +0xab1
github.com/kolkov/racedetector/internal/race/api.raceread()
/home/jaten/go/pkg/mod/github.com/kolkov/racedetector@v0.4.10/internal/race/api/race.go:145 +0xee4
github.com/kolkov/racedetector/internal/race/api.RaceRead()
/home/jaten/go/pkg/mod/github.com/kolkov/racedetector@v0.4.10/internal/race/api/race.go:1108 +0xac7
github.com/kolkov/racedetector/race.RaceRead()
/home/jaten/go/pkg/mod/github.com/kolkov/racedetector@v0.4.10/race/api.go:71 +0xac2
instrumented/src.(*Lexer).Token()
/tmp/racedetector-build-4194930721/src/lexer.go:205 +0xabd
instrumented/src.(*Lexer).DecodeBrace()
/tmp/racedetector-build-4194930721/src/lexer.go:435 +0xc44
instrumented/src.(*Lexer).LexNextRune()
/tmp/racedetector-build-4194930721/src/lexer.go:812 +0x70e
instrumented/src.(*Lexer).PeekNextToken()
/tmp/racedetector-build-4194930721/src/lexer.go:866 +0x1fd
instrumented/src.(*Lexer).GetNextToken()
/tmp/racedetector-build-4194930721/src/lexer.go:886 +0x350
instrumented/src.(*Parser).ParseExpression()
/tmp/racedetector-build-4194930721/src/parser.go:284 +0xda
instrumented/src.(*Parser).ParseTokens.(*Parser).ParsingIter.func1()
/tmp/racedetector-build-4194930721/src/parser.go:656 +0xb10
iter.Pull[...].func1()
/mnt/oldrog/usr/local/go1.25.3/src/iter/iter.go:299 +0xb44
[epoch: 7@3]
Previous Write at 0x000000c0000dcac0 by goroutine 1:
(previous access stack trace not available)
(future enhancement: store stack traces in shadow memory)
[epoch: 3151@1]
==================
... (alot more, omitted for simplicity; easy to reproduce at will by following above example)...
Let's examine the first false alarm race,
at /tmp/racedetector-build-4194930721/src/lexer.go:885 which corresponds to
https://github.com/glycerine/zygomys/blob/master/zygo/lexer.go#L827,
which is:
func (lexer *Lexer) PeekNextToken(extra int) (tok Token, err error) { ... // for reference, note return value is by value
type TokenType int // for reference
type Token struct { // for reference
typ TokenType
str string
}
func (lexer *Lexer) GetNextToken() (tok Token, err error) {
race.RaceWrite(uintptr(unsafe.Pointer(&tok)))
race.RaceWrite(uintptr(unsafe.Pointer(&err))) // maps to /tmp/racedetector-build-4194930721/src/lexer.go:885
tok, err = lexer.PeekNextToken(0)
if err != nil || tok.typ == TokenEnd {
return EndTk, err
}
lexer.tokens = lexer.tokens[1:]
return tok, nil
}
Notice that "err error" is returned by value, both from PeekNextToken and from GetNextToken.
The standard Go race detector does not identify a race here. I, and it, could be wrong, but without
the other "half" (previous read) I have no idea what krd is finding here. I strongly suspect
it is a false positive.
Krd really needs to show the previous read/write.
Thanks!
edit: here is the 2nd reported "race". Clearly it is impossible to have a race on line 205 as krd claims. TokenType is an integer passed by value.
func (lex *Lexer) Token(typ TokenType, str string) Token {
race.RaceRead(uintptr(unsafe.Pointer(&typ))) // line 205 of lexer.go
race.RaceRead(uintptr(unsafe.Pointer(&str)))
t := Token{
typ: typ,
str: str,
}
return t
}