code review 7311052: log/syslog: fix data races in tests

log/syslog: fix data races in tests

Fixes issue 4769.

[jeff.allen, 2013-02-06 09:09:49]

Hello golang-dev@googlegroups.com,

I'd like you to review this change to
http://code.google.com/p/go

[dave_cheney.net, 2013-02-06 10:02:31]

Thanks for the quick response.

https://codereview.appspot.com/7311052/diff/3/src/pkg/log/syslog/syslog.go
File src/pkg/log/syslog/syslog.go (right):

https://codereview.appspot.com/7311052/diff/3/src/pkg/log/syslog/syslog.go#ne...
src/pkg/log/syslog/syslog.go:261: _, err := fmt.Fprintf(w.conn, "<%d>%s %s
%s[%d]: %s%s",
I have a feeling that this will make the tests even less reliable. C'est la vie.

https://codereview.appspot.com/7311052/diff/3/src/pkg/log/syslog/syslog_test.go
File src/pkg/log/syslog/syslog_test.go (right):

https://codereview.appspot.com/7311052/diff/3/src/pkg/log/syslog/syslog_test....
src/pkg/log/syslog/syslog_test.go:51: func beCrashy(x bool) {
func setCrashy

https://codereview.appspot.com/7311052/diff/3/src/pkg/log/syslog/syslog_test....
src/pkg/log/syslog/syslog_test.go:57: func amCrashy() bool {
func crashy (watch out for collision with var crashy)

https://codereview.appspot.com/7311052/diff/3/src/pkg/log/syslog/syslog_test....
src/pkg/log/syslog/syslog_test.go:296: // count all the messages arriving
Can you try without the changes below this line. ct was correctly published via
chan count.

[jeff.allen, 2013-02-06 14:25:10]

https://codereview.appspot.com/7311052/diff/3/src/pkg/log/syslog/syslog.go
File src/pkg/log/syslog/syslog.go (right):

https://codereview.appspot.com/7311052/diff/3/src/pkg/log/syslog/syslog.go#ne...
src/pkg/log/syslog/syslog.go:261: _, err := fmt.Fprintf(w.conn, "<%d>%s %s
%s[%d]: %s%s",
In fact, this was a real bug in the last checkin. The test was hiding it, and
fixing the test's data race showed me this bug which came in the last CL from
too many people giving helpful changes.

https://codereview.appspot.com/7311052/diff/3/src/pkg/log/syslog/syslog_test.go
File src/pkg/log/syslog/syslog_test.go (right):

https://codereview.appspot.com/7311052/diff/3/src/pkg/log/syslog/syslog_test....
src/pkg/log/syslog/syslog_test.go:51: func beCrashy(x bool) {
On 2013/02/06 10:02:31, dfc wrote:
> func setCrashy

Done.

https://codereview.appspot.com/7311052/diff/3/src/pkg/log/syslog/syslog_test....
src/pkg/log/syslog/syslog_test.go:57: func amCrashy() bool {
On 2013/02/06 10:02:31, dfc wrote:
> func crashy (watch out for collision with var crashy)

Done.

https://codereview.appspot.com/7311052/diff/3/src/pkg/log/syslog/syslog_test....
src/pkg/log/syslog/syslog_test.go:296: // count all the messages arriving
Won't work. The data race was from the close(done), which was there to make this
goroutine exit. Now the close(done) is gone, and we get the count while this
goroutine is still running via atomic.LoadUint32. It now dies when the channel
is garbage collected.

[remyoudompheng, 2013-02-08 07:34:24]

https://codereview.appspot.com/7311052/diff/9001/src/pkg/log/syslog/syslog_te...
File src/pkg/log/syslog/syslog_test.go (right):

https://codereview.appspot.com/7311052/diff/9001/src/pkg/log/syslog/syslog_te...
src/pkg/log/syslog/syslog_test.go:290: defer func() { setCrashy(false) }()
can be defer setCrashy(false).

I'm not sure why crashy must be locked because Tests do not run in parallel by
default.

Making the crashy variable locked will spoof the race detector but still makes
the tests racy: if tests run in parallel, crashy would randomly switch between
true and false in the middle of the test.

https://codereview.appspot.com/7311052/diff/9001/src/pkg/log/syslog/syslog_te...
src/pkg/log/syslog/syslog_test.go:300: atomic.AddUint32(&ct, 1)
this is racy as it's possible that this goroutine never runs at all.

https://codereview.appspot.com/7311052/diff/9001/src/pkg/log/syslog/syslog_te...
src/pkg/log/syslog/syslog_test.go:308: w, err := Dial(net, addr,
LOG_USER|LOG_ERR, "tag")
seems like w is never closed.

[jeff.allen, 2013-02-08 08:56:01]

https://codereview.appspot.com/7311052/diff/9001/src/pkg/log/syslog/syslog_te...
File src/pkg/log/syslog/syslog_test.go (right):

https://codereview.appspot.com/7311052/diff/9001/src/pkg/log/syslog/syslog_te...
src/pkg/log/syslog/syslog_test.go:290: defer func() { setCrashy(false) }()
crashy is only locked to shut up the race detector. What are you proposing to
change here?

https://codereview.appspot.com/7311052/diff/9001/src/pkg/log/syslog/syslog_te...
src/pkg/log/syslog/syslog_test.go:308: w, err := Dial(net, addr,
LOG_USER|LOG_ERR, "tag")
On 2013/02/08 07:34:24, remyoudompheng wrote:
> seems like w is never closed.

Done.

[remyoudompheng, 2013-02-08 11:23:40]

I propose not locking crashy at all because there is no race on it and
for the races that exist, locking it does not fix anything.

See CL7314057 for a proposal.

2013/2/8, jeff.allen@gmail.com <jeff.allen@gmail.com>:
>
>
https://codereview.appspot.com/7311052/diff/9001/src/pkg/log/syslog/syslog_te...
> File src/pkg/log/syslog/syslog_test.go (right):
>
>
https://codereview.appspot.com/7311052/diff/9001/src/pkg/log/syslog/syslog_te...
> src/pkg/log/syslog/syslog_test.go:290: defer func() { setCrashy(false)
> }()
> crashy is only locked to shut up the race detector. What are you
> proposing to change here?
>
>
https://codereview.appspot.com/7311052/diff/9001/src/pkg/log/syslog/syslog_te...
> src/pkg/log/syslog/syslog_test.go:308: w, err := Dial(net, addr,
> LOG_USER|LOG_ERR, "tag")
> On 2013/02/08 07:34:24, remyoudompheng wrote:
>> seems like w is never closed.
>
> Done.
>
> https://codereview.appspot.com/7311052/
>

[jeff.allen, 2013-02-08 11:29:16]

This is the race crashyMu is solving:

WARNING: DATA RACE
Write by goroutine 33:
  log/syslog.setCrashy()
      /home/jeffall/go/src/pkg/log/syslog/syslog_test.go:53 +0x36
  log/syslog.TestConcurrentReconnect()
      /home/jeffall/go/src/pkg/log/syslog/syslog_test.go:329 +0x401
  testing.tRunner()
      /home/jeffall/go/src/pkg/testing/testing.go:314 +0xe8

Previous read by goroutine 32:
  log/syslog.func·001()
      /home/jeffall/go/src/pkg/log/syslog/syslog_test.go:73 +0x82
                        for ct := 1; !crashy() || ct&7 != 0; ct++ {

[remyoudompheng, 2013-02-10 21:43:19]

On 2013/02/08 11:29:16, jeff.allen wrote:
> This is the race crashyMu is solving:
> 
> WARNING: DATA RACE
> Write by goroutine 33:
>   log/syslog.setCrashy()
>       /home/jeffall/go/src/pkg/log/syslog/syslog_test.go:53 +0x36

You are only showing a technical race. Locking access to crashy
will make the program conform to the memory model but not eliminate
the actual race, which is that crashy=false can happen before the server stops
serving.

It's enough to simply wait for the server to finish before setting crashy to
false.
Anyway, that doesn't exactly matter on this example, but it feels not right.

[dave_cheney.net, 2013-02-11 00:13:12]

This CL does not apply cleanly anymore. Jeff - can you please hg mail again.

Can I suggest that this CL be committed as is to get the race builder going
again and a followup CL proposed to improve the test afterwards.

https://codereview.appspot.com/7311052/diff/9001/src/pkg/log/syslog/syslog_te...
File src/pkg/log/syslog/syslog_test.go (right):

https://codereview.appspot.com/7311052/diff/9001/src/pkg/log/syslog/syslog_te...
src/pkg/log/syslog/syslog_test.go:49: var crashyBool = false
var crashyBool bool

the zero value for a bool is false. Maybe even say

var (
    crashyMu sync.Mutex
    crashyBool bool
)

[dave_cheney.net, 2013-02-13 10:22:10]

jeff, can you please hg mail this again.