roachtest: decommission/nodes=4/duration=1h0m0s failed [replica stuck in queue processing]

[cockroach-teamcity]

roachtest.decommission/nodes=4/duration=1h0m0s failed with artifacts on release-23.2 @ 935399600693f84fb746715f430ecc245934f3cd:

(decommission.go:381).runDecommission: operation "decommission" timed out after 20m0.001s (given timeout 20m0s): context deadline exceeded
test artifacts and logs in: /artifacts/decommission/nodes=4/duration=1h0m0s/run_1

Parameters: ROACHTEST_arch=amd64 , ROACHTEST_cloud=gce , ROACHTEST_cpu=4 , ROACHTEST_encrypted=false , ROACHTEST_ssd=0

Help

See: roachtest README

See: How To Investigate (internal)

See: Grafana

Same failure on other branches

• roachtest: decommission/nodes=4/duration=1h0m0s failed [replica stuck in queue processing] #110761 roachtest: decommission/nodes=4/duration=1h0m0s failed [C-bug C-test-failure O-roachtest O-robot T-kv branch-master release-blocker]

/cc @cockroachdb/kv-triage

This test on roachdash | Improve this report!

Jira issue: CRDB-32581

[kvoli]

We bumped the logging in #111315 for these roachtests. If this is the same 1 replica "stuck" issue as #110761, we may have an easier time diagnosing.

possible decommission stall detected
n23 still has replica id 61 for range r4

id	is_live	replicas	is_decommissioning	membership	is_draining
23	false	1	true	decommissioning	true

Which it appears it could be.

[kvoli]

Appears different than #110761. Edit, possibly the same underlying issue.

n1 is the leaseholder and notices that the replica on "node4" (n23) needs to be
replaced, enqueuing:

I231020 15:33:32.419045 421852 13@kv/kvserver/allocator/allocatorimpl/allocator.go:1008 ⋮ [T1,Vsystem,n1,replicate,s1,r4/54:‹/System{/tsd-tse}›] 14204  ‹replace decommissioning voter› - replacement for 1 decommissioning voters priority=5000.00
I231020 15:33:32.418873 421852 13@kv/kvserver/allocator/plan/replicate.go:152 ⋮ [T1,Vsystem,n1,replicate,s1,r4/54:‹/System{/tsd-tse}›] 14203  computing range action desc=r4:‹/System{/tsd-tse}› [(n2,s2):56, (n1,s1):54, (n23,s23):61, next=62, gen=236] config=‹range_min_bytes:134217728 range_max_bytes:536870912 gc_policy:<ttl_seconds:14400 protection_policies:<protected_timestamp:<wall_time:1697815800000000000 > ignore_if_excluded_from_backup:true > > num_replicas:3 constraints:<constraints:<type:PROHIBITED value:"node4" > > ›
I231020 15:33:32.419063 421852 13@kv/kvserver/allocator/plan/replicate.go:161 ⋮ [T1,Vsystem,n1,replicate,s1,r4/54:‹/System{/tsd-tse}›] 14205  repair needed (‹replace decommissioning voter›), enqueuing

Approx. 1 minute later, without any range changes, we see that n1 considers the range for rebalancing instead.

I231020 15:34:49.142831 427460 13@kv/kvserver/allocator/plan/replicate.go:152 ⋮ [T1,Vsystem,n1,replicate,s1,r4/54:‹/System{/tsd-tse}›] 14387  computing range action desc=r4:‹/System{/tsd-tse}› [(n2,s2):56, (n1,s1):54, (n23,s23):61, next=62, gen=236] config=‹range_min_bytes:134217728 range_max_bytes:536870912 gc_policy:<ttl_seconds:14400 protection_policies:<protected_timestamp:<wall_time:1697815800000000000 > ignore_if_excluded_from_backup:true > > num_replicas:3 constraints:<constraints:<type:PROHIBITED value:"node4" > > ›
I231020 15:34:49.143268 427460 13@kv/kvserver/allocator/plan/replicate.go:200 ⋮ [T1,Vsystem,n1,replicate,s1,r4/54:‹/System{/tsd-tse}›] 14388  no rebalance target found, not enqueuing

After 5 minutes passes, n23 is considered dead and a replace dead voter action is returned.

