[CASSANDRA-17211] java.lang.IllegalStateException while streaming

• Type: Bug
• Status: Open
• Priority: Normal
• Resolution: Unresolved
• Component/s: Tool/sstable
• Bug Category: Correctness
• Severity: Low
• Complexity: Normal
• Discovered By: User Report
• Platform: All
• Assignee: Unassigned
• Reporter: NISHANT GUPTA
• Created: 15/Dec/21 14:04
• Updated: 20/Dec/21 18:40

Description

Getting following exception with latest cassandra 4.0.1 (https://www.apache.org/dyn/closer.lua/cassandra/4.0.1/apache-cassandra-4.0.1-bin.tar.gz).

DEBUG [Stream-Deserializer-/10.14.20.147:7010-bceedc49] 2021-12-15 18:33:45,143 StreamingInboundHandler.java:179 - [Stream channel: bceedc49] Received keep-alive
INFO  [Stream-Deserializer-/10.14.20.147:7010-bceedc49] 2021-12-15 18:33:45,543 StreamResultFuture.java:114 - Stream #6e073350-5da7-11ec-a3ee-6dd9f5cb6e88 ID#0 Creating new streaming plan for Bulk Load from /10.14.20.147:7010 channel.remote /10.14.20.147:36064 channel.local /10.14.20.148:7010 channel.id bceedc49
DEBUG [Stream-Deserializer-/10.14.20.147:7010-bceedc49] 2021-12-15 18:33:45,544 StreamSession.java:242 - Creating stream session to peer: (/10.14.20.147:7010, null), framing: null, encryption: unencrypted as follower
INFO  [Stream-Deserializer-/10.14.20.147:7010-bceedc49] 2021-12-15 18:33:45,544 StreamResultFuture.java:123 - Stream #6e073350-5da7-11ec-a3ee-6dd9f5cb6e88, ID#0 Received streaming plan for Bulk Load from /10.14.20.147:7010 channel.remote /10.14.20.147:36064 channel.local /10.14.20.148:7010 channel.id bceedc49
DEBUG [Stream-Deserializer-/10.14.20.147:7010-bceedc49] 2021-12-15 18:33:45,544 NettyStreamingMessageSender.java:189 - [Stream #6e073350-5da7-11ec-a3ee-6dd9f5cb6e88 channel: bceedc49] Scheduling keep-alive task with 300s period.
DEBUG [Stream-Deserializer-/10.14.20.147:7010-bceedc49] 2021-12-15 18:33:45,545 StreamingInboundHandler.java:187 - [Stream #6e073350-5da7-11ec-a3ee-6dd9f5cb6e88 channel: bceedc49] Received StreamInitMessage: from = /10.14.20.147:7010, planId = 6e073350-5da7-11ec-a3ee-6dd9f5cb6e88, session index = 0
DEBUG [Stream-Deserializer-/10.14.20.147:7010-bceedc49] 2021-12-15 18:33:45,545 StreamingInboundHandler.java:187 - [Stream #6e073350-5da7-11ec-a3ee-6dd9f5cb6e88 channel: bceedc49] Received Prepare SYN (0 requests,  1 files}
DEBUG [Messaging-EventLoop-3-1] 2021-12-15 18:33:45,545 NettyStreamingMessageSender.java:258 - [Stream #6e073350-5da7-11ec-a3ee-6dd9f5cb6e88 channel: bceedc49] Sending keep-alive
DEBUG [NonPeriodicTasks:1] 2021-12-15 18:33:45,545 NettyStreamingMessageSender.java:258 - [Stream #6e073350-5da7-11ec-a3ee-6dd9f5cb6e88 channel: bceedc49] Sending Prepare SYNACK ( 0 files}
INFO  [NonPeriodicTasks:1] 2021-12-15 18:33:45,545 StreamResultFuture.java:178 - Stream #6e073350-5da7-11ec-a3ee-6dd9f5cb6e88 ID#0 Prepare completed. Receiving 1 files(0.000KiB), sending 0 files(0.000KiB)
INFO  [Messaging-EventLoop-3-2] 2021-12-15 18:33:45,982 InboundConnectionInitiator.java:400 - /10.14.20.147:7010(/10.14.20.147:36068)->/10.14.20.148:7010-STREAMING-553b69ef streaming connection established, version = 12, framing = UNPROTECTED, encryption = unencrypted
DEBUG [Stream-Deserializer-/10.14.20.147:7010-553b69ef] 2021-12-15 18:33:46,383 CassandraIncomingFile.java:70 - Incoming stream entireSSTable=false components=null
DEBUG [Stream-Deserializer-/10.14.20.147:7010-553b69ef] 2021-12-15 18:33:46,383 CassandraCompressedStreamReader.java:73 - Stream #6e073350-5da7-11ec-a3ee-6dd9f5cb6e88 Start receiving file #0 from /10.14.20.147:7010, repairedAt = 0, size = 0, ks = 'nishant_restore_cassandra4', pendingRepair = 'null', table = 'employee'.
DEBUG [Stream-Deserializer-/10.14.20.147:7010-553b69ef] 2021-12-15 18:33:46,384 StreamingInboundHandler.java:187 - [Stream #6e073350-5da7-11ec-a3ee-6dd9f5cb6e88 channel: 553b69ef] Received IncomingStreamMessage{header=Header (tableId: fd5f2c70-5da6-11ec-99bb-fd2b97c714b3, #0, repairedAt: 0, pendingRepair: null, sendByFollower: false), stream=CassandraIncomingFile{sstable=nishant_restore_cassandra4/employee}}
ERROR [Stream-Deserializer-/10.14.20.147:7010-553b69ef] 2021-12-15 18:33:46,384 StreamSession.java:674 - Stream #6e073350-5da7-11ec-a3ee-6dd9f5cb6e88 Streaming error occurred on session with peer 10.14.20.147:7010
java.lang.IllegalStateException: Stream hasn't been read yet
        at com.google.common.base.Preconditions.checkState(Preconditions.java:507)
        at org.apache.cassandra.db.streaming.CassandraIncomingFile.getSize(CassandraIncomingFile.java:96)
        at org.apache.cassandra.streaming.StreamSession.receive(StreamSession.java:787)
        at org.apache.cassandra.streaming.StreamSession.messageReceived(StreamSession.java:588)
        at org.apache.cassandra.streaming.async.StreamingInboundHandler$StreamDeserializingTask.run(StreamingInboundHandler.java:189)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.lang.Thread.run(Thread.java:748)
DEBUG [Stream-Deserializer-/10.14.20.147:7010-553b69ef] 2021-12-15 18:33:46,384 NettyStreamingMessageSender.java:258 - [Stream #6e073350-5da7-11ec-a3ee-6dd9f5cb6e88 channel: bceedc49] Sending Session Failed

This looks to be related to CASSANDRA-16349. Some of the stream's size is shown as 0 and hence the issue. I suspect that this is with small stream sizes.

Issue Links

• is related to: CASSANDRA-16349 SSTableLoader reports error when SSTable(s) do not have data for some nodes