Scylla: nodetool repair and nodetool removenode comands failed during repair process running

[asias]

When one of the node is down, repair is supposed to fail because one of the node is down. The repair continues as best effort mode, meaning repair with whatever node is live. The repair will report the repair is failed in the end.

[asias]

The removenode ops failed because other nodes marked the coordinator node to run the removenode as DOWN during the removenode ops.

14967 2021-01-25T20:08:12+00:00  longevity-cdc-100gb-4h-4-4-db-node-a92a84b6-1 !WARNING | scylla: [shard 13] repair - repair id [id=2, uuid=18943d16-c86b-4f45-b1fa-9d01922ec5d7] on shard 13 failed - 109 ranges failed
14968 2021-01-25T20:08:12+00:00  longevity-cdc-100gb-4h-4-4-db-node-a92a84b6-1 !WARNING | scylla: [shard 9] repair - Repair 504 out of 517 ranges, id=[id=2, uuid=18943d16-c86b-4f45-b1fa-9d01922ec5d7], shard=9, keyspace=system_trace      s, table={events, sessions, node_slow_log, sessions_time_idx, node_slow_log_time_idx}, range=(8540746862393288986, 8549954687201168966], peers={10.0.1.116}, live_peers={}, status=skipped
14969 2021-01-25T20:08:12+00:00  longevity-cdc-100gb-4h-4-4-db-node-a92a84b6-1 !WARNING | scylla: [shard 9] repair - Repair 505 out of 517 ranges, id=[id=2, uuid=18943d16-c86b-4f45-b1fa-9d01922ec5d7], shard=9, keyspace=system_trace      s, table={events, sessions, node_slow_log, sessions_time_idx, node_slow_log_time_idx}, range=(8682823651964586273, 8693545045829343754], peers={10.0.1.116}, live_peers={}, status=skipped
14970 2021-01-25T20:08:12+00:00  longevity-cdc-100gb-4h-4-4-db-node-a92a84b6-1 !WARNING | scylla: [shard 13] repair - repair id [id=2, uuid=18943d16-c86b-4f45-b1fa-9d01922ec5d7] on shard 13 failed: std::runtime_error (repair id [id      =2, uuid=18943d16-c86b-4f45-b1fa-9d01922ec5d7] on shard 13 failed to repair 109 sub ranges)

