Cassandra 4.0 nodes fails to restart

user_16683241 0
Viewed 627

Nodes fail after restart with the error:

INFO  [Messaging-EventLoop-3-12] 2021-08-17 11:09:07,845 InboundConnectionInitiator.java:464 - /X.X.46.68:7000(/X.X.46.68:56090)->/X.X.X.77:7000-URGENT_MESSAGES-cdaa1ab9 messaging connection established, version = 12, framing = LZ4, encryption = unencrypted
INFO  [Messaging-EventLoop-3-1] 2021-08-17 11:09:07,867 InboundConnectionInitiator.java:464 - /X.X.86.42:7000(/X.X.86.42:52188)->/X.X.X.77:7000-URGENT_MESSAGES-9c2d74c5 messaging connection established, version = 12, framing = CRC, encryption = unencrypted
ERROR [main] 2021-08-17 11:09:08,523 CassandraDaemon.java:909 - Exception encountered during startup
java.lang.RuntimeException: Unable to gossip with any peers
    at org.apache.cassandra.gms.Gossiper.doShadowRound(Gossiper.java:1801)
    at org.apache.cassandra.service.StorageService.checkForEndpointCollision(StorageService.java:648)
    at org.apache.cassandra.service.StorageService.prepareToJoin(StorageService.java:934)
    at org.apache.cassandra.service.StorageService.initServer(StorageService.java:784)
    at org.apache.cassandra.service.StorageService.initServer(StorageService.java:729)
    at org.apache.cassandra.service.CassandraDaemon.setup(CassandraDaemon.java:420)
    at org.apache.cassandra.service.CassandraDaemon.activate(CassandraDaemon.java:763)
    at org.apache.cassandra.service.CassandraDaemon.main(CassandraDaemon.java:887)
INFO  [StorageServiceShutdownHook] 2021-08-17 11:09:08,530 HintsService.java:220 - Paused hints dispatch
WARN  [StorageServiceShutdownHook] 2021-08-17 11:09:08,531 Gossiper.java:1989 - No local state, state is in silent shutdown, or node hasn't joined, not announcing shutdown
INFO  [StorageServiceShutdownHook] 2021-08-17 11:09:08,531 MessagingService.java:441 - Waiting for messaging service to quiesce
INFO  [Messaging-EventLoop-3-7] 2021-08-17 11:09:08,534 OutboundConnection.java:1150 - /X.X.X.77:7000(/X.X.X.77:52766)->/X.X.X.76:7000-SMALL_MESSAGES-27a82ea6 successfully connected, version = 12, framing = CRC, encryption = unencrypted
INFO  [Messaging-EventLoop-3-8] 2021-08-17 11:09:08,534 OutboundConnection.java:1150 - /X.X.X.77:7000(/X.X.X.77:52768)->/X.X.X.76:7000-LARGE_MESSAGES-762ad3e9 successfully connected, version = 12, framing = CRC, encryption = unencrypted
INFO  [Messaging-EventLoop-3-1] 2021-08-17 11:09:08,535 OutboundConnection.java:1150 - /X.X.X.77:7000(/X.X.X.77:35938)->/X.X.X.40:7000-SMALL_MESSAGES-97e069da successfully connected, version = 12, framing = CRC, encryption = unencrypted

Seeds and other nodes show the following in the debug log while the node is starting up:

   ERROR [Messaging-EventLoop-3-2] 2021-08-17 11:09:07,535 OutboundConnection.java:1058 - /X.X.X.116:7000->/X.X.X.77:7000-URGENT_MESSAGES-ef747971 channel in potentially inconsistent state after error; closing
java.lang.IllegalArgumentException: Maximum payload size is 128KiB
    at org.apache.cassandra.net.FrameEncoderCrc.encode(FrameEncoderCrc.java:73)
    at org.apache.cassandra.net.FrameEncoder.write(FrameEncoder.java:134)
    at io.netty.channel.AbstractChannelHandlerContext.invokeWrite0(AbstractChannelHandlerContext.java:717)
    at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:764)
    at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:790)
    at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:758)
    at io.netty.channel.DefaultChannelPipeline.writeAndFlush(DefaultChannelPipeline.java:1020)
    at io.netty.channel.AbstractChannel.writeAndFlush(AbstractChannel.java:299)
    at org.apache.cassandra.net.AsyncChannelPromise.writeAndFlush(AsyncChannelPromise.java:77)
    at org.apache.cassandra.net.OutboundConnection$EventLoopDelivery.doRun(OutboundConnection.java:837)
    at org.apache.cassandra.net.OutboundConnection$Delivery.run(OutboundConnection.java:687)
    at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
    at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.lang.Thread.run(Thread.java:748)
