crypto/tls: races detected in BenchmarkCertCache, BenchmarkHandshakeServer, BenchmarkLatency and BenchmarkThroughput

[dmitshur]

The macOS race builder is reporting data races found by briefly running benchmarks. For example:

 ==================
 WARNING: DATA RACE
 Write at 0x00c000152a49 by goroutine 40:
   testing.(*common).Fail()
       /Users/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:955 +0x104
   testing.(*common).Fail()
       /Users/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:947 +0x79
   testing.(*common).Errorf()
       /Users/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:1076 +0xae
   crypto/tls.benchmarkHandshakeServer.func2()
       /Users/swarming/.swarming/w/ir/x/w/goroot/src/crypto/tls/handshake_server_test.go:1346 +0x3ee
 Previous read at 0x00c000152a49 by goroutine 21:
   testing.(*B).Run()
       /Users/swarming/.swarming/w/ir/x/w/goroot/src/testing/benchmark.go:686 +0xa8d
   crypto/tls.BenchmarkHandshakeServer()
       /Users/swarming/.swarming/w/ir/x/w/goroot/src/crypto/tls/handshake_server_test.go:1371 +0x64
   testing.(*B).runN()
       /Users/swarming/.swarming/w/ir/x/w/goroot/src/testing/benchmark.go:193 +0x19c
   testing.(*B).run1.func1()
       /Users/swarming/.swarming/w/ir/x/w/goroot/src/testing/benchmark.go:215 +0x7b
 Goroutine 40 (running) created at:
   crypto/tls.benchmarkHandshakeServer()
       /Users/swarming/.swarming/w/ir/x/w/goroot/src/crypto/tls/handshake_server_test.go:1336 +0xa36
   crypto/tls.BenchmarkHandshakeServer.func2.2()
       /Users/swarming/.swarming/w/ir/x/w/goroot/src/crypto/tls/handshake_server_test.go:1377 +0x9a
   testing.(*B).runN()
       /Users/swarming/.swarming/w/ir/x/w/goroot/src/testing/benchmark.go:193 +0x19c
   testing.(*B).launch()
       /Users/swarming/.swarming/w/ir/x/w/goroot/src/testing/benchmark.go:316 +0x385
   testing.(*B).doBench.gowrap1()
       /Users/swarming/.swarming/w/ir/x/w/goroot/src/testing/benchmark.go:266 +0x33
 Goroutine 21 (running) created at:
   testing.(*B).run1()
       /Users/swarming/.swarming/w/ir/x/w/goroot/src/testing/benchmark.go:208 +0x194
   testing.(*B).Run()
       /Users/swarming/.swarming/w/ir/x/w/goroot/src/testing/benchmark.go:682 +0x9d4
   testing.runBenchmarks.func1()
       /Users/swarming/.swarming/w/ir/x/w/goroot/src/testing/benchmark.go:543 +0x85
   testing.(*B).runN()
       /Users/swarming/.swarming/w/ir/x/w/goroot/src/testing/benchmark.go:193 +0x19c
   testing.runBenchmarks()
       /Users/swarming/.swarming/w/ir/x/w/goroot/src/testing/benchmark.go:552 +0xbb6
   testing.(*M).Run()
       /Users/swarming/.swarming/w/ir/x/w/goroot/src/testing/testing.go:2050 +0x152c
   crypto/tls.runMain()
       /Users/swarming/.swarming/w/ir/x/w/goroot/src/crypto/tls/handshake_test.go:400 +0xde4
   crypto/tls.TestMain()
       /Users/swarming/.swarming/w/ir/x/w/goroot/src/crypto/tls/handshake_test.go:349 +0x10e
   main.main()
       _testmain.go:423 +0x171
 ==================
     handshake_server_test.go:1349: #4: mismatch on read: got:00000000000000000000000000000000000000000000000000000000000000000000000000000000000000 want:1403030001011603030020d6984a2d5e5b03e16c2ff4634b31c8975d4e142adba6a63188219c02e4e81183
     testing.go:1399: race detected during execution of test

From https://logs.chromium.org/logs/golang/buildbucket/cr-buildbucket/8745300644568482689/+/u/step/11/log/2#L333_13. It's happening quite frequently:

Since GOOS=darwin is a first class port, we can't release Go 1.23 without addressing this.

CC @golang/security.

[gabyhelp]

Similar Issues

• crypto/rand: data race in `(*reader).Read` #52739
• x/crypto/ssh/test: data race in `TestCertLogin` #60343
• x/crypto/acme/autocert/internal/acmetest: data race in `(*CAServer).handle` #52170
• ssh/test: data race #4703
• runtime/race: bogus race reports #15739

_{(Emoji vote if this was helpful or unhelpful; more detailed feedback welcome in this discussion.)}

[FiloSottile]

To a first investigation, I think this is a crypto/tls benchmark failure flake that however is tickling a bug in testing's sub-sub-benchmarks package causing the data race. (Note how e.g. BenchmarkHandshakeServer has two levels of nesting.)

testing.B.Errorf is documented to be safe for concurrent use

A benchmark ends when its Benchmark function returns or calls any of the methods FailNow, Fatal, Fatalf, SkipNow, Skip, or Skipf. Those methods must be called only from the goroutine running the Benchmark function. The other reporting methods, such as the variations of Log and Error, may be called simultaneously from multiple goroutines.

and indeed the write to b.parent.failed in the race is done by b.parent.Fail ((*common).Fail()) under b.parent.mu. (Here b is the sub-sub-benchmark and b.parent is a sub-benchmark itself.)

However, the read in the race is done by the top-level benchmark's b.parent.parent.Run ((*B).Run()) on sub.failed (aka b.parent.failed) without holding b.parent.mu.

Not sure if the two levels of nesting are necessary to trigger this, to be honest, or if the correct behavior would be for Errorf to panic with Fail in goroutine after $NAME has completed instead, but the data race is not right.

[gopherbot]

Change https://go.dev/cl/594255 mentions this issue: crypto/tls: replay test recordings without network

[joedian]

@rolandshoemaker is any more updates planned for this?

[rolandshoemaker]

I believe @FiloSottile is continuing to work on this.

[FiloSottile]

I am working on the crypto/tls side, but #67979 (comment) is a little out of my depth in terms of the testing package. I'll open a separate issue for it.