crosscluster/physical: TestStandbyReadTSPollerJob failed

[cockroach-teamcity]

crosscluster/physical.TestStandbyReadTSPollerJob failed on release-25.1 @ 0a31e426c253fe576966dd943b3d9b4897b1137c:

Fatal error:

panic: test timed out after 53m20s
running tests:
	TestStandbyReadTSPollerJob (52m45s)

Stack:

goroutine 441556 [running]:
testing.(*M).startAlarm.func1()
	GOROOT/src/testing/testing.go:2366 +0x265
created by time.goFunc
	GOROOT/src/time/sleep.go:177 +0x45

Log preceding fatal error

=== RUN   TestStandbyReadTSPollerJob
    test_log_scope.go:165: test logs captured to: outputs.zip/logTestStandbyReadTSPollerJob326801155
    test_log_scope.go:76: use -show-logs to present logs inline
    standby_read_ts_poller_job_test.go:50: test setup took 12.226324962s
    testutils.go:603: waited for 3.214716803s to advance to 1739794867.270831355,0

Parameters:

• attempt=1
• race=true
• run=1
• shard=13

Help

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

/cc @cockroachdb/disaster-recovery

This test on roachdash | Improve this report!

Jira issue: CRDB-47921

[cockroach-teamcity]

crosscluster/physical.TestStandbyReadTSPollerJob failed on release-25.1 @ 8d8afd4d92e7eb4cfaa1af1cb51937ccd8efd15e:

Fatal error:

panic: test timed out after 53m20s
running tests:
	TestStandbyReadTSPollerJob (52m32s)

Stack:

goroutine 596688 [running]:
testing.(*M).startAlarm.func1()
	GOROOT/src/testing/testing.go:2366 +0x265
created by time.goFunc
	GOROOT/src/time/sleep.go:177 +0x45

Log preceding fatal error

=== RUN   TestStandbyReadTSPollerJob
    test_log_scope.go:165: test logs captured to: outputs.zip/logTestStandbyReadTSPollerJob2049951961
    test_log_scope.go:76: use -show-logs to present logs inline
    standby_read_ts_poller_job_test.go:50: test setup took 16.799279793s
    testutils.go:603: waited for 3.607376196s to advance to 1740398222.873682487,0

Parameters:

• attempt=1
• race=true
• run=1
• shard=13

Help

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

This test on roachdash | Improve this report!

[msbutler]

In the latest failure, we're hanging on the following select in server startup:
https://github.com/msbutler/cockroach/blob/butler-repl-job-auth/pkg/server/server_controller.go#L369

goroutine 23166 [select, 52 minutes]:
github.com/cockroachdb/cockroach/pkg/server.(*serverController).startAndWaitForRunningServer(0xc00b535a40, {0xe799908, 0x14609540}, {0xc00f8f6d80, 0x14})
  pkg/server/server_controller.go:369 +0x1a9
github.com/cockroachdb/cockroach/pkg/server.(*testServer).StartSharedProcessTenant(_, {_, _}, {{0xc00f8f6d80, 0x14}, {0x3}, {{0x0, 0x0}, {0x0, 0x0}, ...}, ...})
  pkg/server/testserver.go:1378 +0x91a
github.com/cockroachdb/cockroach/pkg/crosscluster/replicationtestutils.(*TenantStreamingClusters).ConnectToReaderTenant(0xc0112ce008, {0xe799908, 0x14609540}, {0x1?}, {0xc00f8f6d80, 0x14}, 0x0)
  pkg/crosscluster/replicationtestutils/testutils.go:215 +0x1eb
github.com/cockroachdb/cockroach/pkg/crosscluster/physical.TestStandbyReadTSPollerJob(0xc00d902000)

[msbutler]

Interesting. we were in the middle of running a permanent upgrade:

goroutine 34195 [select]:
github.com/cockroachdb/cockroach/pkg/util/retry.(*Retry).Next(0xc01348fcd8)
  pkg/util/retry/retry.go:128 +0x350
github.com/cockroachdb/cockroach/pkg/jobs.(*Registry).waitForJobsToBeTerminalOrPaused(0xc00e5ca308, {0xe799c58, 0xc007527b60}, {0xc00e1d7e78, 0x1, 0x1}, 0xc00775db60)
  pkg/jobs/wait.go:102 +0x346
github.com/cockroachdb/cockroach/pkg/jobs.(*Registry).waitForJobs(0xc00e5ca308, {0xe799c58, 0xc007527b60}, {0xc00e1d7e78, 0x1, 0x1}, 0xc00775db60)
  pkg/jobs/wait.go:152 +0x245
github.com/cockroachdb/cockroach/pkg/jobs.(*Registry).Run(0xc00e5ca308, {0xe799c58, 0xc007527b60}, {0xc00e1d7e78, 0x1, 0x1})
  pkg/jobs/wait.go:208 +0x125
github.com/cockroachdb/cockroach/pkg/upgrade/upgrademanager.(*Manager).runMigration.func3({0xe799c58, 0xc007527b60})
  pkg/upgrade/upgrademanager/manager.go:727 +0xb0
