Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Truncate cqlsh command fails to achieve consistency expecting more node that there are present in the cluster #11928

Closed
KnifeyMoloko opened this issue Nov 8, 2022 · 9 comments
Assignees
Labels
Milestone

Comments

@KnifeyMoloko
Copy link
Contributor

Installation details

Kernel Version: 5.15.0-1021-aws
Scylla version (or git commit hash): 2022.2.0~rc3-20221009.994a5f0fbb4c with build-id ad2ce7ef5214afc9f921ccfa2ce00706376f77dc
Relocatable Package: http://downloads.scylladb.com/downloads/scylla-enterprise/relocatable/scylladb-2022.2/scylla-enterprise-aarch64-package-2022.2.0-rc3.0.20221009.994a5f0fbb4c.tar.gz
Cluster size: 6 nodes (im4gn.4xlarge)

Scylla Nodes used in this run:

  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-4 (54.74.223.126 | 10.4.8.186) (shards: 15)
  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-2 (34.244.91.86 | 10.4.11.8) (shards: 15)
  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-8 (63.33.59.83 | 10.4.9.36) (shards: 15)
  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-3 (34.244.34.161 | 10.4.11.184) (shards: 15)
  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-5 (34.244.198.144 | 10.4.8.222) (shards: 15)
  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-11 (34.246.185.229 | 10.4.8.69) (shards: 15)
  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-7 (3.252.148.218 | 10.4.11.0) (shards: 15)
  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-14 (54.78.166.116 | 10.4.11.241) (shards: 15)
  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-13 (54.170.39.69 | 10.4.10.62) (shards: 15)
  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-10 (54.74.187.127 | 10.4.9.87) (shards: 15)
  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-17 (54.217.160.162 | 10.4.9.181) (shards: 15)
  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-6 (54.194.155.233 | 10.4.8.125) (shards: 15)
  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-16 (52.18.244.120 | 10.4.10.251) (shards: 15)
  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-9 (54.74.252.233 | 10.4.10.212) (shards: 15)
  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-18 (52.18.223.205 | 10.4.9.228) (shards: 15)
  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-22 (52.17.24.151 | 10.4.9.33) (shards: 15)
  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-12 (34.242.35.121 | 10.4.8.206) (shards: 15)
  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-19 (34.244.170.40 | 10.4.9.23) (shards: 15)
  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-20 (54.170.213.42 | 10.4.11.112) (shards: 15)
  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-25 (54.216.162.126 | 10.4.9.20) (shards: 15)
  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-15 (54.194.158.55 | 10.4.11.5) (shards: 15)
  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-26 (3.249.36.220 | 10.4.11.208) (shards: 15)
  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-1 (34.245.60.47 | 10.4.10.193) (shards: 15)
  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-21 (63.35.178.122 | 10.4.10.136) (shards: 15)
  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-23 (34.245.48.250 | 10.4.8.143) (shards: 15)
  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-24 (34.255.122.210 | 10.4.9.61) (shards: 15)
  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-27 (54.74.231.159 | 10.4.8.21) (shards: 15)
  • longevity-tls-50gb-3d-2022-2-db-node-7f685b49-28 (54.77.180.124 | 10.4.11.209) (shards: 15)

OS / Image: ami-0dcd7f54f9f910597 (aws: eu-west-1)

Test: longevity-50gb-3days-arm-test
Test id: 7f685b49-4c05-4d4d-987e-8287694d3a4e
Test name: enterprise-2022.2/longevity/longevity-50gb-3days-arm-test
Test config file(s):

Issue description

>>>>>>>
During the Truncate nemesis the cqlsh truncate command failed due to expecting a larger number of nodes for ALL than there was in the cluster at the time. Nodes have been replaced before this error and the cluster was expanded and shrinked with one of the nemesis, as this was > 1 day into the test run.

2022-11-04 22:30:22.432: (DisruptionEvent Severity.ERROR) period_type=end event_id=6b1988b8-044c-414e-a007-76c061f39d66 duration=1m59s: nemesis_name=Truncate target_node=Node longevity-tls-50gb-3d-2022-2-db-node-7f685b49-6 [54.194.155.233 | 10.4.8.125] (seed: False) errors=Encountered a bad command exit code!

Command: 'cqlsh --no-color -u cassandra -p \'cassandra\'  --request-timeout=120 --connect-timeout=60 --ssl -e "TRUNCATE ks_truncate.standard1" 10.4.8.125 9042'

Exit code: 2

Stdout:



Stderr:

<stdin>:1:TruncateError: Error during truncate: exceptions::unavailable_exception (Cannot achieve consistency level for cl ALL. Requires 7, alive 6)


