log: fix data race on log.Target

log: fix data race on log.Target

Many of our test cases set the value of log.Target, then reset it during the test/suite teardown. This has always been racy, but we've worked around it. We're now at the point that it can't be hidden anymore. In this case it is the mgo connection retry logic inside the state tests, but it will always be something.

This proposal makes the setting and getting of log.Target() (actually, log.target.logger) thread safe, and introduces a new nilLogger to make the logic inside each of the logging methods.

There is probably also a race on log.Debug, so a similar proposal will be needed as a followup.

Also, as witnessed by the duplication of logic that sets and resets the log.Target, try to push as much of the log target slight of hand into testing.LoggingSuite.

https://code.launchpad.net/~dave-cheney/juju-core/108-fix-data-race-in-logging-tests/+merge/153978

(do not edit description out of merge proposal)

[dave_cheney.net, 2013-03-19 01:59:51]

Please take a look.

[dave_cheney.net, 2013-03-19 04:56:58]

Please take a look.

https://codereview.appspot.com/7524046/diff/3001/charm/dir_test.go
File charm/dir_test.go (right):

https://codereview.appspot.com/7524046/diff/3001/charm/dir_test.go#newcode120
charm/dir_test.go:120: func (s *DirSuite) TestBundleToWithNonExecutableHooks(c
*C) {
// this is how all the log mocking should work.

https://codereview.appspot.com/7524046/diff/3001/cmd/builddb/main.go
File cmd/builddb/main.go (right):

https://codereview.appspot.com/7524046/diff/3001/cmd/builddb/main.go#newcode10
cmd/builddb/main.go:10: stdlog "log"
// to bring it inline with the other random commands.

https://codereview.appspot.com/7524046/diff/3001/store/store_test.go
File store/store_test.go (right):

https://codereview.appspot.com/7524046/diff/3001/store/store_test.go#newcode49
store/store_test.go:49: log.SetTarget(c)
// the store does not restore the log target at the end of the test. It didn't
before either.

[jameinel, 2013-03-19 08:18:15]

LGTM

[dimitern, 2013-03-19 10:19:41]

LGTM

https://codereview.appspot.com/7524046/diff/3002/cmd/logging_test.go
File cmd/logging_test.go (right):

https://codereview.appspot.com/7524046/diff/3002/cmd/logging_test.go#newcode43
cmd/logging_test.go:43: {"", true, true, []interface{}{NotNil}},
var nothing []interface = []inteface{}{NotNil} probably, to clean it up a bit?

[rog, 2013-03-19 15:54:58]

LGTM with nilLogger gone and some other suggestions below.

https://codereview.appspot.com/7524046/diff/3002/log/log.go
File log/log.go (right):

https://codereview.appspot.com/7524046/diff/3002/log/log.go#newcode13
log/log.go:13: type nilLogger struct{}
i don't think we want to do this. why bother creating the log message just to
throw it away? a nil target seems fine to me and is much cheaper.

https://codereview.appspot.com/7524046/diff/3002/log/log.go#newcode20
log/log.go:20: logger Logger
having the mutex embedded in a use-once struct is cute but i'm not sure it
really helps clarity that much.

i think i'd be more conventional:

var (
   targetMutex sync.Mutex
   target Logger
)

var Debug bool

https://codereview.appspot.com/7524046/diff/3002/log/log.go#newcode40
log/log.go:40: // previous value of the logging target.
and returns its previous value. ?

https://codereview.appspot.com/7524046/diff/3002/log/log.go#newcode51
log/log.go:51: return Target().Output(2, "ERROR: "+fmt.Sprintf(format, a...))
we can do better than repeating this code each time.

func logf(level, prefix string, a ...interface{}) error {
    if target := Target(); target != nil {
        return target.Output(2, prefix+fmt.Sprintf(format, a...))
    }
    return nil
}

func Errorf(format string, a ...interface{}) error {
     return logf("EROR: ", format, a...)
}
etc

but... i'm not entirely sure that it's right to get the logger from Target and
then output to it. that means that even though you've called SetTarget,
something might still be logging to the old target.

perhaps we should hold the mutex while calling Output, in fact.

https://codereview.appspot.com/7524046/diff/3002/testing/log.go
File testing/log.go (left):

https://codereview.appspot.com/7524046/diff/3002/testing/log.go#oldcode12
testing/log.go:12: oldDebug  bool
what was wrong with this? it still seems clear and appropriate to me.

[dave_cheney.net, 2013-03-20 06:13:40]

Please take a look.

https://codereview.appspot.com/7524046/diff/3002/cmd/logging_test.go
File cmd/logging_test.go (right):

https://codereview.appspot.com/7524046/diff/3002/cmd/logging_test.go#newcode43
cmd/logging_test.go:43: {"", true, true, []interface{}{NotNil}},
Reverted most of this as Rog convinced me to remove the NilLogger.

https://codereview.appspot.com/7524046/diff/3002/log/log.go
File log/log.go (right):

https://codereview.appspot.com/7524046/diff/3002/log/log.go#newcode13
log/log.go:13: type nilLogger struct{}
On 2013/03/19 15:54:59, rog wrote:
> i don't think we want to do this. why bother creating the log message just to
> throw it away? a nil target seems fine to me and is much cheaper.

Done.

https://codereview.appspot.com/7524046/diff/3002/log/log.go#newcode20
log/log.go:20: logger Logger
On 2013/03/19 15:54:59, rog wrote:
> having the mutex embedded in a use-once struct is cute but i'm not sure it
> really helps clarity that much.
> 
> i think i'd be more conventional:
> 
> var (
>    targetMutex sync.Mutex
>    target Logger
> )
> 
> var Debug bool

Sorry, I think my version is less stuttering and more explicit.

https://codereview.appspot.com/7524046/diff/3002/log/log.go#newcode40
log/log.go:40: // previous value of the logging target.
On 2013/03/19 15:54:59, rog wrote:
> and returns its previous value. ?

Done.

https://codereview.appspot.com/7524046/diff/3002/log/log.go#newcode51
log/log.go:51: return Target().Output(2, "ERROR: "+fmt.Sprintf(format, a...))
On 2013/03/19 15:54:59, rog wrote:
> we can do better than repeating this code each time.
> 
> func logf(level, prefix string, a ...interface{}) error {
>     if target := Target(); target != nil {
>         return target.Output(2, prefix+fmt.Sprintf(format, a...))
>     }
>     return nil
> }
> 
> func Errorf(format string, a ...interface{}) error {
>      return logf("EROR: ", format, a...)
> }
> etc

Done.

> but... i'm not entirely sure that it's right to get the logger from Target and
> then output to it. that means that even though you've called SetTarget,
> something might still be logging to the old target.

Yes, there is a race here. This proposal does not address that, it just fixes
the data race on the actual log.Target value.
 
> perhaps we should hold the mutex while calling Output, in fact.

I don't think that is necessary, logs either go to nil or the Output safely, but
there is a race if something is changing the log target while a set of calls to
logf are being made.

[fwereade, 2013-03-20 13:04:17]

LGTM; I'm fine fixing just the race that this CL targets.

[rog, 2013-03-20 13:17:38]

https://codereview.appspot.com/7524046/diff/15002/log/log.go
File log/log.go (right):

https://codereview.appspot.com/7524046/diff/15002/log/log.go#newcode47
log/log.go:47: return logf("ERROR: "+format, a...)
better to avoid the string concatenation completely by passing the prefix as a
separate argument, i think. (when the logging is disabled, of course) No need to
add more overhead than necessary.

[rog, 2013-03-20 13:18:08]

LGTM modulo the below, BTW.

On 2013/03/20 13:17:38, rog wrote:
> https://codereview.appspot.com/7524046/diff/15002/log/log.go
> File log/log.go (right):
> 
> https://codereview.appspot.com/7524046/diff/15002/log/log.go#newcode47
> log/log.go:47: return logf("ERROR: "+format, a...)
> better to avoid the string concatenation completely by passing the prefix as a
> separate argument, i think. (when the logging is disabled, of course) No need
to
> add more overhead than necessary.

[thumper, 2013-03-20 22:45:37]

LGTM

I'm not bothered by the concatenation of the prefix prior to the logf call.

[dave_cheney.net, 2013-03-21 00:27:34]

*** Submitted:

log: fix data race on log.Target

Many of our test cases set the value of log.Target, then reset it during the
test/suite teardown. This has always been racy, but we've worked around it.
We're now at the point that it can't be hidden anymore. In this case it is the
mgo connection retry logic inside the state tests, but it will always be
something.

This proposal makes the setting and getting of log.Target() (actually,
log.target.logger) thread safe, and introduces a new nilLogger to make the logic
inside each of the logging methods.

There is probably also a race on log.Debug, so a similar proposal will be needed
as a followup.

Also, as witnessed by the duplication of logic that sets and resets the
log.Target, try to push as much of the log target slight of hand into
testing.LoggingSuite.

R=jameinel, dimitern, rog, fwereade, thumper
CC=
https://codereview.appspot.com/7524046

https://codereview.appspot.com/7524046/diff/15002/log/log.go
File log/log.go (right):

https://codereview.appspot.com/7524046/diff/15002/log/log.go#newcode47
log/log.go:47: return logf("ERROR: "+format, a...)
On 2013/03/20 13:17:38, rog wrote:
> better to avoid the string concatenation completely by passing the prefix as a
> separate argument, i think. (when the logging is disabled, of course) No need
to
> add more overhead than necessary.

There was string concatenation before this CL, and there is string concatenation
now. I am not focusing on the overhead of this allocation, I believe, in the
scope of Juju network usage, it is below the noise threshold.

If we find ourselves logging at such a rate that the logger itself is a
bottleneck, well, we have two problems.