nsqd/nsqlookupd: data race when running test.sh

[MilenkoMarkovic]

I compiled from source nsq on Ubuntu 18.04

git clone https://github.com/nsqio/nsq $GOPATH/src/github.com/nsqio/nsq
cd $GOPATH/src/github.com/nsqio/nsq
dep ensure
dep: WARNING: revision "a3a6125de932" should not be in abbreviated form
dep: WARNING: revision "b1c65ca7ae62" should not be in abbreviated form
dep: WARNING: revision "d9a9656a3a4b" should not be in abbreviated form
dep: WARNING: revision "2e65f85255db" should not be in abbreviated form
dep: WARNING: revision "0c63f026bcd6" should not be in abbreviated form
dep: WARNING: revision "74cfbc9de839" should not be in abbreviated form

When I run tests.sh

WARNING: DATA RACE
Read at 0x00c00043c343 by goroutine 47:
  testing.(*common).logDepth()
      /usr/local/go/src/testing/testing.go:621 +0x94
  testing.(*common).Log()
      /usr/local/go/src/testing/testing.go:614 +0x78
  testing.(*T).Log()
      <autogenerated>:1 +0x61
  github.com/nsqio/nsq/internal/test.(*testLogger).Output()
      /home/miki/go/src/github.com/nsqio/nsq/internal/test/logger.go:16 +0xd6
  github.com/nsqio/nsq/internal/lg.Logf()
      /home/miki/go/src/github.com/nsqio/nsq/internal/lg/lg.go:80 +0x122
  github.com/nsqio/nsq/nsqlookupd.(*LookupProtocolV1).IOLoop()
      /home/miki/go/src/github.com/nsqio/nsq/nsqlookupd/logger.go:18 +0x991
  github.com/nsqio/nsq/nsqlookupd.(*tcpServer).Handle()
      /home/miki/go/src/github.com/nsqio/nsq/nsqlookupd/tcp.go:44 +0xa83

Previous write at 0x00c00043c343 by goroutine 89:
  testing.tRunner.func1()
      /usr/local/go/src/testing/testing.go:856 +0x354
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:869 +0x17f

Goroutine 47 (running) created at:
  github.com/nsqio/nsq/internal/protocol.TCPServer()
      /home/miki/go/src/github.com/nsqio/nsq/internal/protocol/tcp_server.go:33 +0x521
  github.com/nsqio/nsq/nsqlookupd.(*NSQLookupd).Main.func2()
      /home/miki/go/src/github.com/nsqio/nsq/nsqlookupd/nsqlookupd.go:68 +0xb6
  github.com/nsqio/nsq/internal/util.(*WaitGroupWrapper).Wrap.func1()
      /home/miki/go/src/github.com/nsqio/nsq/internal/util/wait_group_wrapper.go:14 +0x34

Goroutine 89 (running) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:916 +0x65a
  testing.runTests.func1()
      /usr/local/go/src/testing/testing.go:1157 +0xa8
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:865 +0x163
  testing.runTests()
      /usr/local/go/src/testing/testing.go:1155 +0x523
  testing.(*M).Run()
      /usr/local/go/src/testing/testing.go:1072 +0x2eb
  main.main()
      _testmain.go:108 +0x222
==================
FAIL
FAIL	github.com/nsqio/nsq/nsqlookupd	2.060s

[ploxiln]

According to golang/go#28169 (comment) the race detector will now notice an unsynchronized goroutine that calls t.Log() - one example fix for this warning in the standard library is https://go.googlesource.com/go/+/dc75744f9c16e6af08f3e4677f28850b874ecc51%5E%21/#F0 - so this looks like a rather subtle and tricky issue.

[boxy-robot]

We also saw this when building with go v1.12. 1.11 seems to still work.

[ploxiln]

should be fixed by #1190