[
https://issues.apache.org/jira/browse/CASSANDRA-10554?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14969187#comment-14969187
]
Alan Boudreault commented on CASSANDRA-10554:
---------------------------------------------
While trying to produce a local test case, I've noticed that I can reproduce
the error easily just by restarting a node. The error might not be related to
the bootstraping anymore at this point since I can see it with a simple node
restart. Here the error produce by my test case:
{code}
ERROR [SSTableBatchOpen:2] 2015-10-22 09:48:04,721 CassandraDaemon.java:195 -
Exception in thread Thread[SSTableBatchOpen:2,5,main]
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.io.sstable.format.SSTableReader.open(SSTableReader.java:477)
~[main/:na]
at
org.apache.cassandra.io.sstable.format.SSTableReader.open(SSTableReader.java:366)
~[main/:na]
at
org.apache.cassandra.io.sstable.format.SSTableReader$4.run(SSTableReader.java:525)
~[main/:na]
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
~[na:1.8.0_45]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
~[na:1.8.0_45]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
~[na:1.8.0_45]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[na:1.8.0_45]
at java.lang.Thread.run(Thread.java:745) [na:1.8.0_45]
ERROR [SSTableBatchOpen:2] 2015-10-22 09:48:04,721 CassandraDaemon.java:195 -
Exception in thread Thread[SSTableBatchOpen:2,5,main]
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.io.sstable.format.SSTableReader.open(SSTableReader.java:477)
~[main/:na]
at
org.apache.cassandra.io.sstable.format.SSTableReader.open(SSTableReader.java:366)
~[main/:na]
at
org.apache.cassandra.io.sstable.format.SSTableReader$4.run(SSTableReader.java:525)
~[main/:na]
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
~[na:1.8.0_45]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
~[na:1.8.0_45]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
~[na:1.8.0_45]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[na:1.8.0_45]
at java.lang.Thread.run(Thread.java:745) [na:1.8.0_45]
ERROR [SSTableBatchOpen:1] 2015-10-22 09:48:04,721 CassandraDaemon.java:195 -
Exception in thread Thread[SSTableBatchOpen:1,5,main]
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.io.sstable.format.SSTableReader.open(SSTableReader.java:477)
~[main/:na]
at
org.apache.cassandra.io.sstable.format.SSTableReader.open(SSTableReader.java:366)
~[main/:na]
at
org.apache.cassandra.io.sstable.format.SSTableReader$4.run(SSTableReader.java:525)
~[main/:na]
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
~[na:1.8.0_45]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
~[na:1.8.0_45]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
~[na:1.8.0_45]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[na:1.8.0_45]
at java.lang.Thread.run(Thread.java:745) [na:1.8.0_45]
ERROR [SSTableBatchOpen:1] 2015-10-22 09:48:04,721 CassandraDaemon.java:195 -
Exception in thread Thread[SSTableBatchOpen:1,5,main]
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.io.sstable.format.SSTableReader.open(SSTableReader.java:477)
~[main/:na]
at
org.apache.cassandra.io.sstable.format.SSTableReader.open(SSTableReader.java:366)
~[main/:na]
at
org.apache.cassandra.io.sstable.format.SSTableReader$4.run(SSTableReader.java:525)
~[main/:na]
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
~[na:1.8.0_45]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
~[na:1.8.0_45]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
~[na:1.8.0_45]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[na:1.8.0_45]
at java.lang.Thread.run(Thread.java:745) [na:1.8.0_45]
INFO [main] 2015-10-22 09:48:04,726 ColumnFamilyStore.java:381 - Initializing
manual.genre_to_user
INFO [main] 2015-10-22 09:48:04,726 ColumnFamilyStore.java:381 - Initializing
manual.genre_to_user
DEBUG [SSTableBatchOpen:1] 2015-10-22 09:48:04,729 SSTableReader.java:470 -
Opening
/home/aboudreault/.ccm/10554/node2/data/manual/genre_to_user-65e9dfd078c311e5a6e729d4c8a5f42b/ma-1-big
(665634 bytes)
ERROR [SSTableBatchOpen:1] 2015-10-22 09:48:04,729 CassandraDaemon.java:195 -
Exception in thread Thread[SSTableBatchOpen:1,5,main]
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.io.sstable.format.SSTableReader.open(SSTableReader.java:477)
~[main/:na]
at
org.apache.cassandra.io.sstable.format.SSTableReader.open(SSTableReader.java:366)
~[main/:na]
at
org.apache.cassandra.io.sstable.format.SSTableReader$4.run(SSTableReader.java:525)
~[main/:na]
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
~[na:1.8.0_45]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
~[na:1.8.0_45]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
~[na:1.8.0_45]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[na:1.8.0_45]
at java.lang.Thread.run(Thread.java:745) [na:1.8.0_45]
ERROR [SSTableBatchOpen:1] 2015-10-22 09:48:04,729 CassandraDaemon.java:195 -
Exception in thread Thread[SSTableBatchOpen:1,5,main]
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.io.sstable.format.SSTableReader.open(SSTableReader.java:477)
~[main/:na]
at
org.apache.cassandra.io.sstable.format.SSTableReader.open(SSTableReader.java:366)
~[main/:na]
at
org.apache.cassandra.io.sstable.format.SSTableReader$4.run(SSTableReader.java:525)
~[main/:na]
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
~[na:1.8.0_45]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
~[na:1.8.0_45]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
~[na:1.8.0_45]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[na:1.8.0_45]
at java.lang.Thread.run(Thread.java:745) [na:1.8.0_45]
INFO [main] 2015-10-22 09:48:04,733 ColumnFamilyStore.java:381 - Initializing
manual.recently_played
INFO [main] 2015-10-22 09:48:04,733 ColumnFamilyStore.java:381 - Initializing
manual.recently_played
INFO [main] 2015-10-22 09:48:04,737 ColumnFamilyStore.java:381 - Initializing
manual.song_to_user
INFO [main] 2015-10-22 09:48:04,737 ColumnFamilyStore.java:381 - Initializing
manual.song_to_user
DEBUG [SSTableBatchOpen:1] 2015-10-22 09:48:04,739 SSTableReader.java:470 -
Opening
/home/aboudreault/.ccm/10554/node2/data/manual/song_to_user-64c97bb078c311e5a6e729d4c8a5f42b/ma-1-big
(465269 bytes)
DEBUG [SSTableBatchOpen:2] 2015-10-22 09:48:04,739 SSTableReader.java:470 -
Opening
/home/aboudreault/.ccm/10554/node2/data/manual/song_to_user-64c97bb078c311e5a6e729d4c8a5f42b/ma-2-big
(588288 bytes)
{code}
My test uses Jake's tool mvbench but I am not using MV at all. Just normal
tables maintained manually with batchlog: [^test.sh]
You'll need to compile mvbench and use my branch which contain the driver
update:
{code}
git clone https://github.com/tjake/mvbench
cd mvbench
git remote add aboudreault https://github.com/aboudreault/mvbench.git
git fetch aboudreault
git checkout driver-and-schema-update
mvn compile
{code}
When test.sh run is finished, you should see the errors in the node2 system.log
file. Let me know if you need anything else.
> Auto Bootstraping a new node fails
> ----------------------------------
>
> Key: CASSANDRA-10554
> URL: https://issues.apache.org/jira/browse/CASSANDRA-10554
> Project: Cassandra
> Issue Type: Bug
> Reporter: Alan Boudreault
> Assignee: Yuki Morishita
> Fix For: 3.0.0
>
> Attachments: 0001-Add-debug.txt, debug.log, system.log, test.sh
>
>
> 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:
> {code}
> 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)
> {code}
> 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?
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
