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

[cockroach-teamcity]

roachtest.decommission/nodes=4/duration=1h0m0s failed with artifacts on master @ 985662236d7bf273b93a7b5e32def8e2d1043640:

(decommission.go:369).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

/cc @cockroachdb/kv-triage

This test on roachdash | Improve this report!

Jira issue: CRDB-31594

[andrewbaptist]

Appears to be a stuck replica on decommissioning.

[cockroach-teamcity]

roachtest.decommission/nodes=4/duration=1h0m0s failed with artifacts on master @ 49eef749235f15d57153cb00f48dfd3b27be6c54:

(decommission.go:369).runDecommission: operation "decommission" timed out after 20m0s (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

This test on roachdash | Improve this report!

[cockroach-teamcity]

roachtest.decommission/nodes=4/duration=1h0m0s failed with artifacts on master @ 43326b23c9057251908704088cbb04854a6c4b57:

(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

This test on roachdash | Improve this report!

[kvoli]

A single replica is getting stuck on the decommissioning node. The replica is getting stuck because the range enters a joint config just before decommissioning begins, where the VOTER_INCOMING is the decommissioning replica, and supposed to take the lease. In order for the decommission to complete, the range needs to exit the joint config, but it never does.

Details:

The test log shows:

  | possible decommission stall detected
  | n68 still has replica id 134 for range r4

Looking at the ranges.json on n68 (n4 originally), it does show that it has a replica for the timeseries range r4 (/System/tsd - /System/\"tse\"). The leaseholder is n2, and the lease is valid:

 "lease_status": {
      "lease": {
        "start": {
          "wall_time": 1695537395693190918
        },
        "replica": {
          "node_id": 2,
          "store_id": 2,
          "replica_id": 133,
          "type": 0
        },
        "epoch": 1,
        "sequence": 59,
        "acquisition_type": 2
      },
    },
    "lease_valid": true

range json on n4

    "span": {
      "start_key": "/System/tsd",
      "end_key": "/System/\"tse\""
    },
    "raft_state": {
      "replica_id": 134,
      "hard_state": {
        "term": 35,
        "vote": 0,
        "commit": 4558
      },
      "lead": 133,
      "state": "StateFollower",
      "applied": 4558,
      "progress": null
    },
    "state": {
      "state": {
        "raft_applied_index": 4558,
        "lease_applied_index": 4348,
        "desc": {
          "range_id": 4,
          "start_key": "BHRzZA==",
          "end_key": "BHRzZQ==",
          "internal_replicas": [
            {
              "node_id": 1,
              "store_id": 1,
              "replica_id": 121,
              "type": 0
            },
            {
              "node_id": 3,
              "store_id": 3,
              "replica_id": 123,
              "type": 0
            },
            {
              "node_id": 2,
              "store_id": 2,
              "replica_id": 133,
              "type": 4
            },
            {
              "node_id": 68,
              "store_id": 68,
              "replica_id": 134,
              "type": 2
            }
          ],
          "next_replica_id": 135,
          "generation": 524,
          "sticky_bit": {}
        },
        "lease": {
          "start": {
            "wall_time": 1695537395693190918
          },
          "replica": {
            "node_id": 2,
            "store_id": 2,
            "replica_id": 133,
            "type": 0
          },
          "proposed_ts": {
            "wall_time": 1695537395706374295
          },
          "epoch": 1,
          "sequence": 59,
          "acquisition_type": 2
        },
        "truncated_state": {
          "index": 4556,
          "term": 35
        },
        "gc_threshold": {},
        "stats": {
          "contains_estimates": 7883606,
          "last_update_nanos": 1695538634556372445,
          "lock_age": 0,
          "gc_bytes_age": 0,
          "live_bytes": 137029800,
          "live_count": 2452,
          "key_bytes": 140635,
          "key_count": 2452,
          "val_bytes": 136889165,
          "val_count": 2452,
          "intent_bytes": 0,
          "intent_count": 0,
          "lock_count": 0,
          "range_key_count": 0,
          "range_key_bytes": 0,
          "range_val_count": 0,
          "range_val_bytes": 0,
          "sys_bytes": 40205,
          "sys_count": 10,
          "abort_span_bytes": 0
        },
        "version": {
          "major": 23,
          "minor": 1,
          "patch": 0,
          "internal": 26
        },
        "raft_closed_timestamp": {
          "wall_time": 1695538631574184807
        },
        "raft_applied_index_term": 35,
        "gc_hint": {
          "latest_range_delete_timestamp": {},
          "gc_timestamp": {},
          "gc_timestamp_next": {}
        }
      },
      "last_index": 4558,
      "raft_log_size": 311620,
      "range_max_bytes": 536870912,
      "active_closed_timestamp": {
        "wall_time": 1695538633418667519
      },
      "tenant_id": 1,
      "closed_timestamp_sidetransport_info": {
        "replica_closed": {
          "wall_time": 1695538633418667519
        },
        "replica_lai": 4348,
        "central_closed": {
          "wall_time": 1695538633418667519
        },
        "central_lai": 4348
      }
    },
    "source_node_id": 68,
    "source_store_id": 68,
    "lease_history": [
      {
        "start": {
          "wall_time": 1695537225344303301
        },
        "replica": {
          "node_id": 3,
          "store_id": 3,
          "replica_id": 123,
          "type": 2
        },
        "proposed_ts": {
          "wall_time": 1695537225349976338
        },
        "epoch": 1,
        "sequence": 57,
        "acquisition_type": 2
      },
      {
        "start": {
          "wall_time": 1695537395693190918
        },
        "replica": {
          "node_id": 2,
          "store_id": 2,
          "replica_id": 133,
          "type": 0
        },
        "proposed_ts": {
          "wall_time": 1695537395706374295
        },
        "epoch": 1,
        "sequence": 59,
        "acquisition_type": 2
      }
    ],
    "problems": {},
    "stats": {
      "writes_per_second": 1003.8535035558502,
      "cpu_time_per_second": 2907339.25304019
    },
    "lease_status": {
      "lease": {
        "start": {
          "wall_time": 1695537395693190918
        },
        "replica": {
          "node_id": 2,
          "store_id": 2,
          "replica_id": 133,
          "type": 0
        },
        "proposed_ts": {
          "wall_time": 1695537395706374295
        },
        "epoch": 1,
        "sequence": 59,
        "acquisition_type": 2
      },
      "now": {
        "wall_time": 1695538636464790850
      },
      "request_time": {
        "wall_time": 1695538636464790850
      },
      "state": 1,
      "liveness": {
        "node_id": 2,
        "epoch": 1,
        "expiration": {
          "wall_time": 1695538642458642952,
          "logical": 0
        }
      },
      "min_valid_observed_timestamp": {}
    },
    "ticking": true,
    "top_k_locks_by_wait_queue_waiters": null,
    "locality": {
      "tiers": [
        {
          "key": "cloud",
          "value": "gce"
        },
        {
          "key": "region",
          "value": "us-east1"
        },
        {
          "key": "zone",
          "value": "us-east1-b"
        }
      ]
    },
    "lease_valid": true

The decommission goes from 06:36:33 until its cancelled 20 minutes later at 06:56:33. The distribution logs on n2 (leaseholder) have a few references to r4:

# Enters joint config, where n68 (being decommissioned) is supposed to take
# the lease in order to exit the joint config.
I230924 06:36:36.129996 291156 13@kv/kvserver/replica_raft.go:384 ⋮ [T1,Vsystem,n2,s2,r4/133:‹/System{/tsd-tse}›] 18309  proposing ENTER_JOINT(r133 l133 v134) [(n68,s68):134VOTER_INCOMING], [(n2,s2):133VOTER_DEMOTING_LEARNER]: after=[(n1,s1):121 (n3,s3):123 (n2,s2):133VOTER_DEMOTING_LEARNER (n68,s68):134VOTER_INCOMING] next=135
I230924 06:36:43.757136 291551 13@kv/kvserver/allocator/plan/replicate.go:161 ⋮ [T1,Vsystem,n2,replicate,s2,r4/133:‹/System{/tsd-tse}›] 18336  repair needed (‹finalize conf change›), enqueuing
# This doesn't occur, and the replicate queue on n2 loops over the same action
# until the decommission times out.
...
I230924 06:55:45.061713 336680 13@kv/kvserver/allocator/plan/replicate.go:161 ⋮ [T1,Vsystem,n2,replicate,s2,r4/133:‹/System{/tsd-tse}›] 20730  repair needed (‹finalize conf change›), enqueuing

[kvoli]

The replica states according to n2:

n1:  VOTER_FULL
n2:  VOTER_DEMOTING_LEARNER (leaseholder)
n3:  VOTER_FULL
n68: VOTER_INCOMING         (decommissioning)

The last log line we see in cockroach.log for r4 is:

E230924 06:36:36.157787 291180 kv/kvserver/replica_raft.go:381 ⋮ [T1,Vsystem,n2,s2,r4/133:‹/System{/tsd-tse}›] 8674  (n2,s2):133VOTER_DEMOTING_LEARNER received invalid ChangeReplicasTrigger LEAVE_JOINT: after=[(n1,s1):121 (n3,s3):123 (n2,s2):133LEARNER (n68,s68):134] next=135 to remove self (leaseholder); lhRemovalAllowed: true; current desc: r4:‹/System{/tsd-tse}› [(n1,s1):121, (n3,s3):123, (n2,s2):133VOTER_DEMOTING_LEARNER, (n68,s68):134VOTER_INCOMING, next=135, gen=524]; proposed desc: r4:‹/System{/tsd-tse}› [(n1,s1):121, (n3,s3):123, (n2,s2):133LEARNER, (n68,s68):134, next=135, gen=525]: lease target replica cannot hold lease

internal replicas on n2 for r4

{
  "node_id": 1,
  "store_id": 1,
  "replica_id": 121,
  "type": 0
},
{
  "node_id": 3,
  "store_id": 3,
  "replica_id": 123,
  "type": 0
},
{
  "node_id": 2,
  "store_id": 2,
  "replica_id": 133,
  "type": 4
},
{
  "node_id": 68,
  "store_id": 68,
  "replica_id": 134,
  "type": 2
}

[kvoli]

@AlexTalks is stressing this atm with some bumped logging.