kv/kvserver: TestCheckConsistencyInconsistent failed

[cockroach-teamcity]

kv/kvserver.TestCheckConsistencyInconsistent failed on master @ f43db402f520dd947d2aa3f742879ba2fe03e048:

Fatal error:

panic: range local key /Local/Range/Table/54/1/1091558191622750209/"legacy_progress"/Transaction/"0c229443-3dc9-4184-9fc9-3713c10ad02c" outside of a known range [recovered]
	panic: range local key /Local/Range/Table/54/1/1091558191622750209/"legacy_progress"/Transaction/"0c229443-3dc9-4184-9fc9-3713c10ad02c" outside of a known range [recovered]
	panic: range local key /Local/Range/Table/54/1/1091558191622750209/"legacy_progress"/Transaction/"0c229443-3dc9-4184-9fc9-3713c10ad02c" outside of a known range [recovered]
	panic: range local key /Local/Range/Table/54/1/1091558191622750209/"legacy_progress"/Transaction/"0c229443-3dc9-4184-9fc9-3713c10ad02c" outside of a known range [recovered]
	panic: range local key /Local/Range/Table/54/1/1091558191622750209/"legacy_progress"/Transaction/"0c229443-3dc9-4184-9fc9-3713c10ad02c" outside of a known range

Stack:

goroutine 28388 [running]:
testing.tRunner.func1.2({0xb6f7160, 0xc007cd5710})
	GOROOT/src/testing/testing.go:1632 +0x3fc
testing.tRunner.func1()
	GOROOT/src/testing/testing.go:1635 +0x6b6
panic({0xb6f7160?, 0xc007cd5710?})
	GOROOT/src/runtime/panic.go:791 +0x132
github.com/cockroachdb/cockroach/pkg/util/leaktest.AfterTest.func2()
	pkg/util/leaktest/leaktest.go:136 +0x51a
panic({0xb6f7160?, 0xc007cd5710?})
	GOROOT/src/runtime/panic.go:791 +0x132
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).recover(0xc0021e4090?, {0xd772668, 0x13abba00})
	pkg/util/stop/stopper.go:226 +0x74
panic({0xb6f7160?, 0xc007cd5710?})
	GOROOT/src/runtime/panic.go:791 +0x132
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).Stop(0xc004e6e3c0, {0xd772668, 0x13abba00})
	pkg/util/stop/stopper.go:566 +0x2c5
panic({0xb6f7160?, 0xc007cd5710?})
	GOROOT/src/runtime/panic.go:791 +0x132
github.com/cockroachdb/cockroach/pkg/kv/kvserver/kvstorage.IterateRangeDescriptorsFromDisk({0xd772668, 0x13abba00}, {0xd7c39a8, 0xc0040ac2c8}, 0xc0021e57e0)
	pkg/kv/kvserver/kvstorage/init.go:302 +0x19b2
github.com/cockroachdb/cockroach/pkg/kv/kvserver_test.TestCheckConsistencyInconsistent(0xc0016c1040)
	pkg/kv/kvserver/consistency_queue_test.go:399 +0x18bf
testing.tRunner(0xc0016c1040, 0xc319248)
	GOROOT/src/testing/testing.go:1690 +0x227
created by testing.(*T).Run in goroutine 1
	GOROOT/src/testing/testing.go:1743 +0x826

Log preceding fatal error

=== RUN   TestCheckConsistencyInconsistent
    test_log_scope.go:171: test logs captured to: outputs.zip/logTestCheckConsistencyInconsistent4157754914
    test_log_scope.go:82: use -show-logs to present logs inline
    consistency_queue_test.go:380: found a checkpoint at auxiliary/checkpoints/r5_at_29
    consistency_queue_test.go:380: found a checkpoint at auxiliary/checkpoints/r5_at_29
