cockroachdb / cockroachdb/cockroach
kv: decommission stall with repeated snapshot transfer timeouts
- Dominant language
- Go
- Stars
- 32.5k
- Forks
- 4.1k
- PR merge metrics
- PR metrics pending
Description
**Describe the problem**
In a test to track down an unrelated crash, I noticed that decommissioning can stall due to snapshot transfer timeouts.
**To Reproduce**
I observed this during a perturbation test, but I don't think it was doing anything unique other than setting the disk bandwidth limit.
Run test:
`COCKROACH_RANDOM_SEED=5641047121427902826 roachtest run perturbation/metamorphic/decommission`
This will create a 5 node cluster and start a workload at about 26K KV ops/sec with a 1K block size against the nodes n1-n4. About 5 minutes after IO is running at this rate, it decommissions n5. The decommission proceeds normally for the first 1-2 minutes, but then stalls with about 15-20 replicas left. It stays in this state for the next 2+ hours until the test fails in some other way.
**Expected behavior**
The decommission should complete normally after a short amount of time.
**Additional data / screenshots**
Attempting to manually enqueue one of the stuck ranges results in this output:
```
2024-12-27 15:01:50 | kv/kvserver/store.go:4038 [n3,s3,r106/4:/Table/106/1/5{66630…-82458…}] running replicate.shouldQueue
-- | --
2024-12-27 15:01:50 | kv/kvserver/allocator/plan/replicate.go:153 [n3,s3,r106/4:/Table/106/1/5{66630…-82458…}] computing range action desc=r106:/Table/106/1/5{666301351667722699-824586147096537864} [(n5,s5):1, (n2,s2):2, (n3,s3):4, (n1,s1):9LEARNER, next=10, gen=34, sticky=1735310269.697384800,0] config=range_min_bytes:134217728 range_max_bytes:536870912 gc_policy: num_replicas:3
2024-12-27 15:01:50 | kv/kvserver/allocator/plan/replicate.go:162 [n3,s3,r106/4:/Table/106/1/5{66630…-82458…}] repair needed (remove learner), enqueuing
2024-12-27 15:01:50 | kv/kvserver/store.go:4040 [n3,s3,r106/4:/Table/106/1/5{66630…-82458…}] shouldQueue=true, priority=12001.000000
2024-12-27 15:01:50 | kv/kvserver/store.go:4046 [n3,s3,r106/4:/Table/106/1/5{66630…-82458…}] running replicate.process
2024-12-27 15:01:50 | kv/kvserver/replicate_queue.go:638 [n3,s3,r106/4:/Table/106/1/5{66630…-82458…}] unable to acquire allocator token to process range: can't acquire allocator token, held by replicate
2024-12-27 15:01:50 | kv/kvserver/store.go:4048 [n3,s3,r106/4:/Table/106/1/5{66630…-82458…}] processed: false (err: can't acquire allocator token, held by replicate)
```
Looking at the logs on n3 around this time, there is the following output (repeated after every failure).
```
241227 15:00:18.520887 610790 13@kv/kvserver/allocator/plan/replicate.go:422 ⋮ [T1,Vsystem,n3,replicate,s3,r106/4:‹/Table/106/1/5{66630…-82458…}›] 564 replacing voter (n5,s5):1 with n4,s4: [1:951091, 2:951091, 4*:951091]
241227 15:00:18.521077 610790 13@kv/kvserver/replica_command.go:2535 ⋮ [T1,Vsystem,n3,replicate,s3,r106/4:‹/Table/106/1/5{66630…-82458…}›] 565 change replicas (add [(n4,s4):8LEARNER] remove []): existing descriptor r106:‹/Table/106/1/5{666301351667722699-824586147096537864}› [(n5,s5):1, (n2,s2):2, (n3,s3):4, next=8, gen=31, sticky=1735310269.697384800,0]
241227 15:00:18.522438 610790 13@kv/kvserver/replica_raft.go:403 ⋮ [T1,Vsystem,n3,s3,r106/4:‹/Table/106/1/5{66630…-82458…}›] 566 proposing SIMPLE(l8) [(n4,s4):8LEARNER]: after=[(n5,s5):1 (n2,s2):2 (n3,s3):4 (n4,s4):8LEARNER] next=9
241227 15:01:38.520892 610790 13@kv/kvserver/replica_command.go:3080 ⋮ [T1,Vsystem,n3,replicate,s3,r106/4:‹/Table/106/1/5{66630…-82458…}›] 569 attempt 1: delegate snapshot ‹range_id:106 coordinator_replica: recipient_replica: delegated_sender: term:8 first_index:951093 sender_queue_name:REPLICATE_QUEUE sender_queue_priority:5000 descriptor_generation:32 queue_on_delegate_len:-1 snap_id:98262148-b7a3-4bae-a8e4-f5362fd0654b › request failed operation "send-snapshot" timed out after 1m19.997s (given timeout 1h0m0s): ‹range_id:106 coordinator_replica: recipient_replica: delegated_sender: term:8 first_index:951093 sender_queue_name:REPLICATE_QUEUE sender_queue_priority:5000 descriptor_generation:32 queue_on_delegate_len:-1 snap_id:98262148-b7a3-4bae-a8e4-f5362fd0654b ›: remote failed to send snapshot: grpc: ‹context deadline exceeded› [code 4/DeadlineExceeded]
241227 15:01:38.520892 610790 13@kv/kvserver/replica_command.go:3080 ⋮ [T1,Vsystem,n3,replicate,s3,r106/4:‹/Table/106/1/5{66630…-82458…}›] 766 attempt 1: delegate snapshot ‹range_id:106 coordinator_replica: recipient_replica: delegated_sender: term:8 first_index:951093 sender_queue_name:REPLICATE_QUEUE sender_queue_priority:5000 descriptor_generation:32 queue_on_delegate_len:-1 snap_id:98262148-b7a3-4bae-a8e4-f5362fd0654b › request failed operation "send-snapshot" timed out after 1m19.997s (given timeout 1h0m0s): ‹range_id:106 coordinator_replica: recipient_replica: delegated_sender: term:8 first_index:951093 sender_queue_name:REPLICATE_QUEUE sender_queue_priority:5000 descriptor_generation:32 queue_on_delegate_len:-1 snap_id:98262148-b7a3-4bae-a8e4-f5362fd0654b ›: remote failed to send snapshot: grpc: ‹context deadline exceeded› [code 4/DeadlineExceeded]
241227 15:01:38.520989 610790 kv/kvserver/replica_command.go:1923 ⋮ [T1,Vsystem,n3,replicate,s3,r106/4:‹/Table/106/1/5{66630…-82458…}›] 767 could not successfully add and upreplicate LEARNER replica(s) on [n4,s4], rolling back: operation "send-snapshot" timed out after 1m19.997s (given timeout 1h0m0s): ‹range_id:106 coordinator_replica: recipient_replica: delegated_sender: term:8 first_index:951093 sender_queue_name:REPLICATE_QUEUE sender_queue_priority:5000 descriptor_generation:32 queue_on_delegate_len:-1 snap_id:98262148-b7a3-4bae-a8e4-f5362fd0654b ›: remote failed to send snapshot: grpc: ‹context deadline exceeded› [code 4/DeadlineExceeded]
241227 15:01:38.521228 610790 13@kv/kvserver/replica_command.go:2535 ⋮ [T1,Vsystem,n3,replicate,s3,r106/4:‹/Table/106/1/5{66630…-82458…}›] 570 change replicas (add [] remove [(n4,s4):8LEARNER]): existing descriptor r106:‹/Table/106/1/5{666301351667722699-824586147096537864}› [(n5,s5):1, (n2,s2):2, (n3,s3):4, (n4,s4):8LEARNER, next=9, gen=32, sticky=1735310269.697384800,0]
241227 15:01:38.533985 610790 13@kv/kvserver/replica_raft.go:403 ⋮ [T1,Vsystem,n3,s3,r106/4:‹/Table/106/1/5{66630…-82458…}›] 571 proposing SIMPLE(r8) [(n4,s4):8LEARNER]: after=[(n5,s5):1 (n2,s2):2 (n3,s3):4] next=9
241227 15:01:38.535137 610790 kv/kvserver/replica_command.go:2200 ⋮ [T1,Vsystem,n3,replicate,s3,r106/4:‹/Table/106/1/5{66630…-82458…}›] 768 rolled back LEARNER n4,s4 in r106:‹/Table/106/1/5{666301351667722699-824586147096537864}› [(n5,s5):1, (n2,s2):2, (n3,s3):4, (n4,s4):8LEARNER, next=9, gen=32, sticky=1735310269.697384800,0]
241227 15:01:38.535308 610790 13@kv/kvserver/replicate_queue.go:784 ⋮ [T1,Vsystem,n3,replicate,s3,r106/4:‹/Table/106/1/5{66630…-82458…}›] 572 error processing replica: operation "send-snapshot" timed out after 1m19.997s (given timeout 1h0m0s): ‹range_id:106 coordinator_replica: recipient_replica: delegated_sender: term:8 first_index:951093 sender_queue_name:REPLICATE_QUEUE sender_queue_priority:5000 descriptor_generation:32 queue_on_delegate_len:-1 snap_id:98262148-b7a3-4bae-a8e4-f5362fd0654b ›: remote failed to send snapshot: grpc: ‹context deadline exceeded› [code 4/DeadlineExceeded]
```
Looking at n4, there are no snapshots queued `store.range.snapshots.recv-queue=0` and there is relatively light load on the node in terms of both CPU and IO (<50% on both).
This is a link to the [grafana](https://grafana.testeng.crdb.io/d/J-yAVzkVddd/detailed?orgId=1&var-cluster=baptistcockroachlabscom-1735309707-01-n6cpu32sm&var-DS_PROMETHEUS=v9Zz2K6nz&var-node=All&var-rate_interval=1m&var-token_type=All&from=1735310771103&to=1735311281546), but most important are the range graphs:
The decommission of n5 started at 14:47:30
**Environment:**
- CockroachDB version [master]
**Additional context**
This test with this configuration fails about 50% of the time with this run configuration (in my tests 2/4 times). Typically this exposes some other problem later in the test and the test might fail for a different reason. Eventually the decommission might complete after ~2 hours.
Jira issue: CRDB-45865
Contributor guide
Assessment
This issue has not been assessed yet.