storage: TestReopenConnection failed under stress

[cockroach-teamcity]

SHA: https://github.com/cockroachdb/cockroach/commits/e84c2b220b8095da07b335f8574f494dc3ecb49c

Parameters:

TAGS=
GOFLAGS=-race

To repro, try:

# Don't forget to check out a clean suitable branch and experiment with the
# stress invocation until the desired results present themselves. For example,
# using stress instead of stressrace and passing the '-p' stressflag which
# controls concurrency.
./scripts/gceworker.sh start && ./scripts/gceworker.sh mosh
cd ~/go/src/github.com/cockroachdb/cockroach && \
stdbuf -oL -eL \
make stressrace TESTS=TestReopenConnection PKG=github.com/cockroachdb/cockroach/pkg/storage TESTTIMEOUT=5m STRESSFLAGS='-maxtime 20m -timeout 10m' 2>&1 | tee /tmp/stress.log

Failed test: https://teamcity.cockroachdb.com/viewLog.html?buildId=1342995&tab=buildLog

I190617 08:37:50.401826 244527 vendor/github.com/cockroachdb/circuitbreaker/circuitbreaker.go:322  circuitbreaker: rpc ->2 tripped: failed to connect to n2 at 127.0.0.1:46193: initial connection heartbeat failed: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = "transport: Error while dialing dial tcp 127.0.0.1:46193: connect: connection refused"
I190617 08:37:50.402707 244527 vendor/github.com/cockroachdb/circuitbreaker/circuitbreaker.go:447  circuitbreaker: rpc ->2 event: BreakerTripped
I190617 08:37:50.402825 244527 rpc/nodedialer/nodedialer.go:143  unable to connect to n2: failed to connect to n2 at 127.0.0.1:46193: initial connection heartbeat failed: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = "transport: Error while dialing dial tcp 127.0.0.1:46193: connect: connection refused"
I190617 08:37:50.406122 244527 vendor/github.com/cockroachdb/circuitbreaker/circuitbreaker.go:322  circuitbreaker: rpc ->3 tripped: failed to connect to n3 at 127.0.0.1:46193: initial connection heartbeat failed: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = "transport: Error while dialing dial tcp 127.0.0.1:46193: connect: connection refused"
I190617 08:37:50.406400 244527 vendor/github.com/cockroachdb/circuitbreaker/circuitbreaker.go:447  circuitbreaker: rpc ->3 event: BreakerTripped
I190617 08:37:50.406534 244527 rpc/nodedialer/nodedialer.go:143  unable to connect to n3: failed to connect to n3 at 127.0.0.1:46193: initial connection heartbeat failed: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = "transport: Error while dialing dial tcp 127.0.0.1:46193: connect: connection refused"
panic: locally configured maximum clock offset (1ns) does not match that of node 127.0.0.1:37969 (500ms)

goroutine 244420 [running]:
github.com/cockroachdb/cockroach/pkg/rpc.(*HeartbeatService).Ping(0xc00b391920, 0x4b41c80, 0xc0007abe00, 0xc000a1a0e0, 0xc00b391920, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/rpc/heartbeat.go:105 +0x1865
github.com/cockroachdb/cockroach/pkg/rpc._Heartbeat_Ping_Handler.func1(0x4b41c80, 0xc0007abe00, 0x3bb65a0, 0xc000a1a0e0, 0x3bb65a0, 0xc000a1a0e0, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/rpc/heartbeat.pb.go:224 +0xa2
github.com/cockroachdb/cockroach/vendor/github.com/grpc-ecosystem/grpc-opentracing/go/otgrpc.OpenTracingServerInterceptor.func1(0x4b41c80, 0xc0007abe00, 0x3bb65a0, 0xc000a1a0e0, 0xc00c2fb440, 0xc00c2fb460, 0x0, 0x0, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/vendor/github.com/grpc-ecosystem/grpc-opentracing/go/otgrpc/server.go:44 +0xc23
github.com/cockroachdb/cockroach/pkg/rpc.NewServerWithInterceptor.func4(0x4b41c80, 0xc0007abe00, 0x3bb65a0, 0xc000a1a0e0, 0xc00c2fb440, 0xc00c2fb460, 0xc0007abe00, 0x4b41c80, 0xc0007abe00, 0xc000925970)
	/go/src/github.com/cockroachdb/cockroach/pkg/rpc/context.go:252 +0xea
github.com/cockroachdb/cockroach/pkg/rpc._Heartbeat_Ping_Handler(0x394ab60, 0xc00b391920, 0x4b41c80, 0xc0007abe00, 0xc000a1a070, 0xc0016d2d90, 0x0, 0x0, 0xc001abec00, 0xc00005e000)
	/go/src/github.com/cockroachdb/cockroach/pkg/rpc/heartbeat.pb.go:226 +0x1d9
github.com/cockroachdb/cockroach/vendor/google.golang.org/grpc.(*Server).processUnaryRPC(0xc00bb56380, 0x4b6eb40, 0xc000a4e800, 0xc001abec00, 0xc001f10f00, 0x66eafa0, 0x0, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/vendor/google.golang.org/grpc/server.go:1011 +0xda8
github.com/cockroachdb/cockroach/vendor/google.golang.org/grpc.(*Server).handleStream(0xc00bb56380, 0x4b6eb40, 0xc000a4e800, 0xc001abec00, 0x0)
	/go/src/github.com/cockroachdb/cockroach/vendor/google.golang.org/grpc/server.go:1249 +0x138e
github.com/cockroachdb/cockroach/vendor/google.golang.org/grpc.(*Server).serveStreams.func1.1(0xc00028a070, 0xc00bb56380, 0x4b6eb40, 0xc000a4e800, 0xc001abec00)
	/go/src/github.com/cockroachdb/cockroach/vendor/google.golang.org/grpc/server.go:680 +0xad

[tbg]

Hmm 19.1, didn't we think we'd fixed all of these @knz? Maybe a missing backport?

[knz]

I just stress tested this locally and on the gceworker using the latest release-19.1 branch, and did not find any failure after 5mn.

Now trying again with the specific SHA mentioned in the original failure.

[knz]

Doesn't repro with the SHA. However, I now have a suspicion that we're seeing a test connecting to a node started by another test. Will now try again enabling all tests in that package instead of just 1 test.

[knz]

Nope, no repro in the particular SHA after 40mn of stress testing (same with stressrace)

[knz]

I'm going to close this as unactionable.

@tbg FYI the master fix to check the node ID in tests (#34197) was not backported to 19.1, so the tests in that branch are potentially vulnerable to hard-to-diagnoses cases of misconnections (test A connecting to server started by test B).

(And even with #34197 on master this risk persists, albeit at lower probability, for tests that use the multitest RPC thing because that runs with node ID checks disabled.)