Hmm, I wish that were the case, since once those messages start appearing .. they never stop .. resulting in timeouts on all client requests until I stop the server.

When I restart the server and try querying for anything via the index the messages then resumed.

Right now the problem has gone away, but only because I have stopped deleting any rows that have indexes defined on them (for now) but thats not a long term solution of course.



On Wed, Oct 13, 2010 at 2:52 PM, Gary Dusbabek <gdusbabek@gmail.com> wrote:
If you're not seeing the NullPointerException at this point, things
are probably good.  These messages are expected when logging at DEBUG.

Gary.

On Tue, Oct 12, 2010 at 02:35, J T <jt4websites@googlemail.com> wrote:
> 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
>>>>
>>>>
>>>
>>
>
>