I rinsed & repeated after updating to the latest trunk version and checking if the 1571 patch was included (which it appeared to be) and the start of the repeating error sequence was:

DEBUG [pool-1-thread-21] 2010-10-12 08:30:31,143 ClientState.java (line 81) logged in: #<User allow_all groups=[]>
DEBUG [pool-1-thread-21] 2010-10-12 08:30:31,166 CassandraServer.java (line 543) scan
DEBUG [pool-1-thread-21] 2010-10-12 08:30:31,169 StorageProxy.java (line 563) restricted single token match for query [0,0]
DEBUG [pool-1-thread-21] 2010-10-12 08:30:31,169 StorageProxy.java (line 649) scan ranges are [0,0]
DEBUG [pool-1-thread-21] 2010-10-12 08:30:31,179 StorageProxy.java (line 669) reading org.apache.cassandra.db.IndexScanCommand@b3a5a0 from 101@localhost/127.0.0.1
DEBUG [ReadStage:6] 2010-10-12 08:30:31,194 SliceQueryFilter.java (line 122) collecting 0 of 1: null:false:0@1286840713
DEBUG [ReadStage:6] 2010-10-12 08:30:31,198 SliceQueryFilter.java (line 122) collecting 0 of 2147483647: is_confirmed:false:5@1286840713
DEBUG [ReadStage:6] 2010-10-12 08:30:31,198 SliceQueryFilter.java (line 122) collecting 1 of 2147483647: request_type:false:6@1286840713
DEBUG [ReadStage:6] 2010-10-12 08:30:31,199 SliceQueryFilter.java (line 122) collecting 2 of 2147483647: requested:false:58@1286840713
DEBUG [ReadStage:6] 2010-10-12 08:30:31,200 SliceQueryFilter.java (line 122) collecting 3 of 2147483647: requestor:false:58@1286840713
DEBUG [ReadStage:6] 2010-10-12 08:30:31,200 SliceQueryFilter.java (line 122) collecting 4 of 2147483647: requestor_network:false:57@1286840713
DEBUG [ReadStage:6] 2010-10-12 08:30:31,206 SliceQueryFilter.java (line 122) collecting 0 of 1: null:false:0@1286840713
DEBUG [ReadStage:6] 2010-10-12 08:30:31,209 SliceQueryFilter.java (line 122) collecting 0 of 1: null:false:0@1286840713
DEBUG [ReadStage:6] 2010-10-12 08:30:31,211 SliceQueryFilter.java (line 122) collecting 0 of 1: null:false:0@1286840713
DEBUG [ReadStage:6] 2010-10-12 08:30:31,214 SliceQueryFilter.java (line 122) collecting 0 of 1: null:false:0@1286840713
DEBUG [ReadStage:6] 2010-10-12 08:30:31,217 SliceQueryFilter.java (line 122) collecting 0 of 1: null:false:0@1286840713
DEBUG [ReadStage:6] 2010-10-12 08:30:31,220 SliceQueryFilter.java (line 122) collecting 0 of 1: null:false:0@1286840713
DEBUG [ReadStage:6] 2010-10-12 08:30:31,223 SliceQueryFilter.java (line 122) collecting 0 of 1: null:false:0@1286840713
DEBUG [ReadStage:6] 2010-10-12 08:30:31,225 SliceQueryFilter.java (line 122) collecting 0 of 1: null:false:0@1286840713


On Tue, Oct 12, 2010 at 7:50 AM, J T <jt4websites@googlemail.com> wrote:

Hi,

Looks like I was premature in my response.

I had cause today to wipe my datastore and restart cassandra and reload the .yaml containing the schema definition.

After doing a restart of my app which essentially inserted into a CF with a 2ndary idx and then queried that CF I was left with log files full of the following.

DEBUG [ReadStage:1] 2010-10-12 07:29:26,849 SliceQueryFilter.java (line 122) collecting 0 of 1: null:false:0@1286840713

DEBUG [ReadStage:1] 2010-10-12 07:29:26,850 SliceQueryFilter.java (line 122) collecting 0 of 1: null:false:0@1286840713

DEBUG [ReadStage:1] 2010-10-12 07:29:26,851 SliceQueryFilter.java (line 122) collecting 0 of 1: null:false:0@1286840713

DEBUG [ReadStage:1] 2010-10-12 07:29:26,852 SliceQueryFilter.java (line 122) collecting 0 of 1: null:false:0@1286840713

DEBUG [ReadStage:3] 2010-10-12 07:29:26,798 SliceQueryFilter.java (line 122) collecting 0 of 1: null:false:0@1286840713

DEBUG [ReadStage:1] 2010-10-12 07:29:26,853 SliceQueryFilter.java (line 122) collecting 0 of 1: null:false:0@1286840713

DEBUG [ReadStage:3] 2010-10-12 07:29:26,854 SliceQueryFilter.java (line 122) collecting 0 of 1: null:false:0@1286840713

DEBUG [ReadStage:1] 2010-10-12 07:29:26,854 SliceQueryFilter.java (line 122) collecting 0 of 1: null:false:0@1286840713

DEBUG [ReadStage:3] 2010-10-12 07:29:26,855 SliceQueryFilter.java (line 122) collecting 0 of 1: null:false:0@1286840713

DEBUG [ReadStage:1] 2010-10-12 07:29:26,855 SliceQueryFilter.java (line 122) collecting 0 of 1: null:false:0@1286840713

DEBUG [ReadStage:3] 2010-10-12 07:29:26,856 SliceQueryFilter.java (line 122) collecting 0 of 1: null:false:0@1286840713

