Yes, RF=6 for system auth. Sorry my bad.
No, we are not using cassandra user for the application. We have
a custom super user for our operational and administrative tasks
and a separate role with needed perms for the application.
role | super | login | options
------------------------+-------+-------+---------
EviveCassandra | True | True | {}
ccusr | False | True | {}
* gc_warn_threshold_in_ms: 1000
* read_request_timeout_in_ms: 15000 // been the same since the
start
* cross_node_timeout: false // but we have ntp on
each server and the clocks are synced.
* On checking the logs a little more I found out these:
INFO [ScheduledTasks:1] 2021-07-26 07:21:33,279
MessagingService.java:1013 - READ messages were dropped
in last 5000 ms: 289 for internal timeout and 0 for cross
node timeout
INFO [ScheduledTasks:1] 2021-07-26 07:22:33,894
MessagingService.java:1013 - READ messages were dropped
in last 5000 ms: 273 for internal timeout and 0 for cross
node timeout
INFO [ScheduledTasks:1] 2021-07-27 06:12:03,988
MessagingService.java:1013 - READ messages were dropped
in last 5000 ms: 160 for internal timeout and 0 for cross
node timeout
INFO [ScheduledTasks:1] 2021-07-27 06:13:09,125
MessagingService.java:1013 - READ messages were dropped
in last 5000 ms: 223 for internal timeout and 0 for cross
node timeout
INFO [ScheduledTasks:1] 2021-07-27 06:13:44,212
MessagingService.java:1013 - READ messages were dropped
in last 5000 ms: 72 for internal timeout and 0 for cross
node timeout
INFO [ScheduledTasks:1] 2021-07-27 06:14:14,496
MessagingService.java:1013 - READ messages were dropped
in last 5000 ms: 16036 for internal timeout and 0 for
cross node timeout
INFO [ScheduledTasks:1] 2021-07-27 06:15:59,744
MessagingService.java:1013 - READ messages were dropped
in last 5000 ms: 287 for internal timeout and 0 for cross
node timeout
* Also, I am checking cfstats and proxyhistorgrams is in
progress, will update incase anythings suspicious.
On Tue, 27 Jul 2021 at 18:09, Bowen Song <bo...@bso.ng>
<mailto:bo...@bso.ng> wrote:
Hello Chahat,
You haven't replied to the first point, are you using the
"cassandra" user?
The schema and your description don't quite match. When you said:
/the system_auth for 2 DCs : //*us-east*//with 6 nodes
(and RF=3) and ...
/
I assume you meant to say 6 nodes and RF=6? That sounds
totally fine.
As of the GC logs, do you see any WARN level logs? You may
also want to double check the choice of the
gc_warn_threshold_in_ms value is reasonable. I'm a bit
surprised to see the GC logs full of ~1.6ms GC pauses. AFAIK,
by default Cassandra only logs GC pauses longer than 200ms. I
have to assume that's the result of your custom script. You
may want to double check the script actually does what it
says on the tin, just in case it misses something.
Then, the other relevant questions.
Do you use cross node timeout? If so, are the clocks in sync
between all servers?
What is the timeout values in the cassandra.yaml file?
(read_request_timeout_in_ms, etc.) Are they reasonably long
enough for the corresponding request type to complete?
Since you've only got 7 nodes, I'd also recommend you to
check the nodetool cfstats & nodetool cfhistograms output for
the tables in the system_auth keyspace on each node, and see
if you can spot anything out of ordinary.
Regards,
Bowen
On 27/07/2021 09:23, Chahat Bhatia wrote:
Thanks for the prompt response.
*
Here is the system_schema.keyspaces entry:*
system_auth | True | {'class':
'org.apache.cassandra.locator.NetworkTopologyStrategy',
'us-east': '6', 'us-east-backup': '1'}
census | True |
{'class':
'org.apache.cassandra.locator.NetworkTopologyStrategy',
'us-east': '3', 'us-east-backup': '1'}
So, the system_auth for 2 DCs : /*us-east* with 6 nodes
(and RF=3) and *us-east-backup* with a single node and 100%
of the data./
*Keyspace census* showing RF=3 for the main DC and RF=1 for
the backup site.
And for running the application, we have a user
specifically created for that application itself and
that user also has its appropriate permissions in
cassandra to select, modify and delete from concerned
tables. And it uses LOCAL_QUORUM for querying the data
and the local-dc is set to 'us-east'.
Also, there is no excessive GC for any of the nodes, we run
a custom script to trackthe GC stats (from the cassandra log
itself) and output it. Below is the output from the current
running script and its similar for all the servers:
2021-07-27 03:04:45,072 INFO gcstats:58 -
Application Thread stop time 0.001656 seconds.
2021-07-27 03:04:45,080 INFO gcstats:58 -
Application Thread stop time 0.001669 seconds.
2021-07-27 03:04:45,087 INFO gcstats:58 -
Application Thread stop time 0.001601 seconds.
2021-07-27 03:04:45,095 INFO gcstats:58 -
Application Thread stop time 0.001713 seconds.
2021-07-27 03:04:45,103 INFO gcstats:58 -
Application Thread stop time 0.001586 seconds.
2021-07-27 03:04:45,110 INFO gcstats:58 -
Application Thread stop time 0.001671 seconds.
2021-07-27 03:04:45,118 INFO gcstats:58 -
Application Thread stop time 0.001691 seconds.
2021-07-27 03:04:45,127 INFO gcstats:58 -
Application Thread stop time 0.001860 seconds.
2021-07-27 03:04:45,134 INFO gcstats:58 -
Application Thread stop time 0.001630 seconds.
2021-07-27 03:04:45,141 INFO gcstats:58 -
Application Thread stop time 0.001515 seconds.
2021-07-27 03:04:45,148 INFO gcstats:58 -
Application Thread stop time 0.001533 seconds.
2021-07-27 03:04:45,156 INFO gcstats:58 -
Application Thread stop time 0.001630 seconds.
2021-07-27 03:04:45,163 INFO gcstats:58 -
Application Thread stop time 0.001577 seconds.
2021-07-27 03:04:45,170 INFO gcstats:58 -
Application Thread stop time 0.001538 seconds.
2021-07-27 03:04:45,177 INFO gcstats:58 -
Application Thread stop time 0.001615 seconds.
2021-07-27 03:04:45,186 INFO gcstats:58 -
Application Thread stop time 0.001584 seconds.
2021-07-27 03:04:45,193 INFO gcstats:58 -
Application Thread stop time 0.001558 seconds.
2021-07-27 03:04:45,200 INFO gcstats:58 -
Application Thread stop time 0.001696 seconds.
2021-07-27 03:04:45,208 INFO gcstats:58 -
Application Thread stop time 0.001658 seconds.
2021-07-27 03:04:45,215 INFO gcstats:58 -
Application Thread stop time 0.001592 seconds.
2021-07-27 03:04:45,222 INFO gcstats:58 -
Application Thread stop time 0.001618 seconds.
2021-07-27 03:05:08,907 INFO gcstats:58 -
Application Thread stop time 0.001624 seconds.
2021-07-27 03:06:34,436 INFO gcstats:58 -
Application Thread stop time 0.297773 seconds.
On Tue, 27 Jul 2021 at 13:23, 'Bowen Song' via Infra Updates
<infra-upda...@goevive.com
<mailto:infra-upda...@goevive.com>> wrote:
Hello Chahat,
First, can you please make sure the Cassandra user used
by the application is not "cassandra"? Because the
"cassandra" user uses QUORUM consistency level to read
the auth tables.
Then, can you please make sure the replication strategy
is set correctly for the system_auth namespace? I.e.:
ensure the old DC is not present, and the new DC has
sufficient number of replicas for fault tolerance.
Finally, can you please check the GC logs, and make sure
there isn't JVM GC issues, espicially long STW pauses?
Regards,
Bowen
On 27/07/2021 08:34, Chahat Bhatia wrote:
Hi Community,
Context: We are running a cluster of 6 nodes in
production with a RF=3 in AWS.
We recently moved from physical servers to cloud by
adding a new DC and then removing the old one.
Everything is working fine in all the other
applications except this one.
*As we recently started experiencing read timeouts in
one of our production applications where the client threw
*
Error An unexpected error occurred server side
onip-IP.ec2.internal:com.google.common.util.concurrent.*UncheckedExecutionException*:*com.google.common.util.concurrent.UncheckedExecutionException:**java.lang.RuntimeException:org.apache.cassandra.exceptions.ReadTimeoutException:Operation
timed out-received
only0responses.*com.datastax.driver.core.exceptions.ServerError:An
unexpected error occurred server side
:com.google.common.util.concurrent.UncheckedExecutionException:com.google.common.util.concurrent.UncheckedExecutionException:java.lang.RuntimeException:org.apache.cassandra.exceptions.ReadTimeoutException:Operation
timed out-received only0responses.
at
com.datastax.driver.core.exceptions.ServerError.copy(ServerError.java:63)~[cassandra-driver-core-3.3.0-shaded.jar!/:?]at
com.datastax.driver.core.exceptions.ServerError.copy(ServerError.java:25)~[cassandra-driver-core-3.3.0-shaded.jar!/:?]at
com.datastax.driver.core.DriverThrowables.propagateCause(DriverThrowables.java:37)~[cassandra-driver-core-3.3.0-shaded.jar!/:?]at
com.datastax.driver.core.DefaultResultSetFuture.getUninterruptibly(DefaultResultSetFuture.java:245)~[cassandra-driver-core-3.3.0-shaded.jar!/:?]at
com.datastax.driver.core.AbstractSession.execute(AbstractSession.java:68)~[cassandra-driver-core-3.3.0-shaded.jar!/:?
]
............ cntd
com.datastax.driver.core.exceptions.ReadTimeoutException:
Cassandra timeout during read query at
consistency LOCAL_QUORUM (2 responses were
required but only 1 replica responded)
*And around the same time these were the errors on the
server side (from cassandra logs):
*
*ERROR [RolesCacheRefresh:1] 2021-07-26
06:32:43,094 CassandraDaemon.java:207 -
Exception in thread
Thread[RolesCacheRefresh:1,5,main]
java.lang.RuntimeException:
org.apache.cassandra.exceptions.ReadTimeoutException:
Operation timed out - received only 0 responses.
* at
org.apache.cassandra.auth.CassandraRoleManager.getRole(CassandraRoleManager.java:512)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.auth.CassandraRoleManager.getRoles(CassandraRoleManager.java:280)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.auth.RolesCache$1$1.call(RolesCache.java:135)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.auth.RolesCache$1$1.call(RolesCache.java:130)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
java.util.concurrent.FutureTask.run(FutureTask.java:266)
~[na:1.8.0_131]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
~[na:1.8.0_131]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[na:1.8.0_131]
at
org.apache.cassandra.concurrent.NamedThreadFactory.lambda$threadLocalDeallocator$0(NamedThreadFactory.java:79)
[apache-cassandra-3.0.13.jar:3.0.13]
at
java.lang.Thread.run(Thread.java:748)
~[na:1.8.0_131]
Caused by:
org.apache.cassandra.exceptions.ReadTimeoutException:
Operation timed out - received only 0 responses.
at
org.apache.cassandra.service.ReadCallback.awaitResults(ReadCallback.java:132)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.service.ReadCallback.get(ReadCallback.java:137)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.service.AbstractReadExecutor.get(AbstractReadExecutor.java:145)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.service.StorageProxy$SinglePartitionReadLifecycle.awaitResultsAndRetryOnDigestMismatch(StorageProxy.java:1715)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.service.StorageProxy.fetchRows(StorageProxy.java:1664)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.service.StorageProxy.readRegular(StorageProxy.java:1605)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.service.StorageProxy.read(StorageProxy.java:1524)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.db.SinglePartitionReadCommand$Group.execute(SinglePartitionReadCommand.java:955)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.cql3.statements.SelectStatement.execute(SelectStatement.java:263)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.cql3.statements.SelectStatement.execute(SelectStatement.java:224)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.auth.CassandraRoleManager.getRoleFromTable(CassandraRoleManager.java:520)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.auth.CassandraRoleManager.getRole(CassandraRoleManager.java:502)
~[apache-cassandra-3.0.13.jar:3.0.13]
*ERROR [PermissionsCacheRefresh:1] 2021-07-26
07:11:25,804 CassandraDaemon.java:207 -
Exception in thread
Thread[PermissionsCacheRefresh:1,5,main]
java.lang.RuntimeException:
org.apache.cassandra.exceptions.ReadTimeoutException:
Operation timed out - received only 0 responses.
* at
org.apache.cassandra.auth.CassandraRoleManager.getRole(CassandraRoleManager.java:512)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.auth.CassandraRoleManager.isSuper(CassandraRoleManager.java:304)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.auth.Roles.hasSuperuserStatus(Roles.java:52)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.auth.AuthenticatedUser.isSuper(AuthenticatedUser.java:71)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.auth.CassandraAuthorizer.authorize(CassandraAuthorizer.java:76)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.auth.PermissionsCache$1$1.call(PermissionsCache.java:136)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.auth.PermissionsCache$1$1.call(PermissionsCache.java:131)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
java.util.concurrent.FutureTask.run(FutureTask.java:266)
~[na:1.8.0_131]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
~[na:1.8.0_131]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[na:1.8.0_131]
at
org.apache.cassandra.concurrent.NamedThreadFactory.lambda$threadLocalDeallocator$0(NamedThreadFactory.java:79)
[apache-cassandra-3.0.13.jar:3.0.13]
at
java.lang.Thread.run(Thread.java:748)
~[na:1.8.0_131]
Caused by:
org.apache.cassandra.exceptions.ReadTimeoutException:
Operation timed out - received only 0 responses.
at
org.apache.cassandra.service.ReadCallback.awaitResults(ReadCallback.java:132)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.service.ReadCallback.get(ReadCallback.java:137)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.service.AbstractReadExecutor.get(AbstractReadExecutor.java:145)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.service.StorageProxy$SinglePartitionReadLifecycle.awaitResultsAndRetryOnDigestMismatch(StorageProxy.java:1715)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.service.StorageProxy.fetchRows(StorageProxy.java:1664)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.service.StorageProxy.readRegular(StorageProxy.java:1605)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.service.StorageProxy.read(StorageProxy.java:1524)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.db.SinglePartitionReadCommand$Group.execute(SinglePartitionReadCommand.java:955)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.cql3.statements.SelectStatement.execute(SelectStatement.java:263)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.cql3.statements.SelectStatement.execute(SelectStatement.java:224)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.auth.CassandraRoleManager.getRoleFromTable(CassandraRoleManager.java:520)
~[apache-cassandra-3.0.13.jar:3.0.13]
at
org.apache.cassandra.auth.CassandraRoleManager.getRole(CassandraRoleManager.java:502)
~[apache-cassandra-3.0.13.jar:3.0.13]
*These are the values of these params in my
configuration file
*
permissions_validity_in_ms: 300000
permissions_update_interval_in_ms: 20000
roles_validity_in_ms: 300000
roles_update_interval_in_ms: 20000
This was not the case earlier and since this comes from
a single app alone we are not sure if this is actually
the issue. Can anyone please point out if these values
are misconfigured and hence causing the issue or is it
somewhere else we should be looking at?
Any help would be appreciated.
Thanks & Regards,
Chahat.
--
Thanks & Regards,
Chahat Bhatia
Systems Engineer
*Evive*
+91 7087629779
--
Thanks & Regards,
Chahat Bhatia
Systems Engineer
*Evive*
+91 7087629779
