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.

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

data race in events monitoring code #511

Closed
cezarsa opened this issue Apr 20, 2016 · 10 comments
Closed

data race in events monitoring code #511

cezarsa opened this issue Apr 20, 2016 · 10 comments

Comments

@cezarsa
Copy link
Collaborator

cezarsa commented Apr 20, 2016

I could only get this race trace when running the tests with Go tip. It seems like a write on closed channel panic is possible after taking a quick look at this.

$ go test -race
==================
WARNING: DATA RACE
Write by goroutine 80:
  runtime.closechan()
      /Users/cezarsa/code/go/src/runtime/chan.go:303 +0x0
  github.com/fsouza/go-dockerclient.(*eventMonitoringState).disableEventMonitoring()
      /Users/cezarsa/go/src/github.com/fsouza/go-dockerclient/event.go:184 +0x112
  github.com/fsouza/go-dockerclient.(*Client).RemoveEventListener()
      /Users/cezarsa/go/src/github.com/fsouza/go-dockerclient/event.go:111 +0x109
  github.com/fsouza/go-dockerclient.testEventListeners.func2()
      /Users/cezarsa/go/src/github.com/fsouza/go-dockerclient/event_test.go:235 +0x51
  github.com/fsouza/go-dockerclient.testEventListeners()
      /Users/cezarsa/go/src/github.com/fsouza/go-dockerclient/event_test.go:258 +0x187e
  github.com/fsouza/go-dockerclient.TestTLSEventListeners()
      /Users/cezarsa/go/src/github.com/fsouza/go-dockerclient/event_test.go:50 +0x8a
  testing.tRunner()
      /Users/cezarsa/code/go/src/testing/testing.go:547 +0xbf

Previous read by goroutine 17:
  runtime.chansend()
      /Users/cezarsa/code/go/src/runtime/chan.go:122 +0x0
  github.com/fsouza/go-dockerclient.(*Client).eventHijack.func1()
      /Users/cezarsa/go/src/github.com/fsouza/go-dockerclient/event.go:315 +0x489

Goroutine 80 (running) created at:
  testing.(*T).Run()
      /Users/cezarsa/code/go/src/testing/testing.go:578 +0x385
  testing.RunTests.func1()
      /Users/cezarsa/code/go/src/testing/testing.go:724 +0xa0
  testing.tRunner()
      /Users/cezarsa/code/go/src/testing/testing.go:547 +0xbf
  testing.RunTests()
      /Users/cezarsa/code/go/src/testing/testing.go:730 +0x448
  testing.(*M).Run()
      /Users/cezarsa/code/go/src/testing/testing.go:675 +0x125
  main.main()
      github.com/fsouza/go-dockerclient/_test/_testmain.go:440 +0x19f

Goroutine 17 (finished) created at:
  github.com/fsouza/go-dockerclient.(*Client).eventHijack()
      /Users/cezarsa/go/src/github.com/fsouza/go-dockerclient/event.go:330 +0x6f6
  github.com/fsouza/go-dockerclient.(*eventMonitoringState).connectWithRetry()
      /Users/cezarsa/go/src/github.com/fsouza/go-dockerclient/event.go:230 +0xbd
  github.com/fsouza/go-dockerclient.(*eventMonitoringState).monitorEvents()
      /Users/cezarsa/go/src/github.com/fsouza/go-dockerclient/event.go:195 +0x79
==================
@robbertkl
Copy link
Contributor

Just experienced this (or at least something similar) when playing around with the event listener:

panic: send on closed channel

goroutine 34 [running]:
panic(0x344740, 0xc82000ef40)
  /usr/local/Cellar/go/1.6.2/libexec/src/runtime/panic.go:481 +0x3e6
github.com/fsouza/go-dockerclient.(*Client).eventHijack.func1(0xc82011c6b0, 0xc8201043f0, 0xc820111c20, 0xc820111c80, 0xc82034ea20, 0xc82033fad0)
 $GOPATH/src/github.com/fsouza/go-dockerclient/event.go:328 +0x390
