[CASSANDRA-5024] Secondary Index seen as empty

• Type: Bug
• Status: Resolved
• Priority: Normal
• Resolution: Duplicate
• Fix Version/s: 1.2.0 rc2
• Component/s: Feature/2i Index
• Labels: cql secondaryIndex

Environment

Linux X86_64 Ubuntu 12.04

• Severity: Normal
• Assignee: Unassigned
• Reporter: Cyril Scetbon
• Created: 03/Dec/12 21:47
• Updated: 16/Apr/19 09:32
• Resolved: 24/Dec/12 10:58

Description

We got an issue here with cassandra 1.1.6 where a secondary index seems to be seen as empty. We did a lot of inserts/deletes on our table (benchmarks)
If I try to see what are the first 10 values I have :

cqlsh:pns_fr> select mailendwnd from syndic limit 10;
mailendwnd
--------------------------
2012-11-29 23:30:00+0000
2012-11-29 02:35:00+0000
2012-11-29 06:35:00+0000
2012-11-29 00:30:00+0000
2012-11-29 07:10:00+0000
2012-11-29 02:10:00+0000
2012-11-29 01:55:00+0000
2012-11-29 23:45:00+0000
2012-11-29 07:25:00+0000
2012-11-29 06:55:00+0000

However, even if there is a secondary index on mailendwnd, we can't get any record :

cqlsh:pns_fr> select mailendwnd from syndic where mailendwnd = '2012-11-29 02:35:00+0000' limit 1000;

FYI, It's resolved by repairing the index and it happened a few times. I launched cassandra in debug mode and noticed that it thinks there is no data in the index :

DEBUG [Thrift:14] 2012-11-30 08:35:20,756 CassandraServer.java (line 1232) execute_cql_query
DEBUG [Thrift:14] 2012-11-30 08:35:20,758 QueryProcessor.java (line 445) CQL statement type: SELECT
DEBUG [Thrift:14] 2012-11-30 08:35:20,777 StorageProxy.java (line 842) Command/ConsistencyLevel is RangeSliceCommand

{keyspace='pns_fr', column_family='syndic', super_column=null, predicate=SlicePredicate(column_names:[java.nio.HeapByteBuffer[pos=0 lim=10 cap=10]]), range=[min(-1),m in(-1)], row_filter =[IndexExpression(column_name:6D 61 69 6C 65 6E 64 77 6E 64, op:EQ, value:00 00 01 3B 4A 04 64 20)], maxResults=10000, maxIsColumns=false}

/ONE
DEBUG [Thrift:14] 2012-11-30 08:35:20,778 StorageProxy.java (line 1073) restricted ranges for query [min(-1),min(-1)] are [[min(-1),max(0)], (max(0),max(21267647932558653966460912964485513216)], (max(21267647932558653966460912964485513216),max(42535295865117307932921825928971026432
)], (max(42535295865117307932921825928971026432),max(63802943797675961899382738893456539648)], (max(63802943797675961899382738893456539648),max(85070591730234615865843651857942052864)], (max(85070591730234615865843651857942052864),max(106338239662793269832304564822427566080)], (max
(106338239662793269832304564822427566080),max(127605887595351923798765477786913079296)], (max(127605887595351923798765477786913079296),max(148873535527910577765226390751398592512)], (max(148873535527910577765226390751398592512),min(-1)]]
DEBUG [Thrift:14] 2012-11-30 08:35:20,779 NetworkTopologyStrategy.java (line 125) /10.244.136.105,/10.244.137.238,/10.244.130.226 endpoints in datacenter us-west-2 for token 0
DEBUG [Thrift:14] 2012-11-30 08:35:20,780 StorageProxy.java (line 869) local range slice
DEBUG [Thrift:14] 2012-11-30 08:35:20,782 ExtendedFilter.java (line 181) adding columns to original Filter to cover additional expressions
DEBUG [Thrift:14] 2012-11-30 08:35:20,782 KeysSearcher.java (line 99) Primary scan clause is mailendwnd
DEBUG [Thrift:14] 2012-11-30 08:35:20,783 ColumnFamilyStore.java (line 1449) Filtering org.apache.cassandra.db.index.keys.KeysSearcher$1@60ce274e for rows matching org.apache.cassandra.db.filter.ExtendedFilter$FilterWithClauses@7e76a388
DEBUG [Thrift:14] 2012-11-30 08:35:20,784 KeysSearcher.java (line 135) Scanning index 'syndic.mailendwnd EQ 2012-11-29 02:35:00+0000' starting with
DEBUG [Thrift:14] 2012-11-30 08:35:20,784 CollationController.java (line 227) collectAllData
DEBUG [Thrift:14] 2012-11-30 08:35:20,784 KeysSearcher.java(line 145) fetched null
DEBUG [Thrift:14] 2012-11-30 08:35:20,784 KeysSearcher.java (line 148) no data, all done <----- THIS IS WHAT IT SAYS HERE

The issue comes from the following lines (KeysSearcher.java in package org.apache.cassandra.db.index.keys) :

if (logger.isDebugEnabled())
logger.debug(String.format("Scanning index %s starting with %s",
expressionString(primary), index.getBaseCfs().metadata.getKeyValidator().getString(startKey)));

QueryFilter indexFilter = QueryFilter.getSliceFilter(indexKey,
new QueryPath(index.getIndexCfs().getColumnFamilyName()),
lastSeenKey,
endKey,
false,
rowsPerQuery);
ColumnFamily indexRow = index.getIndexCfs().getColumnFamily(indexFilter); <---- it returns null
logger.debug("fetched {}", indexRow);
if (indexRow == null)

{ logger.debug("no data, all done"); return endOfData(); }

The matter is that indexFilter returns a new instance of QueryFilter with value

QueryFilter(key=DecoratedKey(2012-11-29 02:35:00+0000, 0000013b4a046420), path=QueryPath(columnFamilyName='syndic.mailIndex', superColumnName='null', columnName='null'), filter=SliceQueryFilter(start=java.nio.HeapByteBuffer[pos=0 lim=0 cap=0], finish=java.nio.HeapByteBuffer[pos=0 lim=0 cap=0], reversed=false, count=10000])

but then index.getIndexCfs().getColumnFamily(indexFilter) returns null !

The null value comes from the function removeDeletedCF in file ColumnFamilyStore.java where cf.getColumnCount() = 0 and cf.isMarkedForDelete()=false

Issue Links

• is duplicated by: CASSANDRA-5079 Compaction deletes ExpiringColumns in Secondary Indexes