[ https://issues.apache.org/jira/browse/CASSANDRA-15172?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16900581#comment-16900581 ]
feroz shaik edited comment on CASSANDRA-15172 at 8/6/19 3:37 AM: ----------------------------------------------------------------- We have also hit this problem today while upgrading from 2.1.16 to 3.11.4/ we encountered this as soon as node started up with 3.11.4 WARN [ReadStage-4] 2019-08-06 02:57:57,408 AbstractLocalAwareExecutorService.java:167 - Uncaught exception on thread Thread[ReadStage-4,5,main]: {} java.lang.NullPointerException: null ERROR [Native-Transport-Requests-32] 2019-08-06 02:14:20,353 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null and the below errors continued in the logfile as long as the process was up. ERROR [Native-Transport-Requests-12] 2019-08-06 03:00:47,135 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null ERROR [Native-Transport-Requests-8] 2019-08-06 03:00:48,778 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null ERROR [Native-Transport-Requests-13] 2019-08-06 03:00:57,454 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null ERROR [Native-Transport-Requests-11] 2019-08-06 03:00:57,482 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null ERROR [Native-Transport-Requests-2] 2019-08-06 03:00:58,543 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null ERROR [Native-Transport-Requests-8] 2019-08-06 03:00:58,899 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null ERROR [Native-Transport-Requests-17] 2019-08-06 03:00:59,074 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null ERROR [Native-Transport-Requests-12] 2019-08-06 03:01:08,123 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null ERROR [Native-Transport-Requests-17] 2019-08-06 03:01:19,055 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null ERROR [Native-Transport-Requests-4] 2019-08-06 03:01:20,880 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null WARN [ReadStage-13] 2019-08-06 03:01:29,983 AbstractLocalAwareExecutorService.java:167 - Uncaught exception on thread Thread[ReadStage-13,5,main]: {} java.lang.NullPointerException: null ERROR [Native-Transport-Requests-2] 2019-08-06 03:01:31,119 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null ERROR [Native-Transport-Requests-6] 2019-08-06 03:01:46,262 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null ERROR [Native-Transport-Requests-15] 2019-08-06 03:01:46,520 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null WARN [ReadStage-2] 2019-08-06 03:01:48,842 AbstractLocalAwareExecutorService.java:167 - Uncaught exception on thread Thread[ReadStage-2,5,main]: {} java.lang.NullPointerException: null ERROR [Native-Transport-Requests-1] 2019-08-06 03:01:50,351 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null ERROR [Native-Transport-Requests-5] 2019-08-06 03:02:06,061 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null WARN [ReadStage-8] 2019-08-06 03:02:07,616 AbstractLocalAwareExecutorService.java:167 - Uncaught exception on thread Thread[ReadStage-8,5,main]: {} java.lang.NullPointerException: null ERROR [Native-Transport-Requests-17] 2019-08-06 03:02:08,384 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null ERROR [Native-Transport-Requests-5] 2019-08-06 03:02:10,244 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null The nodetool version says 3.11.4 and the no of connections on 9042 was similar to other nodes. The exceptions were scary that we had to call off the change. Any help and insights to this problem from the community is appreciated. was (Author: ferozshaik...@gmail.com): We have also hit this problem today while upgrading from 2.1.16 to 3.11.4/ we encountered this as soon as node started up with 3.11.4 ERROR [Native-Transport-Requests-32] 2019-08-06 02:14:20,353 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null and the below errors continued in the logfile as long as the process was up. ERROR [Native-Transport-Requests-12] 2019-08-06 03:00:47,135 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null ERROR [Native-Transport-Requests-8] 2019-08-06 03:00:48,778 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null ERROR [Native-Transport-Requests-13] 2019-08-06 03:00:57,454 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null ERROR [Native-Transport-Requests-11] 2019-08-06 03:00:57,482 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null ERROR [Native-Transport-Requests-2] 2019-08-06 03:00:58,543 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null ERROR [Native-Transport-Requests-8] 2019-08-06 03:00:58,899 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null ERROR [Native-Transport-Requests-17] 2019-08-06 03:00:59,074 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null ERROR [Native-Transport-Requests-12] 2019-08-06 03:01:08,123 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null ERROR [Native-Transport-Requests-17] 2019-08-06 03:01:19,055 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null ERROR [Native-Transport-Requests-4] 2019-08-06 03:01:20,880 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null WARN [ReadStage-13] 2019-08-06 03:01:29,983 AbstractLocalAwareExecutorService.java:167 - Uncaught exception on thread Thread[ReadStage-13,5,main]: {} java.lang.NullPointerException: null ERROR [Native-Transport-Requests-2] 2019-08-06 03:01:31,119 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null ERROR [Native-Transport-Requests-6] 2019-08-06 03:01:46,262 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null ERROR [Native-Transport-Requests-15] 2019-08-06 03:01:46,520 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null WARN [ReadStage-2] 2019-08-06 03:01:48,842 AbstractLocalAwareExecutorService.java:167 - Uncaught exception on thread Thread[ReadStage-2,5,main]: {} java.lang.NullPointerException: null ERROR [Native-Transport-Requests-1] 2019-08-06 03:01:50,351 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null ERROR [Native-Transport-Requests-5] 2019-08-06 03:02:06,061 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null WARN [ReadStage-8] 2019-08-06 03:02:07,616 AbstractLocalAwareExecutorService.java:167 - Uncaught exception on thread Thread[ReadStage-8,5,main]: {} java.lang.NullPointerException: null ERROR [Native-Transport-Requests-17] 2019-08-06 03:02:08,384 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null ERROR [Native-Transport-Requests-5] 2019-08-06 03:02:10,244 ErrorMessage.java:384 - Unexpected exception during request java.lang.NullPointerException: null The nodetool version says 3.11.4 and the no of connections on 9042 was similar to other nodes. The exceptions were scary that we had to call off the change. Any help and insights to this problem from the community is appreciated. > AbstractLocalAwareExecutorService Exception During Upgrade to 3.11.4 > -------------------------------------------------------------------- > > Key: CASSANDRA-15172 > URL: https://issues.apache.org/jira/browse/CASSANDRA-15172 > Project: Cassandra > Issue Type: Bug > Reporter: Shalom > Priority: Normal > > Hi All, > This is the first time I open an issue, so apologies if I'm not following the > rules properly. > > After upgrading a node from version 2.1.21 to 3.11.4, we've started seeing a > lot of AbstractLocalAwareExecutorService exceptions. This happened right > after the node successfully started up with the new 3.11.4 binaries. > INFO [main] 2019-06-05 04:41:37,730 Gossiper.java:1715 - No gossip backlog; > proceeding > INFO [main] 2019-06-05 04:41:38,036 NativeTransportService.java:70 - Netty > using native Epoll event loop > INFO [main] 2019-06-05 04:41:38,117 Server.java:155 - Using Netty Version: > [netty-buffer=netty-buffer-4.0.44.Final.452812a, > netty-codec=netty-codec-4.0.44.Final.452812a, > netty-codec-haproxy=netty-codec-haproxy-4.0.44.Final.452812a, > netty-codec-http=netty-codec-http-4.0.44.Final.452812a, > netty-codec-socks=netty-codec-socks-4.0.44.Final.452812a, > netty-common=netty-common-4.0.44.Final.452812a, > netty-handler=netty-handler-4.0.44.Final.452812a, > netty-tcnative=netty-tcnative-1.1.33.Fork26.142ecbb, > netty-transport=netty-transport-4.0.44.Final.452812a, > netty-transport-native-epoll=netty-transport-native-epoll-4.0.44.Final.452812a, > netty-transport-rxtx=netty-transport-rxtx-4.0.44.Final.452812a, > netty-transport-sctp=netty-transport-sctp-4.0.44.Final.452812a, > netty-transport-udt=netty-transport-udt-4.0.44.Final.452812a] > INFO [main] 2019-06-05 04:41:38,118 Server.java:156 - Starting listening for > CQL clients on /0.0.0.0:9042 (unencrypted)... > INFO [main] 2019-06-05 04:41:38,179 CassandraDaemon.java:556 - Not starting > RPC server as requested. Use JMX (StorageService->startRPCServer()) or > nodetool (enablethrift) to start it > INFO [Native-Transport-Requests-21] 2019-06-05 04:41:39,145 > AuthCache.java:161 - (Re)initializing PermissionsCache (validity > period/update interval/max entries) (2000/2000/1000) > INFO [OptionalTasks:1] 2019-06-05 04:41:39,729 CassandraAuthorizer.java:409 > - Converting legacy permissions data > INFO [HANDSHAKE-/10.10.10.8] 2019-06-05 04:41:39,808 > OutboundTcpConnection.java:561 - Handshaking version with /10.10.10.8 > INFO [HANDSHAKE-/10.10.10.9] 2019-06-05 04:41:39,808 > OutboundTcpConnection.java:561 - Handshaking version with /10.10.10.9 > INFO [HANDSHAKE-dc1_02/10.10.10.6] 2019-06-05 04:41:39,809 > OutboundTcpConnection.java:561 - Handshaking version with dc1_02/10.10.10.6 > WARN [ReadStage-2] 2019-06-05 04:41:39,857 > AbstractLocalAwareExecutorService.java:167 - Uncaught exception on thread > Thread[ReadStage-2,5,main]: {} > java.lang.ArrayIndexOutOfBoundsException: 1 > at > org.apache.cassandra.db.AbstractBufferClusteringPrefix.get(AbstractBufferClusteringPrefix.java:55) > at > org.apache.cassandra.db.LegacyLayout$LegacyRangeTombstoneList.serializedSizeCompound(LegacyLayout.java:2545) > at > org.apache.cassandra.db.LegacyLayout$LegacyRangeTombstoneList.serializedSize(LegacyLayout.java:2522) > at > org.apache.cassandra.db.LegacyLayout.serializedSizeAsLegacyPartition(LegacyLayout.java:565) > at > org.apache.cassandra.db.ReadResponse$Serializer.serializedSize(ReadResponse.java:446) > at > org.apache.cassandra.db.ReadResponse$Serializer.serializedSize(ReadResponse.java:352) > at > org.apache.cassandra.net.MessageOut.payloadSize(MessageOut.java:171) > at > org.apache.cassandra.net.OutboundTcpConnectionPool.getConnection(OutboundTcpConnectionPool.java:77) > at > org.apache.cassandra.net.MessagingService.getConnection(MessagingService.java:802) > at > org.apache.cassandra.net.MessagingService.sendOneWay(MessagingService.java:953) > at > org.apache.cassandra.net.MessagingService.sendReply(MessagingService.java:929) > at > org.apache.cassandra.db.ReadCommandVerbHandler.doVerb(ReadCommandVerbHandler.java:62) > at > org.apache.cassandra.net.MessageDeliveryTask.run(MessageDeliveryTask.java:66) > at > java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) > at > org.apache.cassandra.concurrent.AbstractLocalAwareExecutorService$FutureTask.run(AbstractLocalAwareExecutorService.java:162) > at > org.apache.cassandra.concurrent.AbstractLocalAwareExecutorService$LocalSessionFutureTask.run(AbstractLocalAwareExecutorService.java:134) > at org.apache.cassandra.concurrent.SEPWorker.run(SEPWorker.java:114) > at java.lang.Thread.run(Thread.java:745) > > > After several of the above warnings, the following warning appeared as well: > WARN [ReadStage-9] 2019-06-05 04:42:04,369 > AbstractLocalAwareExecutorService.java:167 - Uncaught exception on thread > Thread[ReadStage-9,5,main]: {} > java.lang.ArrayIndexOutOfBoundsException: null > WARN [ReadStage-11] 2019-06-05 04:42:04,381 > AbstractLocalAwareExecutorService.java:167 - Uncaught exception on thread > Thread[ReadStage-11,5,main]: {} > java.lang.ArrayIndexOutOfBoundsException: null > WARN [ReadStage-10] 2019-06-05 04:42:04,396 > AbstractLocalAwareExecutorService.java:167 - Uncaught exception on thread > Thread[ReadStage-10,5,main]: {} > java.lang.ArrayIndexOutOfBoundsException: null > WARN [ReadStage-2] 2019-06-05 04:42:04,443 > AbstractLocalAwareExecutorService.java:167 - Uncaught exception on thread > Thread[ReadStage-2,5,main]: {} > java.lang.ArrayIndexOutOfBoundsException: null > > Then suddenly, Validation errors appeared although *no repair was running on > any of the nodes*! Checked with ps -ef command and nodetool compactionstats > on the entire cluster. > > ERROR [ValidationExecutor:2] 2019-06-05 04:42:47,979 Validator.java:268 - > Failed creating a merkle tree for [repair > #e54b4090-876d-11e9-a3f4-c33d22c45471 on ks1/table1, []], / > 10.10.10.6 (see log for details) > ERROR [ValidationExecutor:2] 2019-06-05 04:42:47,979 CassandraDaemon.java:228 > - Exception in thread Thread[ValidationExecutor:2,1,main] > java.lang.NullPointerException: null > at > org.apache.cassandra.db.compaction.CompactionManager.doValidationCompaction(CompactionManager.java:1363) > at > org.apache.cassandra.db.compaction.CompactionManager.access$600(CompactionManager.java:83) > at > org.apache.cassandra.db.compaction.CompactionManager$13.call(CompactionManager.java:977) > at java.util.concurrent.FutureTask.run(FutureTask.java:266) > at > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) > at > org.apache.cassandra.concurrent.NamedThreadFactory.lambda$threadLocalDeallocator$0(NamedThreadFactory.java:81) > at java.lang.Thread.run(Thread.java:745) > > Following those, client requests started to fail and NTR tasks started to > pile up and get blocked and GC was impacted. > INFO [ScheduledTasks:1] 2019-06-05 04:43:11,660 StatusLogger.java:51 - > Native-Transport-Requests 128 197 594810 65 > 2725 > > FWIW, these are the warnings I found during startup: > -WARN in net.logstash.logback.encoder.LogstashEncoder@140e5a13 - Logback > version is prior to 1.2.0. Enabling backwards compatible encoding. Logback > 1.2.1 or greater is recommended. > > WARN [main] 2019-06-05 08:44:18,568 NativeLibrary.java:187 - Unable to lock > JVM memory (ENOMEM). This can result in part of the JVM being swapped out, > especially with mmapped I/O enabled. Increase RLIMIT_MEMLOCK or run Cassandra > as root. > WARN [main] 2019-06-05 08:44:18,569 StartupChecks.java:136 - jemalloc shared > library could not be preloaded to speed up memory allocations > > WARN [main] 2019-06-05 08:44:20,225 Optional.java:159 - Legacy auth tables > credentials, users, permissions in keyspace system_auth still exist and have > not been properly migrated. > WARN [MessagingService-Outgoing-dc1_03/10.10.10.4-Gossip] 2019-06-05 > 08:44:49,582 OutboundTcpConnection.java:486 - Seed gossip version is 8; will > not connect with that version > WARN [MessagingService-Outgoing-dc2_02/10.20.20.4-Gossip] 2019-06-05 > 08:44:49,620 OutboundTcpConnection.java:486 - Seed gossip version is 8; will > not connect with that version > WARN [MessagingService-Outgoing-dc2_01/10.20.20.1-Gossip] 2019-06-05 > 08:44:49,621 OutboundTcpConnection.java:486 - Seed gossip version is 8; will > not connect with that version > WARN [MessagingService-Outgoing-dc2_03/10.20.20.5-Gossip] 2019-06-05 > 08:44:49,621 OutboundTcpConnection.java:486 - Seed gossip version is 8; will > not connect with that version > WARN [GossipTasks:1] 2019-06-05 08:44:51,631 FailureDetector.java:278 - Not > marking nodes down due to local pause of 30943606906 > 5000000000 > > We've naturally stopped the upgrade but we still wish to upgrade from 2.1.21 > and hopefully find the root cause of this matter. > I'll be happy to provide additional details if needs be. > > -- This message was sent by Atlassian JIRA (v7.6.14#76016) --------------------------------------------------------------------- To unsubscribe, e-mail: commits-unsubscr...@cassandra.apache.org For additional commands, e-mail: commits-h...@cassandra.apache.org