created by github.com/fsouza/go-dockerclient.(*Client).eventHijack
  $GOPATH/src/github.com/fsouza/go-dockerclient/event.go:330 +0x6be

This happened when I stopped the docker daemon it was streaming events from (connected through TCP+TLS). I had already received the channel close notification, which I could see from output of my code before the panic. The docker daemon I stopped had no containers running, so I'm not sure what event it was even trying to send.

It happened only once. I've been trying to reproduce it, but no luck so far. A race condition sounds very likely.

@robbertkl
Copy link
Contributor

After more testing, I was able to reproduce my issue, described above. I traced the problem and fixed it in #514. I'm not sure if this covers the possible race condition/trace starting this issue.

@fsouza
Copy link
Owner

fsouza commented Apr 22, 2016

@cezarsa I've been failing to detect this race with go test -race. I tested with Go at master and 1.6.2 in OS X, what's your environment?

@cezarsa
Copy link
Collaborator Author

cezarsa commented Apr 25, 2016

@fsouza For some reason the race detector is only catching these data races on linux with:

$ go version
go version devel +46efe0b Wed Apr 20 17:02:14 2016 +0000 linux/amd64

Running against master I can see that there are still race conditions even after #514:

==================
WARNING: DATA RACE
Write by goroutine 59:
  github.com/fsouza/go-dockerclient.(*eventMonitoringState).enableEventMonitoring()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event.go:166 +0x11c
  github.com/fsouza/go-dockerclient.(*Client).AddEventListener()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event.go:92 +0xfe
  github.com/fsouza/go-dockerclient.TestEventListenerReAdding()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event_test.go:283 +0x1d3
  testing.tRunner()
      /home/vagrant/.gimme/versions/go/src/testing/testing.go:547 +0xbf

Previous read by goroutine 60:
  github.com/fsouza/go-dockerclient.(*eventMonitoringState).connectWithRetry()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event.go:230 +0x3e
  github.com/fsouza/go-dockerclient.(*eventMonitoringState).monitorEvents()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event.go:195 +0x79

Goroutine 59 (running) created at:
  testing.(*T).Run()
      /home/vagrant/.gimme/versions/go/src/testing/testing.go:583 +0x51f
  testing.RunTests.func1()
      /home/vagrant/.gimme/versions/go/src/testing/testing.go:730 +0xa0
  testing.tRunner()
      /home/vagrant/.gimme/versions/go/src/testing/testing.go:547 +0xbf
  testing.RunTests()
      /home/vagrant/.gimme/versions/go/src/testing/testing.go:736 +0x486
  testing.(*M).Run()
      /home/vagrant/.gimme/versions/go/src/testing/testing.go:680 +0x11f
  main.main()
      github.com/fsouza/go-dockerclient/_test/_testmain.go:448 +0x196

Goroutine 60 (running) created at:
  github.com/fsouza/go-dockerclient.(*eventMonitoringState).enableEventMonitoring()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event.go:169 +0x20d
  github.com/fsouza/go-dockerclient.(*Client).AddEventListener()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event.go:92 +0xfe
  github.com/fsouza/go-dockerclient.TestEventListenerReAdding()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event_test.go:272 +0x170
  testing.tRunner()
      /home/vagrant/.gimme/versions/go/src/testing/testing.go:547 +0xbf
==================
==================
WARNING: DATA RACE
Write by goroutine 59:
  github.com/fsouza/go-dockerclient.(*eventMonitoringState).enableEventMonitoring()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event.go:167 +0x175
  github.com/fsouza/go-dockerclient.(*Client).AddEventListener()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event.go:92 +0xfe
  github.com/fsouza/go-dockerclient.TestEventListenerReAdding()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event_test.go:283 +0x1d3
  testing.tRunner()
      /home/vagrant/.gimme/versions/go/src/testing/testing.go:547 +0xbf

