Skip to content

jobs: TestJobInfoUpgradeRegressionTests failed #106246

@cockroach-teamcity

Description

@cockroach-teamcity

jobs.TestJobInfoUpgradeRegressionTests failed with artifacts on release-23.1 @ fa2d7f7c9894d701ac4a393f058aa84552957087:

Fatal error:

panic: interface conversion: tree.Datum is tree.dNull, not *tree.DString [recovered]
	panic: interface conversion: tree.Datum is tree.dNull, not *tree.DString

Stack:

goroutine 15353344 [running]:
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).recover(0x2f4?, {0x67ee618, 0xc0095b1290})
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:229 +0x6a
panic({0x4bf7f60, 0xc00c93e210})
	GOROOT/src/runtime/panic.go:884 +0x212
github.com/cockroachdb/cockroach/pkg/jobs/metricspoller.updatePausedMetrics.func1({0x67ee618, 0xc007589a40}, {0x6842c60, 0xc00c909900})
	github.com/cockroachdb/cockroach/pkg/jobs/metricspoller/job_statistics.go:60 +0x2e8
github.com/cockroachdb/cockroach/pkg/sql.(*InternalDB).Txn.func1({0x67ee618?, 0xc007589a40?}, 0x68485a0?)
	github.com/cockroachdb/cockroach/pkg/sql/internal.go:1620 +0x31
github.com/cockroachdb/cockroach/pkg/sql.(*InternalDB).txn.func4({0x67ee618, 0xc007589a40}, 0xc0116ee420)
	github.com/cockroachdb/cockroach/pkg/sql/internal.go:1698 +0x3b4
github.com/cockroachdb/cockroach/pkg/kv.runTxn.func1({0x67ee618?, 0xc007589a40?}, 0x43f6a5?)
	github.com/cockroachdb/cockroach/pkg/kv/db.go:965 +0x27
github.com/cockroachdb/cockroach/pkg/kv.(*Txn).exec(0xc0116ee420, {0x67ee618, 0xc007589a40}, 0xc00db05010)
	github.com/cockroachdb/cockroach/pkg/kv/txn.go:928 +0xae
github.com/cockroachdb/cockroach/pkg/kv.runTxn({0x67ee618, 0xc007589a40}, 0xc007589a40?, 0xf989ba68?)
	github.com/cockroachdb/cockroach/pkg/kv/db.go:964 +0x6b
github.com/cockroachdb/cockroach/pkg/kv.(*DB).TxnWithAdmissionControl(0x7f7ef989ba68?, {0x67ee618, 0xc007589a40}, 0xc45c000?, 0xc0?, 0x0?, 0x0?)
	github.com/cockroachdb/cockroach/pkg/kv/db.go:927 +0xa7
github.com/cockroachdb/cockroach/pkg/kv.(*DB).Txn(0x438f07?, {0x67ee618?, 0xc007589a40?}, 0x1?)
	github.com/cockroachdb/cockroach/pkg/kv/db.go:902 +0x2d
github.com/cockroachdb/cockroach/pkg/sql.(*InternalDB).txn(0xc00c6d8e10, {0x67ee618, 0xc007589a40}, 0xc005456850, {0x0, 0x0, 0x4cf1e60?})
	github.com/cockroachdb/cockroach/pkg/sql/internal.go:1686 +0x2a7
github.com/cockroachdb/cockroach/pkg/sql.(*InternalDB).Txn(0x0?, {0x67ee618, 0xc007589a40}, 0xc005456830, {0x0, 0x0, 0x0})
	github.com/cockroachdb/cockroach/pkg/sql/internal.go:1621 +0x9f
github.com/cockroachdb/cockroach/pkg/jobs/metricspoller.updatePausedMetrics({0x67ee618, 0xc007589a40}, {0x683db40, 0xc0107329a8})
	github.com/cockroachdb/cockroach/pkg/jobs/metricspoller/job_statistics.go:42 +0xd6
github.com/cockroachdb/cockroach/pkg/jobs/metricspoller.(*metricsPoller).Resume.func1({0x5379e47?, 0xc0055d73c8?}, 0x56aa550)
	github.com/cockroachdb/cockroach/pkg/jobs/metricspoller/poller.go:64 +0xb1
