zaptest: test logger seems susceptible to data races (?)

[bobheadxi]

I've run into this quite a bit - here's an example: https://travis-ci.com/ubclaunchpad/pinpoint/jobs/183635090#L564 (relevant PR: ubclaunchpad/pinpoint#152 - race condition only appeared after converting test loggers to zaptest)

and another one: https://travis-ci.com/RTradeLtd/Nexus/builds/103797950#L717

# snip
  testing.(*common).logDepth()
      /home/travis/.gimme/versions/go1.12.linux.amd64/src/testing/testing.go:621 +0x94
  testing.(*common).Log()
      /home/travis/.gimme/versions/go1.12.linux.amd64/src/testing/testing.go:614 +0x78
# snip

it seems to me that testing.T.Log() etc are not thread safe? while it kinda makes sense that the test logger isn't thread-safe (it's only meant to be used sequentially in a test after all), once it is passed to zaptest.NewLogger() it enters all sorts of potentially racey conditions, which makes this rather problematic

I think this can be resolved by just adding a mutex in testingWriter - I'd be happy to submit a patch! Let me know if this is a known/intended behaviour, or if there's something else i should be doing differently on my end

edit actually, i just saw this note:

	// Note: t.Log is safe for concurrent use.
	w.t.Logf("%s", p)
	if w.markFailed {
		w.t.Fail()
	}

am I doing something wrong here? 🤔

edit2 I added a crude test and under -race nothing seems to be off on its own:

func TestTestLoggerConcurrent(t *testing.T) {
	log := NewLogger(t).Sugar()
	go log.Info("received work order")
	go log.Debug("starting work")
	go log.Warn("work may fail")
	go log.Errorw("work failed", "error", errors.New("tremendous sadness"))
	time.Sleep(time.Millisecond)
}

any help would be appreciated!

[Sauraus]

The issue that you are running into does it perhaps the side effect of opening 100+ /dev/pts/X sessions and thus at some point running out of file handles?

[prashantv]

The race detector has the following logs:

WARNING: DATA RACE
Read at 0x00c00018c943 by goroutine 44:
  testing.(*common).logDepth()
      /home/travis/.gimme/versions/go1.12.linux.amd64/src/testing/testing.go:629 +0x132
  testing.(*common).Logf()
      /home/travis/.gimme/versions/go1.12.linux.amd64/src/testing/testing.go:614 +0x90
  testing.(*T).Logf()
      <autogenerated>:1 +0x75

and

Previous write at 0x00c00018c943 by goroutine 19:
  testing.tRunner.func1()
      /home/travis/.gimme/versions/go1.12.linux.amd64/src/testing/testing.go:856 +0x33e
  testing.tRunner()
      /home/travis/.gimme/versions/go1.12.linux.amd64/src/testing/testing.go:869 +0x17f

If we look at the file:line of the write (testing.go:856) we see the following:

 854     // Do not lock t.done to allow race detector to detect race in case
 855     // the user does not appropriately synchronizes a goroutine.
 856     t.done = true

t.Log is safe for concurrent use, but it's not safe to call t.Log as the test is ending, which I think is causing the race detector to go off. You should make sure that any background goroutines are stopped before the test ends.

Closing the issue as this doesn't seem like a zap issue, please let me know if that's not the case.

[bobheadxi]

ah thanks @prashantv , that definitely seems like a likely culprit 👍 appreciate the help!

update: fixed by making sure no goroutines log after a test ends as suggested