Previous read by goroutine 60:
  github.com/fsouza/go-dockerclient.(*eventMonitoringState).connectWithRetry()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event.go:230 +0x74
  github.com/fsouza/go-dockerclient.(*eventMonitoringState).monitorEvents()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event.go:195 +0x79

Goroutine 59 (running) created at:
  testing.(*T).Run()
      /home/vagrant/.gimme/versions/go/src/testing/testing.go:583 +0x51f
  testing.RunTests.func1()
      /home/vagrant/.gimme/versions/go/src/testing/testing.go:730 +0xa0
  testing.tRunner()
      /home/vagrant/.gimme/versions/go/src/testing/testing.go:547 +0xbf
  testing.RunTests()
      /home/vagrant/.gimme/versions/go/src/testing/testing.go:736 +0x486
  testing.(*M).Run()
      /home/vagrant/.gimme/versions/go/src/testing/testing.go:680 +0x11f
  main.main()
      github.com/fsouza/go-dockerclient/_test/_testmain.go:448 +0x196

Goroutine 60 (running) created at:
  github.com/fsouza/go-dockerclient.(*eventMonitoringState).enableEventMonitoring()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event.go:169 +0x20d
  github.com/fsouza/go-dockerclient.(*Client).AddEventListener()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event.go:92 +0xfe
  github.com/fsouza/go-dockerclient.TestEventListenerReAdding()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event_test.go:272 +0x170
  testing.tRunner()
      /home/vagrant/.gimme/versions/go/src/testing/testing.go:547 +0xbf
==================
==================
WARNING: DATA RACE
Write by goroutine 59:
  github.com/fsouza/go-dockerclient.(*eventMonitoringState).enableEventMonitoring()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event.go:168 +0x1ce
  github.com/fsouza/go-dockerclient.(*Client).AddEventListener()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event.go:92 +0xfe
  github.com/fsouza/go-dockerclient.TestEventListenerReAdding()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event_test.go:283 +0x1d3
  testing.tRunner()
      /home/vagrant/.gimme/versions/go/src/testing/testing.go:547 +0xbf

Previous read by goroutine 60:
  github.com/fsouza/go-dockerclient.(*eventMonitoringState).connectWithRetry()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event.go:230 +0x8e
  github.com/fsouza/go-dockerclient.(*eventMonitoringState).monitorEvents()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event.go:195 +0x79

Goroutine 59 (running) created at:
  testing.(*T).Run()
      /home/vagrant/.gimme/versions/go/src/testing/testing.go:583 +0x51f
  testing.RunTests.func1()
      /home/vagrant/.gimme/versions/go/src/testing/testing.go:730 +0xa0
  testing.tRunner()
      /home/vagrant/.gimme/versions/go/src/testing/testing.go:547 +0xbf
  testing.RunTests()
      /home/vagrant/.gimme/versions/go/src/testing/testing.go:736 +0x486
  testing.(*M).Run()
      /home/vagrant/.gimme/versions/go/src/testing/testing.go:680 +0x11f
  main.main()
      github.com/fsouza/go-dockerclient/_test/_testmain.go:448 +0x196

Goroutine 60 (running) created at:
  github.com/fsouza/go-dockerclient.(*eventMonitoringState).enableEventMonitoring()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event.go:169 +0x20d
  github.com/fsouza/go-dockerclient.(*Client).AddEventListener()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event.go:92 +0xfe
  github.com/fsouza/go-dockerclient.TestEventListenerReAdding()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event_test.go:272 +0x170
  testing.tRunner()
      /home/vagrant/.gimme/versions/go/src/testing/testing.go:547 +0xbf
==================
PASS
Found 3 data race(s)

@fsouza
Copy link
Owner

fsouza commented Apr 25, 2016

These data races should be fixed now. I enabled race detector in Travis to help us detect this kind of error in the future.