$ cat longevity-cdc-100gb-4h-4-4-db-node-a92a84b6-*/messages.log|grep 10.0.0.196|grep DOWN
2021-01-25T20:14:03+00:00  longevity-cdc-100gb-4h-4-4-db-node-a92a84b6-2 !INFO    | scylla: [shard 0] gossip - InetAddress 10.0.0.196 is now DOWN, status = NORMAL
2021-01-25T20:15:20+00:00  longevity-cdc-100gb-4h-4-4-db-node-a92a84b6-2 !INFO    | scylla: [shard 0] gossip - InetAddress 10.0.0.196 is now DOWN, status = NORMAL
2021-01-25T20:16:07+00:00  longevity-cdc-100gb-4h-4-4-db-node-a92a84b6-2 !INFO    | scylla: [shard 0] gossip - InetAddress 10.0.0.196 is now DOWN, status = NORMAL
2021-01-25T20:17:19+00:00  longevity-cdc-100gb-4h-4-4-db-node-a92a84b6-2 !INFO    | scylla: [shard 0] gossip - InetAddress 10.0.0.196 is now DOWN, status = NORMAL
2021-01-25T20:18:57+00:00  longevity-cdc-100gb-4h-4-4-db-node-a92a84b6-2 !INFO    | scylla: [shard 0] gossip - InetAddress 10.0.0.196 is now DOWN, status = NORMAL
2021-01-25T20:19:58+00:00  longevity-cdc-100gb-4h-4-4-db-node-a92a84b6-2 !INFO    | scylla: [shard 0] gossip - InetAddress 10.0.0.196 is now DOWN, status = NORMAL
2021-01-25T20:15:02+00:00  longevity-cdc-100gb-4h-4-4-db-node-a92a84b6-4 !INFO    | scylla: [shard 0] gossip - InetAddress 10.0.0.196 is now DOWN, status = NORMAL
2021-01-25T20:17:17+00:00  longevity-cdc-100gb-4h-4-4-db-node-a92a84b6-4 !INFO    | scylla: [shard 0] gossip - InetAddress 10.0.0.196 is now DOWN, status = NORMAL
2021-01-25T20:18:57+00:00  longevity-cdc-100gb-4h-4-4-db-node-a92a84b6-4 !INFO    | scylla: [shard 0] gossip - InetAddress 10.0.0.196 is now DOWN, status = NORMAL
2021-01-25T20:20:03+00:00  longevity-cdc-100gb-4h-4-4-db-node-a92a84b6-4 !INFO    | scylla: [shard 0] gossip - InetAddress 10.0.0.196 is now DOWN, status = NORMAL
2021-01-25T20:14:48+00:00  longevity-cdc-100gb-4h-4-4-db-node-a92a84b6-5 !INFO    | scylla: [shard 0] gossip - InetAddress 10.0.0.196 is now DOWN, status = NORMAL
2021-01-25T20:17:57+00:00  longevity-cdc-100gb-4h-4-4-db-node-a92a84b6-5 !INFO    | scylla: [shard 0] gossip - InetAddress 10.0.0.196 is now DOWN, status = NORMAL
2021-01-25T20:18:54+00:00  longevity-cdc-100gb-4h-4-4-db-node-a92a84b6-5 !INFO    | scylla: [shard 0] gossip - InetAddress 10.0.0.196 is now DOWN, status = NORMAL
2021-01-25T20:14:59+00:00  longevity-cdc-100gb-4h-4-4-db-node-a92a84b6-6 !INFO    | scylla: [shard 0] gossip - InetAddress 10.0.0.196 is now DOWN, status = NORMAL
2021-01-25T20:16:36+00:00  longevity-cdc-100gb-4h-4-4-db-node-a92a84b6-6 !INFO    | scylla: [shard 0] gossip - InetAddress 10.0.0.196 is now DOWN, status = NORMAL
2021-01-25T20:17:23+00:00  longevity-cdc-100gb-4h-4-4-db-node-a92a84b6-6 !INFO    | scylla: [shard 0] gossip - InetAddress 10.0.0.196 is now DOWN, status = NORMAL
2021-01-25T20:18:59+00:00  longevity-cdc-100gb-4h-4-4-db-node-a92a84b6-6 !INFO    | scylla: [shard 0] gossip - InetAddress 10.0.0.196 is now DOWN, status = NORMAL
2021-01-25T20:20:02+00:00  longevity-cdc-100gb-4h-4-4-db-node-a92a84b6-6 !INFO    | scylla: [shard 0] gossip - InetAddress 10.0.0.196 is now DOWN, status = NORMAL

[asias]

The metrics looks horrible.

[bhalevy]

The removenode ops failed because other nodes marked the coordinator node to run the removenode as DOWN during the removenode ops.

@asias why did that happen? what is the root cause?

[asias]

@aleksbykov hydra investigate show-monitor failed for me.

$ hydra investigate show-monitor a92a84b6-e2e9-4d07-8aa6-a85bf96363f8
Docker version 20.10.2, build 2291f61
There is scylladb/hydra:v0.85 in local cache, use it.
Obtaining QA SSH keys...
QA SSH keys obtained.
Making sure the ownerships of results directories are of the user
Going to run './sct.py investigate show-monitor a92a84b6-e2e9-4d07-8aa6-a85bf96363f8'...

We trust you have received the usual lecture from the local System
Administrator. It usually boils down to these three things:

    #1) Respect the privacy of others.
    #2) Think before you type.
    #3) With great power comes great responsibility.

