[
https://issues.apache.org/jira/browse/CASSANDRA-17411?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17514899#comment-17514899
]
Brandon Williams commented on CASSANDRA-17411:
----------------------------------------------
Here it is with more time:
{noformat}
2022-03-30 18:57:07,763 - target-dc1 - cassandra.connection - WARNING -
Heartbeat failed for connection (139719619682112) to 127.0.0.1:9042
2022-03-30 18:57:07,776 - target-dc3 - cassandra.connection - WARNING -
Heartbeat failed for connection (139719619681680) to 127.0.0.1:9042
2022-03-30 18:57:07,980 - target-dc2 - __main__ - INFO - Got 0/579 (0.000000)
timeouts/total_rqs in the last 1 minute
2022-03-30 18:57:08,094 - target-dc3 - __main__ - INFO - Got 0/579 (0.000000)
timeouts/total_rqs in the last 1 minute
2022-03-30 18:57:12,768 - target-dc1 - cassandra.cluster - WARNING - [control
connection] Error connecting to 127.0.0.1:9042:
Traceback (most recent call last):
File
"/home/drift/cassandra-dtest/venv/src/cassandra-driver/cassandra/cluster.py",
line 3522, in _reconnect_internal
return self._try_connect(host)
File
"/home/drift/cassandra-dtest/venv/src/cassandra-driver/cassandra/cluster.py",
line 3544, in _try_connect
connection = self._cluster.connection_factory(host.endpoint,
is_control_connection=True)
File
"/home/drift/cassandra-dtest/venv/src/cassandra-driver/cassandra/cluster.py",
line 1620, in connection_factory
return self.connection_class.factory(endpoint, self.connect_timeout, *args,
**kwargs)
File
"/home/drift/cassandra-dtest/venv/src/cassandra-driver/cassandra/connection.py",
line 831, in factory
conn = cls(endpoint, *args, **kwargs)
File
"/home/drift/cassandra-dtest/venv/src/cassandra-driver/cassandra/io/asyncorereactor.py",
line 344, in __init__
self._connect_socket()
File
"/home/drift/cassandra-dtest/venv/src/cassandra-driver/cassandra/connection.py",
line 898, in _connect_socket
raise socket.error(sockerr.errno, "Tried connecting to %s. Last error: %s" %
OSError: [Errno None] Tried connecting to [('127.0.0.1', 9042)]. Last error:
timed out
2022-03-30 18:57:12,831 - target-dc1 - __main__ - INFO - Got 5/190 (2.631579)
timeouts/total_rqs in the last 1 minute
2022-03-30 18:57:37,774 - target-dc1 - cassandra.connection - WARNING -
Heartbeat failed for connection (139719602362976) to 127.0.0.1:9042
2022-03-30 18:57:37,775 - target-dc1 - cassandra.cluster - WARNING - Host
127.0.0.1:9042 has been marked down
2022-03-30 18:57:43,983 - target-dc1 - cassandra.pool - WARNING - Error
attempting to reconnect to 127.0.0.1:9042, scheduling retry in 1.74 seconds:
[Errno None] Tried connecting to [('127.0.0.1', 9042)]. Last error: timed out
2022-03-30 18:57:50,790 - target-dc1 - cassandra.pool - WARNING - Error
attempting to reconnect to 127.0.0.1:9042, scheduling retry in 4.52 seconds:
[Errno None] Tried connecting to [('127.0.0.1', 9042)]. Last error: timed out
2022-03-30 18:58:00,403 - target-dc1 - cassandra.pool - WARNING - Error
attempting to reconnect to 127.0.0.1:9042, scheduling retry in 7.04 seconds:
[Errno None] Tried connecting to [('127.0.0.1', 9042)]. Last error: timed out
2022-03-30 18:58:08,006 - target-dc2 - __main__ - INFO - Got 0/582 (0.000000)
timeouts/total_rqs in the last 1 minute
2022-03-30 18:58:08,144 - target-dc3 - __main__ - INFO - Got 0/582 (0.000000)
timeouts/total_rqs in the last 1 minute
2022-03-30 18:58:12,519 - target-dc1 - cassandra.pool - WARNING - Error
attempting to reconnect to 127.0.0.1:9042, scheduling retry in 16.0 seconds:
[Errno None] Tried connecting to [('127.0.0.1', 9042)]. Last error: timed out
2022-03-30 18:58:14,102 - target-dc1 - __main__ - INFO - Got 9/15 (60.000000)
timeouts/total_rqs in the last 1 minute
2022-03-30 18:58:33,550 - target-dc1 - cassandra.pool - WARNING - Error
attempting to reconnect to 127.0.0.1:9042, scheduling retry in 33.28 seconds:
[Errno None] Tried connecting to [('127.0.0.1', 9042)]. Last error: timed out
2022-03-30 18:59:08,102 - target-dc2 - __main__ - INFO - Got 0/584 (0.000000)
timeouts/total_rqs in the last 1 minute
2022-03-30 18:59:08,221 - target-dc3 - __main__ - INFO - Got 0/584 (0.000000)
timeouts/total_rqs in the last 1 minute
2022-03-30 18:59:11,914 - target-dc1 - cassandra.pool - WARNING - Error
attempting to reconnect to 127.0.0.1:9042, scheduling retry in 55.04 seconds:
[Errno None] Tried connecting to [('127.0.0.1', 9042)]. Last error: timed out
2022-03-30 18:59:16,479 - target-dc1 - __main__ - INFO - Got 12/23 (52.173913)
timeouts/total_rqs in the last 1 minute
2022-03-30 19:00:08,126 - target-dc2 - __main__ - INFO - Got 0/586 (0.000000)
timeouts/total_rqs in the last 1 minute
2022-03-30 19:00:08,246 - target-dc3 - __main__ - INFO - Got 0/586 (0.000000)
timeouts/total_rqs in the last 1 minute
2022-03-30 19:00:12,003 - target-dc1 - cassandra.pool - WARNING - Error
attempting to reconnect to 127.0.0.1:9042, scheduling retry in 125.44 seconds:
[Errno None] Tried connecting to [('127.0.0.1', 9042)]. Last error: timed out
2022-03-30 19:00:18,924 - target-dc1 - __main__ - INFO - Got 12/24 (50.000000)
timeouts/total_rqs in the last 1 minute
2022-03-30 19:01:08,141 - target-dc2 - __main__ - INFO - Got 0/586 (0.000000)
timeouts/total_rqs in the last 1 minute
2022-03-30 19:01:08,302 - target-dc3 - __main__ - INFO - Got 0/586 (0.000000)
timeouts/total_rqs in the last 1 minute
2022-03-30 19:01:20,657 - target-dc1 - __main__ - INFO - Got 12/17 (70.588235)
timeouts/total_rqs in the last 1 minute
2022-03-30 19:02:08,164 - target-dc2 - __main__ - INFO - Got 0/587 (0.000000)
timeouts/total_rqs in the last 1 minute
2022-03-30 19:02:08,374 - target-dc3 - __main__ - INFO - Got 0/587 (0.000000)
timeouts/total_rqs in the last 1 minute
2022-03-30 19:02:22,510 - target-dc1 - cassandra.pool - WARNING - Error
attempting to reconnect to 127.0.0.1:9042, scheduling retry in 225.28 seconds:
[Errno None] Tried connecting to [('127.0.0.1', 9042)]. Last error: timed out
2022-03-30 19:02:23,033 - target-dc1 - __main__ - INFO - Got 12/23 (52.173913)
timeouts/total_rqs in the last 1 minute
{noformat}
node1 appears down to others:
{noformat}
Datacenter: dc1
===============
Status=Up/Down
|/ State=Normal/Leaving/Joining/Moving
-- Address Load Tokens Owns (effective) Host ID
Rack
UN 127.0.0.2 91.08 KiB 1 100.0%
b79a56f9-74bb-488a-ae7a-def71b9d2e32 r1
DN 127.0.0.1 91.15 KiB 1 100.0%
f90307f3-fda3-47c9-9f78-e6f570a67790 r1
Datacenter: dc2
===============
Status=Up/Down
|/ State=Normal/Leaving/Joining/Moving
-- Address Load Tokens Owns (effective) Host ID
Rack
UN 127.0.0.4 91.09 KiB 1 100.0%
d0b5d218-544f-4d06-802f-f526c8c7c106 r1
UN 127.0.0.3 91.09 KiB 1 100.0%
d8212283-807c-4ca2-a866-91320faaa9d2 r1
Datacenter: dc3
===============
Status=Up/Down
|/ State=Normal/Leaving/Joining/Moving
-- Address Load Tokens Owns (effective) Host ID
Rack
UN 127.0.0.5 91.11 KiB 1 100.0%
82b6222b-79fc-42e6-b1d9-8a3710bb033b r1
UN 127.0.0.6 91.09 KiB 1 100.0%
ca8c4b9b-d470-43f6-82cc-f6d910f282b3 r1
{noformat}
and everything appears down to node1:
{noformat}
Datacenter: dc1
===============
Status=Up/Down
|/ State=Normal/Leaving/Joining/Moving
-- Address Load Tokens Owns (effective) Host ID
Rack
DN 127.0.0.2 91.08 KiB 1 100.0%
b79a56f9-74bb-488a-ae7a-def71b9d2e32 r1
UN 127.0.0.1 91.15 KiB 1 100.0%
f90307f3-fda3-47c9-9f78-e6f570a67790 r1
Datacenter: dc2
===============
Status=Up/Down
|/ State=Normal/Leaving/Joining/Moving
-- Address Load Tokens Owns (effective) Host ID
Rack
DN 127.0.0.4 91.09 KiB 1 100.0%
d0b5d218-544f-4d06-802f-f526c8c7c106 r1
DN 127.0.0.3 91.09 KiB 1 100.0%
d8212283-807c-4ca2-a866-91320faaa9d2 r1
Datacenter: dc3
===============
Status=Up/Down
|/ State=Normal/Leaving/Joining/Moving
-- Address Load Tokens Owns (effective) Host ID
Rack
DN 127.0.0.5 91.11 KiB 1 100.0%
82b6222b-79fc-42e6-b1d9-8a3710bb033b r1
DN 127.0.0.6 91.09 KiB 1 100.0%
ca8c4b9b-d470-43f6-82cc-f6d910f282b3 r1
{noformat}
All behavior from the server side looks as expected, so I guess this is indeed
a driver problem.
> Network partition causes write ONE timeouts when using counters in Cassandra 4
> ------------------------------------------------------------------------------
>
> Key: CASSANDRA-17411
> URL: https://issues.apache.org/jira/browse/CASSANDRA-17411
> Project: Cassandra
> Issue Type: Bug
> Components: Consistency/Coordination
> Reporter: Pere Balaguer
> Assignee: Brandon Williams
> Priority: Normal
> Fix For: 4.0.x
>
> Attachments: app.py
>
>
> h5. Affected versions:
> * 4.x
> h5. Observed behavior:
> When executing CL=ONE writes on a table with a counter column, if one of the
> nodes is network partitioned from the others, clients keep sending requests
> to it.
> Even though this may be a "driver" problem, I've been able to reproduce it
> with both java and python datastax drivers using their latest available
> versions and given the behavior only changes depending on the Cassandra
> version, well, here I am.
> h5. Expected behavior:
> In Cassandra 3 after all inflight requests fail (expected), no new requests
> are sent to the partitioned node. The expectation is that Cassandra 4 behaves
> the same way.
> h5. How to reproduce:
> {noformat}
> # Create a cluster with the desired version, will go with 4.x for this example
> ccm create bug-report -v 4.0.3
> ccm populate -n 2:2:2
> ccm start
> # Create schemas and so on
> CQL=$(cat <<END
> CONSISTENCY ALL;
> DROP KEYSPACE IF EXISTS demo;
> CREATE KEYSPACE demo WITH REPLICATION = {'class': 'NetworkTopologyStrategy',
> 'dc1': 2, 'dc2': 2, 'dc3': 2};
> CREATE TABLE demo.demo (pk uuid PRIMARY KEY, count counter) WITH compaction =
> {'class': 'LeveledCompactionStrategy'};
> END
> )
> ccm node1 cqlsh --verbose --exec="${CQL}"
> # Launch the attached app.py
> # requires cassandra-driver
> python3 app.py "127.0.0.1" "9042"
> # Wait a bit for the app to settle, proceed to next step once you see 3
> messages in stdout like:
> # 2022-03-01 15:41:51,557 - target-dc2 - __main__ - INFO - Got 0/572
> (0.000000) timeouts/total_rqs in the last 1 minute
> # Partition one node with iptables
> iptables -A INPUT -p tcp --destination 127.0.0.1 --destination-port 7000 -j
> DROP; iptables -A INPUT -p tcp --destination 127.0.0.1 --destination-port
> 9042 -j DROP
> {noformat}
> Some time after executing the iptables command in cassandra-3 the output
> should be similar to:
> {noformat}
> 2022-03-01 15:41:51,557 - target-dc2 - __main__ - INFO - Got 0/572 (0.000000)
> timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:41:51,576 - target-dc3 - __main__ - INFO - Got 0/572 (0.000000)
> timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:41:58,032 - target-dc1 - __main__ - INFO - Got 6/252 (2.380952)
> timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:42:51,560 - target-dc2 - __main__ - INFO - Got 0/570 (0.000000)
> timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:42:51,620 - target-dc3 - __main__ - INFO - Got 0/570 (0.000000)
> timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:42:58,101 - target-dc1 - __main__ - INFO - Got 2/354 (0.564972)
> timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:43:51,602 - target-dc2 - __main__ - INFO - Got 0/571 (0.000000)
> timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:43:51,672 - target-dc3 - __main__ - INFO - Got 0/571 (0.000000)
> timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:43:58,153 - target-dc1 - __main__ - INFO - Got 0/572 (0.000000)
> timeouts/total_rqs in the last 1 minute
> {noformat}
> as the timeouts/rqs shows, in about 2 minutes the partitioned node stops
> receiving traffic
> while as in cassandra-4
> {noformat}
> 2022-03-01 15:49:39,068 - target-dc3 - __main__ - INFO - Got 0/566 (0.000000)
> timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:49:39,107 - target-dc2 - __main__ - INFO - Got 0/566 (0.000000)
> timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:49:41,206 - target-dc1 - __main__ - INFO - Got 2/444 (0.450450)
> timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:50:39,095 - target-dc3 - __main__ - INFO - Got 0/569 (0.000000)
> timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:50:39,148 - target-dc2 - __main__ - INFO - Got 0/569 (0.000000)
> timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:50:42,589 - target-dc1 - __main__ - INFO - Got 7/13 (53.846154)
> timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:51:39,125 - target-dc3 - __main__ - INFO - Got 0/567 (0.000000)
> timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:51:39,159 - target-dc2 - __main__ - INFO - Got 0/567 (0.000000)
> timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:51:44,902 - target-dc1 - __main__ - INFO - Got 12/22
> (54.545455) timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:52:39,188 - target-dc2 - __main__ - INFO - Got 0/567 (0.000000)
> timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:52:39,202 - target-dc3 - __main__ - INFO - Got 0/568 (0.000000)
> timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:52:46,994 - target-dc1 - __main__ - INFO - Got 12/20
> (60.000000) timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:53:39,202 - target-dc2 - __main__ - INFO - Got 0/568 (0.000000)
> timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:53:39,238 - target-dc3 - __main__ - INFO - Got 0/568 (0.000000)
> timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:53:48,765 - target-dc1 - __main__ - INFO - Got 12/17
> (70.588235) timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:54:39,203 - target-dc2 - __main__ - INFO - Got 0/568 (0.000000)
> timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:54:39,291 - target-dc3 - __main__ - INFO - Got 0/568 (0.000000)
> timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:54:51,291 - target-dc1 - __main__ - INFO - Got 12/24
> (50.000000) timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:55:39,258 - target-dc2 - __main__ - INFO - Got 0/570 (0.000000)
> timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:55:39,327 - target-dc3 - __main__ - INFO - Got 0/570 (0.000000)
> timeouts/total_rqs in the last 1 minute
> 2022-03-01 15:55:53,365 - target-dc1 - __main__ - INFO - Got 12/20
> (60.000000) timeouts/total_rqs in the last 1 minute
> {noformat}
> as the timeouts/rqs shows, the partitioned node keeps receving traffic until
> the iptables rules are removed
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
