Andres de la Peña created CASSANDRA-16752:
---------------------------------------------
Summary: Python dtest queries executed after restarting a node
might fail
Key: CASSANDRA-16752
URL: https://issues.apache.org/jira/browse/CASSANDRA-16752
Project: Cassandra
Issue Type: Bug
Components: Test/dtest/python
Reporter: Andres de la Peña
We have multiple dtest failures in queries with CL=ALL that are executed right
after restarting a node:
*
[test_14330|https://ci-cassandra.apache.org/job/Cassandra-4.0.0/26/testReport/dtest.consistency_test/TestConsistency/test_14330/]
*
[test_multiple_repair|https://ci-cassandra.apache.org/job/Cassandra-4.0.0/29/testReport/dtest.repair_tests.incremental_repair_test/TestIncRepair/test_multiple_repair/]
*
[test_multiple_repair(offheap)|https://ci-cassandra.apache.org/job/Cassandra-4.0.0/26/testReport/dtest-offheap.repair_tests.incremental_repair_test/TestIncRepair/test_multiple_repair/]
The error is a server-side failure telling that there aren't enough replicas
alive to achieve the required consistency level:
{code:java}
tools/assertions.py:182: in assert_all
res = session.execute(simple_query) if timeout is None else
session.execute(simple_query, timeout=timeout)
../venv/src/cassandra-driver/cassandra/cluster.py:2618: in execute
return self.execute_async(query, parameters, trace, custom_payload,
timeout, execution_profile, paging_state, host, execute_as).result()
...
E cassandra.Unavailable: Error from server: code=1000 [Unavailable
exception] message="Cannot achieve consistency level ALL" info={'consistency':
'ALL', 'required_replicas': 2, 'alive_replicas': 1}
{code}
The Jenkins failure in {{test_14330}} can be reproduced in the multiplexer,
although it requires many iterations:
*
[https://app.circleci.com/pipelines/github/adelapena/cassandra/600/workflows/2f1b7455-1217-4553-985a-a255fe98ba47/jobs/5784]
*
[https://app.circleci.com/pipelines/github/adelapena/cassandra/600/workflows/2f1b7455-1217-4553-985a-a255fe98ba47/jobs/5786]
As a hint, this same test [survives the
multiplexer|https://app.circleci.com/pipelines/github/adelapena/cassandra/605/workflows/aba5e7a6-c988-40d9-ab56-7848e711b5e1]
if we add [a short
sleep|https://github.com/adelapena/cassandra-dtest/commit/28ca11bf31db4c836e9c34500d18cbb9316e3cca]
right after restarting the node.
I think that the reason for the failure is that CCM is no properly waiting for
the propagation of the node status. So, the session uses a not-restarted nodes
to run the query with CL=ALL before that node actually sees the restarted node.
The parameter {{wait_other_notice}} in {{node.start}} should guarantee that
this doesn't happen, but I suspect that it isn't working as expected. When
using the {{wait_other_notice}} option on node start, the
[{{node.watch_log_for_alive}}|https://github.com/riptano/ccm/blob/358c06781c4a8b85dcfca49449232b7405dacc0c/ccmlib/node.py#L657-L664]
function looks for the regexp {{%s.* now UP}} in the logs of the other nodes,
to ensure that they consider that node as up. However, that expression is
matched by two different log entries emitted on log restart:
{code:java}
Node /127.0.0.2:7000 has restarted, now UP
...
Node /127.0.0.2:7000 is now UP
{code}
The first message is emitted by
[{{Gossiper.handleMajorStateChange}}|https://github.com/apache/cassandra/blob/cassandra-4.0.0/src/java/org/apache/cassandra/gms/Gossiper.java#L1313],
while the second message is emitted by
[{{Gossiper.realMarkAlive}}|https://github.com/apache/cassandra/blob/cassandra-4.0.0/src/java/org/apache/cassandra/gms/Gossiper.java#L1263].
I think that we need to wait for the second one, while CCM is waiting only for
the first one.
Indeed, we can easily reproduce the failure in any of the affected dtests by
adding a sleep at the beginning of {{Gossiper.realMarkAlive}}. We can get
around the failure if we manually modify the test to wait for the right log
message, as it's done
[here|https://github.com/adelapena/cassandra-dtest/commit/7355be7dd94c91c44b78bd2ccfa1c731a00d6a63].
With that wait the test [survives the multiplexer
rounds|https://app.circleci.com/pipelines/github/adelapena/cassandra/605/workflows/6ec189fc-4701-4a27-a7af-382a6c53dd0d].
This problem seems quite unlikely to happen since the time window is very
short, but we have seen it in CI and it affects multiple Python dtests.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