[sudo] password for asias: 
Obtaining QA SSH keys...
QA SSH keys obtained.
New directory created: /home/asias/sct-results/20210202-020900-603914-investigate-show-monitor
Search monitoring stack archive files for test id a92a84b6-e2e9-4d07-8aa6-a85bf96363f8 and restoring...
Checking that docker is available...
Docker is available
Restoring monitoring stack from archive a92a84b6-e2e9-4d07-8aa6-a85bf96363f8/20210125_232251/monitor-set-a92a84b6.zip
Download file https://cloudius-jenkins-test.s3.amazonaws.com/a92a84b6-e2e9-4d07-8aa6-a85bf96363f8/20210125_232251/monitor-set-a92a84b6.zip to directory /tmp/tmpb8oxh6gp
Downloading a92a84b6-e2e9-4d07-8aa6-a85bf96363f8/20210125_232251/monitor-set-a92a84b6.zip from cloudius-jenkins-test
Downloaded finished
Error executing command: "cd /tmp/tmpb8oxh6gp/scylla-monitoring-src;
            ./start-all.sh             -g 33201 -m 32935 -p 51663             -s /tmp/tmpb8oxh6gp/scylla-monitoring-src/config/scylla_servers.yml             -n /tmp/tmpb8oxh6gp/scylla-monitoring-src/config/node_exporter_servers.yml             -d /tmp/tmpb8oxh6gp/monitoring_data_dir/20210125T232322Z-78629a0f5f3f164f -v 4.4"; Exit status: 1
Start docker containers [try #1]

[asias]

The removenode ops failed because other nodes marked the coordinator node to run the removenode as DOWN during the removenode ops.

@asias why did that happen? what is the root cause?

The system is heavily loaded. I need the monitor data to dig more. It is probably related to CDC because we do not see such huge drops without CDC. HH can also contribute extra workload like we saw: https://github.com/scylladb/scylla/issues/7976.

I suggest aleksbykov to give me a sct branch and a run.sh script inside, so I can modify and run the test myself. I want to limit scope of the tests. I also want to understand the exact workload used.

Test1:
1) Run c-s with cdc workload
2) Kill one node
3) Run repair

Test 2:
1) Run c-s with cdc workload
2) Kill one node
3) Run removenode ops

[aleksbykov]

@asias i restored the monitoring stack on aws instance: http://13.51.48.255:3000/d/gFYbtaYGz/my_gemini-scylla-per-server-metrics-nemesis-master?orgId=1&from=1611601085679&to=1611618200744
(If you will not see results, filter for last 30 days)

[asias]

Thanks. I can see the monitor now.

[asias]

@aleksbykov

The test yaml says:

stress_cmd: [ "cassandra-stress user no-warmup profile=/tmp/cdc_profile.yaml ops'(insert=2,read1=1,update_number=1,update_name=1,delete1=1)' cl=QUORUM duration=200m -port jmx=6868 -mode cql3 native -rate threads=100",
              "cassandra-stress user no-warmup profile=/tmp/cdc_profile_preimage.yaml ops'(insert=2,read1=1,update_number=1,update_name=1,delete1=1)' cl=QUORUM duration=200m -port jmx=6868 -mode cql3 native -rate threads=100",
              "cassandra-stress user no-warmup profile=/tmp/cdc_profile_postimage.yaml ops'(insert=2,read1=1,update_number=1,update_name=1,delete1=1)' cl=QUORUM duration=200m -port jmx=6868 -mode cql3 native -rate threads=100",
              "cassandra-stress user no-warmup profile=/tmp/cdc_profile_preimage_postimage.yaml ops'(insert=2,read1=1,update_number=1,update_name=1,delete1=1)' cl=QUORUM duration=200m -port jmx=6868 -mode cql3 native -rate threads=100"
             ]

n_db_nodes: 6
n_loaders: 2
n_monitor_nodes: 1

instance_type_db: 'i3.4xlarge'

There was only 2 loaders. Will each loader run all the 4 c-s cmds at the same time (2*4 c-s in parallel)? Also, I see not QPS limit in the c-s cmd, so the loaders will run at full speed to load the cluster to the extreme?

