roachtest: schemachange/mixed-versions failed [attempting to append refresh spans after the tracked timestamp has moved forward]

[cockroach-teamcity]

roachtest.schemachange/mixed-versions failed with artifacts on release-23.2.5-rc @ e7576d10aaaa61940cebf8bd8f157ce0e1651e7b:

(mixedversion.go:592).Run: mixed-version test failure while running step 17 (run "run schemachange workload and validation in mixed version"): full command output in run_061857.471987998_n4_COCKROACHRANDOMSEED6.log: COMMAND_PROBLEM: exit status 1
test artifacts and logs in: /artifacts/schemachange/mixed-versions/run_1

Parameters:

• ROACHTEST_arch=amd64
• ROACHTEST_cloud=gce
• ROACHTEST_coverageBuild=false
• ROACHTEST_cpu=4
• ROACHTEST_encrypted=false
• ROACHTEST_metamorphicBuild=false
• ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

See: Grafana

Same failure on other branches

• roachtest: schemachange/mixed-versions failed [descriptor ID generator unavailable, migration in progress] #122350 roachtest: schemachange/mixed-versions failed [descriptor ID generator unavailable, migration in progress] [C-test-failure O-roachtest O-robot T-sql-foundations branch-release-23.1]
• roachtest: schemachange/mixed-versions failed [attempting to append refresh spans after the tracked timestamp has moved forward] #122274 roachtest: schemachange/mixed-versions failed [attempting to append refresh spans after the tracked timestamp has moved forward] [C-test-failure O-roachtest O-robot T-kv branch-release-23.2 release-blocker]
• roachtest: schemachange/mixed-versions failed [enum removal not yet in 23.2 release] #121411 roachtest: schemachange/mixed-versions failed [enum removal not yet in 23.2 release] [C-test-failure O-roachtest O-robot P-1 T-sql-foundations branch-release-24.1]

/cc @cockroachdb/sql-foundations

This test on roachdash | Improve this report!

Jira issue: CRDB-38291

[annrpom]

 "message": "***UNEXPECTED ERROR; Failed to generate a random operation: ... []: ERROR: 
internal error: attempting to append refresh spans after the tracked timestamp has moved forward. batchTimestamp: 
1713939553.051103790,0 refreshedTimestamp: 1713939553.485973655,1 (SQLSTATE XX000)",


"query": "WITH database_id AS (SELECT id FROM system.namespace WHERE ((\"parentID\" = 0) AND (\"parentSchemaID\" 
= 0)) AND (name = current_database())), schema_id AS (SELECT nsp.id FROM system.namespace AS nsp JOIN database_id 
ON ((\"parentID\" = database_id.id) AND (\"parentSchemaID\" = 0)) AND (name = $1)), descriptor_ids AS (SELECT nsp.id 
FROM system.namespace AS nsp, schema_id, database_id WHERE (nsp.\"parentID\" = database_id.id) AND 
(nsp.\"parentSchemaID\" = schema_id.id)), descriptors AS (SELECT 
crdb_internal.pb_to_json('cockroach.sql.sqlbase.Descriptor', descriptor) AS descriptor FROM system.descriptor AS 
descriptors JOIN descriptor_ids ON descriptors.id = descriptor_ids.id), types AS (SELECT descriptor FROM descriptors 
WHERE (descriptor-\u003e'type') IS NOT NULL), table_references AS (SELECT json_array_elements((descriptor-
\u003e'table')-\u003e'dependedOnBy') AS ref FROM descriptors WHERE (descriptor-\u003e'table') IS NOT NULL), 
dependent AS (SELECT (ref-\u003e\u003e'id')::INT8 AS id FROM table_references), referenced_descriptors AS (SELECT 
json_array_elements_text((descriptor-\u003e'type')-\u003e'referencingDescriptorIds')::INT8 AS id FROM types) SELECT 
EXISTS (SELECT * FROM system.namespace WHERE ((id IN (SELECT id FROM referenced_descriptors)Error: 
***UNEXPECTED ERROR; Failed to generate a random operation: Collect: CollectRows: "WITH \"descriptors\" AS 
(SELECT\n\t\tdescriptor.id,\n\t\t\"parentSchemaID\" AS schema_id,\n\t\tnamespace.name AS 
name,\n\t\tcrdb_internal.pb_to_json('desc', descriptor) AS descriptor\n\tFROM system.descriptor\n\tJOIN 
system.namespace ON namespace.id = descriptor.id\n\tWHERE \"parentID\" = (SELECT id FROM system.namespace WHERE 
name = current_database() AND \"parentID\" = 0)\n\t),\n\"enums\" AS (SELECT id, schema_id, name, descriptor->'type' AS 
descriptor FROM descriptors WHERE descriptor ? 'type'),\n\"enum_members\" AS (SELECT *, 
jsonb_array_elements(descriptor->'enumMembers') AS member FROM 
enums)\nSELECT\n\t\t\t\tquote_ident(schema_id::REGNAMESPACE::TEXT) || '.' || quote_ident(name) AS 
name,\n\t\t\t\tquote_literal(member->>'logicalRepresentation') AS value,\n\t\t\t\tCOALESCE(member->>'direction' = 
'REMOVE', false) AS dropping,\n\t\t\t\tCOALESCE(json_array_length(descriptor->'referencingDescriptorIds') > 0, false) AS 
has_references\n\t\t\tFROM enum_members\n\t" []: ERROR: internal error: attempting to append refresh spans after the 
tracked timestamp has moved forward. batchTimestamp: 1713939553.051103790,0 refreshedTimestamp: 
1713939553.485973655,1 (SQLSTATE XX000)

[rafiss]

The error comes from here:

cockroach/pkg/kv/kvclient/kvcoord/txn_interceptor_span_refresher.go

Lines 720 to 734 in 8a37c9b

	// assertRefreshSpansAtInvalidTimestamp returns an error if the timestamp at
	// which a set of reads was performed is below the largest timestamp that this
	// transaction has already refreshed to.
	func (sr *txnSpanRefresher) assertRefreshSpansAtInvalidTimestamp(
	readTimestamp hlc.Timestamp,
	) error {
	if readTimestamp.Less(sr.refreshedTimestamp) {
	// This can happen with (illegal) concurrent txn use, but that's supposed to
	// be detected by the gatekeeper interceptor.
	return errors.AssertionFailedf("attempting to append refresh spans after the tracked"+
	" timestamp has moved forward. batchTimestamp: %s refreshedTimestamp: %s",
	errors.Safe(readTimestamp), errors.Safe(sr.refreshedTimestamp))
	}
	return nil
	}

According to the comment, the gatekeeper interceptor should detect this error, but it looks like that isn't working, so checking if KV has any ideas why.

[nvanbenschoten]

See discussion on #122274. This is an indication that a RootTxn is used while there are outstanding LeafTxns. Maybe in the REGNAMESPACE cast, which I believe uses an internal executor in planner.ResolveOIDFromOID.

[yuzefovich]

closing as a dup of #122274