github.com/cockroachdb/cockroach/pkg/jobs/metricspoller.(*metricsPoller).Resume(0xc00888d040?, {0x67ee618, 0xc007589a40}, {0x50df440?, 0xc0107329a8})
	github.com/cockroachdb/cockroach/pkg/jobs/metricspoller/poller.go:75 +0x31a
github.com/cockroachdb/cockroach/pkg/jobs.(*Registry).stepThroughStateMachine.func2(0xc00888d040?, 0x0?, {0x67c45d8?, 0xc002f6a4e8?}, {0x67ee618?, 0xc004a0a030?}, {0x50df440?, 0xc0107329a8?}, 0xc00db05800)
	github.com/cockroachdb/cockroach/pkg/jobs/registry.go:1628 +0xcc
github.com/cockroachdb/cockroach/pkg/jobs.(*Registry).stepThroughStateMachine(0xc004c08000, {0x67ee618, 0xc011af0a50}, {0x50df440, 0xc0107329a8}, {0x67c45d8, 0xc002f6a4e8}, 0xc00888d040, {0xc00e379af0, 0x7}, ...)
	github.com/cockroachdb/cockroach/pkg/jobs/registry.go:1629 +0xa3f
github.com/cockroachdb/cockroach/pkg/jobs.(*Registry).runJob(0xc004c08000, {0x67ee570, 0xc0064b67c0}, {0x67c45d8, 0xc002f6a4e8}, 0xc00888d040, {0xc00e379af0, 0x7}, {0xc00e379be8, 0x7})
	github.com/cockroachdb/cockroach/pkg/jobs/adopt.go:474 +0x637
github.com/cockroachdb/cockroach/pkg/jobs.(*Registry).resumeJob.func2({0x67ee618?, 0xc0095b1290?})
	github.com/cockroachdb/cockroach/pkg/jobs/adopt.go:388 +0x146
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2()
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:470 +0x146
created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx
	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:461 +0x43b
Log preceding fatal error

I230706 08:44:03.015836 18025066 sql/backfill.go:725  [T1,n1,job=SCHEMA CHANGE id=880026065761632257,scExec,id=52,mutation=2] 2041  finished adding constraints
I230706 08:44:03.015931 18025066 sql/backfill.go:740  [T1,n1,job=SCHEMA CHANGE id=880026065761632257,scExec,id=52,mutation=2] 2042  validating 1 new constraints
I230706 08:44:03.083702 18091767 jobs/registry.go:1588  [T1,n1] 2043  AUTO CREATE STATS job 880026067961741313: stepping through state running
I230706 08:44:03.095344 18103994 sql/check.go:68  [T1,n1,job=SCHEMA CHANGE id=880026065761632257,scExec,id=52,mutation=2] 2044  validating check constraint "owner_id IS NOT NULL" with query "SELECT connection_name, created, updated, connection_type, connection_details, owner, owner_id FROM [52 AS t] WHERE NOT (owner_id IS NOT NULL) LIMIT 1"
I230706 08:44:03.106665 18025066 sql/backfill.go:836  [T1,n1,job=SCHEMA CHANGE id=880026065761632257,scExec,id=52,mutation=2] 2045  finished validating new constraints
I230706 08:44:03.106729 18025066 sql/backfill.go:384  [T1,n1,job=SCHEMA CHANGE id=880026065761632257,scExec,id=52,mutation=2] 2046  completed backfill for "external_connections", v=6
I230706 08:44:03.106767 18025066 sql/schema_changer.go:1926  [T1,n1,job=SCHEMA CHANGE id=880026065761632257,scExec,id=52,mutation=2] 2047  marking schema change as complete
I230706 08:44:03.147441 18025066 5@util/log/event_log.go:32  [T1,n1,job=SCHEMA CHANGE id=880026065761632257,scExec,id=52,mutation=2] 2048 ={"Timestamp":1688633043106796723,"EventType":"finish_schema_change","InstanceID":1,"DescriptorID":52,"MutationID":2}
I230706 08:44:03.185789 18111228 sql/catalog/lease/descriptor_state.go:142  [n1] 2049  new lease: tabledesc.immutable: {ID: 52, Version: 8, ModificationTime: "1688633043.106796723,0", ParentID: 1, ParentSchemaID: 29, State: PUBLIC, NextColumnID: 8, Columns: [{ID: 1, TypeID: 25, Null: false}, {ID: 2, TypeID: 1114, Null: false, HasDefault: true}, {ID: 3, TypeID: 1114, Null: false, HasDefault: true}, {ID: 4, TypeID: 25, Null: false}, {ID: 5, TypeID: 17, Null: false}, {ID: 6, TypeID: 25, Null: false}, {ID: 7, TypeID: 26, Null: false}], NextFamilyID: 1, Families: [{ID: 0, Columns: [1, 2, 3, 4, 5, 6, 7]}], PrimaryIndex: 1, NextIndexID: 2, Indexes: [{ID: 1, Unique: true, KeyColumns: [{ID: 1, Dir: ASC}], StoreColumns: [2, 3, 4, 5, 6, 7]}]}
I230706 08:44:03.195777 18025066 sql/catalog/lease/lease.go:169  [T1,n1,job=SCHEMA CHANGE id=880026065761632257,scExec,id=52,mutation=2] 2050  waiting for 1 leases to expire: desc=[{external_connections 52 7}]
I230706 08:44:03.230580 18025066 sql/schema_changer.go:1340  [T1,n1,job=SCHEMA CHANGE id=880026065761632257,scExec,id=52,mutation=2] 2051  waiting for a single version...
I230706 08:44:03.247573 18025066 sql/schema_changer.go:1345  [T1,n1,job=SCHEMA CHANGE id=880026065761632257,scExec,id=52,mutation=2] 2052  waiting for a single version... done (at v 8), took 16.992257ms
I230706 08:44:03.247745 18025066 jobs/registry.go:1588  [T1,n1] 2053  SCHEMA CHANGE job 880026065761632257: stepping through state succeeded
I230706 08:44:03.378132 18005517 jobs/wait.go:145  [T1,n1,job=MIGRATION id=880026063800270849,upgrade=22.2-76,intExec=migration-alter-table-52] 2054  waited for 1 [880026065761632257] queued jobs to complete 1.128372438s
I230706 08:44:03.393740 17975256 jobs/registry.go:1588  [T1,n1] 2055  MIGRATION job 880026063800270849: stepping through state succeeded
I230706 08:44:03.535651 11527615 jobs/wait.go:145  [T1,n1,client=127.0.0.1:32980,hostssl,user=root,migration-mgr] 2056  waited for 1 [880026063800270849] queued jobs to complete 1.782025552s
I230706 08:44:03.535872 11527615 upgrade/upgrademanager/manager.go:657  [T1,n1,client=127.0.0.1:32980,hostssl,user=root,migration-mgr] 2057  executing operation bump-cluster-version=22.2-76
I230706 08:44:03.539724 11527615 upgrade/upgradecluster/cluster.go:121  [T1,n1,client=127.0.0.1:32980,hostssl,user=root,migration-mgr] 2058  executing bump-cluster-version=22.2-76 on nodes n{1}
I230706 08:44:03.553620 18152826 server/migration.go:150  [T1,n1,bump-cluster-version] 2059  active cluster version setting is now 22.2-76 (up from 22.2-75(fence))
I230706 08:44:03.702850 11527615 upgrade/upgrademanager/manager.go:517  [T1,n1,client=127.0.0.1:32980,hostssl,user=root,migration-mgr] 2060  stepping through 22.2-78
I230706 08:44:03.703001 11527615 upgrade/upgrademanager/manager.go:657  [T1,n1,client=127.0.0.1:32980,hostssl,user=root,migration-mgr] 2061  executing operation bump-cluster-version=22.2-77(fence)
I230706 08:44:03.707073 11527615 upgrade/upgradecluster/cluster.go:121  [T1,n1,client=127.0.0.1:32980,hostssl,user=root,migration-mgr] 2062  executing bump-cluster-version=22.2-77(fence) on nodes n{1}
I230706 08:44:03.707867 18170068 server/migration.go:150  [T1,n1,bump-cluster-version] 2063  active cluster version setting is now 22.2-77(fence) (up from 22.2-76)
I230706 08:44:03.717172 11527615 upgrade/upgrademanager/manager.go:657  [T1,n1,client=127.0.0.1:32980,hostssl,user=root,migration-mgr] 2064  executing operation validate-cluster-version=22.2-78
I230706 08:44:03.724763 11527615 upgrade/upgradecluster/cluster.go:121  [T1,n1,client=127.0.0.1:32980,hostssl,user=root,migration-mgr] 2065  executing validate-cluster-version=22.2-78 on nodes n{1}
I230706 08:44:03.732132 18091767 jobs/registry.go:1588  [T1,n1] 2066  AUTO CREATE STATS job 880026067961741313: stepping through state succeeded
I230706 08:44:03.741027 11527615 upgrade/upgrademanager/manager.go:657  [T1,n1,client=127.0.0.1:32980,hostssl,user=root,migration-mgr] 2067  executing operation bump-cluster-version=22.2-78
I230706 08:44:03.756135 11527615 upgrade/upgradecluster/cluster.go:121  [T1,n1,client=127.0.0.1:32980,hostssl,user=root,migration-mgr] 2068  executing bump-cluster-version=22.2-78 on nodes n{1}
I230706 08:44:03.774763 18175067 server/migration.go:150  [T1,n1,bump-cluster-version] 2069  active cluster version setting is now 22.2-78 (up from 22.2-77(fence))
I230706 08:44:03.829366 11527615 upgrade/upgrademanager/manager.go:517  [T1,n1,client=127.0.0.1:32980,hostssl,user=root,migration-mgr] 2070  stepping through 22.2-80
I230706 08:44:03.829503 11527615 upgrade/upgrademanager/manager.go:657  [T1,n1,client=127.0.0.1:32980,hostssl,user=root,migration-mgr] 2071  executing operation bump-cluster-version=22.2-79(fence)
I230706 08:44:03.834126 11527615 upgrade/upgradecluster/cluster.go:121  [T1,n1,client=127.0.0.1:32980,hostssl,user=root,migration-mgr] 2072  executing bump-cluster-version=22.2-79(fence) on nodes n{1}
I230706 08:44:03.834737 18184876 server/migration.go:150  [T1,n1,bump-cluster-version] 2073  active cluster version setting is now 22.2-79(fence) (up from 22.2-78)
I230706 08:44:03.844908 11527615 upgrade/upgrademanager/manager.go:657  [T1,n1,client=127.0.0.1:32980,hostssl,user=root,migration-mgr] 2074  executing operation validate-cluster-version=22.2-80
I230706 08:44:03.850099 11527615 upgrade/upgradecluster/cluster.go:121  [T1,n1,client=127.0.0.1:32980,hostssl,user=root,migration-mgr] 2075  executing validate-cluster-version=22.2-80 on nodes n{1}
I230706 08:44:03.870518 14204783 sql/stats/automatic_stats.go:910  [T1,n1] 2076  automatically executing "CREATE STATISTICS __auto__ FROM [42] WITH OPTIONS THROTTLING 0.9 AS OF SYSTEM TIME '-30s'"
I230706 08:44:04.156149 18206880 jobs/registry.go:1588  [T1,n1] 2077  AUTO CREATE STATS job 880026071522770945: stepping through state running
I230706 08:44:04.158615 11527615 upgrade/upgrademanager/manager.go:742  [T1,n1,client=127.0.0.1:32980,hostssl,user=root,migration-mgr] 2078  running Upgrade to 22.2-80: "backfill the system.jobs_info table with the payload and progress of each job in the system.jobs table"
I230706 08:44:04.158944 18213256 jobs/adopt.go:261  [T1,n1,client=127.0.0.1:32980,hostssl,user=root,migration-mgr] 2079  job 880026071385899009: resuming execution
I230706 08:44:04.196505 18216768 jobs/adopt.go:261  [T1,n1] 2080  job 880026071385899009: resuming execution
I230706 08:44:04.279540 18218090 jobs/registry.go:1588  [T1,n1] 2081  MIGRATION job 880026071385899009: stepping through state running
I230706 08:44:04.773658 11192440 2@util/log/event_log.go:32  [T1,n1] 2082 ={"Timestamp":1688633044773653839,"EventType":"runtime_stats","MemRSSBytes":536621056,"GoroutineCount":530,"MemStackSysBytes":8454144,"GoAllocBytes":242272872,"GoTotalBytes":394302824,"GoStatsStaleness":0.001769384,"HeapFragmentBytes":75478424,"HeapReservedBytes":28344320,"HeapReleasedBytes":106823680,"CGoAllocBytes":18371680,"CGoTotalBytes":42106880,"CGoCallRate":7.700403,"CPUUserPercent":217.8114,"CPUSysPercent":4.1002145,"GCPausePercent":0.7760702,"GCRunCount":205,"NetHostRecvBytes":61948,"NetHostSendBytes":61948}
I230706 08:44:04.784355 11192440 2@server/status/runtime_log.go:47  [T1,n1] 2083  runtime stats: 512 MiB RSS, 530 goroutines (stacks: 8.1 MiB), 231 MiB/376 MiB Go alloc/total(stale) (heap fragmentation: 72 MiB, heap reserved: 27 MiB, heap released: 102 MiB), 18 MiB/40 MiB CGO alloc/total (7.7 CGO/sec), 217.8/4.1 %(u/s)time, 0.8 %gc (205x), 60 KiB/60 KiB (r/w)net
I230706 08:44:05.379203 18218090 upgrade/upgrades/backfill_jobs_info_table_migration.go:75  [T1,n1,job=MIGRATION id=880026071385899009,upgrade=22.2-80] 2084  backfilling job_info, step0, batch0 done; resume after 0, done false
I230706 08:44:05.522550 18218090 upgrade/upgrades/backfill_jobs_info_table_migration.go:75  [T1,n1,job=MIGRATION id=880026071385899009,upgrade=22.2-80] 2085  backfilling job_info, step0, batch1 done; resume after 880026071522770945, done true
I230706 08:44:05.708147 18206880 jobs/registry.go:1588  [T1,n1] 2086  AUTO CREATE STATS job 880026071522770945: stepping through state succeeded
I230706 08:44:05.815381 14204783 sql/stats/automatic_stats.go:910  [T1,n1] 2087  automatically executing "CREATE STATISTICS __auto__ FROM [51] WITH OPTIONS THROTTLING 0.9 AS OF SYSTEM TIME '-30s'"
I230706 08:44:06.049668 18399292 jobs/registry.go:1588  [T1,n1] 2088  AUTO CREATE STATS job 880026078007689217: stepping through state running
I230706 08:44:06.133480 18415104 kv/kvserver/replica_consistency.go:233  [T1,n1,consistencyChecker,s1,r62/1:/Table/1{5/5-6}] 2089  triggering stats recomputation to resolve delta of {ContainsEstimates:2 LastUpdateNanos:1688633045876393810 IntentAge:0 GCBytesAge:0 LiveBytes:0 LiveCount:0 KeyBytes:0 KeyCount:0 ValBytes:0 ValCount:0 IntentBytes:0 IntentCount:0 SeparatedIntentCount:0 RangeKeyCount:0 RangeKeyBytes:0 RangeValCount:0 RangeValBytes:0 SysBytes:0 SysCount:0 AbortSpanBytes:0}
I230706 08:44:06.354379 18218090 upgrade/upgrades/backfill_jobs_info_table_migration.go:75  [T1,n1,job=MIGRATION id=880026071385899009,upgrade=22.2-80] 2090  backfilling job_info, step1, batch0 done; resume after 0, done false

Parameters: TAGS=bazel,gss,deadlock

Help

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

/cc @cockroachdb/jobs

This test on roachdash | Improve this report!

Jira issue: CRDB-29458

Metadata

Metadata

Assignees

Labels

C-test-failureBroken test (automatically or manually discovered).O-robotOriginated from a bot.T-jobsbranch-release-23.1Used to mark GA and release blockers, technical advisories, and bugs for 23.1release-blockerIndicates a release-blocker. Use with branch-release-2x.x label to denote which branch is blocked.v23.1.9

Type

No type

Projects

No projects

Relationships

None yet

Development

No branches or pull requests

Issue actions