Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
corhere opened this issue Mar 3, 2022 · 5 comments
Closed

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

corhere opened this issue Mar 3, 2022 · 5 comments
Labels
FrozenDueToAge WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.

Comments

@corhere
Copy link

corhere commented Mar 3, 2022

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
@mengzhuo
Copy link
Contributor

mengzhuo commented Mar 4, 2022

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

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

corhere commented Mar 4, 2022

@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
Copy link

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

@howardjohn
Copy link
Contributor

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
Copy link

ysmood commented Apr 11, 2022

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

@wagslane wagslane mentioned this issue Apr 24, 2022
Closed
@golang golang locked and limited conversation to collaborators May 9, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@corhere @howardjohn @mengzhuo @ysmood @gopherbot