sql: TestRaceWithBackfill failed

[cockroach-teamcity]

sql.TestRaceWithBackfill failed with artifacts on release-22.2 @ f38ef200f5f1d9f87fba0d5f2956b7fdd7c539b1:

=== RUN   TestRaceWithBackfill
    test_log_scope.go:161: test logs captured to: /artifacts/tmp/_tmp/b287de7194e17a0386ee1775f0d198ba/logTestRaceWithBackfill1910564040
    test_log_scope.go:79: use -show-logs to present logs inline
    schema_changer_test.go:337: schema change ALTER TABLE t.test ADD COLUMN x DECIMAL DEFAULT (DECIMAL '1.4') CHECK (x >= 0) took 7.539652455s
    schema_changer_test.go:337: schema change ALTER TABLE t.test DROP pi took 3.96684779s
    schema_changer_test.go:337: schema change CREATE UNIQUE INDEX foo ON t.test (v) took 12.97907424s
    schema_changer_test.go:337: schema change CREATE INDEX bar ON t.test(k) STORING (v) took 9.572502337s
    schema_changer_test.go:417: pq: scrub-index: batch timestamp 1686301951.849521007,0 must be after replica GC threshold 1686301963.443382897,0
    panic.go:522: -- test log scope end --
test logs left over in: /artifacts/tmp/_tmp/b287de7194e17a0386ee1775f0d198ba/logTestRaceWithBackfill1910564040
--- FAIL: TestRaceWithBackfill (122.29s)

Parameters: TAGS=bazel,gss,deadlock

Help

See also: How To Investigate a Go Test Failure (internal)

/cc @cockroachdb/sql-foundations

This test on roachdash | Improve this report!

Jira issue: CRDB-28655

[rharding6373]

The index scrub query is issued as an internal transaction and looks something like:

//	SELECT pri.k  pri.l, pri.a, pri.b,
//	       sec.k, sec.l, sec.a, sec.b
//	FROM
//	  (SELECT k, l, a, b FROM [tbl_id AS table_pri]@{FORCE_INDEX=[pri_idx_id]}) AS pri
//	FULL OUTER JOIN
//	  (SELECT k, l, a, b FROM [tbl_id AS table_sec]@{FORCE_INDEX=[idx_id]} AS sec
//	ON
//	  pri.k = sec.k AND
//	  pri.l = sec.l AND
//	  pri.a IS NOT DISTINCT FROM sec.a AND
//	  pri.b IS NOT DISTINCT FROM sec.b
//	WHERE
//	  pri.k IS NULL OR sec.k IS NUL

where k,l are columns in the primary key and a, b are columns in an index. This does a full scan of both the primary index and the secondary index.

From comments in kv, it looks like this error comes up if a request's read timestamp is below the range's GC threshold. I think KV will need to look into why it was unable to produce a good read timestamp and advise if there are ways that we can make this query more resilient.

[pav-kv]

@rharding6373 Do you happen to have the logs/artifacts? They are no longer present in TeamCity.

[pav-kv]

Batch timestamp is Friday, 9 June 2023 09:12:31.849 GMT, which is ~12s before the replica GC threshold Friday, 9 June 2023 09:12:43.443 GMT.

I wonder why the GC threshold was not like 24h ago, but almost "right now" while the test was running. Probably because of this:

cockroach/pkg/sql/schema_changer_test.go

Lines 622 to 623 in 0ddbe83

	// Add a zone config for the table so that garbage collection happens rapidly.
	if _, err := sqltestutils.AddImmediateGCZoneConfig(sqlDB, tableDesc.GetID()); err != nil {

The AddImmediateGCZoneConfig func comment says it must be used with disabled GC TTL enforcement, which we don't seem to do in this test. It is used in other tests, like this:

cockroach/pkg/sql/schema_changer_test.go

Lines 1038 to 1040 in 0ddbe83

	// Disable strict GC TTL enforcement because we're going to shove a zero-value
	// TTL into the system with AddImmediateGCZoneConfig.
	defer sqltestutils.DisableGCTTLStrictEnforcement(t, sqlDB)()

Fix should probably be as simple as adding this call.

[pav-kv]

Returning this back to SQL as this seems like a bug in the test.

[rharding6373]

Thanks @pavelkalinnikov for the pointers! I'll put a fix out now.