[Bug]: Race condition detected in tests

[yurishkuro]

This could be a good first issue for someone inclined to troubleshoot things.

What happened?

https://github.com/jaegertracing/jaeger/actions/runs/4518004921/jobs/7957592851#step:7:909

Steps to reproduce

unknown, these tests did not fail in the past

Expected behavior

no race

Relevant log output

=== RUN   TestStartHTTPServerParams
    logger.go:130: 2023-03-25T07:01:45.819Z	INFO	Starting jaeger-collector HTTP server	{"http host-port": ":14268"}
==================
WARNING: DATA RACE
Read at 0x00c0003fd3c3 by goroutine 227:
  testing.(*common).logDepth()
      /opt/hostedtoolcache/go/1.20.2/x64/src/testing/testing.go:998 +0x4c4
  testing.(*common).log()
      /opt/hostedtoolcache/go/1.20.2/x64/src/testing/testing.go:985 +0xa4
  testing.(*common).Logf()
      /opt/hostedtoolcache/go/1.20.2/x64/src/testing/testing.go:1036 +0x6a
  testing.(*T).Logf()
      <autogenerated>:1 +0x75
  go.uber.org/zap/zaptest.testingWriter.Write()
      /home/runner/go/pkg/mod/go.uber.org/[email protected]/zaptest/logger.go:130 +0x12c
  go.uber.org/zap/zaptest.(*testingWriter).Write()
      <autogenerated>:1 +0x7e
  go.uber.org/zap/zapcore.(*ioCore).Write()
      /home/runner/go/pkg/mod/go.uber.org/[email protected]/zapcore/core.go:99 +0x199
  go.uber.org/zap/zapcore.(*CheckedEntry).Write()
      /home/runner/go/pkg/mod/go.uber.org/[email protected]/zapcore/entry.go:255 +0x2ce
  go.uber.org/zap.(*Logger).Error()
      /home/runner/go/pkg/mod/go.uber.org/[email protected]/logger.go:236 +0x6d
  go.uber.org/zap.(*Logger).Error-fm()
      <autogenerated>:1 +0x77
  go.uber.org/zap.(*loggerWriter).Write()
      /home/runner/go/pkg/mod/go.uber.org/[email protected]/global.go:167 +0x96
  log.(*Logger).Output()
      /opt/hostedtoolcache/go/1.20.2/x64/src/log/log.go:194 +0x437
  log.(*Logger).Printf()
      /opt/hostedtoolcache/go/1.20.2/x64/src/log/log.go:204 +0xa4
  net/http.(*Server).logf()
      /opt/hostedtoolcache/go/1.20.2/x64/src/net/http/server.go:3215 +0x99
  net/http.(*conn).serve()
      /opt/hostedtoolcache/go/1.20.2/x64/src/net/http/server.go:1886 +0x18bd
  net/http.(*Server).Serve.func3()
      /opt/hostedtoolcache/go/1.20.2/x64/src/net/http/server.go:3089 +0x58

Previous write at 0x00c0003fd3c3 by goroutine 64:
  testing.tRunner.func1()
      /opt/hostedtoolcache/go/1.20.2/x64/src/testing/testing.go:1563 +0x82d
  runtime.deferreturn()
      /opt/hostedtoolcache/go/1.20.2/x64/src/runtime/panic.go:476 +0x32
  testing.(*T).Run.func1()
      /opt/hostedtoolcache/go/1.20.2/x64/src/testing/testing.go:1629 +0x47

Goroutine 227 (running) created at:
  net/http.(*Server).Serve()
      /opt/hostedtoolcache/go/1.20.2/x64/src/net/http/server.go:3089 +0x817
  net/http.(*Server).ServeTLS()
      /opt/hostedtoolcache/go/1.20.2/x64/src/net/http/server.go:3129 +0x6e8
  github.com/jaegertracing/jaeger/cmd/collector/app/server.serveHTTP.func1()
      /home/runner/work/jaeger/jaeger/cmd/collector/app/server/http.go:105 +0xac

Goroutine 64 (finished) created at:
  testing.(*T).Run()
      /opt/hostedtoolcache/go/1.20.2/x64/src/testing/testing.go:1629 +0x805
  testing.runTests.func1()
      /opt/hostedtoolcache/go/1.20.2/x64/src/testing/testing.go:2036 +0x8d
  testing.tRunner()
      /opt/hostedtoolcache/go/1.20.2/x64/src/testing/testing.go:1576 +0x216
  testing.runTests()
      /opt/hostedtoolcache/go/1.20.2/x64/src/testing/testing.go:2034 +0x87c
  testing.(*M).Run()
      /opt/hostedtoolcache/go/1.20.2/x64/src/testing/testing.go:1906 +0xb44
  main.main()
      _testmain.go:102 +0x2fc
==================
    testing.go:1446: race detected during execution of test
--- FAIL: TestStartHTTPServerParams (0.00s)
...
FAIL	github.com/jaegertracing/jaeger/cmd/collector/app/server	1.521s

### Screenshot

_No response_

### Additional context

_No response_

### Jaeger backend version

_No response_

### SDK

_No response_

### Pipeline

_No response_

### Stogage backend

_No response_

### Operating system

_No response_

### Deployment model

_No response_

### Deployment configs

_No response_

[yurishkuro]

Based on the code in testing.go it seems we are trying to log things via t.Logf() after the test has finished, likely from a server running on the background.

[ChillOrb]

@yurishkuro I spent some time trying to debug this . Unfortunately, i was not able to reproduce this error. However, I wanted to discuss this part of code following it from trace stack

go.uber.org/zap/zaptest.testingWriter.Write()
      /home/runner/go/pkg/mod/go.uber.org/[email protected]/zaptest/logger.go:130 +0x12c

which is this mentions that LogF is safe for concurrent use.

  testing.(*common).Logf()
      /opt/hostedtoolcache/go/1.20.2/x64/src/testing/testing.go:1036 +0x6a

How does this get called shouldn't logf called above be a implementation within testingWriter interface instead of using implementation attached to common as shown below?

which is this

func (c *common) Logf(format string, args ...any) {
	c.checkFuzzFn("Logf")
	c.log(fmt.Sprintf(format, args...))
}

LogF here is method to common struct , and inside common struct we see

raceErrors int // Number of races detected during test.

And since the error testing.go:1446: race detected during execution of test is because of this flag. Our assumption here
here is wrong?

Please take a look if i am thinking in the right direction?

[yurishkuro]

The race detector complains about this access to t.done:

https://cs.opensource.google/go/go/+/release-branch.go1.20:src/testing/testing.go;l=1563;drc=38cfb3be9d486833456276777155980d1ec0823e

The comment above that line says that the t.done field is intentionally unsynchronized to detect a race condition in the user code. I doubt that the issue is with the logging or testing libraries, it's most likely something in our code.

[ChillOrb]

@yurishkuro , i see that server here was not closed. Closed it in PR #4344

[ChillOrb]

I couldn't find anything else wrong the test function :/