roachtest: admission-control/tpcc-olap/nodes=3/cpu=8/w=50/c=96 failed

[cockroach-teamcity]

roachtest.admission-control/tpcc-olap/nodes=3/cpu=8/w=50/c=96 failed with artifacts on master @ 5fbcd8a8deac0205c7df38e340c1eb9692854383:

test artifacts and logs in: /artifacts/admission-control/tpcc-olap/nodes=3/cpu=8/w=50/c=96/run_1
(admission_control_tpcc_overload.go:113).verifyNodeLiveness: failed to fetch liveness metrics: status: 503 Service Unavailable, content-type: application/json, body: {
  "error": "connection error: desc = \"transport: Error while dialing connection interrupted (did the remote node shut down or are there networking issues?)\"",
  "code": 14,
  "message": "connection error: desc = \"transport: Error while dialing connection interrupted (did the remote node shut down or are there networking issues?)\"",
  "details": [
  ]
}, error: <nil>

Parameters: ROACHTEST_cloud=gce , ROACHTEST_cpu=8 , ROACHTEST_encrypted=true , ROACHTEST_fs=ext4 , ROACHTEST_localSSD=true , ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

/cc @cockroachdb/kv-triage

This test on roachdash | Improve this report!

Jira issue: CRDB-24178

[tbg]

These are likely related to the overload going on in this test. I see them in the node logs too:

W230204 06:55:36.780806 42344 google.golang.org/grpc/grpclog/component.go:41 ⋮ [T1] 655  ‹[core]›‹[Channel #2 SubChannel #3] grpc: addrConn.createTransport failed to connect to {›
W230204 06:55:36.780806 42344 google.golang.org/grpc/grpclog/component.go:41 ⋮ [T1] 655 +‹  "Addr": "10.128.0.188:26257",›
W230204 06:55:36.780806 42344 google.golang.org/grpc/grpclog/component.go:41 ⋮ [T1] 655 +‹  "ServerName": "10.128.0.188:26257",›
W230204 06:55:36.780806 42344 google.golang.org/grpc/grpclog/component.go:41 ⋮ [T1] 655 +‹  "Attributes": null,›
W230204 06:55:36.780806 42344 google.golang.org/grpc/grpclog/component.go:41 ⋮ [T1] 655 +‹  "BalancerAttributes": null,›
W230204 06:55:36.780806 42344 google.golang.org/grpc/grpclog/component.go:41 ⋮ [T1] 655 +‹  "Type": 0,›
W230204 06:55:36.780806 42344 google.golang.org/grpc/grpclog/component.go:41 ⋮ [T1] 655 +‹  "Metadata": null›
W230204 06:55:36.780806 42344 google.golang.org/grpc/grpclog/component.go:41 ⋮ [T1] 655 +‹}. Err: connection error: desc = "transport: Error while dialing connection interrupted (did the remote node shut down or are there networking issues?)"›

It's curious that connections aren't stable under high CPU load. I wish there were more information in the logs.

But, it looks like this is not a new failure mode, as the test addresses it:

cockroach/pkg/cmd/roachtest/tests/admission_control_tpcc_overload.go

Lines 96 to 111 in c68e94a

	var response tspb.TimeSeriesQueryResponse
	// Retry because timeseries queries can fail if the underlying inter-node
	// connections are in a failed state which can happen due to overload.
	// Now that the load has stopped, this should resolve itself soon.
	// Even with 60 retries we'll at most spend 30s attempting to fetch
	// the metrics.
	if err := retry.WithMaxAttempts(ctx, retry.Options{
	MaxBackoff: 500 * time.Millisecond,
	}, 60, func() (err error) {
	response, err = getMetrics(adminURLs[0], now.Add(-runDuration), now, []tsQuery{
	{
	name: "cr.node.liveness.heartbeatfailures",
	queryType: total,
	},
	})
	return err

The retrying seems to not have been sufficient in this case.

Ideally we would look into making gRPC more resilient here or at least produce better errors. The error we're getting is from here

cockroach/pkg/rpc/context.go

Lines 1813 to 1845 in 79e3bd7

	func (ood *onlyOnceDialer) dial(ctx context.Context, addr string) (net.Conn, error) {
	ood.mu.Lock()
	defer ood.mu.Unlock()
	if err := ood.mu.err; err != nil {
	// Not first dial.
	if !errors.Is(err, grpcutil.ErrConnectionInterrupted) {
	// Hitting this path would indicate that gRPC retried even though it
	// received an error not marked as retriable. At the time of writing, at
	// least in simple experiments, as expected we don't see this error.
	err = errors.Wrap(err, "previous dial failed")
	}
	return nil, err
	}
	// First dial.
	dialer := net.Dialer{
	LocalAddr: sourceAddr,
	}
	conn, err := dialer.DialContext(ctx, "tcp", addr)
	if err != nil {
	// Return an error and make sure it's not marked as temporary, so that
	// ideally we don't even use the dialer again. (If the caller still does
	// it's fine, but it will cause more confusing error logging, etc).
	err = &notTemporaryError{error: err}
	ood.mu.err = err
	return nil, err
	}
	ood.mu.err = grpcutil.ErrConnectionInterrupted
	return conn, nil
	}

meaning that we dialed successfully, but then the connection broke and we're preventing gRPC from re-dialing.