[CASSANDRA-10554] Batch that updates two or more table can produce unreadable SSTable (was: Auto Bootstraping a new node fails)

• Type: Bug
• Status: Resolved
• Priority: Urgent
• Resolution: Fixed
• Fix Version/s: 3.0.0
• Severity: Critical
• Assignee: Sylvain Lebresne
• Reporter: Alan Boudreault

Authors

Sylvain Lebresne

Reviewers

Branimir Lambov

• Tester: Alan Boudreault
• Created: 19/Oct/15 21:36
• Updated: 16/Apr/19 09:30
• Resolved: 27/Oct/15 12:55

Description

I've been trying to add a new node in my 3.0 cluster and it seems to fail. All my nodes are using apache/cassandra-3.0.0 branch. At the beginning, I can see the following error:

INFO  18:45:55 [Stream #9f95fa90-7691-11e5-931f-5b735851f84a ID#0] Prepare completed. Receiving 42 files(1910066622 bytes), sending 0 files(0 bytes)
WARN  18:45:55 [Stream #9f95fa90-7691-11e5-931f-5b735851f84a] Retrying for following error
java.lang.RuntimeException: Unknown column added_time during deserialization
        at org.apache.cassandra.db.SerializationHeader$Component.toHeader(SerializationHeader.java:331) ~[main/:na]
        at org.apache.cassandra.streaming.StreamReader.createWriter(StreamReader.java:136) ~[main/:na]
        at org.apache.cassandra.streaming.compress.CompressedStreamReader.read(CompressedStreamReader.java:77) ~[main/:na]
        at org.apache.cassandra.streaming.messages.IncomingFileMessage$1.deserialize(IncomingFileMessage.java:50) [main/:na]
        at org.apache.cassandra.streaming.messages.IncomingFileMessage$1.deserialize(IncomingFileMessage.java:39) [main/:na]
        at org.apache.cassandra.streaming.messages.StreamMessage.deserialize(StreamMessage.java:59) [main/:na]
        at org.apache.cassandra.streaming.ConnectionHandler$IncomingMessageHandler.run(ConnectionHandler.java:261) [main/:na]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_45]
ERROR 18:45:55 [Stream #9f95fa90-7691-11e5-931f-5b735851f84a] Streaming error occurred
java.lang.IllegalArgumentException: Unknown type 0
        at org.apache.cassandra.streaming.messages.StreamMessage$Type.get(StreamMessage.java:97) ~[main/:na]
        at org.apache.cassandra.streaming.messages.StreamMessage.deserialize(StreamMessage.java:58) ~[main/:na]
        at org.apache.cassandra.streaming.ConnectionHandler$IncomingMessageHandler.run(ConnectionHandler.java:261) ~[main/:na]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_45]
INFO  18:45:55 [Stream #9f95fa90-7691-11e5-931f-5b735851f84a] Session with /54.210.187.114 is complete
INFO  18:45:56 [Stream #9f95fa90-7691-11e5-931f-5b735851f84a ID#0] Prepare completed. Receiving 38 files(2323537628 bytes), sending 0 files(0 bytes)
WARN  18:45:56 [Stream #9f95fa90-7691-11e5-931f-5b735851f84a] Retrying for following error
java.lang.RuntimeException: Unknown column added_time during deserialization
        at org.apache.cassandra.db.SerializationHeader$Component.toHeader(SerializationHeader.java:331) ~[main/:na]
        at org.apache.cassandra.streaming.StreamReader.createWriter(StreamReader.java:136) ~[main/:na]
        at org.apache.cassandra.streaming.compress.CompressedStreamReader.read(CompressedStreamReader.java:77) ~[main/:na]
        at org.apache.cassandra.streaming.messages.IncomingFileMessage$1.deserialize(IncomingFileMessage.java:50) [main/:na]
        at org.apache.cassandra.streaming.messages.IncomingFileMessage$1.deserialize(IncomingFileMessage.java:39) [main/:na]
        at org.apache.cassandra.streaming.messages.StreamMessage.deserialize(StreamMessage.java:59) [main/:na]
        at org.apache.cassandra.streaming.ConnectionHandler$IncomingMessageHandler.run(ConnectionHandler.java:261) [main/:na]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_45]
ERROR 18:45:56 [Stream #9f95fa90-7691-11e5-931f-5b735851f84a] Streaming error occurred
java.lang.IllegalArgumentException: Unknown type 0
        at org.apache.cassandra.streaming.messages.StreamMessage$Type.get(StreamMessage.java:97) ~[main/:na]
        at org.apache.cassandra.streaming.messages.StreamMessage.deserialize(StreamMessage.java:58) ~[main/:na]
        at org.apache.cassandra.streaming.ConnectionHandler$IncomingMessageHandler.run(ConnectionHandler.java:261) ~[main/:na]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_45]
INFO  18:45:56 [Stream #9f95fa90-7691-11e5-931f-5b735851f84a] Session with /54.210.184.198 is complete
INFO  18:45:56 [Stream #9f95fa90-7691-11e5-931f-5b735851f84a ID#0] Prepare completed. Receiving 35 files(2069893759 bytes), sending 0 files(0 bytes)
WARN  18:45:57 [Stream #9f95fa90-7691-11e5-931f-5b735851f84a] Retrying for following error
java.lang.AssertionError: null
        at org.apache.cassandra.db.PartitionColumns$Builder.add(PartitionColumns.java:168) ~[main/:na]
        at org.apache.cassandra.db.SerializationHeader$Component.toHeader(SerializationHeader.java:333) ~[main/:na]
        at org.apache.cassandra.streaming.StreamReader.createWriter(StreamReader.java:136) ~[main/:na]
        at org.apache.cassandra.streaming.compress.CompressedStreamReader.read(CompressedStreamReader.java:77) ~[main/:na]
        at org.apache.cassandra.streaming.messages.IncomingFileMessage$1.deserialize(IncomingFileMessage.java:50) [main/:na]
        at org.apache.cassandra.streaming.messages.IncomingFileMessage$1.deserialize(IncomingFileMessage.java:39) [main/:na]
        at org.apache.cassandra.streaming.messages.StreamMessage.deserialize(StreamMessage.java:59) [main/:na]
        at org.apache.cassandra.streaming.ConnectionHandler$IncomingMessageHandler.run(ConnectionHandler.java:261) [main/:na]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_45]
ERROR 18:45:57 [Stream #9f95fa90-7691-11e5-931f-5b735851f84a] Streaming error occurred
java.lang.IllegalArgumentException: Unknown type 0
        at org.apache.cassandra.streaming.messages.StreamMessage$Type.get(StreamMessage.java:97) ~[main/:na]
        at org.apache.cassandra.streaming.messages.StreamMessage.deserialize(StreamMessage.java:58) ~[main/:na]
        at org.apache.cassandra.streaming.ConnectionHandler$IncomingMessageHandler.run(ConnectionHandler.java:261) ~[main/:na]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_45]
INFO  18:45:57 [Stream #9f95fa90-7691-11e5-931f-5b735851f84a] Session with /54.210.157.2 is complete
WARN  18:45:57 [Stream #9f95fa90-7691-11e5-931f-5b735851f84a] Stream failed
ERROR 18:45:57 Error while waiting on bootstrap to complete. Bootstrap will have to be restarted.
java.util.concurrent.ExecutionException: org.apache.cassandra.streaming.StreamException: Stream failed
        at com.google.common.util.concurrent.AbstractFuture$Sync.getValue(AbstractFuture.java:299) ~[guava-18.0.jar:na]
        at com.google.common.util.concurrent.AbstractFuture$Sync.get(AbstractFuture.java:286) ~[guava-18.0.jar:na]
        at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:116) ~[guava-18.0.jar:na]
        at org.apache.cassandra.service.StorageService.bootstrap(StorageService.java:1245) [main/:na]
        at org.apache.cassandra.service.StorageService.joinTokenRing(StorageService.java:935) [main/:na]
        at org.apache.cassandra.service.StorageService.initServer(StorageService.java:710) [main/:na]
        at org.apache.cassandra.service.StorageService.initServer(StorageService.java:581) [main/:na]
        at org.apache.cassandra.service.CassandraDaemon.setup(CassandraDaemon.java:345) [main/:na]
        at org.apache.cassandra.service.CassandraDaemon.activate(CassandraDaemon.java:561) [main/:na]
        at org.apache.cassandra.service.CassandraDaemon.main(CassandraDaemon.java:689) [main/:na]
Caused by: org.apache.cassandra.streaming.StreamException: Stream failed
        at org.apache.cassandra.streaming.management.StreamEventJMXNotifier.onFailure(StreamEventJMXNotifier.java:85) ~[main/:na]
        at com.google.common.util.concurrent.Futures$6.run(Futures.java:1310) ~[guava-18.0.jar:na]
        at com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:457) ~[guava-18.0.jar:na]
        at com.google.common.util.concurrent.ExecutionList.executeListener(ExecutionList.java:156) ~[guava-18.0.jar:na]
        at com.google.common.util.concurrent.ExecutionList.execute(ExecutionList.java:145) ~[guava-18.0.jar:na]
        at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:202) ~[guava-18.0.jar:na]
        at org.apache.cassandra.streaming.StreamResultFuture.maybeComplete(StreamResultFuture.java:210) ~[main/:na]
        at org.apache.cassandra.streaming.StreamResultFuture.handleSessionComplete(StreamResultFuture.java:186) ~[main/:na]
        at org.apache.cassandra.streaming.StreamSession.closeSession(StreamSession.java:430) ~[main/:na]
        at org.apache.cassandra.streaming.StreamSession.onError(StreamSession.java:525) ~[main/:na]
        at org.apache.cassandra.streaming.ConnectionHandler$IncomingMessageHandler.run(ConnectionHandler.java:279) ~[main/:na]
        at java.lang.Thread.run(Thread.java:745) ~[na:1.8.0_45]
Oct 19, 2015 6:45:57 PM com.google.common.util.concurrent.ExecutionList executeListener
SEVERE: RuntimeException while executing runnable com.google.common.util.concurrent.Futures$6@59444306 with executor INSTANCE
java.lang.NullPointerException
        at org.apache.cassandra.service.StorageService$2.onFailure(StorageService.java:1240)
        at com.google.common.util.concurrent.Futures$6.run(Futures.java:1310)
        at com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:457)
        at com.google.common.util.concurrent.ExecutionList.executeListener(ExecutionList.java:156)
        at com.google.common.util.concurrent.ExecutionList.execute(ExecutionList.java:145)
        at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:202)
        at org.apache.cassandra.streaming.StreamResultFuture.maybeComplete(StreamResultFuture.java:210)
        at org.apache.cassandra.streaming.StreamResultFuture.handleSessionComplete(StreamResultFuture.java:186)
        at org.apache.cassandra.streaming.StreamSession.closeSession(StreamSession.java:430)
        at org.apache.cassandra.streaming.StreamSession.onError(StreamSession.java:525)
        at org.apache.cassandra.streaming.ConnectionHandler$IncomingMessageHandler.run(ConnectionHandler.java:279)
        at java.lang.Thread.run(Thread.java:745)

The "added_time" is a bigint column. I do see that the node is marked as UJ in nodetool status and the bootstraping continue to run. But at a certain point, it hangs forever and restarting it doesn't help. I'm not 100% sure the hang issue is related to the above error though. But I'd like to fix this one before trying again. Any idea what's going on with that bigint type?