The fix is far from ideal, I want to have a deeper look in the event monitoring code and potentially refactor it soon.

@fsouza fsouza closed this as completed Apr 25, 2016
@cezarsa
Copy link
Collaborator Author

cezarsa commented Apr 25, 2016

I think there's still a race condition there. It took about 20 minutes of running while ./go-dockerclient.test; do true; done for it to show up, but here it is:

==================
WARNING: DATA RACE
Write by goroutine 26:
  runtime.closechan()
      /home/vagrant/.gimme/versions/go/src/runtime/chan.go:303 +0x0
  github.com/fsouza/go-dockerclient.(*eventMonitoringState).disableEventMonitoring()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event.go:183 +0x10f
  github.com/fsouza/go-dockerclient.(*Client).RemoveEventListener()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event.go:111 +0x106
  github.com/fsouza/go-dockerclient.testEventListeners.func2()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event_test.go:235 +0x51
  github.com/fsouza/go-dockerclient.testEventListeners()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event_test.go:258 +0x1878
  github.com/fsouza/go-dockerclient.TestEventListeners()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event_test.go:21 +0x5b
  testing.tRunner()
      /home/vagrant/.gimme/versions/go/src/testing/testing.go:547 +0xbf

Previous read by goroutine 29:
  runtime.chansend()
      /home/vagrant/.gimme/versions/go/src/runtime/chan.go:122 +0x0
  github.com/fsouza/go-dockerclient.(*Client).eventHijack.func1()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event.go:322 +0x52d

Goroutine 26 (running) created at:
  testing.(*T).Run()
      /home/vagrant/.gimme/versions/go/src/testing/testing.go:583 +0x51f
  testing.RunTests.func1()
      /home/vagrant/.gimme/versions/go/src/testing/testing.go:730 +0xa0
  testing.tRunner()
      /home/vagrant/.gimme/versions/go/src/testing/testing.go:547 +0xbf
  testing.RunTests()
      /home/vagrant/.gimme/versions/go/src/testing/testing.go:736 +0x486
  testing.(*M).Run()
      /home/vagrant/.gimme/versions/go/src/testing/testing.go:680 +0x11f
  main.main()
      github.com/fsouza/go-dockerclient/_test/_testmain.go:448 +0x196

Goroutine 29 (finished) created at:
  github.com/fsouza/go-dockerclient.(*Client).eventHijack()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event.go:337 +0x6ed
  github.com/fsouza/go-dockerclient.(*eventMonitoringState).connectWithRetry()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event.go:232 +0xce
  github.com/fsouza/go-dockerclient.(*eventMonitoringState).monitorEvents()
      /home/vagrant/go/src/github.com/fsouza/go-dockerclient/event.go:194 +0x79
==================
PASS
Found 1 data race(s)

@cezarsa cezarsa reopened this Apr 25, 2016
@fsouza
Copy link
Owner

fsouza commented Apr 25, 2016

Looks like travis caught this one as well: https://travis-ci.org/fsouza/go-dockerclient/jobs/125598582.

@fsouza
Copy link
Owner

fsouza commented Jan 20, 2019

Closing this, as I believe we've made progress fixing the data races in the event monitoring code. Also, I've run the while ./go-dockerclient.test experiment for ~30 minutes on both Mac and Linux, so we should be good.

@fsouza fsouza closed this as completed Jan 20, 2019
@fsouza
Copy link
Owner

fsouza commented Jan 20, 2019

Re-opening as I just got one more lol

==================
WARNING: DATA RACE
Write at 0x00c0003b6b50 by goroutine 167:
  runtime.closechan()
      /usr/local/go/src/runtime/chan.go:334 +0x0
  github.com/fsouza/go-dockerclient.(*eventMonitoringState).disableEventMonitoring()
      /code/event.go:191 +0x10e
  github.com/fsouza/go-dockerclient.(*Client).RemoveEventListener()
      /code/event.go:113 +0xd1
  github.com/fsouza/go-dockerclient.testEventListeners.func2()
      /code/event_test.go:238 +0x46
  github.com/fsouza/go-dockerclient.testEventListeners()
      /code/event_test.go:269 +0x1022
  github.com/fsouza/go-dockerclient.TestTLSEventListeners()
      /code/event_test.go:28 +0x8e
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:862 +0x163