Traceback (most recent call last):
  File "/home/ubuntu/scylla-cluster-tests/sdcm/nemesis.py", line 3693, in wrapper
    result = method(*args, **kwargs)
  File "/home/ubuntu/scylla-cluster-tests/sdcm/nemesis.py", line 1729, in disrupt_truncate
    self.target_node.run_cqlsh(cmd='TRUNCATE {}.{}'.format(keyspace_truncate, table), timeout=120)
  File "/home/ubuntu/scylla-cluster-tests/sdcm/cluster.py", line 2720, in run_cqlsh
    cqlsh_out = self.remoter.run(cmd, timeout=timeout + 30,  # we give 30 seconds to cqlsh timeout mechanism to work
  File "/home/ubuntu/scylla-cluster-tests/sdcm/remote/remote_base.py", line 613, in run
    result = _run()
  File "/home/ubuntu/scylla-cluster-tests/sdcm/utils/decorators.py", line 67, in inner
    return func(*args, **kwargs)
  File "/home/ubuntu/scylla-cluster-tests/sdcm/remote/remote_base.py", line 604, in _run
    return self._run_execute(cmd, timeout, ignore_status, verbose, new_session, watchers)
  File "/home/ubuntu/scylla-cluster-tests/sdcm/remote/remote_base.py", line 537, in _run_execute
    result = connection.run(**command_kwargs)
  File "/home/ubuntu/scylla-cluster-tests/sdcm/remote/libssh2_client/__init__.py", line 620, in run
    return self._complete_run(channel, exception, timeout_reached, timeout, result, warn, stdout, stderr)
  File "/home/ubuntu/scylla-cluster-tests/sdcm/remote/libssh2_client/__init__.py", line 654, in _complete_run
    raise UnexpectedExit(result)
sdcm.remote.libssh2_client.exceptions.UnexpectedExit: Encountered a bad command exit code!

less than a second later we run nodetool status to get the snapshot of the cluster's status, which lists only 6 nodes in the cluster:

< t:2022-11-04 22:30:28,764 f:base.py         l:228  c:RemoteLibSSH2CmdRunner p:DEBUG > Datacenter: eu-west
< t:2022-11-04 22:30:28,764 f:base.py         l:228  c:RemoteLibSSH2CmdRunner p:DEBUG > ===================
< t:2022-11-04 22:30:28,765 f:base.py         l:228  c:RemoteLibSSH2CmdRunner p:DEBUG > Status=Up/Down
< t:2022-11-04 22:30:28,765 f:base.py         l:228  c:RemoteLibSSH2CmdRunner p:DEBUG > |/ State=Normal/Leaving/Joining/Moving
< t:2022-11-04 22:30:28,765 f:base.py         l:228  c:RemoteLibSSH2CmdRunner p:DEBUG > --  Address      Load       Tokens       Owns    Host ID                               Rack
< t:2022-11-04 22:30:28,774 f:base.py         l:228  c:RemoteLibSSH2CmdRunner p:DEBUG > UN  10.4.10.212  15.78 GB   256          ?       d680c599-7c7f-4ac3-96d7-45016653f895  1c
< t:2022-11-04 22:30:28,792 f:base.py         l:228  c:RemoteLibSSH2CmdRunner p:DEBUG > UN  10.4.9.87    16.53 GB   256          ?       efe6c06b-176a-41d7-b67f-1ff792c7b7df  1c
< t:2022-11-04 22:30:28,792 f:base.py         l:228  c:RemoteLibSSH2CmdRunner p:DEBUG > UN  10.4.11.0    17.39 GB   256          ?       5223432c-3a5e-4aa1-987e-7262b1159cde  1c
< t:2022-11-04 22:30:28,800 f:base.py         l:228  c:RemoteLibSSH2CmdRunner p:DEBUG > UN  10.4.10.193  16.84 GB   256          ?       9084055d-a022-488e-8599-1d7f7d619729  1c
< t:2022-11-04 22:30:28,804 f:base.py         l:228  c:RemoteLibSSH2CmdRunner p:DEBUG > UN  10.4.8.125   16.32 GB   256          ?       ade46f38-db93-4a52-a6e4-f62d0f485086  1c
< t:2022-11-04 22:30:28,810 f:base.py         l:228  c:RemoteLibSSH2CmdRunner p:DEBUG > UN  10.4.8.222   17.6 GB    256          ?       e7d5ac93-16d5-44ec-8729-d52990096abb  1c

<<<<<<<

  • Restore Monitor Stack command: $ hydra investigate show-monitor 7f685b49-4c05-4d4d-987e-8287694d3a4e
  • Restore monitor on AWS instance using Jenkins job
  • Show all stored logs command: $ hydra investigate show-logs 7f685b49-4c05-4d4d-987e-8287694d3a4e

Logs:

Jenkins job URL

@bhalevy
Copy link
Member

bhalevy commented Nov 9, 2022

@asias, given https://github.com/scylladb/scylla-enterprise/blob/994a5f0fbb4c4ceb09a5a79b0bfbe67257842fdd/service/storage_proxy.cc#L5073

    auto all_endpoints = _gossiper.get_live_token_owners();

And https://github.com/scylladb/scylla-enterprise/blob/994a5f0fbb4c4ceb09a5a79b0bfbe67257842fdd/gms/gossiper.cc#L1042

        if (es && !is_dead_state(*es) && get_token_metadata_ptr()->is_member(member)) {

Compounded with #11925 (comment)
causing a stale endpoint to be in topology

Maybe we're hitting #11935,
causing gossiper::get_live_token_owners to return a stale endpoint.

What do you think?

Cc @xemul

@asias
Copy link
Contributor

asias commented Nov 9, 2022

I have the following a patch when debugging 10296 the truncate issue. I suspected that _topology is out of sync. It seemed to help.

commit 6edf6a43129e131cdc0f7a60a0eb351551cd6a0b
Author: Asias He <asias@scylladb.com>
Date:   Mon Oct 31 08:41:47 2022 +0800

    gossip: Imporve gossiper::get_live_token_owners and gossiper::get_unreachable_token_owners

diff --git a/gms/gossiper.cc b/gms/gossiper.cc
index 1535b44cec..43dc0f3a1c 100644
--- a/gms/gossiper.cc
+++ b/gms/gossiper.cc
@@ -1037,21 +1037,22 @@ std::set<inet_address> gossiper::get_live_members() {
 
 std::set<inet_address> gossiper::get_live_token_owners() {
     std::set<inet_address> token_owners;
-    for (auto& member : get_live_members()) {
-        auto es = get_endpoint_state_for_endpoint_ptr(member);
-        if (es && !is_dead_state(*es) && get_token_metadata_ptr()->is_member(member)) {
-            token_owners.insert(member);
+    auto normal_token_owners = get_token_metadata_ptr()->get_all_endpoints();
+    for (auto& node: normal_token_owners) {
+        if (is_alive(node)) {
+            token_owners.insert(node);
         }
     }
     return token_owners;
+
 }
 
 std::set<inet_address> gossiper::get_unreachable_token_owners() {
     std::set<inet_address> token_owners;
-    for (auto&& x : _unreachable_endpoints) {
-        auto& endpoint = x.first;
-        if (get_token_metadata_ptr()->is_member(endpoint)) {
-            token_owners.insert(endpoint);
+    auto normal_token_owners = get_token_metadata_ptr()->get_all_endpoints();
+    for (auto& node: normal_token_owners) {
+        if (!is_alive(node)) {
+            token_owners.insert(node);
         }
     }
     return token_owners;

@bhalevy
Copy link
Member

bhalevy commented Nov 9, 2022

@asias the patch above makes sense.
Is this a duplicate of #10296?

asias added a commit to asias/scylla that referenced this issue Nov 11, 2022
The get_live_token_owners returns the nodes that are part of the ring
and live.

The get_unreachable_token_owners returns the nodes that are part of the ring
and is not alive.

The token_metadata::get_all_endpoints returns nodes that are part of the
ring.

The patch changes both functions to use the more authoritative source to
get the nodes that are part of the ring and call is_alive to check if
the node is up or down. So that the correctness does not depend on
any derived information.

This patch fixes a truncate issue in storage_proxy::truncate_blocking
where it calls get_live_token_owners and get_unreachable_token_owners to
decide the nodes to talk with for truncate operation. The truncate
failed because incorrect nodes were returned.

Fixes scylladb#10296
Fixes scylladb#11928
@fgelcer fgelcer added this to the 5.1 milestone Nov 14, 2022
@fgelcer
Copy link

fgelcer commented Nov 14, 2022

@asias , just to confirm that you are working on a fix for this issue on #11952 ?

asias added a commit to asias/scylla that referenced this issue Nov 15, 2022
The get_live_token_owners returns the nodes that are part of the ring
and live.

The get_unreachable_token_owners returns the nodes that are part of the ring
and is not alive.

The token_metadata::get_all_endpoints returns nodes that are part of the
ring.

The patch changes both functions to use the more authoritative source to
get the nodes that are part of the ring and call is_alive to check if
the node is up or down. So that the correctness does not depend on
any derived information.

This patch fixes a truncate issue in storage_proxy::truncate_blocking
where it calls get_live_token_owners and get_unreachable_token_owners to
decide the nodes to talk with for truncate operation. The truncate
failed because incorrect nodes were returned.

Fixes scylladb#10296
Fixes scylladb#11928
xemul pushed a commit that referenced this issue Nov 15, 2022
The get_live_token_owners returns the nodes that are part of the ring
and live.

The get_unreachable_token_owners returns the nodes that are part of the ring
and is not alive.

The token_metadata::get_all_endpoints returns nodes that are part of the
ring.

The patch changes both functions to use the more authoritative source to
get the nodes that are part of the ring and call is_alive to check if
the node is up or down. So that the correctness does not depend on
any derived information.

This patch fixes a truncate issue in storage_proxy::truncate_blocking
where it calls get_live_token_owners and get_unreachable_token_owners to
decide the nodes to talk with for truncate operation. The truncate
failed because incorrect nodes were returned.

Fixes #10296
Fixes #11928

Closes #11952
@asias
Copy link
Contributor

asias commented Nov 16, 2022

@asias , just to confirm that you are working on a fix for this issue on #11952 ?

Yup. The fix is now in master.

avikivity pushed a commit that referenced this issue Nov 17, 2022
The get_live_token_owners returns the nodes that are part of the ring
and live.

The get_unreachable_token_owners returns the nodes that are part of the ring
and is not alive.

The token_metadata::get_all_endpoints returns nodes that are part of the
ring.

The patch changes both functions to use the more authoritative source to
get the nodes that are part of the ring and call is_alive to check if
the node is up or down. So that the correctness does not depend on
any derived information.

This patch fixes a truncate issue in storage_proxy::truncate_blocking
where it calls get_live_token_owners and get_unreachable_token_owners to
decide the nodes to talk with for truncate operation. The truncate
failed because incorrect nodes were returned.

Fixes #10296
Fixes #11928

Closes #11952

(cherry picked from commit 16bd9ec)
@fruch
Copy link
Contributor

fruch commented Jan 5, 2023

@asias
could be that the issue fixed here, is also needs fixing in 5.0 / 2022.1 branches ?

just seen something very similar in 2022.1.3

Command: 'cqlsh --no-color   --request-timeout=120 --connect-timeout=60  -e "TRUNCATE ks_truncate.standard1" 10.80.5.6 9042'

Exit code: 2

Stdout:



Stderr:

<stdin>:1:TruncateError: Error during truncate: exceptions::unavailable_exception (Cannot achieve consistency level for cl ALL. Requires 5, alive 2)

can you take a look ?

Installation details

Kernel Version: 5.15.0-1020-gke
Scylla version (or git commit hash): 2022.1.3-20220922.539a55e35 with build-id d1fb2faafd95058a04aad30b675ff7d2b930278d
Relocatable Package: http://downloads.scylladb.com/unstable/scylla-enterprise/enterprise-2022.1/relocatable/2022-09-22T13:36:03Z/scylla-enterprise-x86_64-package.tar.gz
Operator Image: scylladb/scylla-operator:1.8.0-rc.0
Operator Helm Version: 1.8.0-rc.0
Operator Helm Repository: https://storage.googleapis.com/scylla-operator-charts/latest
Cluster size: 4 nodes (n1-highmem-16)

Scylla Nodes used in this run:
No resources left at the end of the run

OS / Image: N/A (k8s-gke: us-east1)

Test: longevity-scylla-operator-basic-12h-gke
Test id: 7a41565f-b96a-45f4-b0be-6aa3191808fd
Test name: scylla-operator/operator-1.8/gke/longevity-scylla-operator-basic-12h-gke
Test config file(s):

Logs and commands
  • Restore Monitor Stack command: $ hydra investigate show-monitor 7a41565f-b96a-45f4-b0be-6aa3191808fd
  • Restore monitor on AWS instance using Jenkins job
  • Show all stored logs command: $ hydra investigate show-logs 7a41565f-b96a-45f4-b0be-6aa3191808fd

Logs:

Jenkins job URL

@asias
Copy link
Contributor

asias commented Jan 5, 2023

Yes, I think we need the backport.

@fruch
Copy link
Contributor

fruch commented Jan 8, 2023

Yes, I think we need the backport.

@scylladb/scylla-maint so this is a confirmation that at least 2022.1 need this backport

denesb pushed a commit that referenced this issue Jan 9, 2023
The get_live_token_owners returns the nodes that are part of the ring
and live.

The get_unreachable_token_owners returns the nodes that are part of the ring
and is not alive.

The token_metadata::get_all_endpoints returns nodes that are part of the
ring.

The patch changes both functions to use the more authoritative source to
get the nodes that are part of the ring and call is_alive to check if
the node is up or down. So that the correctness does not depend on
any derived information.

This patch fixes a truncate issue in storage_proxy::truncate_blocking
where it calls get_live_token_owners and get_unreachable_token_owners to
decide the nodes to talk with for truncate operation. The truncate
failed because incorrect nodes were returned.

Fixes #10296
Fixes #11928

Closes #11952

(cherry picked from commit 16bd9ec)
@denesb
Copy link
Contributor

denesb commented Jan 9, 2023

Backported to 5.0.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging a pull request may close this issue.

7 participants