Reassigning global Logger output for testing throws race condition

[stevestotter]

I've noticed that when I'm trying to test the output of logs in some tests, it can cause a race condition to be detected. This is because reassigning the global logger's output is not thread-safe. Just to clarify, I've understood that the only way to do this is log.Logger = log.Output(<writer>). log.Logger.Output() returns a copy of the global logger, it doesn't adjust itself.

In the Go standard library, log.SetOutput() is thread-safe. Can we implement the same here? If so, I'd be happy to do the PR.

Example code to make it as simple as possible to replicate the issue:
(run it with go test -race -count=1 ./...)

package log

import (
	"bytes"
	"os"
	"testing"

	"github.com/rs/zerolog"
	"github.com/rs/zerolog/log"
)

func TestLogsToOutputInGoRoutine(t *testing.T) {
	go logSomething("blah")
}

func TestLogsToBuffer(t *testing.T) {
	logBuffer := new(bytes.Buffer)
	log.Logger = log.Output(zerolog.SyncWriter(logBuffer))
	t.Cleanup(func() {
		log.Logger = log.Output(os.Stderr)
	})
	logSomething("blah")
	//assertContainsLog(t, *logBuffer, "blah") // omitted to keep example small
}

func logSomething(s string) {
	log.Info().Msg(s)
}

Output is:

go test -race -count=1 ./...
{"level":"info","time":"2020-06-17T17:08:53+01:00","message":"blah"}
==================
WARNING: DATA RACE
Write at 0x0000013ef720 by goroutine 9:
  zerolog-race-condition.TestLogsToBuffer()
      /Users/steve/workspace/zerolog-race-condition/log_test.go:21 +0x24d
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:991 +0x1eb

Previous read at 0x0000013ef720 by goroutine 8:
  github.com/rs/zerolog.(*Logger).newEvent()
      /Users/steve/go/pkg/mod/github.com/rs/zerolog@v1.18.0/log.go:412 +0x7a
  github.com/rs/zerolog.(*Logger).Info()
      /Users/steve/go/pkg/mod/github.com/rs/zerolog@v1.18.0/log.go:296 +0x49
  github.com/rs/zerolog/log.Info()
      /Users/steve/go/pkg/mod/github.com/rs/zerolog@v1.18.0/log/log.go:66 +0x2b
  zerolog-race-condition.logSomething()
      /Users/steve/workspace/zerolog-race-condition/log_test.go:30 +0x80

Goroutine 9 (running) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:1042 +0x660
  testing.runTests.func1()
      /usr/local/go/src/testing/testing.go:1284 +0xa6
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:991 +0x1eb
  testing.runTests()
      /usr/local/go/src/testing/testing.go:1282 +0x527
  testing.(*M).Run()
      /usr/local/go/src/testing/testing.go:1199 +0x2ff
  main.main()
      _testmain.go:46 +0x223

Goroutine 8 (finished) created at:
  zerolog-race-condition.TestLogsToOutputInGoRoutine()
      /Users/steve/workspace/zerolog-race-condition/log_test.go:16 +0x57
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:991 +0x1eb

Interestingly, rearranging the tests the other way "fixes" the issue, but of course that's super brittle and doesn't solve the problem 😅

[rs]

This would introduce serialization of all the writes of a logger, just to handle this edge case. For me it's a no-go.

You should only change the global logger before you start using it concurrently (during your app init for instance). If you tests need to customize the global logger, it should be creating it's own logger and not rely on the global logger.

[stevestotter]

It's a design decision for sure and I do appreciate that. The problem for me is that I've come from using logrus which I could do this as it was thread-safe. Looking at zap's global logger, it also allows this.

I mean don't get me wrong, a global logger stinks of an anti-pattern and screams dependency injection - it's just so damn convenient (and is accepted in the standard library).

In the case of logrus, they have a MutexWrap on the logger, which can essentially turn on serialisation across the logger. This would solve the problem and we could get rid of the SyncWriter, but I appreciate this is a big change...

[rs]

I wouldn’t like my logging library to add mutexes in my back :)

[dylan-bourque]

This is only tangentially related, but we're looking to use Zerolog and we're running into a similar data race when zerolog.Context instances are passed across goroutines. Glad to split out into another issue if you'd prefer.

This test consistently reproduces the problem for me

func TestZerologRaces(t *testing.T) {
	zl := zerolog.New(io.Discard).With()
	f := func(c zerolog.Context, wg *sync.WaitGroup) {
		defer wg.Done()
		for i := 0; i < 10000; i++ {
			l := c.Int("i", i).Str("yee", "haw").Str("bar", "baz").Logger()
			l.Info().Msg("foo")
		}
	}

	var wg sync.WaitGroup
	wg.Add(4)
	go f(zl.Str("name", "1"), &wg)
	go f(zl.Str("name", "2"), &wg)
	go f(zl.Str("name", "3"), &wg)
	go f(zl.Str("name", "4"), &wg)
	wg.Wait()
}

The data races are happening during writes to the Logger.context byte slice.

What is the expected/recommended usage of Zerolog in a concurrent environment? Are Logger instances - rather than Context - safe to pass across goroutines?

[rs]

A given Logger instance is not thread safe (by design). Passing a logger through a context is meant to be used in the context of an HTTP request for instance, with a single goroutine per context. If you are getting the logger from a different goroutine you should make a copy before using it.

[dylan-bourque]

Thanks for the reply. We've updated our code to pass around Logger instances instead of Context and we're not seeing the data races anymore.

[Slach]

@rs could you share the link or code snippet where explain how to use zerolog properly for multiple go-routines?

How to properly instance logger based on global logger?

When I try

import "github.com/rs/zerolog/log"

func .. {
  go somethingDo(log.With().Str("logger","somtehing").Logger())
}

I still got race conditions

[Slach]

@rs
I tried to use diode as a thread-safe writer ;(
but still get a lot of race conditions
please help, how to properly initialize childs from global logger? which will thread safe?