roachtest: cdc/crdb-chaos failed

[cockroach-teamcity]

roachtest.cdc/crdb-chaos failed with artifacts on release-23.1.9-rc @ 8970df10ccd36578aa106f67cd34d4e57460a342:

(latency_verifier.go:195).assertValid: max latency was more than allowed: 7m27.813242527s vs 5m0s
(monitor.go:140).Wait: monitor failure: function passed to monitor.Go failed: t.Fatal() was called
(test_runner.go:1120).func1: 1 dead node(s) detected
test artifacts and logs in: /artifacts/cdc/crdb-chaos/run_1

Parameters: ROACHTEST_arch=amd64 , ROACHTEST_cloud=gce , ROACHTEST_cpu=16 , ROACHTEST_encrypted=false , ROACHTEST_fs=ext4 , ROACHTEST_localSSD=true , ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

/cc @cockroachdb/cdc

This test on roachdash | Improve this report!

Jira issue: CRDB-30694

Epic CRDB-11732

[jayshrivastava]

We hit a point in the test where the changefeed stops updating its highwater:

10:45:33 latency_verifier.go:145: test status: watching changefeed[default]: end-to-end steady latency 20.379s; max steady latency so far 1m33.498s; highwater 2023-08-17 10:45:12.691229681 +0000 UTC
CHAOS: 10:45:38 chaos.go:146: killing :2
10:45:38 cluster.go:864: test worker status: stopping nodes :2
teamcity-11354786-1692251179-44-n4cpu16: stopping
10:45:43 latency_verifier.go:145: test status: watching changefeed[default]: end-to-end steady latency 20.23s; max steady latency so far 1m33.498s; highwater 2023-08-17 10:45:23.113362738 +0000 UTC

From the stacks for node 1, I can see that the changefeed gets blocked during the retry backoff:

goroutine 10452 [select, 5 minutes]:
github.com/cockroachdb/cockroach/pkg/util/retry.(*Retry).Next(0xc0198511a8)
	github.com/cockroachdb/cockroach/pkg/util/retry/retry.go:128 +0x13e
github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl.(*Retry).Next(0xc005d2b1a8)
	github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/retry.go:72 +0xf4
github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl.(*changefeedResumer).resumeWithRetries(0x7300450?, {0x7300450, 0xc0080c1a70}, {0x73570b0, 0xc00ae7d0d0}, 0x0?, {0xc01a05d710, {0xc004d52560, 0x19}, 0xc01a05d6e0, ...}, ...)
	github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/changefeed_stmt.go:1219 +0x1a5
github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl.(*changefeedResumer).Resume(0xc00ae7d0b0, {0x7300450, 0xc0080c1a70}, {0x5a22ba0?, 0xc00ae7d0d0})
	github.com/cockroachdb/cockroach/pkg/ccl/changefeedccl/changefeed_stmt.go:1077 +0x2b2
github.com/cockroachdb/cockroach/pkg/jobs.(*Registry).stepThroughStateMachine.func2(0xc0045e9380?, 0x0?, {0x72d1330?, 0xc00ae7d0b0?}, {0x7300450?, 0xc0080c1a70?}, {0x5a22ba0?, 0xc00ae7d0d0?}, 0xc019851810)
	github.com/cockroachdb/cockroach/pkg/jobs/registry.go:1628 +0xcc
github.com/cockroachdb/cockroach/pkg/jobs.(*Registry).stepThroughStateMachine(0xc000172000, {0x7300450, 0xc008f2ff50}, {0x5a22ba0, 0xc00ae7d0d0}, {0x72d1330, 0xc00ae7d0b0}, 0xc0045e9380, {0xc00c4cf1a0, 0x7}, ...)
	github.com/cockroachdb/cockroach/pkg/jobs/registry.go:1629 +0xa3f
github.com/cockroachdb/cockroach/pkg/jobs.(*Registry).runJob(0xc000172000, {0x73003a8, 0xc002017a40}, {0x72d1330, 0xc00ae7d0b0}, 0xc0045e9380, {0xc00c4cf1a0, 0x7}, {0xc005a68168, 0x16})
	github.com/cockroachdb/cockroach/pkg/jobs/adopt.go:474 +0x637

The test shuts a node down for 20 seconds every 2 minutes. The retry config is

opts := retry.Options{
    InitialBackoff: 5 * time.Second,
    Multiplier:     2,
    MaxBackoff:     10 * time.Minute,
}

and we only reset the retry if the changefeed runs successfully for 10 mins

cockroach/pkg/ccl/changefeedccl/retry.go

Lines 69 to 71 in 4ccf567

	if timeutil.Since(r.lastRetry) > resetRetryAfter {
	r.Reset()
	}

Say that we often kill the node running the retry loop. In this case, we will end up resetting the retries because the retry loop will start fresh on another node. However, in this case, it seems we got unlucky. From the cockroach stdout log, node 1 is only restarted once at 10:24 (the test runs from 10:21 - 10:50) and runs the retry loop for a long time.

The max backoff from retries can exceed the max latency allowed (5mins / 5.9 retries), then the test will fatal. Also, if the maximum backoff is over 2 mins / 4.6 retries, then there is a risk of another restart causing another retryable error before the changefeed can emit anything.

[jayshrivastava]

This env var should be setting fast retries, but the test does not have fast retries for some reason

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

Line 538 in d51c2f4

settings.Env = append(settings.Env, "COCKROACH_CHANGEFEED_TESTING_FAST_RETRY=true")