runtime: race detector mis-identifies `runtime.racereadrange()` as the read location #51459

corhere · 2022-03-03T18:40:10Z

What version of Go are you using (`go version`)?

$ go version
go version go1.17.7 darwin/amd64

Does this issue reproduce with the latest release?

Yes: go1.18rc1

What operating system and processor architecture are you using (`go env`)?

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/corhere/Library/Caches/go-build"
GOENV="/Users/corhere/Library/Application Support/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Volumes/Workspace/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Volumes/Workspace"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/Cellar/go/1.17.7/libexec"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go/1.17.7/libexec/pkg/tool/darwin_amd64"
GOVCS=""
GOVERSION="go1.17.7"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/corhere/tmp/racereadrange/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -arch x86_64 -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/8p/tzn5bkn967vfgttpr2d2kpjm0000gq/T/go-build2641762923=/tmp/go-build -gno-record-gcc-switches -fno-common"
GOROOT/bin/go version: go version go1.17.7 darwin/amd64
GOROOT/bin/go tool compile -V: compile version go1.17.7
uname -v: Darwin Kernel Version 20.6.0: Wed Jan 12 22:22:42 PST 2022; root:xnu-7195.141.19~2/RELEASE_X86_64
ProductName:	macOS
ProductVersion:	11.6.4
BuildVersion:	20G417
lldb --version: lldb-1205.0.27.3
Apple Swift version 5.4 (swiftlang-1205.0.26.9 clang-1205.0.19.55)

What did you do?

Ran tests with go test -race.

package racereadrange

import (
	"testing"
	"time"
)

func TestReadRange(t *testing.T) {
	var a time.Time
	ch := make(chan bool)
	go func() {
		a = time.Now()
		ch <- true
	}()
	_ = a
	<-ch
}

func TestNarrowValue(t *testing.T) {
	var a int
	ch := make(chan bool)
	go func() {
		a = 3
		ch <- true
	}()
	_ = a
	<-ch
}

What did you expect to see?

The data race warnings printed list the locations in user code of both the racing read and write in all cases.

What did you see instead?

The read location of a time.Time value is identified in the stack trace as runtime.racereadrange().

==================
WARNING: DATA RACE
Write at 0x00c00013e048 by goroutine 8:
  github.com/corhere/racereadrange.TestReadRange.func1()
      race_test.go:12 +0x56

Previous read at 0x00c00013e048 by goroutine 7:
  runtime.racereadrange()
      <autogenerated>:1 +0x1b
  testing.tRunner()
      /usr/local/Cellar/go/1.17.7/libexec/src/testing/testing.go:1259 +0x22f
  testing.(*T).Run·dwrap·21()
      /usr/local/Cellar/go/1.17.7/libexec/src/testing/testing.go:1306 +0x47

Goroutine 8 (running) created at:
  github.com/corhere/racereadrange.TestReadRange()
      race_test.go:11 +0x124
  testing.tRunner()
      /usr/local/Cellar/go/1.17.7/libexec/src/testing/testing.go:1259 +0x22f
  testing.(*T).Run·dwrap·21()
      /usr/local/Cellar/go/1.17.7/libexec/src/testing/testing.go:1306 +0x47

Goroutine 7 (running) created at:
  testing.(*T).Run()
      /usr/local/Cellar/go/1.17.7/libexec/src/testing/testing.go:1306 +0x726
  testing.runTests.func1()
      /usr/local/Cellar/go/1.17.7/libexec/src/testing/testing.go:1598 +0x99
  testing.tRunner()
      /usr/local/Cellar/go/1.17.7/libexec/src/testing/testing.go:1259 +0x22f
  testing.runTests()
      /usr/local/Cellar/go/1.17.7/libexec/src/testing/testing.go:1596 +0x7ca
  testing.(*M).Run()
      /usr/local/Cellar/go/1.17.7/libexec/src/testing/testing.go:1504 +0x9d1
  main.main()
      _testmain.go:45 +0x22b
==================
--- FAIL: TestReadRange (0.00s)
    testing.go:1152: race detected during execution of test

In contrast, the race output from `TestNarrowValue` correctly identifies the read and write locations in user code

==================
WARNING: DATA RACE
Write at 0x00c00001c268 by goroutine 10:
  github.com/corhere/racereadrange.TestNarrowValue.func1()
      race_test.go:23 +0x39

Previous read at 0x00c00001c268 by goroutine 9:
  github.com/corhere/racereadrange.TestNarrowValue()
      race_test.go:26 +0x106
  testing.tRunner()
      /usr/local/Cellar/go/1.17.7/libexec/src/testing/testing.go:1259 +0x22f
  testing.(*T).Run·dwrap·21()
      /usr/local/Cellar/go/1.17.7/libexec/src/testing/testing.go:1306 +0x47

Goroutine 10 (running) created at:
  github.com/corhere/racereadrange.TestNarrowValue()
      race_test.go:22 +0xfc
  testing.tRunner()
      /usr/local/Cellar/go/1.17.7/libexec/src/testing/testing.go:1259 +0x22f
  testing.(*T).Run·dwrap·21()
      /usr/local/Cellar/go/1.17.7/libexec/src/testing/testing.go:1306 +0x47