stress_cmd: [ "cassandra-stress user no-warmup profile=/tmp/cdc_profile.yaml ops'(insert=2,read1=1,update_number=1,update_name=1,delete1=1)' cl=QUORUM duration=200m -port jmx=6868 -mode cql3 native -rate threads=100",
              "cassandra-stress user no-warmup profile=/tmp/cdc_profile_preimage.yaml ops'(insert=2,read1=1,update_number=1,update_name=1,delete1=1)' cl=QUORUM duration=200m -port jmx=6868 -mode cql3 native -rate threads=100",
              "cassandra-stress user no-warmup profile=/tmp/cdc_profile_postimage.yaml ops'(insert=2,read1=1,update_number=1,update_name=1,delete1=1)' cl=QUORUM duration=200m -port jmx=6868 -mode cql3 native -rate threads=100",
              "cassandra-stress user no-warmup profile=/tmp/cdc_profile_preimage_postimage.yaml ops'(insert=2,read1=1,update_number=1,update_name=1,delete1=1)' cl=QUORUM duration=200m -port jmx=6868 -mode cql3 native -rate threads=100"
             ]

[asias]

node 10.0.1.116 is being shut down

 2021-01-25T20:06:55+00:00  longevity-cdc-100gb-4h-4-4-db-node-a92a84b6-1 !INFO    | scylla: [shard 0] gossip - InetAddress 10.0.1.116 is now DOWN, status = shutdown

At time 20:09:08, node1 10.0.0.196 was the coordinator to run the removnoede cmd, and the repair for remoovenode ops started

 2021-01-25T20:09:08+00:00  longevity-cdc-100gb-4h-4-4-db-node-a92a84b6-1 !INFO    | scylla: [shard 0] storage_service - removenode[680d8ebf-f2bd-4e15-9a4b-f670782c86ad]: Started removenode operation, removing node=10.0.1.116,       sync_nodes={10.0.2.15, 10.0.1.199, 10.0.0.86, 10.0.3.211, 10.0.0.196}, ignore_nodes=[]

A spike of sstable reads and streaming io was observed.

No spike of hints during the problematic period around 20:09

Spike of cache misses:

Despite all those spikes, I do not understand why the CQL dropped to floor. @slivne @avikivity Do you have any insights? The monitor is still alive.

The minimum reproducer would be:

start 6 nodes, run c-s above, kill one node, run removenode

[asias]

BTW, I think it is better to rate limit c-s to generate a constant workload on the loader with the throttle option, like

cassandra-stress user no-warmup profile=data_dir/cdc_profile_preimage.yaml ops'(insert=2,read1=1,update_number=1,update_name=1,delete1=1)' cl=QUORUM duration=200m -port jmx=6868 -mode cql3 native -rate 'threads=100 throttle=5000/s'

Tune the throttle option according to the cluster capacity, e.g., to load the system 80%.

Otherwise, c-s is sending requests as fast as it can.

[slivne]

@slivne ping

[aleksbykov]

