Data race when calling assert.Eventually()

[snebel29]

Hi,
Today I realize that one of my tests is flaky, working most of times but failing others with a data race being reported.

I'm using github.com/stretchr/testify v1.4.0

I have the impression that the following return causes the function to exit and close checkPassed channel.

testify/assert/assertions.go

Lines 1486 to 1487 in 221dbe5

	case <-timer.C:
	return Fail(t, "Condition never satisfied", msgAndArgs...)

Which is still being targeted by the following goroutine.

testify/assert/assertions.go

Lines 1493 to 1495 in 221dbe5

	go func() {
	checkPassed <- condition()
	}()

This would only happen when the goroutine with condition() is running but not finish yet, and the timer hits causing the return close.

Assuming I'm right I'm not sure yet what's the best way to fix it, may be decoupling those two into different select and using more channels, or may be there is some trick to not try to send if the channel was closed/deallocated, I would happily create a PR once/if in agreement...

Here is the data race trace.

WARNING: DATA RACE
Write at 0x00c00011a190 by goroutine 9:
  runtime.closechan()
      /usr/local/go/src/runtime/chan.go:334 +0x0
  github.com/stretchr/testify/assert.Eventually()
      /home/user/workspace/project/vendor/github.com/stretchr/testify/assert/assertions.go:1487 +0x3d5
  github.com/stretchr/testify/assert.Eventuallyf()
      /home/user/workspace/project/vendor/github.com/stretchr/testify/assert/assertion_format.go:124 +0x197
  example.com/group/project/pkg/configwatcher.TestFileWatcherReturnErrorOnTimeoutWhenFileNotExist_Start()
      /home/user/workspace/project/pkg/configwatcher/file_watcher_test.go:55 +0x3d7
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:909 +0x199

Previous read at 0x00c00011a190 by goroutine 25:
  runtime.chansend()
      /usr/local/go/src/runtime/chan.go:142 +0x0
  github.com/stretchr/testify/assert.Eventually.func1()
      /home/user/workspace/project/vendor/github.com/stretchr/testify/assert/assertions.go:1494 +0x54
Data 
Goroutine 9 (running) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:960 +0x651
  testing.runTests.func1()
      /usr/local/go/src/testing/testing.go:1202 +0xa6
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:909 +0x199
  testing.runTests()
      /usr/local/go/src/testing/testing.go:1200 +0x521
  testing.(*M).Run()
      /usr/local/go/src/testing/testing.go:1117 +0x2ff
  main.main()
      _testmain.go:52 +0x223

Goroutine 25 (running) created at:
  github.com/stretchr/testify/assert.Eventually()
      /home/user/workspace/project/vendor/github.com/stretchr/testify/assert/assertions.go:1493 +0x369
  github.com/stretchr/testify/assert.Eventuallyf()
      /home/user/workspace/project/vendor/github.com/stretchr/testify/assert/assertion_format.go:124 +0x197
  example.com/group/project/pkg/configwatcher.TestFileWatcherReturnErrorOnTimeoutWhenFileNotExist_Start()
      /home/user/workspace/project/pkg/configwatcher/file_watcher_test.go:55 +0x3d7
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:909 +0x199
==================
--- FAIL: TestFileWatcherReturnErrorOnTimeoutWhenFileNotExist_Start (0.14s)
    file_watcher_test.go:55: 
                Error Trace:    file_watcher_test.go:55
                Error:          Condition never satisfied
                Test:           TestFileWatcherReturnErrorOnTimeoutWhenFileNotExist_Start
                Messages:       Start() never returned an error before timeout 90ms
    testing.go:853: race detected during execution of test
panic: send on closed channel

goroutine 26 [running]:
github.com/stretchr/testify/assert.Eventually.func1(0xc00011a180, 0xc000118040)
        /home/user/workspace/project/vendor/github.com/stretchr/testify/assert/assertions.go:1494 +0x55
created by github.com/stretchr/testify/assert.Eventually
        /home/user/workspace/project/vendor/github.com/stretchr/testify/assert/assertions.go:1493 +0x36a
FAIL    example.com/group/project/pkg/configwatcher        0.650s
FAIL

Thanks!

[snebel29]

Today, I found sometime and managed to reproduce the issue.

Build

$ go build -race Eventually.go

Eventually.go

package main

import (
        "time"
        "fmt"
)

func main() {
        f := func() bool {
                time.Sleep(100 * time.Millisecond)
                return true
        }
        fmt.Printf("Eventually result is %v\n", Eventually(f, 100 * time.Millisecond, 1 * time.Millisecond))
}

func Eventually(condition func() bool, waitFor time.Duration, tick time.Duration) bool {
        timer := time.NewTimer(waitFor)
        ticker := time.NewTicker(tick)
        checkPassed := make(chan bool)
        defer timer.Stop()
        defer ticker.Stop()
        defer close(checkPassed)
        for {
                select {
                case <-timer.C:
                        return false
                case result := <-checkPassed:
                        if result { return true }
                case <-ticker.C:
                        go func() {
                                checkPassed <- condition()
                        }()
                }
        }
}

Data Race

Eventually result is false
==================
WARNING: DATA RACE
Read at 0x00c000088070 by goroutine 8:
  runtime.chansend()
      /usr/local/go/src/runtime/chan.go:142 +0x0
  main.Eventually.func1()
      /home/s00510495/eventually.go:33 +0x54

Previous write at 0x00c000088070 by main goroutine:
  runtime.closechan()
      /usr/local/go/src/runtime/chan.go:334 +0x0
  main.Eventually()
      /home/s00510495/eventually.go:28 +0x329
  main.main()
      /home/s00510495/eventually.go:13 +0x50

Goroutine 8 (running) created at:
  main.Eventually()
      /home/s00510495/eventually.go:32 +0x31b
  main.main()
      /home/s00510495/eventually.go:13 +0x50
==================
==================
WARNING: DATA RACE
Read at 0x00c000088070 by goroutine 10:
  runtime.chansend()
      /usr/local/go/src/runtime/chan.go:142 +0x0
  main.Eventually.func1()
      /home/s00510495/eventually.go:33 +0x54

Previous write at 0x00c000088070 by main goroutine:
  runtime.closechan()
      /usr/local/go/src/runtime/chan.go:334 +0x0
  main.Eventually()
      /home/s00510495/eventually.go:28 +0x329
  main.main()
      /home/s00510495/eventually.go:13 +0x50

Goroutine 10 (running) created at:
  main.Eventually()
      /home/s00510495/eventually.go:32 +0x31b
  main.main()
      /home/s00510495/eventually.go:13 +0x50
==================
panic: send on closed channel

goroutine 34 [running]:
main.Eventually.func1(0xc000088060, 0x530210)
	/home/s00510495/eventually.go:33 +0x55
created by main.Eventually
	/home/s00510495/eventually.go:32 +0x31c

Solution?

I think If you simply remove the following statement

defer close(checkPassed)

There would be no data race and/or panic due to sending to a closed channel, the channel should eventually (when the goroutines with the conditions finish) be garbage collected, there is no need to close the channel on return.

[snebel29]

In fact, while trying to pull request a fix found that this was fixed couple of months ago with #808 but don't released yet, any idea when this will be released?

Related to #805 and #835