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 @ e61e140a75b2f7dde9f5410c1d90e557d009c437:

(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_062406.146932602_n4_COCKROACHRANDOMSEED1.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 [missing version gate for UDF calling UDF] #121821 roachtest: schemachange/mixed-versions failed [issue renaming and using a function in the same txn] [C-test-failure GA-blocker O-roachtest O-robot P-1 T-sql-foundations branch-master]
• roachtest: schemachange/mixed-versions failed [enum removal not yet in 23.2 release] #121411 roachtest: schemachange/mixed-versions failed [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-37787

[cockroach-teamcity]

roachtest.schemachange/mixed-versions failed with artifacts on release-23.2 @ 7d5f4ef0d54fe03f947c500c68f9859ec54376e7:

(mixedversion.go:592).Run: mixed-version test failure while running step 19 (run "run schemachange workload and validation in mixed version"): full command output in run_062716.670799808_n4_COCKROACHRANDOMSEED1.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 [missing version gate for UDF calling UDF] #121821 roachtest: schemachange/mixed-versions failed [issue renaming and using a function in the same txn] [C-test-failure GA-blocker O-roachtest O-robot P-1 T-sql-foundations branch-master]
• roachtest: schemachange/mixed-versions failed [enum removal not yet in 23.2 release] #121411 roachtest: schemachange/mixed-versions failed [C-test-failure O-roachtest O-robot P-1 T-sql-foundations branch-release-24.1]

This test on roachdash | Improve this report!

[annrpom]

both errors 🤔

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: 1712903047.798542923,0 refreshedTimestamp: 
1712903048.151257948,1 (SQLSTATE XX000)

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: 1713076039.563133728,0 refreshedTimestamp: 
1713076039.640271771,1 (SQLSTATE XX000)

[fqazi]

@cockroachdb/kv We are running into the following inside this workload:

ERROR: internal error: attempting to append refresh spans after the 
tracked timestamp has moved forward. batchTimestamp: 1713076039.563133728,0 refreshedTimestamp: 

[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]

This is generally a symptom of misuse of the Txn API. We have seen it happen in the past if a RootTxn is used while there are outstanding LeafTxns.

[yuzefovich]

For reference, the query was:

WITH
	descriptors
		AS (
			SELECT
				descriptor.id,
				"parentSchemaID" AS schema_id,
				namespace.name AS name,
				crdb_internal.pb_to_json('desc', descriptor) AS descriptor
			FROM
				system.descriptor JOIN system.namespace ON namespace.id = descriptor.id
			WHERE
				"parentID" = (SELECT id FROM system.namespace WHERE name = current_database() AND "parentID" = 0)
		),
	enums AS (SELECT id, schema_id, name, descriptor->'type' AS descriptor FROM descriptors WHERE descriptor ? 'type'),
	enum_members AS (SELECT *, jsonb_array_elements(descriptor->'enumMembers') AS member FROM enums)
SELECT
	quote_ident(schema_id::REGNAMESPACE::STRING) || '.' || quote_ident(name) AS name,
	quote_literal(member->>'logicalRepresentation') AS value,
	COALESCE(member->>'direction' = 'REMOVE', false) AS dropping,
	COALESCE(json_array_length(descriptor->'referencingDescriptorIds') > 0, false) AS has_references
FROM
	enum_members;

for which we don't use the streamer API since we have a local plan node.

I doubt it's a regression (it's more likely that we just started running this query in the workload generator somewhat recently which exposed an existing bug), so I'm removing the release blocker label.

[yuzefovich]

Nathan in this has a hypothesis:

Maybe in the REGNAMESPACE cast, which I believe uses an internal executor in planner.ResolveOIDFromOID.

[yuzefovich]

I think I see the problem. (I reproduced the mixed-version state of the cluster when this problem happened, but I don't think it matters.) Here is the bundle I got
stmt-bundle-963463120295755777.zip

On 23.1 version we have the plan different from 23.2+ version. On 23.1 we have a main query within which we use the streamer API for the lookup join, so this forces us to use the LeafTxn for the main query. We also have cast to REGNAMESPACE within the main query which uses the internal executor, and we use planner's txn which is RootTxn to perform that internal query. Thus, we have a concurrent usage of LeafTxn in the main query and RootTxn in the internal query which is not allowed. We need to disable the usage of the Streamer API in such a case.

[yuzefovich]

Hm, this might be quite tricky to solve properly. Effectively, we're running into #41992 where things like miscellaneous builtins can currently use the RootTxn at any point in time during query evaluation. I think for the time being I'll disable the streamer in this particular case (when we have a cast to Oid type), but it won't solve the problem more generally.