Goroutine 9 (running) created at:
  testing.(*T).Run()
      /usr/local/Cellar/go/1.17.7/libexec/src/testing/testing.go:1306 +0x726
  testing.runTests.func1()
      /usr/local/Cellar/go/1.17.7/libexec/src/testing/testing.go:1598 +0x99
  testing.tRunner()
      /usr/local/Cellar/go/1.17.7/libexec/src/testing/testing.go:1259 +0x22f
  testing.runTests()
      /usr/local/Cellar/go/1.17.7/libexec/src/testing/testing.go:1596 +0x7ca
  testing.(*M).Run()
      /usr/local/Cellar/go/1.17.7/libexec/src/testing/testing.go:1504 +0x9d1
  main.main()
      _testmain.go:45 +0x22b
==================
--- FAIL: TestNarrowValue (0.00s)
    testing.go:1152: race detected during execution of test

The text was updated successfully, but these errors were encountered:

mengzhuo · 2022-03-04T02:28:06Z

It seems related to #51247, could you reproduce this issue on master?

corhere · 2022-03-04T17:15:16Z

@mengzhuo I can reproduce this issue on master.

$ gotip version
go version devel go1.19-46afa89 Fri Mar 4 15:48:03 2022 +0000 darwin/amd64

I can also reproduce it on linux/amd64.

gopherbot · 2022-03-15T20:34:54Z

Change https://go.dev/cl/393154 mentions this issue: runtime: make racereadrange ABIinternal

howardjohn · 2022-03-21T23:38:45Z

Some additional info if this wasn't known:

Previous read at 0x00c001248b80 by goroutine 159:
  runtime.racereadrange()
      <autogenerated>:1 +0x1b
  istio.io/istio/pilot/pkg/serviceregistry/serviceentry.(*ServiceEntryStore).workloadEntryHandler-fm()
      <autogenerated>:1 +0x147
  istio.io/istio/pilot/pkg/config/memory.(*configStoreMonitor).applyHandlers()
      /usr/local/google/home/howardjohn/go/src/istio.io/istio/pilot/pkg/config/memory/monitor.go:118 +0x322
  istio.io/istio/pilot/pkg/config/memory.(*configStoreMonitor).processConfigEvent()

Not only does racereadrange show up, but also my workloadEntryHandler function line number is corrupted.

I built from https://go.dev/cl/393154 and now it shows as:

Previous read at 0x00c0010f5080 by goroutine 156:
  istio.io/istio/pilot/pkg/serviceregistry/serviceentry.convertWorkloadEntry()
      /usr/local/google/home/howardjohn/go/src/istio.io/istio/pilot/pkg/serviceregistry/serviceentry/servicediscovery.go:178 +0x6e4
  istio.io/istio/pilot/pkg/serviceregistry/serviceentry.(*ServiceEntryStore).workloadEntryHandler()
      /usr/local/google/home/howardjohn/go/src/istio.io/istio/pilot/pkg/serviceregistry/serviceentry/servicediscovery.go:190 +0x312
  istio.io/istio/pilot/pkg/serviceregistry/serviceentry.(*ServiceEntryStore).workloadEntryHandler-fm()
      <autogenerated>:1 +0x147
  istio.io/istio/pilot/pkg/config/memory.(*configStoreMonitor).applyHandlers()
      /usr/local/google/home/howardjohn/go/src/istio.io/istio/pilot/pkg/config/memory/monitor.go:118 +0x322

ysmood · 2022-04-11T08:07:46Z

I can reproduce it with go version go1.18 darwin/amd64

mengzhuo added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Mar 4, 2022

wagslane mentioned this issue Apr 24, 2022

data race when calling Publisher.Close() wagslane/go-rabbitmq#71

Closed

gopherbot closed this as completed in f566fe3 May 9, 2022

golang locked and limited conversation to collaborators May 9, 2023

gopherbot added the FrozenDueToAge label May 9, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

runtime: race detector mis-identifies `runtime.racereadrange()` as the read location #51459

runtime: race detector mis-identifies `runtime.racereadrange()` as the read location #51459

corhere commented Mar 3, 2022

mengzhuo commented Mar 4, 2022

corhere commented Mar 4, 2022

gopherbot commented Mar 15, 2022

howardjohn commented Mar 21, 2022

ysmood commented Apr 11, 2022

runtime: race detector mis-identifies runtime.racereadrange() as the read location #51459

runtime: race detector mis-identifies runtime.racereadrange() as the read location #51459

Comments

corhere commented Mar 3, 2022

What version of Go are you using (go version)?

Does this issue reproduce with the latest release?

What operating system and processor architecture are you using (go env)?

What did you do?

What did you expect to see?

What did you see instead?

mengzhuo commented Mar 4, 2022

corhere commented Mar 4, 2022

gopherbot commented Mar 15, 2022

howardjohn commented Mar 21, 2022

ysmood commented Apr 11, 2022

runtime: race detector mis-identifies `runtime.racereadrange()` as the read location #51459

runtime: race detector mis-identifies `runtime.racereadrange()` as the read location #51459

What version of Go are you using (`go version`)?

What operating system and processor architecture are you using (`go env`)?