Previous read at 0x00c0003b6b50 by goroutine 410:
  runtime.chansend()
      /usr/local/go/src/runtime/chan.go:142 +0x0
  github.com/fsouza/go-dockerclient.(*Client).eventHijack.func1()
      /code/event.go:356 +0x65d

Goroutine 167 (running) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:913 +0x699
  testing.runTests.func1()
      /usr/local/go/src/testing/testing.go:1154 +0xa8
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:862 +0x163
  testing.runTests()
      /usr/local/go/src/testing/testing.go:1152 +0x523
  testing.(*M).Run()
      /usr/local/go/src/testing/testing.go:1069 +0x2eb
  main.main()
      _testmain.go:656 +0x222

Goroutine 410 (finished) created at:
  github.com/fsouza/go-dockerclient.(*Client).eventHijack()
      /code/event.go:344 +0x56a
  github.com/fsouza/go-dockerclient.(*eventMonitoringState).connectWithRetry()
      /code/event.go:255 +0xdc
  github.com/fsouza/go-dockerclient.(*eventMonitoringState).monitorEvents()
      /code/event.go:217 +0xba
==================

@fsouza fsouza reopened this Jan 20, 2019
fsouza added a commit that referenced this issue Jan 20, 2019
This change causes a data race:

```
==================
WARNING: DATA RACE
Write at 0x00c0003b6b50 by goroutine 167:
  runtime.closechan()
      /usr/local/go/src/runtime/chan.go:334 +0x0
  github.com/fsouza/go-dockerclient.(*eventMonitoringState).disableEventMonitoring()
      /code/event.go:191 +0x10e
  github.com/fsouza/go-dockerclient.(*Client).RemoveEventListener()
      /code/event.go:113 +0xd1
  github.com/fsouza/go-dockerclient.testEventListeners.func2()
      /code/event_test.go:238 +0x46
  github.com/fsouza/go-dockerclient.testEventListeners()
      /code/event_test.go:269 +0x1022
  github.com/fsouza/go-dockerclient.TestTLSEventListeners()
      /code/event_test.go:28 +0x8e
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:862 +0x163

Previous read at 0x00c0003b6b50 by goroutine 410:
  runtime.chansend()
      /usr/local/go/src/runtime/chan.go:142 +0x0
  github.com/fsouza/go-dockerclient.(*Client).eventHijack.func1()
      /code/event.go:356 +0x65d

Goroutine 167 (running) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:913 +0x699
  testing.runTests.func1()
      /usr/local/go/src/testing/testing.go:1154 +0xa8
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:862 +0x163
  testing.runTests()
      /usr/local/go/src/testing/testing.go:1152 +0x523
  testing.(*M).Run()
      /usr/local/go/src/testing/testing.go:1069 +0x2eb
  main.main()
      _testmain.go:656 +0x222

Goroutine 410 (finished) created at:
  github.com/fsouza/go-dockerclient.(*Client).eventHijack()
      /code/event.go:344 +0x56a
  github.com/fsouza/go-dockerclient.(*eventMonitoringState).connectWithRetry()
      /code/event.go:255 +0xdc
  github.com/fsouza/go-dockerclient.(*eventMonitoringState).monitorEvents()
      /code/event.go:217 +0xba
==================
```

My bad x)

Related to #511.

This reverts commit a107859.
@fsouza
Copy link
Owner

fsouza commented Jan 20, 2019

Ok, I'm confident now :)

@fsouza fsouza closed this as completed Jan 20, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants