jobs: "system.job_info does not exist" during cluster upgrade

[renatolabs]

While testing some changes to the backup-restore/mixed-version roachtest, I saw a restore fail with the following error:

pq: CreateAdoptableJobInTxn: write-job-info-delete: relation "system.job_info" does not exist

This seems to happen when a RESTORE is run while the cluster is upgrading (migrations running in the background). Since the error message happens in the job layer, I believe the issue is unrelated to the restore logic itself.

Reproduction

#103228 contains the work-in-progress changes I was testing; the last commit in that PR is a series of changes to make the issue reproduce more quickly. Running the backup-restore/mixed-version test on that branch with a specific seed [1] (known to cause a restore to run during upgrade) reproduces this bug about ~10-20% of the times in about 15 mins.

For convenience, see TC run on the aforementioned PR [2], where we saw 2 failures out of 10 runs.

Let me know what else I can do to help debug this.

Update: an easier way to reproduce this bug seems to be by running the simpler acceptance/version-upgrade test using a seed that causes the schemachange workload to run concurrently with migrations. -8690666577594439584 is one such seed.

[1] 2167957990363226999
[2] https://teamcity.cockroachdb.com/viewLog.html?buildId=10059101&buildTypeId=Cockroach_Nightlies_RoachtestNightlyGceBazel&tab=buildLog#_state=600

Jira issue: CRDB-27894

[renatolabs]

cc @cockroachdb/jobs @cockroachdb/disaster-recovery

Also directly pinging @adityamaru since you've worked on a lot of the system.job_info-related changes recently.

[renatolabs]

Friendly ping @adityamaru. FYI, this also happens in CI (local cluster): #103269 (comment)

[adityamaru]

Sorry for the delay on this @renatolabs, other things have bumped this from my list. I will carve out time to dig into this tomorrow.

[adityamaru]

I tried writing a unit test that steps through the upgrade while repeatedly calling CreateAdoptableJobWithTxn. I wasn't able to tickle the failure, so I'm going to just use the roachtest to dig further.

[adityamaru]

posting a summary of a conversation with @dt @stevendanna @fqazi

• Cluster settings are not scoped to a txn. So it is possible to end up in a situation where we are reading at a historical timestamp but our clusterVersion.IsActive() is reporting true based on a migration that ran at a future timestamp. This problem is not unique to the jobs migration.

• In this roachtest failure however it appears to be a write that is occurring at a timestamp before the commit timestamp of the migration that creates the job_info table. This is unusual, because as part of the migration we bump the system.jobs descriptor version and wait for all leases on the older descriptor version to expire. This should ensure that any concurrent operation such as a schema change or restore that is writing to the system.jobs table will have their txn bumped to a timestamp higher than the one that committed the job_info migration. This points to some gap in our understanding of how leases held by a concurrent operation serialize with the migration.

The next steps are to gather more debug information here and potentially get some schema folks involved to better understand descriptor leasing.

[jeffswenson]

In this roachtest failure however it appears to be a write that is occurring at a timestamp before the commit timestamp of the migration that creates the job_info table. This is unusual, because as part of the migration we bump the system.jobs descriptor version and wait for all leases on the older descriptor version to expire. This should ensure that any concurrent operation such as a schema change or restore that is writing to the system.jobs table will have their txn bumped to a timestamp higher than the one that committed the job_info migration. This points to some gap in our understanding of how leases held by a concurrent operation serialize with the migration.

A transaction is allowed to keep its commit timestamp when the descriptor lease is dropped, its just not allowed to advance its timestamp passed the lease's expiration time. The read of the descriptor is not done within the txn, so a change to the descriptor does not generate read refresh conflicts at commit time.

cockroach/pkg/sql/catalog/descs/leased_descriptors.go

Line 177 in cf4e6d1

if setDeadline {

As long as the version check is not in a performance critical code path, we could use the utility I created during the 23.1 development cycle for checking a version gate in a txn:

cockroach/pkg/server/settingswatcher/version_guard.go

Line 37 in cf4e6d1

type VersionGuard struct {

Alternatively, instead of relying exclusively on the version gate, txns could check for the version gate and the existence of the job_info descriptor before reading/writing to the table.

[DrewKimball]

Hi @adityamaru, do you have an idea for when we'll fix this one? It might be possible to reproduce with TestJSONForwardingIndexes since it's flaking now.

[adityamaru]

@DrewKimball I'll look into this this week! The failures on those tests however are of the form system-jobs-scan: column "job_type" does not exist and not system.job_info does not exist. I suspect they fall in a similar class of problems as described by @jeffswenson over here - https://cockroachlabs.slack.com/archives/C04U1BTF8/p1689269073307619 but I'm not clear if we're pursuing a one-size fits all solution at the moment.

[adityamaru]

In a bid to apply a similar fix as #107570 to this test I kicked off a 20 run and only one failed with a dead node error:

ERROR: a panic has occurred!
* use of Span after Finish. Span: /cockroach.roachpb.Internal/Batch. Finish previously called at: <stack not captured. Set debugUseAfterFinish>
* (1) attached stack trace
*   -- stack trace:
*   | runtime.gopanic
*   |   GOROOT/src/runtime/panic.go:884
*   | [...repeated from below...]
* Wraps: (2) assertion failure
* Wraps: (3) attached stack trace
*   -- stack trace:
*   | github.com/cockroachdb/cockroach/pkg/util/tracing.(*Span).detectUseAfterFinish
*   |   github.com/cockroachdb/cockroach/pkg/util/tracing/span.go:182
*   | github.com/cockroachdb/cockroach/pkg/util/tracing.(*Span).Tracer
*   |   github.com/cockroachdb/cockroach/pkg/util/tracing/span.go:225
*   | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*replicaDecoder).createTracingSpans
*   |   github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_application_decoder.go:154
*   | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*replicaDecoder).DecodeAndBind
*   |   github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_application_decoder.go:63
*   | github.com/cockroachdb/cockroach/pkg/kv/kvserver/apply.(*Task).Decode
*   |   github.com/cockroachdb/cockroach/pkg/kv/kvserver/apply/task.go:142
*   | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).handleRaftReadyRaftMuLocked
*   |   github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_raft.go:878
*   | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).handleRaftReady
*   |   github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_raft.go:728
*   | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).processReady
*   |   github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/store_raft.go:689
*   | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftSchedulerShard).worker
*   |   github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/scheduler.go:418
*   | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftScheduler).Start.func2
*   |   github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/scheduler.go:321
*   | github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2
*   |   github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:484
*   | runtime.goexit
*   |   GOROOT/src/runtime/asm_amd64.s:1594
* Wraps: (4) use of Span after Finish. Span: /cockroach.roachpb.Internal/Batch. Finish previously called at: <stack not captured. Set debugUseAfterFinish>
* Error types: (1) *withstack.withStack (2) *assert.withAssertionFailure (3) *withstack.withStack (4) *errutil.leafError
*

I'll chase down this failure before kicking off another repro run.

[adityamaru]

Looks like #107242 saw a similar panic and the fix is being tracked in #107521.

[adityamaru]

an easier way to reproduce this bug seems to be by running the simpler acceptance/version-upgrade test using a seed that causes the schemachange workload to run concurrently with migrations. -8690666577594439584 is one such seed.

20 runs of this doesn't tickle this bug. Kicking off 50 now.

[adityamaru]

50 runs on master passed as well 🤔 . I'm going to try on release-23.1 now.