DEBUG [ReadStage:1] 2010-10-12 07:29:26,856 SliceQueryFilter.java (line 122) collecting 0 of 1: null:false:0@1286840713

DEBUG [ReadStage:3] 2010-10-12 07:29:26,857 SliceQueryFilter.java (line 122) collecting 0 of 1: null:false:0@1286840713

DEBUG [ReadStage:3] 2010-10-12 07:29:26,858 SliceQueryFilter.java (line 122) collecting 0 of 1: null:false:0@1286840713

DEBUG [ReadStage:3] 2010-10-12 07:29:26,859 SliceQueryFilter.java (line 122) collecting 0 of 1: null:false:0@1286840713


This resulted in timeouts in my app.


Jason


On Wed, Oct 6, 2010 at 7:11 PM, J T <jt4websites@googlemail.com> wrote:
Hi,

On a first pass, that patch seems to have solved the problem.
I'll be testing that functionality repeatedly in the next day or so I'll let you know how it fairs.

Thanks

Jason


On Wed, Oct 6, 2010 at 4:06 PM, Stu Hood <stu.hood@rackspace.com> wrote:
Hey JT,

I believe this issue should be fixed by CASSANDRA-1571... if you're able to test that patch, it would be very helpful.

Thanks,
Stu

-----Original Message-----
From: "J T" <jt4websites@googlemail.com>
Sent: Tuesday, October 5, 2010 9:50pm
To: cassandra-user@incubator.apache.org
Subject: Null Pointer Exception / Secondary Indices

Hi,

I've been battling against some errors that only seem to crop up when I'm
messing around with secondary indices in 0.7-beta2.

Namely I seem to get errors like this start to happen, after I 'delete' a
row in a CF that has a couple of secondary indices on it and then at some
point later try to query for any rows from that CF.
Usually I don;t get the Null pointer exception below, instead what often
happens is that the SliceQueryFilter.java line before it, repeats itself
forever bever stopping until I kill the server

On this occasion I got a null pointer exception as well. This is on trunk as
of tonight (but I was getting it over the weekend as well).

DEBUG [pool-1-thread-149] 2010-10-06 03:43:15,436 ClientState.java (line
102) logged in: #<User allow_all groups=[]>
DEBUG [pool-1-thread-99] 2010-10-06 03:43:15,444 CassandraServer.java (line
536) scan
DEBUG [pool-1-thread-99] 2010-10-06 03:43:15,444 StorageProxy.java (line
571) computing restricted ranges for query [0,0]
DEBUG [pool-1-thread-99] 2010-10-06 03:43:15,445 StorageProxy.java (line
583) Adding to restricted ranges (91870423363853801063842423182856312085,0]
for
(91870423363853801063842423182856312085,91870423363853801063842423182856312085]
DEBUG [pool-1-thread-99] 2010-10-06 03:43:15,446 StorageProxy.java (line
583) Adding to restricted ranges (0,91870423363853801063842423182856312085]
for
(91870423363853801063842423182856312085,91870423363853801063842423182856312085]
DEBUG [pool-1-thread-99] 2010-10-06 03:43:15,447 StorageProxy.java (line
617) Sorted ranges are [(0,91870423363853801063842423182856312085],
(91870423363853801063842423182856312085,0]]
DEBUG [pool-1-thread-99] 2010-10-06 03:43:15,447 StorageProxy.java (line
680) scan ranges are
(0,91870423363853801063842423182856312085],(91870423363853801063842423182856312085,0]
DEBUG [pool-1-thread-99] 2010-10-06 03:43:15,448 StorageProxy.java (line
700) reading org.apache.cassandra.db.IndexScanCommand@1422265 from
1268@localhost/127.0.0.1
*DEBUG [ReadStage:24] 2010-10-06 03:43:15,450 SliceQueryFilter.java (line
122) collecting 0 of 1: null:false:0@1286332576*
ERROR [ReadStage:24] 2010-10-06 03:43:15,451
DebuggableThreadPoolExecutor.java (line 103) Error in ThreadPoolExecutor
java.lang.RuntimeException: java.lang.NullPointerException
at
org.apache.cassandra.service.IndexScanVerbHandler.doVerb(IndexScanVerbHandler.java:50)
at
org.apache.cassandra.net.MessageDeliveryTask.run(MessageDeliveryTask.java:50)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:636)
Caused by: java.lang.NullPointerException
at
org.apache.cassandra.db.ColumnFamilyStore.satisfies(ColumnFamilyStore.java:1297)
at
org.apache.cassandra.db.ColumnFamilyStore.scan(ColumnFamilyStore.java:1245)
at
org.apache.cassandra.service.IndexScanVerbHandler.doVerb(IndexScanVerbHandler.java:41)
... 4 more
ERROR [ReadStage:24] 2010-10-06 03:43:15,453 AbstractCassandraDaemon.java
(line 88) Fatal exception in thread Thread[ReadStage:24,5,main]
java.lang.RuntimeException: java.lang.NullPointerException
at
org.apache.cassandra.service.IndexScanVerbHandler.doVerb(IndexScanVerbHandler.java:50)
at
org.apache.cassandra.net.MessageDeliveryTask.run(MessageDeliveryTask.java:50)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:636)
Caused by: java.lang.NullPointerException
at
org.apache.cassandra.db.ColumnFamilyStore.satisfies(ColumnFamilyStore.java:1297)
at
org.apache.cassandra.db.ColumnFamilyStore.scan(ColumnFamilyStore.java:1245)
at
org.apache.cassandra.service.IndexScanVerbHandler.doVerb(IndexScanVerbHandler.java:41)
... 4 more