pkg/ccl/jobsccl/jobsprotectedtsccl/jobsprotectedtsccl_test: TestSchedulesProtectedTimestamp failed

[cockroach-teamcity]

pkg/ccl/jobsccl/jobsprotectedtsccl/jobsprotectedtsccl_test.TestSchedulesProtectedTimestamp failed with artifacts on release-23.1 @ 7a7662927238b74e58260ffc084d5dd018140f75:

I240429 06:23:37.326474 9912 upgrade/upgrademanager/manager.go:742  [T10,nsql1] 696  running Upgrade to 0.0-12: "create default databases"
I240429 06:23:37.326626 12291 jobs/adopt.go:261  [T10,nsql1] 697  job 964366884129996801: resuming execution
I240429 06:23:37.347908 12327 jobs/registry.go:1628  [T10,nsql1] 698  MIGRATION job 964366884129996801: stepping through state running
I240429 06:23:37.370159 12390 5@util/log/event_log.go:32  [T10,nsql1,job=MIGRATION id=964366884129996801,upgrade=0.0-12,intExec=create-default-DB] 699 ={"Timestamp":1714371817358881838,"EventType":"create_database","Statement":"CREATE DATABASE IF NOT EXISTS defaultdb","Tag":"CREATE DATABASE","User":"root","DescriptorID":100,"ApplicationName":"$ internal-create-default-DB","DatabaseName":"defaultdb"}
I240429 06:23:37.378015 12382 5@util/log/event_log.go:32  [T10,nsql1,job=MIGRATION id=964366884129996801,upgrade=0.0-12,intExec=create-default-DB] 700 ={"Timestamp":1714371817370528146,"EventType":"create_database","Statement":"CREATE DATABASE IF NOT EXISTS postgres","Tag":"CREATE DATABASE","User":"root","DescriptorID":102,"ApplicationName":"$ internal-create-default-DB","DatabaseName":"postgres"}
I240429 06:23:37.381137 12327 jobs/registry.go:1628  [T10,nsql1] 701  MIGRATION job 964366884129996801: stepping through state succeeded
I240429 06:23:37.401823 9912 jobs/wait.go:145  [T10,nsql1] 702  waited for 1 [964366884129996801] queued jobs to complete 75.213002ms
I240429 06:23:37.402249 9912 upgrade/upgrademanager/manager.go:283  [T10,nsql1] 703  running permanent upgrade for version 22.1-42
I240429 06:23:37.419604 9912 upgrade/upgrademanager/manager.go:742  [T10,nsql1] 704  running Upgrade to 22.1-42: "add default SQL schema telemetry schedule"
I240429 06:23:37.419743 12619 jobs/adopt.go:261  [T10,nsql1] 705  job 964366884544053249: resuming execution
I240429 06:23:37.435444 12527 jobs/registry.go:1628  [T10,nsql1] 706  MIGRATION job 964366884544053249: stepping through state running
I240429 06:23:37.453822 12527 jobs/registry.go:1628  [T10,nsql1] 707  MIGRATION job 964366884544053249: stepping through state succeeded
I240429 06:23:37.479594 12823 13@kv/kvserver/replicate_queue.go:865  [T1,n1,replicate,s1,r20/1:/Table/1{8-9}] 708  error processing replica: 0 of 1 live stores are able to take a new replica for the range (1 already has a voter, 0 already have a non-voter); likely not enough nodes in cluster
I240429 06:23:37.481221 9912 jobs/wait.go:145  [T10,nsql1] 709  waited for 1 [964366884544053249] queued jobs to complete 61.491664ms
I240429 06:23:37.482878 9912 upgrade/upgrademanager/manager.go:283  [T10,nsql1] 710  running permanent upgrade for version 22.2-38
I240429 06:23:37.504123 9912 upgrade/upgrademanager/manager.go:742  [T10,nsql1] 711  running Upgrade to 22.2-38: "create jobs metrics polling job"
I240429 06:23:37.504177 12932 jobs/adopt.go:261  [T10,nsql1] 712  job 964366884807999489: resuming execution
I240429 06:23:37.520397 12949 jobs/registry.go:1628  [T10,nsql1] 713  MIGRATION job 964366884807999489: stepping through state running
I240429 06:23:37.543478 12949 jobs/registry.go:1628  [T10,nsql1] 714  MIGRATION job 964366884807999489: stepping through state succeeded
I240429 06:23:37.565575 9912 jobs/wait.go:145  [T10,nsql1] 715  waited for 1 [964366884807999489] queued jobs to complete 61.410786ms
I240429 06:23:37.566181 9912 upgrade/upgrademanager/manager.go:283  [T10,nsql1] 716  running permanent upgrade for version 22.2-90
I240429 06:23:37.588600 9912 upgrade/upgrademanager/manager.go:742  [T10,nsql1] 717  running Upgrade to 22.2-90: "create auto config runner job"
I240429 06:23:37.588663 13146 jobs/adopt.go:261  [T10,nsql1] 718  job 964366885081186305: resuming execution
I240429 06:23:37.607968 13160 jobs/registry.go:1628  [T10,nsql1] 719  MIGRATION job 964366885081186305: stepping through state running
I240429 06:23:37.640559 13261 jobs/adopt.go:261  [T10,nsql1,job=MIGRATION id=964366885081186305,upgrade=22.2-90] 720  job 102: resuming execution
I240429 06:23:37.642083 13160 jobs/registry.go:1628  [T10,nsql1] 721  MIGRATION job 964366885081186305: stepping through state succeeded
I240429 06:23:37.661090 13300 jobs/registry.go:1628  [T10,nsql1] 722  AUTO CONFIG RUNNER job 102: stepping through state running
I240429 06:23:37.672383 13300 server/autoconfig/auto_config.go:97  [T10,nsql1,job=AUTO CONFIG RUNNER id=102] 723  using provider with type acprovider.NoTaskProvider
I240429 06:23:37.672831 13300 server/autoconfig/auto_config.go:74  [T10,nsql1,job=AUTO CONFIG RUNNER id=102] 724  waiting for environment activation...
I240429 06:23:37.672870 13300 server/autoconfig/auto_config.go:74  [T10,nsql1,job=AUTO CONFIG RUNNER id=102] 725  waiting for environment activation...
I240429 06:23:37.674105 9912 jobs/wait.go:145  [T10,nsql1] 726  waited for 1 [964366885081186305] queued jobs to complete 85.455228ms
I240429 06:23:37.674498 9912 upgrade/upgrademanager/manager.go:283  [T10,nsql1] 727  running permanent upgrade for version 22.2-102
I240429 06:23:37.696733 9912 upgrade/upgrademanager/manager.go:742  [T10,nsql1] 728  running Upgrade to 22.2-102: "create sql activity updater job"
I240429 06:23:37.696881 13343 jobs/adopt.go:261  [T10,nsql1] 729  job 964366885436096513: resuming execution
I240429 06:23:37.713118 13372 jobs/registry.go:1628  [T10,nsql1] 730  MIGRATION job 964366885436096513: stepping through state running
I240429 06:23:37.744464 13372 jobs/registry.go:1628  [T10,nsql1] 731  MIGRATION job 964366885436096513: stepping through state succeeded
I240429 06:23:37.768284 9912 jobs/wait.go:145  [T10,nsql1] 732  waited for 1 [964366885436096513] queued jobs to complete 71.418467ms
I240429 06:23:37.768431 9912 server/server_sql.go:1638  [T10,nsql1] 733  done ensuring all necessary startup migrations have run
I240429 06:23:37.768925 13687 jobs/job_scheduler.go:407  [T10,nsql1] 734  waiting 2m0s before scheduled jobs daemon start
I240429 06:23:37.768943 9912 1@server/server_sql.go:1756  [T10,nsql1] 735  serving sql connections
I240429 06:23:37.774487 13700 13@kv/kvserver/replicate_queue.go:865  [T1,n1,replicate,s1,r47/1:/Table/4{5-6}] 736  error processing replica: 0 of 1 live stores are able to take a new replica for the range (1 already has a voter, 0 already have a non-voter); likely not enough nodes in cluster
I240429 06:23:37.790844 13689 sql/syntheticprivilegecache/cache.go:204  [T10,nsql1] 737  warmed privileges for virtual tables in 21.65686ms
    jobs_protected_ts_test.go:316: 
        	Error Trace:	pkg/ccl/jobsccl/jobsprotectedtsccl/jobsprotectedtsccl_test/pkg/ccl/jobsccl/jobsprotectedtsccl/jobs_protected_ts_test.go:279
        	            				pkg/ccl/jobsccl/jobsprotectedtsccl/jobsprotectedtsccl_test/pkg/ccl/jobsccl/jobsprotectedtsccl/jobs_protected_ts_test.go:316
        	Error:      	Not equal: 
        	            	expected: 1
        	            	actual  : 0
        	Test:       	TestSchedulesProtectedTimestamp/secondary-tenant
    --- FAIL: TestSchedulesProtectedTimestamp/secondary-tenant (1.48s)

Parameters:

• TAGS=bazel,gss

Help

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

/cc @cockroachdb/jobs

This test on roachdash | Improve this report!

Jira issue: CRDB-38237

[msbutler]

test failed because node metrics query failed after pts removal. this does not need to hold up the release.

// Verify that the two jobs we just observed as removed were recorded in the
	// metrics.
	var removed int
	runner.QueryRow(t, `
SELECT
    value
FROM
    crdb_internal.node_metrics
WHERE
    name = 'kv.protectedts.reconciliation.records_removed';
`).Scan(&removed)
	require.Equal(t, 1, removed)
	```