*
* ERROR: a panic has occurred!
* range local key /Local/Range/Table/54/1/1091558191622750209/"legacy_progress"/Transaction/"0c229443-3dc9-4184-9fc9-3713c10ad02c" outside of a known range
* (1) attached stack trace
*   -- stack trace:
*   | runtime.gopanic
*   | 	GOROOT/src/runtime/panic.go:791
*   | github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).Stop
*   | 	pkg/util/stop/stopper.go:566
*   | runtime.gopanic
*   | 	GOROOT/src/runtime/panic.go:791
*   | [...repeated from below...]
* Wraps: (2) assertion failure
* Wraps: (3) attached stack trace
*   -- stack trace:
*   | github.com/cockroachdb/cockroach/pkg/kv/kvserver/kvstorage.IterateRangeDescriptorsFromDisk
*   | 	pkg/kv/kvserver/kvstorage/init.go:302
*   | github.com/cockroachdb/cockroach/pkg/kv/kvserver_test.TestCheckConsistencyInconsistent
*   | 	pkg/kv/kvserver/consistency_queue_test.go:399
*   | testing.tRunner
*   | 	GOROOT/src/testing/testing.go:1690
*   | runtime.goexit
*   | 	src/runtime/asm_amd64.s:1700
* Wraps: (4) range local key /Local/Range/Table/54/1/1091558191622750209/"legacy_progress"/Transaction/"0c229443-3dc9-4184-9fc9-3713c10ad02c" outside of a known range
* Error types: (1) *withstack.withStack (2) *assert.withAssertionFailure (3) *withstack.withStack (4) *errutil.leafError
*
    stopper.go:226: -- test log scope end --

ERROR: a panic has occurred!
Details cannot be printed yet because we are still unwinding.
Hopefully the test harness prints the panic below, otherwise check the test logs.
    stopper.go:226: panic: range local key /Local/Range/Table/54/1/1091558191622750209/"legacy_progress"/Transaction/"0c229443-3dc9-4184-9fc9-3713c10ad02c" outside of a known range

test logs left over in: outputs.zip/logTestCheckConsistencyInconsistent4157754914
--- FAIL: TestCheckConsistencyInconsistent (47.57s)

Parameters:

• attempt=1
• race=true
• run=2
• shard=10

Help

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

/cc @cockroachdb/kv-triage

This test on roachdash | Improve this report!

Jira issue: CRDB-52836

[miraradeva]

The key in question, /Local/Range/Table/54/1/1091558191622750209/"legacy_progress"/Transaction/"0c229443-3dc9-4184-9fc9-3713c10ad02c" looks like a transaction record for a transaction issued by job. We do see that 1091558191622750209 is the ID of a span config reconciliation job:

I250722 12:32:04.730295 30712 13@spanconfig/spanconfigstore/store.go:364 ⋮ [T1,Vsystem,n1,job=AUTO SPAN CONFIG RECONCILIATION id=1091558191622750209] 74  changing the spanconfig for span:‹/Table/1{6-7}› from:{RangeMinBytes:134217728 RangeMaxBytes:536870912 GCPolicy:{TTLSeconds:14400 ProtectionPolicies:[] IgnoreStrictEnforcement:false} GlobalReads:false NumReplicas:5 NumVoters:0 Constraints:[] VoterConstraints:[] LeasePreferences:[] RangefeedEnabled:false ExcludeDataFromBackup:false} to:{RangeMinBytes:0 RangeMaxBytes:0 GCPolicy:{TTLSeconds:0 ProtectionPolicies:[] IgnoreStrictEnforcement:false} GlobalReads:false NumReplicas:0 NumVoters:0 Constraints:[] VoterConstraints:[] LeasePreferences:[] RangefeedEnabled:false ExcludeDataFromBackup:false}

The fact that this key was left behind and its range is gone, probably means that the range was split/merged and the relevant GC didn't happen before the test shut down. This is just a theory; there is nothing in the logs about the transaction or the range. But in any case, this seems like a test issue.

This test has never failed for this reason, and it hasn't failed in a while either. I'm going to restrict the test to the scratch range to avoid interfering with jobs' states, and will investigate more if it reoccurs.