I did an extra test, again starting from scratch but with replication factor 1.
I still get the dead/up messages and timeout exceptions, but the system keeps
running and storing. However I ran out of disk space, logically producing a lot
of other errors.
Then I restarted the Cassandra servers, so they were able to cleanup and
restart without errors.
Then I did some queries I normally do and got again exceptions like " invalid
column name length 0", but also other like " Corrupt (negative) value length
encountered".
Exception : see below.
With this test, I run Cassandra embedded, so a lot of processing ( and object
allocations ) are done within the same JVM. I will modify the code so that 'my
processing/allcations' are done outside and the Cassandra jvm only has to store
the records. But that's for tomorrow.
Did anyone ran into this type of error? And what was the reason? Any help?
2011-10-03 11:49:21.035 Fatal exception in thread Thread[ReadStage:623,5,main]
java.io.IOError: java.io.IOException: Corrupt (negative) value length
encountered
at
org.apache.cassandra.io.util.ColumnIterator.deserializeNext(ColumnSortedMap.java:265)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.io.util.ColumnIterator.next(ColumnSortedMap.java:281)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.io.util.ColumnIterator.next(ColumnSortedMap.java:236)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
java.util.concurrent.ConcurrentSkipListMap.buildFromSorted(ConcurrentSkipListMap.java:1493)
~[na:1.6.0_24]
at
java.util.concurrent.ConcurrentSkipListMap.<init>(ConcurrentSkipListMap.java:1443)
~[na:1.6.0_24]
at
org.apache.cassandra.db.SuperColumnSerializer.deserialize(SuperColumn.java:445)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.db.SuperColumnSerializer.deserialize(SuperColumn.java:428)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.db.SuperColumnSerializer.deserialize(SuperColumn.java:418)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.db.SuperColumnSerializer.deserialize(SuperColumn.java:380)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.db.columniterator.IndexedSliceReader$IndexedBlockFetcher.getNextBlock(IndexedSliceReader.java:179)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.db.columniterator.IndexedSliceReader.computeNext(IndexedSliceReader.java:121)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.db.columniterator.IndexedSliceReader.computeNext(IndexedSliceReader.java:49)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:140)
~[guava-r08.jar:na]
at
com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:135)
~[guava-r08.jar:na]
at
org.apache.cassandra.db.columniterator.SSTableSliceIterator.hasNext(SSTableSliceIterator.java:108)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.commons.collections.iterators.CollatingIterator.set(CollatingIterator.java:283)
~[commons-collections-3.2.1.jar:3.2.1]
at
org.apache.commons.collections.iterators.CollatingIterator.least(CollatingIterator.java:326)
~[commons-collections-3.2.1.jar:3.2.1]
at
org.apache.commons.collections.iterators.CollatingIterator.next(CollatingIterator.java:230)
~[commons-collections-3.2.1.jar:3.2.1]
at
org.apache.cassandra.utils.ReducingIterator.computeNext(ReducingIterator.java:69)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:140)
~[guava-r08.jar:na]
at
com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:135)
~[guava-r08.jar:na]
at
org.apache.cassandra.db.filter.SliceQueryFilter.collectReducedColumns(SliceQueryFilter.java:116)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.db.filter.QueryFilter.collectCollatedColumns(QueryFilter.java:142)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.db.ColumnFamilyStore.getTopLevelColumns(ColumnFamilyStore.java:1427)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.db.ColumnFamilyStore.getColumnFamily(ColumnFamilyStore.java:1304)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.db.ColumnFamilyStore.getColumnFamily(ColumnFamilyStore.java:1261)
~[apache-cassandra-0.8.6.jar:0.8.6]
at org.apache.cassandra.db.Table.getRow(Table.java:385)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.db.SliceFromReadCommand.getRow(SliceFromReadCommand.java:61)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.db.ReadVerbHandler.doVerb(ReadVerbHandler.java:69)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.net.MessageDeliveryTask.run(MessageDeliveryTask.java:59)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
~[na:1.6.0_24]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
~[na:1.6.0_24]
at java.lang.Thread.run(Thread.java:662) ~[na:1.6.0_24]
Caused by: java.io.IOException: Corrupt (negative) value length encountered
at
org.apache.cassandra.utils.ByteBufferUtil.readWithLength(ByteBufferUtil.java:348)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.db.ColumnSerializer.deserialize(ColumnSerializer.java:108)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.io.util.ColumnIterator.deserializeNext(ColumnSortedMap.java:261)
~[apache-cassandra-0.8.6.jar:0.8.6]
... 32 common frames omitted
2011-10-03 11:55:01.745 Fatal exception in thread Thread[ReadStage:624,5,main]
java.io.IOError:
org.apache.cassandra.db.ColumnSerializer$CorruptColumnException: invalid column
name length 0
at
org.apache.cassandra.io.util.ColumnIterator.deserializeNext(ColumnSortedMap.java:265)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.io.util.ColumnIterator.next(ColumnSortedMap.java:281)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.io.util.ColumnIterator.next(ColumnSortedMap.java:236)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
java.util.concurrent.ConcurrentSkipListMap.buildFromSorted(ConcurrentSkipListMap.java:1493)
~[na:1.6.0_24]
at
java.util.concurrent.ConcurrentSkipListMap.<init>(ConcurrentSkipListMap.java:1443)
~[na:1.6.0_24]
at
org.apache.cassandra.db.SuperColumnSerializer.deserialize(SuperColumn.java:445)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.db.SuperColumnSerializer.deserialize(SuperColumn.java:428)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.db.SuperColumnSerializer.deserialize(SuperColumn.java:418)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.db.SuperColumnSerializer.deserialize(SuperColumn.java:380)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.db.columniterator.IndexedSliceReader$IndexedBlockFetcher.getNextBlock(IndexedSliceReader.java:179)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.db.columniterator.IndexedSliceReader.computeNext(IndexedSliceReader.java:121)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.db.columniterator.IndexedSliceReader.computeNext(IndexedSliceReader.java:49)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:140)
~[guava-r08.jar:na]
at
com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:135)
~[guava-r08.jar:na]
at
org.apache.cassandra.db.columniterator.SSTableSliceIterator.hasNext(SSTableSliceIterator.java:108)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.commons.collections.iterators.CollatingIterator.anyHasNext(CollatingIterator.java:364)
~[commons-collections-3.2.1.jar:3.2.1]
at
org.apache.commons.collections.iterators.CollatingIterator.hasNext(CollatingIterator.java:217)
~[commons-collections-3.2.1.jar:3.2.1]
at
org.apache.cassandra.utils.ReducingIterator.computeNext(ReducingIterator.java:55)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:140)
~[guava-r08.jar:na]
at
com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:135)
~[guava-r08.jar:na]
at
org.apache.cassandra.db.filter.SliceQueryFilter.collectReducedColumns(SliceQueryFilter.java:116)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.db.filter.QueryFilter.collectCollatedColumns(QueryFilter.java:142)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.db.ColumnFamilyStore.getTopLevelColumns(ColumnFamilyStore.java:1427)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.db.ColumnFamilyStore.getColumnFamily(ColumnFamilyStore.java:1304)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.db.ColumnFamilyStore.getColumnFamily(ColumnFamilyStore.java:1261)
~[apache-cassandra-0.8.6.jar:0.8.6]
at org.apache.cassandra.db.Table.getRow(Table.java:385)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.db.SliceFromReadCommand.getRow(SliceFromReadCommand.java:61)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.db.ReadVerbHandler.doVerb(ReadVerbHandler.java:69)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.net.MessageDeliveryTask.run(MessageDeliveryTask.java:59)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
~[na:1.6.0_24]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
~[na:1.6.0_24]
at java.lang.Thread.run(Thread.java:662) ~[na:1.6.0_24]
Caused by: org.apache.cassandra.db.ColumnSerializer$CorruptColumnException:
invalid column name length 0
at
org.apache.cassandra.db.ColumnSerializer.deserialize(ColumnSerializer.java:89)
~[apache-cassandra-0.8.6.jar:0.8.6]
at
org.apache.cassandra.io.util.ColumnIterator.deserializeNext(ColumnSortedMap.java:261)
~[apache-cassandra-0.8.6.jar:0.8.6]
... 31 common frames omitted
2011-10-03 14:18:53.436 Saved CodeStructure-Computers-KeyCache (1 items) in 16
ms
2011-10-03 14:19:24.804 Saved KsFullIdx-ReverseLabelValues-KeyCache (123981
items) in 192 ms
-----Original Message-----
From: Desimpel, Ignace [mailto:ignace.desim...@nuance.com]
Sent: dinsdag 27 september 2011 17:51
To: user@cassandra.apache.org
Subject: RE: invalid column name length 0
No, brand new, started from scratch, no data at all.
My setup get into trouble after a couple of hours since it then starts giving
the Dead/up messages.
I also get messages like '11 MUTATION messages dropped in server lifetime'
Later on I got this type of exception also.
-----Original Message-----
From: Jonathan Ellis [mailto:jbel...@gmail.com]
Sent: dinsdag 27 september 2011 17:41
To: user@cassandra.apache.org
Subject: Re: invalid column name length 0
Is this upgraded from an earlier version?
On Tue, Sep 27, 2011 at 8:51 AM, Desimpel, Ignace <ignace.desim...@nuance.com>
wrote:
> Version 0.8.6.
>
> After an extreme load to 4 (embedded) cassandra servers with
> replication factor 3 ( Ubuntu 10.4, dual six core, 64 bit, no swap, 1
> 15000 rpm commitlog disk, 1 15000 rpm datafile disk, ) I get a fatal
> exception as listed below.
>
> No more messages were found after that.
>
>
>
> Probably other things are going wrong like the message "410 Could not
> complete hinted handoff to /xxx.yyy.zzz.60", or the Dead/Up messages
> (occurring long before this exception).
>
> But maybe this exception can point me in the right direction or even
> point out some bug in Cassandra.
>
>
>
> Thanks,
>
> Ignace
>
>
>
>
>
> 2011-09-27 06:59:46,383 Compacting large row
> KsFullIdx/ForwardStringValues:3237343034 (178032211 bytes)
> incrementally
>
> 2011-09-27 07:00:09,738 GC for ParNew: 311 ms for 1 collections,
> 8139389704 used; max is 33344716800
>
> 2011-09-27 07:00:12,818 Compacting large row
> KsFullIdx/ForwardStringValues:31363437 (1281862723 bytes)
> incrementally
>
> 2011-09-27 07:02:16,025 Compacting large row
> KsFullIdx/ForwardStringValues:31363438 (1623095072 bytes)
> incrementally
>
> 2011-09-27 07:04:38,332 GC for ParNew: 534 ms for 1 collections,
> 7811259472 used; max is 33344716800
>
> 2011-09-27 07:04:52,803 Compacting large row
> KsFullIdx/ForwardStringValues:3238313433 (1435774436 bytes)
> incrementally
>
> 2011-09-27 07:06:57,160 Compacted to
> /media/datadrive1/capd.cassandra.capd/dbdatafile/KsFullIdx/ForwardStringValues-tmp-g-542-Data.db.
> 43,244,902,670 to 42,780,624,408 (~98% of original) bytes for 1,260 keys.
> Time: 4,321,960ms.
>
> 2011-09-27 08:01:42,090 Saved KsFullIdx-ForwardStringValues-KeyCache
> (572
> items) in 16 ms
>
> 2011-09-27 08:01:42,182 Saved KsFullIdx-ReverseStringValues-KeyCache
> (25688
> items) in 63 ms
>
> 2011-09-27 08:18:13,078 InetAddress /xxx.yyy.zzz.62 is now dead.
>
> 2011-09-27 08:18:16,467 InetAddress /xxx.yyy.zzz.62 is now UP
>
> 2011-09-27 08:48:56,410 Could not complete hinted handoff to
> /xxx.yyy.zzz.60
>
> 2011-09-27 08:48:56,410 Enqueuing flush of
> Memtable-HintsColumnFamily@2083796703(12097/196566 serialized/live
> bytes,
> 254 ops)
>
> 2011-09-27 08:48:56,411 Writing
> Memtable-HintsColumnFamily@2083796703(12097/196566 serialized/live
> bytes,
> 254 ops)
>
> 2011-09-27 08:48:56,411 Nothing to compact in HintsColumnFamily; use
> forceUserDefinedCompaction if you wish to force compaction of single
> sstables (e.g. for tombstone collection)
>
> 2011-09-27 08:48:56,411 Finished hinted handoff of 254 rows to
> endpoint
> /xxx.yyy.zzz.60
>
> 2011-09-27 08:48:56,490 Completed flushing
> /media/datadrive1/capd.cassandra.capd/dbdatafile/system/HintsColumnFam
> ily-g-10-Data.db
> (25079 bytes)
>
> 2011-09-27 08:49:42,858 Started hinted handoff for endpoint
> /xxx.yyy.zzz.62
>
> 2011-09-27 12:01:42,100 Saved KsFullIdx-ForwardStringValues-KeyCache
> (712
> items) in 27 ms
>
> 2011-09-27 12:01:42,182 Saved KsFullIdx-ReverseStringValues-KeyCache
> (30742
> items) in 55 ms
>
> 2011-09-27 12:10:01,016 InetAddress /xxx.yyy.zzz.59 is now dead.
>
> 2011-09-27 12:10:02,272 InetAddress /xxx.yyy.zzz.59 is now UP
>
> 2011-09-27 12:17:34,596 Fatal exception in thread
> Thread[HintedHandoff:1,5,RMI Runtime]
>
> java.io.IOError:
> org.apache.cassandra.db.ColumnSerializer$CorruptColumnException:
> invalid column name length 0
>
> at
> org.apache.cassandra.io.util.ColumnIterator.deserializeNext(ColumnSort
> edMap.java:265)
>
> at
> org.apache.cassandra.io.util.ColumnIterator.next(ColumnSortedMap.java:
> 281)
>
> at
> org.apache.cassandra.io.util.ColumnIterator.next(ColumnSortedMap.java:
> 236)
>
> at
> java.util.concurrent.ConcurrentSkipListMap.buildFromSorted(ConcurrentS
> kipListMap.java:1493)
>
> at
> java.util.concurrent.ConcurrentSkipListMap.<init>(ConcurrentSkipListMa
> p.java:1443)
>
> at
> org.apache.cassandra.db.SuperColumnSerializer.deserialize(SuperColumn.
> java:445)
>
> at
> org.apache.cassandra.db.SuperColumnSerializer.deserialize(SuperColumn.
> java:428)
>
> at
> org.apache.cassandra.db.SuperColumnSerializer.deserialize(SuperColumn.
> java:418)
>
> at
> org.apache.cassandra.db.SuperColumnSerializer.deserialize(SuperColumn.
> java:380)
>
> at
> org.apache.cassandra.db.columniterator.IndexedSliceReader$IndexedBlock
> Fetcher.getNextBlock(IndexedSliceReader.java:179)
>
> at
> org.apache.cassandra.db.columniterator.IndexedSliceReader.computeNext(
> IndexedSliceReader.java:121)
>
> at
> org.apache.cassandra.db.columniterator.IndexedSliceReader.computeNext(
> IndexedSliceReader.java:49)
>
> at
> com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIt
> erator.java:140)
>
> at
> com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.ja
> va:135)
>
> at
> org.apache.cassandra.db.columniterator.SSTableSliceIterator.hasNext(SS
> TableSliceIterator.java:108)
>
> at
> org.apache.commons.collections.iterators.CollatingIterator.set(Collati
> ngIterator.java:283)
>
> at
> org.apache.commons.collections.iterators.CollatingIterator.least(Colla
> tingIterator.java:326)
>
> at
> org.apache.commons.collections.iterators.CollatingIterator.next(Collat
> ingIterator.java:230)
>
> at
> org.apache.cassandra.utils.ReducingIterator.computeNext(ReducingIterat
> or.java:69)
>
> at
> com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIt
> erator.java:140)
>
> at
> com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.ja
> va:135)
>
> at
> org.apache.cassandra.db.filter.SliceQueryFilter.collectReducedColumns(
> SliceQueryFilter.java:116)
>
> at
> org.apache.cassandra.db.filter.QueryFilter.collectCollatedColumns(Quer
> yFilter.java:142)
>
> at
> org.apache.cassandra.db.ColumnFamilyStore.getTopLevelColumns(ColumnFam
> ilyStore.java:1427)
>
> at
> org.apache.cassandra.db.ColumnFamilyStore.getColumnFamily(ColumnFamily
> Store.java:1304)
>
> at
> org.apache.cassandra.db.ColumnFamilyStore.getColumnFamily(ColumnFamily
> Store.java:1261)
>
> at
> org.apache.cassandra.db.HintedHandOffManager.sendRow(HintedHandOffMana
> ger.java:155)
>
> at
> org.apache.cassandra.db.HintedHandOffManager.deliverHintsToEndpoint(Hi
> ntedHandOffManager.java:350)
>
> at
> org.apache.cassandra.db.HintedHandOffManager.access$100(HintedHandOffM
> anager.java:89)
>
> at
> org.apache.cassandra.db.HintedHandOffManager$2.runMayThrow(HintedHandO
> ffManager.java:397)
>
> at
> org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:30
> )
>
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecu
> tor.java:886)
>
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.
> java:908)
>
> at java.lang.Thread.run(Thread.java:662)
>
> Caused by: org.apache.cassandra.db.ColumnSerializer$CorruptColumnException:
> invalid column name length 0
>
> at
> org.apache.cassandra.db.ColumnSerializer.deserialize(ColumnSerializer.
> java:89)
>
> at
> org.apache.cassandra.io.util.ColumnIterator.deserializeNext(ColumnSort
> edMap.java:261)
>
> ... 33 more
>
> 2011-09-27 12:17:53,291 Started hinted handoff for endpoint
> /xxx.yyy.zzz.59
--
Jonathan Ellis
Project Chair, Apache Cassandra
co-founder of DataStax, the source for professional Cassandra support
http://www.datastax.com
