Data race in `singleflight.Group` when checking call duplicates

colega commented 2 years ago

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

$ go version
go version go1.17.3 linux/amd64

Does this issue reproduce with the latest release?

Yes

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

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN="/home/oleg/go/bin"
GOCACHE="/home/oleg/.cache/go-build"
GOENV="/home/oleg/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/oleg/go/pkg/mod"
GONOPROXY="github.com/grafana"
GONOSUMDB="github.com/grafana"
GOOS="linux"
GOPATH="/home/oleg/go"
GOPRIVATE="github.com/grafana"
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.17.3"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/oleg/w/github.com/grafana/transmog/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 -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build1736033566=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I wrote this test:

package main

import (
    "runtime"
    "sync"
    "testing"

    "golang.org/x/sync/singleflight"
)

func TestSingleflightGroup(t *testing.T) {
    sfg := &singleflight.Group{}

    wg := sync.WaitGroup{}
    race := make(chan struct{})
    do := func(shared *bool) {
        <-race
        _, _, s := sfg.Do("", func() (interface{}, error) {
            runtime.Gosched()
            return nil, nil
        })
        wg.Done()
        *shared = s
    }

    var s1, s2 bool
    wg.Add(2)
    go do(&s1)
    go do(&s2)

    close(race)
    wg.Wait()

    t.Logf("%t %t", s1, s2)
}

And ran it with race detector:

go test -race ./singleflight_race_test.go

What did you expect to see?

Test should pass.

What did you see instead?

There's a DATA RACE.

Test output

``` $ go test -race singleflight_race_test.go ================== WARNING: DATA RACE Read at 0x00c00001e25f by goroutine 7: command-line-arguments.TestSingleflightGroup() /tmp/golang-issue/singleflight_race_test.go:34 +0x3aa testing.tRunner() /usr/local/go/src/testing/testing.go:1259 +0x22f testing.(*T).Run·dwrap·21() /usr/local/go/src/testing/testing.go:1306 +0x47 Previous write at 0x00c00001e25f by goroutine 8: command-line-arguments.TestSingleflightGroup.func1() /tmp/golang-issue/singleflight_race_test.go:23 +0x88 command-line-arguments.TestSingleflightGroup·dwrap·1() /tmp/golang-issue/singleflight_race_test.go:28 +0x47 Goroutine 7 (running) created at: testing.(*T).Run() /usr/local/go/src/testing/testing.go:1306 +0x726 testing.runTests.func1() /usr/local/go/src/testing/testing.go:1598 +0x99 testing.tRunner() /usr/local/go/src/testing/testing.go:1259 +0x22f testing.runTests() /usr/local/go/src/testing/testing.go:1596 +0x7ca testing.(*M).Run() /usr/local/go/src/testing/testing.go:1504 +0x9d1 main.main() _testmain.go:43 +0x22b Goroutine 8 (finished) created at: command-line-arguments.TestSingleflightGroup() /tmp/golang-issue/singleflight_race_test.go:28 +0x2d3 testing.tRunner() /usr/local/go/src/testing/testing.go:1259 +0x22f testing.(*T).Run·dwrap·21() /usr/local/go/src/testing/testing.go:1306 +0x47 ================== ================== WARNING: DATA RACE Read at 0x00c00001e26f by goroutine 7: command-line-arguments.TestSingleflightGroup() /tmp/golang-issue/singleflight_race_test.go:34 +0x3c7 testing.tRunner() /usr/local/go/src/testing/testing.go:1259 +0x22f testing.(*T).Run·dwrap·21() /usr/local/go/src/testing/testing.go:1306 +0x47 Previous write at 0x00c00001e26f by goroutine 9: command-line-arguments.TestSingleflightGroup.func1() /tmp/golang-issue/singleflight_race_test.go:23 +0x88 command-line-arguments.TestSingleflightGroup·dwrap·2() /tmp/golang-issue/singleflight_race_test.go:29 +0x47 Goroutine 7 (running) created at: testing.(*T).Run() /usr/local/go/src/testing/testing.go:1306 +0x726 testing.runTests.func1() /usr/local/go/src/testing/testing.go:1598 +0x99 testing.tRunner() /usr/local/go/src/testing/testing.go:1259 +0x22f testing.runTests() /usr/local/go/src/testing/testing.go:1596 +0x7ca testing.(*M).Run() /usr/local/go/src/testing/testing.go:1504 +0x9d1 main.main() _testmain.go:43 +0x22b Goroutine 9 (finished) created at: command-line-arguments.TestSingleflightGroup() /tmp/golang-issue/singleflight_race_test.go:29 +0x386 testing.tRunner() /usr/local/go/src/testing/testing.go:1259 +0x22f testing.(*T).Run·dwrap·21() /usr/local/go/src/testing/testing.go:1306 +0x47 ================== --- FAIL: TestSingleflightGroup (0.00s) singleflight_race_test.go:34: false false testing.go:1152: race detected during execution of test FAIL FAIL command-line-arguments 0.004s FAIL ```

Extra info

In Do() implementation: https://github.com/golang/go/blob/45bae64015975a4d7ede597a55397545571d8bc5/src/internal/singleflight/singleflight.go#L47-L65

When c.dup > 0 is checked on line 64, caller isn't holding the lock anymore, and other call can increment that value on line 53.

seankhliao commented 2 years ago

When line 64 is reached, that instance of c (created on line 58) has already been removed from the map on line 99, after which c.dups is only read, not written to.

Your test case shows a race in your test code read/write race to s1/shared and s2/shared

colega commented 2 years ago

Oh, no, of course, I switched the order of the lines

        *shared = s
        wg.Done()

And that's why it's failing in my test.

I completely misunderstood the way Forget works in this package, and that's the reason for my confusion.

golang / go