INFO  [Messaging-EventLoop-3-10] 2021-08-17 11:09:08,540 InboundConnectionInitiator.java:464 - /X.X.X.77:7000(/X.X.X.77:36684)->/X.X.X.116:7000-SMALL_MESSAGES-8ab4a5dc messaging connection established, version = 12, framing = CRC, encryption = unencrypted
INFO  [Messaging-EventLoop-3-11] 2021-08-17 11:09:08,540 InboundConnectionInitiator.java:464 - /X.X.X.77:7000(/X.X.X.77:36686)->/X.X.X.116:7000-LARGE_MESSAGES-7f053d49 messaging connection established, version = 12, framing = CRC, encryption = unencrypted
INFO  [Messaging-EventLoop-3-2] 2021-08-17 11:09:15,680 NoSpamLogger.java:92 - /X.X.X.116:7000->/X.X.X.77:7000-URGENT_MESSAGES-[no-channel] failed to connect
io.netty.channel.AbstractChannel$AnnotatedConnectException: finishConnect(..) failed: Connection refused: /X.X.X.77:7000
Caused by: java.net.ConnectException: finishConnect(..) failed: Connection refused
    at io.netty.channel.unix.Errors.throwConnectException(Errors.java:124)
    at io.netty.channel.unix.Socket.finishConnect(Socket.java:251)
    at io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe.doFinishConnect(AbstractEpollChannel.java:673)
    at io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe.finishConnect(AbstractEpollChannel.java:650)
    at io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe.epollOutReady(AbstractEpollChannel.java:530)
    at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:470)
    at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:378)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.lang.Thread.run(Thread.java:748)
INFO  [Messaging-EventLoop-3-2] 2021-08-17 11:09:45,714 NoSpamLogger.java:92 - /X.X.X.116:7000->/X.X.X.77:7000-URGENT_MESSAGES-[no-channel] failed to connect

Started happening after upgrading from 3.10 to 4.0. Not a firewall issue or a bad configuration, as the same configuration was working prior.

cassandra
2 Answers

Neither of those are errors so they're not the cause of your nodes failing to restart.

The first entry for gossip is logged at DEBUG so it's not an issue. The second entry for messaging is logged at INFO level so it's just informational and nothing to be concerned with.

You need to review the system.log and pay attention to the last 1 or 2 ERROR entries because those are relevant for understanding why the nodes failed to restart. Cheers!

[EDIT] This error indicates that there is an issue with contacting the seed nodes:

ERROR [main] 2021-08-17 11:09:08,523 CassandraDaemon.java:909 - Exception encountered during startup
java.lang.RuntimeException: Unable to gossip with any peers
    at org.apache.cassandra.gms.Gossiper.doShadowRound(Gossiper.java:1801)
    at org.apache.cassandra.service.StorageService.checkForEndpointCollision(StorageService.java:648)
    ...

In Cassandra 4.0, nodes are now identified by a combination of their IP + port (CASSANDRA-7544) so make sure that you've configured the seeds list accordingly. For example:

seed_provider:
    - class_name: org.apache.cassandra.locator.SimpleSeedProvider
      parameters:
          - seeds: "10.1.2.3:7000,10.1.2.4:7000,10.1.2.5:7000"

It's very important that at least one of the seed nodes is up and fully operational. For this reason, it is recommended to upgrade the seed nodes first.

Also ensure that there is network connectivity between nodes using Linux utilities such as nc and telnet. Check that traffic between nodes on port 7000 is not being blocked by firewalls (for example iptables or firewalld). If you rebooted the servers, it's quite common for firewalls to be enabled by accident.

[UPDATE] Check that the clocks on the servers are in sync. If there is too much drift, nodes will not be able to gossip. Cheers!

user_42695350

The below error message in the question was due to the size of gossip messages sent when a node (re)starts may exceed the hard limit in large cluster.

 ERROR [Messaging-EventLoop-3-2] 2021-08-17 11:09:07,535 OutboundConnection.java:1058 - /X.X.X.116:7000->/X.X.X.77:7000-URGENT_MESSAGES-ef747971 channel in potentially inconsistent state after error; closing
java.lang.IllegalArgumentException: Maximum payload size is 128KiB

This is a bug since 4.0-alpha1 and was fixed in 4.0.1. Check CASSANDRA-16877.

Also if you see log message like below in one of the seed node, It is due to drift in time clock among node which Erick has mentioned in his updated answer.

INFO  [ScheduledTasks:1] 2021-09-10 11:14:26,567 MessagingMetrics.java:206 - GOSSIP_DIGEST_SYN messages were dropped in last 5000 ms: 0 internal and 1 cross node. Mean internal dropped latency: 0 ms and Mean cross-node dropped latency: 15137813 ms
user_24922420
Related