github.com/cockroachdb/cockroach/pkg/util/startup.RunIdempotentWithRetry.func1({0xe799c58, 0xc007527b60})
  pkg/util/startup/retry.go:116 +0x3f
github.com/cockroachdb/cockroach/pkg/util/startup.RunIdempotentWithRetryEx[...]({0xe79bc80?, 0xc00d995400}, 0xc007715560, {0xb1ffb45, 0x10}, 0xc013490638)
  pkg/util/startup/retry.go:137 +0x407
github.com/cockroachdb/cockroach/pkg/util/startup.RunIdempotentWithRetry({0xe79bc80, 0xc00d995400}, 0xc007715560, {0xb1ffb45, 0x10}, 0xc011d76888)
  pkg/util/startup/retry.go:115 +0xa8
github.com/cockroachdb/cockroach/pkg/upgrade/upgrademanager.(*Manager).runMigration(0xc00749b100, {0xe79bc80, 0xc00d995400}, {0xe7a2878, 0xc000deba80}, {{0xb1b098d?, 0xb2d7bff?}}, {0x0, 0x0, 0x0, ...}, ...)
  pkg/upgrade/upgrademanager/manager.go:724 +0x786
github.com/cockroachdb/cockroach/pkg/upgrade/upgrademanager.(*Manager).RunPermanentUpgrades(0xc00749b100, {0xe79bc80, 0xc00d995400}, {0x19, 0x1, 0x0, 0x0})
  pkg/upgrade/upgrademanager/manager.go:246 +0xb3d
github.com/cockroachdb/cockroach/pkg/server.(*SQLServer).preStart(_, {_, _}, _, {{0x0, 0x0}, {0x0, 0x0}, {0x0, 0x0}, ...}, ...)
  pkg/server/server_sql.go:1707 +0x175f
github.com/cockroachdb/cockroach/pkg/server.(*SQLServerWrapper).PreStart(0xc00749b200, {0xe79bc80, 0xc00eaf0960})
  pkg/server/tenant.go:803 +0x3765
github.com/cockroachdb/cockroach/pkg/server.(*tenantServerWrapper).preStart(0xc00dd2ac90, {0xe79bc80, 0xc00eaf0960})
  pkg/server/server_controller.go:604 +0x52
github.com/cockroachdb/cockroach/pkg/server.(*channelOrchestrator).startControlledServer.func5.2(0xc0089d3860, 0xc007986e20, 0xc00c0f65a0, 0xc013493a78, {0xe79bc80, 0xc0073dc460}, 0xc0073dc500, 0xc003b73dc0)
  pkg/server/server_controller_channel_orchestrator.go:380 +0x1e5
github.com/cockroachdb/cockroach/pkg/server.(*channelOrchestrator).startControlledServer.func5({0x0?, 0xe799c20?})
  pkg/server/server_controller_channel_orchestrator.go:393 +0xa53
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2({0xb22289b, 0x15})
  pkg/util/stop/stopper.go:498 +0x339
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx in goroutine 28150
  pkg/util/stop/stopper.go:488 +0x730

[msbutler]

aha, we're failing on perm upgrade to set up the reader tenant!

I250304 15:10:46.754446 88428 upgrade/upgrades/permanent_upgrades.go:77 ⋮ [T3,Vdestination-readonly,n1,job=MIGRATION id=1051952301111771137,upgrade=0.0-upgrading-step-004] 1802  executing bootstrap step ‹"maybe initialize replication standby read-only catalog"›
I250304 15:10:46.772958 88428 upgrade/upgrades/permanent_maybe_setup_pcr_reader.go:36 ⋮ [T3,Vdestination-readonly,n1,job=MIGRATION id=1051952301111771137,upgrade=0.0-upgrading-step-004] 1803  setting up read-only catalog as of 1741101045.000000000,0 reading from tenant 2
E250304 15:10:47.153596 88428 jobs/registry.go:1758 ⋮ [T3,Vdestination-readonly,n1,job=1051952301111771137] 1804  job 1051952301111771137: running execution encountered retriable error: non-cancelable: running migration for 0.0-upgrading-step-004: bootstrap step ‹"maybe initialize replication standby read-only catalog"› failed: existing descriptor in the reader catalog collides with a descriptor in the from tenant, with differring parent databases.

[msbutler]

looks like the postgres db in the reader tenant claimed id 106, so it seems there can be some descriptor id bumping when creating certain objects at startup:

E250304 15:10:47.153596 88428 jobs/registry.go:1758 ⋮ [T3,Vdestination-readonly,n1,job=1051952301111771137] 1804 +  | existing descriptor ‹postgres› (id: 106, parentID: 0)
E250304 15:10:47.153596 88428 jobs/registry.go:1758 ⋮ [T3,Vdestination-readonly,n1,job=1051952301111771137] 1804 +  |  from descriptor: ‹t1› (id: 106, parentID: 104)

[msbutler]

I've confirmed this repros on master but not 24.3