The issue reproduced with Scylla version 4.5.dev-0.20210206.e1261d10f with build-id 6c45f8a236b89fa9dbdcd135bb26dccf4ffaf154 (ami-0e75b72c70e2d89a5(eu-north-1) during job: https://jenkins.scylladb.com/view/master/job/scylla-master/job/longevity/job/longevity-100gb-4h-test/300/

Again during the nemesis TerminateAndRemove after scylla was stopped on node8 and instance was terminated, Repair and nodetool remove were failed.

db logs: https://cloudius-jenkins-test.s3.amazonaws.com/db26ca4d-328c-4797-8b17-8910694acd11/20210207_050405/db-cluster-db26ca4d.zip

@asias I added script which allow to start the repo:
https://github.com/aleksbykov/scylla-cluster-tests/tree/repo_7965
file: repo_7965.sh

[asias]

The issue reproduced with Scylla version 4.5.dev-0.20210206.e1261d10f with build-id 6c45f8a236b89fa9dbdcd135bb26dccf4ffaf154 (ami-0e75b72c70e2d89a5(eu-north-1) during job: https://jenkins.scylladb.com/view/master/job/scylla-master/job/longevity/job/longevity-100gb-4h-test/300/

Again during the nemesis TerminateAndRemove after scylla was stopped on node8 and instance was terminated, Repair and nodetool remove were failed.

db logs: https://cloudius-jenkins-test.s3.amazonaws.com/db26ca4d-328c-4797-8b17-8910694acd11/20210207_050405/db-cluster-db26ca4d.zip

@asias I added script which allow to start the repo:
https://github.com/aleksbykov/scylla-cluster-tests/tree/repo_7965
file: repo_7965.sh

Thanks.

[asias]

Refs: https://github.com/scylladb/scylla/issues/8030 CDC uses TWCS strategy.
I think it is a combination of repair triggered on all nodes by removenode ops + TWCS triggered by CDC workload + unlimited cql workload generated by c-s (no throttle parameter) overwhelmed the node. Then the node was marked as down and failed the removenode ops.

[slivne]

@asias tried to have a look and I am lost

(assuming this is without repair node operation and repair is done prior to removenode - like users are asked todo)

• One node was stopped a nodetool repair was run - that repair failed - yet we need it to succeed (without repair based operations) - how can we make it succeed by ignoring the failed node? I think we have been chasing this before as well - and I am not sure I got an answer how to ignore the failed node during repair. @asias - how can we do that ?

• The repair is indeed running in the background (at least based on the sum(irate(scylla_repair_rx_row_nr[30s])) - ontop of that - we are able todo a removenode - really strange the ranges to repair and the token range ownerhsip are changing for repair under its feet and it continues to run ?

We really need to find a way to run repair without the node that is going to be removed.

Next trying to see whats going on during the part we do not have any CQL traffic.

@bhalevy / @raphaelsc

So its seems compaction is taking full control of our cpus but the strange thing is that it does not align with disk_io - thats strange - how come compaction is using ALL CPU but is not doing almost ANY IO ?

and we do have compactions running like crazy - but still - where is the IO associated with compaction ?

Based on the task quota violations we may have large stalls embedded inside - we need to set the stall detector to lower values to find them (50ms is expected to find something)

[bhalevy]

Cc @raphaelsc

[asias]

* One node was stopped a nodetool repair was run - that repair failed - yet we need it to succeed (without repair based operations) - how can we make it succeed by ignoring the failed node? I think we have been chasing this before as well - and I am not sure I got an answer how to ignore the failed node during repair. @asias - how can we do that ?

See here: https://github.com/scylladb/scylla/issues/7806#issuecomment-751922355.

I suggested adding an option to ignore dead nodes explicitly. I got no response yet.

[asias]

* The repair is indeed running in the background (at least based on the `sum(irate(scylla_repair_rx_row_nr[30s]))` - ontop of that - we are able todo a removenode - really strange the ranges to repair and the token range ownerhsip are changing for repair under its feet and it continues to run ?

The repair is triggered by removenode ops, not the regular repair triggered by user.

After

commit 829b4c14380020fa4058335c4c43cefec135b3de
Author: Asias He <[email protected]>
Date:   Mon Nov 16 16:13:44 2020 +0800

    repair: Make removenode safe by default

We always use repair based node ops for removenode operations.

[bhalevy]

we do have compactions running like crazy - but still - where is the IO associated with compaction ?

@raphaelsc suspects an issue with backlog tracker.
See #6054

[raphaelsc]

If compaction aggressiveness doesn't match the actual amount of compaction backlog (i.e. compaction work left), then we very likely have a problem in the controller. Given that this issue involves CDC, which in turn uses TWCS, it may potentially be #6054. The patch which fixed it was merged into next. Once it reaches master, we can try another run to see if this issue was fixed. /CC @asias @aleksbykov

[avikivity]

Offending commit (829b4c1) reverted on 4.4 only.

[slivne]

Can be tested on 4.4.rc3