I231020 15:39:26.227729 440688 13@kv/kvserver/allocator/plan/replicate.go:152 ⋮ [T1,Vsystem,n1,replicate,s1,r4/54:‹/System{/tsd-tse}›] 15053  computing range action desc=r4:‹/System{/tsd-tse}› [(n2,s2):56, (n1,s1):54, (n23,s23):61, next=62, gen=236] config=‹range_min_bytes:134217728 range_max_bytes:536870912 gc_policy:<ttl_seconds:14400 protection_policies:<protected_timestamp:<wall_time:1697815800000000000 > ignore_if_excluded_from_backup:true > > num_replicas:3 constraints:<constraints:<type:PROHIBITED value:"node4" > > ›
I231020 15:39:26.227938 440688 13@kv/kvserver/allocator/allocatorimpl/allocator.go:1000 ⋮ [T1,Vsystem,n1,replicate,s1,r4/54:‹/System{/tsd-tse}›] 15054  ‹replace dead voter› - replacement for 1 dead voters priority=12000.00
I231020 15:39:26.227971 440688 13@kv/kvserver/allocator/plan/replicate.go:161 ⋮ [T1,Vsystem,n1,replicate,s1,r4/54:‹/System{/tsd-tse}›] 15055  repair needed (‹replace dead voter›), enqueuing

What doesn't add up, is that n1 does not log processing r4, but does log enqueueing it into the replicate queue. It should be fairly straightforward to remove (n23,s23):61 and replace it with (n3:s3):62.

We can see that n3 is considered live and a valid candidate from lease transfer logging throughout.

The last time the replicate queue processed a change was @ 15:33:24, which we can tell by grepping for next replica action, logged here.

I231020 15:33:24.156824 419900 13@kv/kvserver/allocator/plan/replicate.go:266 ⋮ [T1,Vsystem,n1,replicate,s1,r17/15:‹/Table/1{4-5}›] 14160  next replica action: ‹replace decommissioning voter›

Two unexpected things to follow up on:

1. Why did n23's liveness status switch from decommissioning to being considered for rebalancing (non-decommissioning) between 15:33 and 15:39, that is unexpected.
2. Why did the replicate queue on n1 not process changes after 15:33:24.

[kvoli]

The TSDump shows no pending replicas and no replicas in purgatory on n1, which means the stuck replica didn't make it into the repl queue:

[kvoli]

Why did n23's liveness status switch from decommissioning to being considered for rebalancing (non-decommissioning) between 15:33 and 15:39, that is unexpected.

This is the issue described here #99064.

[kvoli]

1/20 stress runs last night failed with the same issue.

Interestingly, this only ever fails with the timeseries range (r4) having a replica stuck on the dead+decommissioning node.

The past test failures are the same, back to 23.1.

• roachtest: decommission/nodes=4/duration=1h0m0s failed #103029
• roachtest: decommission/nodes=4/duration=1h0m0s failed [replica stuck in queue processing] #110761

I'm suspecting something is going wrong here with purgatory/requeuing (atm looks unrelated to #113045). Branch with added logging. Similar sentiment to the last few times this test failed:

There were also no replicas in purgatory. There must be a bug somewhere because the replica doesn't seem to even be making it into the process loop of the queue - where it should pass the checks as the lease is valid, liveness info looks good on n1 (decommissioning n13) and otherwise identical to the rhs of the split which did process.

[kvoli]

Edited above comment.

My theory is that the bug is around the baseQueue addInternal function, which won't add a replica to the queue for processing on a few conditions, even if the queue implementation returns shouldQueue=true:

The allocator and replicate queue log lines show that the stuck range most certainly wants to be queued on the leaseholder:

I231020 15:39:26.227971 440688 13@kv/kvserver/allocator/plan/replicate.go:161 ⋮ [T1,Vsystem,n1,replicate,s1,r4/54:‹/System{/tsd-tse}›] 15055  repair needed (‹replace dead voter›), enqueuing

And the code path back to addInternal is uninterrupted. Within addInternal, I think we are hitting one of the conditions which causes the replica to not be added.

More specifically the already processing check:

cockroach/pkg/kv/kvserver/queue.go

Lines 766 to 771 in b13be53

	// Replica is already processing. Mark to be requeued.
	if item.processing {
	wasRequeued := item.requeue
	item.requeue = true
	return !wasRequeued, nil
	}

The other checks here can be proven to not be hit. The descriptor must be initialized because it passed the initial shouldQueue. The replica is not in purgatory, because the purgatory length is 0. The queue is not disabled.