incubator-cassandra-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From mike dooley <doo...@apple.com>
Subject Re: cli 'list' command not returning all data, get_range_slices bug?
Date Thu, 23 Dec 2010 21:31:06 GMT
sorry i should also have included my cassandra.yml
and schema file too.  here they are

 

the only difference between the 2 nodes is the initial token, 0 for the local node (17.224.36.17)
and 85070591730234615865843651857942052864 for the remote node (17.224.109.80)




On Dec 23, 2010, at 1:00 PM, mike dooley wrote:

> hi,
> 
> i wrote a little test program to duplicate the problem and eliminate pelops (attached)
> <CClient.java>
> .
> 
> i think the problem may be related to
> 
> https://issues.apache.org/jira/browse/CASSANDRA-1198
> 
> because watching the logs (at debug level) i see the remote node returning
> its data, but not the local node.
> 
> here is the test program output:
> 
> === starting
> === inserting row: test-key-0
> === inserting row: test-key-1
> === inserting row: test-key-2
> === inserting row: test-key-3
> === inserting row: test-key-4
> === inserting row: test-key-5
> === inserting row: test-key-6
> === inserting row: test-key-7
> === inserting row: test-key-8
> === inserting row: test-key-9
> === 1) got test-key-1 = (dummy-col,twas brillig and the slithy toves did gyre and gimble
in the wabe-1)
> === 2) got test-key-0 = (dummy-col,twas brillig and the slithy toves did gyre and gimble
in the wabe-0)
> === 3) got test-key-3 = (dummy-col,twas brillig and the slithy toves did gyre and gimble
in the wabe-3)
> === 4) got test-key-7 = (dummy-col,twas brillig and the slithy toves did gyre and gimble
in the wabe-7)
> === 5) got test-key-8 = (dummy-col,twas brillig and the slithy toves did gyre and gimble
in the wabe-8)
> === 6) got test-key-6 = (dummy-col,twas brillig and the slithy toves did gyre and gimble
in the wabe-6)
> === !!!!!! didnt retrieve all the keys, 4 not found
> === crush all boxes
> 
> and here is what i see in the local logs
> 
> DEBUG [pool-1-thread-4] 2010-12-23 12:54:26,958 CassandraServer.java (line 479) range_slice
> DEBUG [pool-1-thread-4] 2010-12-23 12:54:26,958 StorageProxy.java (line 412) RangeSliceCommand{keyspace='Harvest',
column_family='TestCentroids', super_column=null, predicate=SlicePredicate(slice_range:SliceRange(start:80
01 00 01 00 00 00 10 67 65 74 5F 72 61 6E 67 65 5F 73 6C 69 63 65 73 00 00 00 0C 0C 00 01
0B 00 03 00 00 00 0D 54 65 73 74 43 65 6E 74 72 6F 69 64 73 00 0C 00 02 0C 00 02 0B 00 01
00 00 00 00, finish:80 01 00 01 00 00 00 10 67 65 74 5F 72 61 6E 67 65 5F 73 6C 69 63 65 73
00 00 00 0C 0C 00 01 0B 00 03 00 00 00 0D 54 65 73 74 43 65 6E 74 72 6F 69 64 73 00 0C 00
02 0C 00 02 0B 00 01 00 00 00 00 0B 00 02 00 00 00 00, reversed:false, count:1)), range=[0,0],
max_keys=11}
> DEBUG [pool-1-thread-4] 2010-12-23 12:54:26,958 StorageProxy.java (line 597) restricted
ranges for query [0,0] are [[0,0]]
> DEBUG [pool-1-thread-4] 2010-12-23 12:54:26,959 StorageProxy.java (line 423) === endpoint:
belize1.apple.com/17.224.36.17 for range.right 0
> DEBUG [pool-1-thread-4] 2010-12-23 12:54:26,963 StorageProxy.java (line 429) local range
slice
> DEBUG [pool-1-thread-4] 2010-12-23 12:54:26,964 SliceQueryFilter.java (line 129) collecting
0 of 1: dummy-col:false:67@0
> DEBUG [pool-1-thread-4] 2010-12-23 12:54:26,964 ColumnFamilyStore.java (line 1302) scanned
DecoratedKey(95096621805687029609476958853893340535, 746573742d6b65792d31)
> DEBUG [pool-1-thread-4] 2010-12-23 12:54:26,966 SliceQueryFilter.java (line 129) collecting
0 of 1: dummy-col:false:67@0
> DEBUG [pool-1-thread-4] 2010-12-23 12:54:26,967 ColumnFamilyStore.java (line 1302) scanned
DecoratedKey(102055691560625453887671437019240094911, 746573742d6b65792d30)
> DEBUG [pool-1-thread-4] 2010-12-23 12:54:26,969 SliceQueryFilter.java (line 129) collecting
0 of 1: dummy-col:false:67@0
> DEBUG [pool-1-thread-4] 2010-12-23 12:54:26,970 ColumnFamilyStore.java (line 1302) scanned
DecoratedKey(117642756708984234120792643012013573692, 746573742d6b65792d33)
> DEBUG [pool-1-thread-4] 2010-12-23 12:54:26,971 SliceQueryFilter.java (line 129) collecting
0 of 1: dummy-col:false:67@0
> DEBUG [pool-1-thread-4] 2010-12-23 12:54:26,971 ColumnFamilyStore.java (line 1302) scanned
DecoratedKey(120602233599396762327284348453927679148, 746573742d6b65792d37)
> DEBUG [pool-1-thread-4] 2010-12-23 12:54:26,971 SliceQueryFilter.java (line 129) collecting
0 of 1: dummy-col:false:67@0
> DEBUG [pool-1-thread-4] 2010-12-23 12:54:26,972 ColumnFamilyStore.java (line 1302) scanned
DecoratedKey(137773384635200264868762149853169090749, 746573742d6b65792d38)
> DEBUG [pool-1-thread-4] 2010-12-23 12:54:26,972 SliceQueryFilter.java (line 129) collecting
0 of 1: dummy-col:false:67@0
> DEBUG [pool-1-thread-4] 2010-12-23 12:54:26,972 ColumnFamilyStore.java (line 1302) scanned
DecoratedKey(145724861122056045272863275223173725919, 746573742d6b65792d36)
> DEBUG [pool-1-thread-4] 2010-12-23 12:54:27,013 ClientState.java (line 88) logged out:
#<User allow_all groups=[]>
> 
> and here are the remote node logs
> 
> DEBUG [MutationStage:17] 2010-12-23 12:55:32,735 RowMutationVerbHandler.java (line 54)
Applying RowMutation(keyspace='Harvest', key='746573742d6b65792d32', modifications=[ColumnFamily(TestCentroids
[dummy-col:false:67@0,])])
> DEBUG [MutationStage:17] 2010-12-23 12:55:32,736 Table.java (line 386) applying mutation
of row 746573742d6b65792d32
> DEBUG [MutationStage:17] 2010-12-23 12:55:32,736 RowMutationVerbHandler.java (line 78)
RowMutation(keyspace='Harvest', key='746573742d6b65792d32', modifications=[ColumnFamily(TestCentroids
[dummy-col:false:67@0,])]) applied.  Sending response to 20602@/17.224.36.17
> DEBUG [MutationStage:18] 2010-12-23 12:55:32,741 RowMutationVerbHandler.java (line 54)
Applying RowMutation(keyspace='Harvest', key='746573742d6b65792d34', modifications=[ColumnFamily(TestCentroids
[dummy-col:false:67@0,])])
> DEBUG [MutationStage:18] 2010-12-23 12:55:32,742 Table.java (line 386) applying mutation
of row 746573742d6b65792d34
> DEBUG [MutationStage:18] 2010-12-23 12:55:32,742 RowMutationVerbHandler.java (line 78)
RowMutation(keyspace='Harvest', key='746573742d6b65792d34', modifications=[ColumnFamily(TestCentroids
[dummy-col:false:67@0,])]) applied.  Sending response to 20603@/17.224.36.17
> DEBUG [MutationStage:19] 2010-12-23 12:55:32,745 RowMutationVerbHandler.java (line 54)
Applying RowMutation(keyspace='Harvest', key='746573742d6b65792d35', modifications=[ColumnFamily(TestCentroids
[dummy-col:false:67@0,])])
> DEBUG [MutationStage:19] 2010-12-23 12:55:32,745 Table.java (line 386) applying mutation
of row 746573742d6b65792d35
> DEBUG [MutationStage:19] 2010-12-23 12:55:32,746 RowMutationVerbHandler.java (line 78)
RowMutation(keyspace='Harvest', key='746573742d6b65792d35', modifications=[ColumnFamily(TestCentroids
[dummy-col:false:67@0,])]) applied.  Sending response to 20604@/17.224.36.17
> DEBUG [MutationStage:20] 2010-12-23 12:55:32,753 RowMutationVerbHandler.java (line 54)
Applying RowMutation(keyspace='Harvest', key='746573742d6b65792d39', modifications=[ColumnFamily(TestCentroids
[dummy-col:false:67@0,])])
> DEBUG [MutationStage:20] 2010-12-23 12:55:32,754 Table.java (line 386) applying mutation
of row 746573742d6b65792d39
> DEBUG [MutationStage:20] 2010-12-23 12:55:32,754 RowMutationVerbHandler.java (line 78)
RowMutation(keyspace='Harvest', key='746573742d6b65792d39', modifications=[ColumnFamily(TestCentroids
[dummy-col:false:67@0,])]) applied.  Sending response to 20605@/17.224.36.17
> 
> so it seems that all 6 of the results that are returned are coming from the remote node,
> and nothing is being retrieved from the local node.
> 
> thanks,
> -mike
> 
> 
> 
> On Dec 22, 2010, at 1:42 PM, Jonathan Ellis wrote:
> 
>> what do you see in the logs during the list command at debug level?
>> 
>> On Tue, Dec 21, 2010 at 5:01 PM, mike dooley <dooley@apple.com> wrote:
>>> hi,
>>> i am using version 0.7-rc2 and pelops-c642967 from java.  when i try
>>> to export all the data in a column family i don't get all of the data that
>>> was inserted.  i suspect that this points to an underlying problem with
>>> the get_range_slices method.
>>> i can reproduce the problem just using the command line interface
>>> as follows:
>>> 1) create a 2 node cluster using the default cassandra.yml with these
>>> changes:
>>> * set the initial token for the 1st node:
>>> initial_token: 0
>>> * set the initial token for the 2nd node:
>>> initial_token: 85070591730234615865843651857942052864
>>> *comment out:
>>> #listen_address: localhost
>>> #rpc_address: localhost
>>> *set the seeds (change ip's)
>>> seeds:
>>>    - 17.224.109.80
>>>    - 17.224.109.81
>>> 2) start both nodes
>>> 3) put these commands in a file called schema.txt
>>> create keyspace Test with replication_factor = 1 and placement_strategy =
>>> 'org.apache.cassandra.locator.SimpleStrategy';
>>> use Test;
>>> create column family Configs with column_type = 'Standard' and comparator =
>>> 'UTF8Type';
>>> and load them with the command line tool like this:
>>> ./bin/cassandra-cli --host 17.224.109.80 < schema.txt
>>> 4) put these commands in a file called config.txt
>>> use Test;
>>> set Configs['row-a']['key-a'] = '1';
>>> set Configs['row-a']['key-b'] = '2';
>>> set Configs['row-a']['key-c'] = '3';
>>> set Configs['row-b']['key-a'] = '4';
>>> set Configs['row-b']['key-b'] = '5';
>>> set Configs['row-b']['key-c'] = '6';
>>> set Configs['row-c']['key-a'] = '7';
>>> set Configs['row-c']['key-b'] = '8';
>>> set Configs['row-c']['key-c'] = '9';
>>> and load them with the command line tool like this:
>>> ./bin/cassandra-cli --host 17.224.109.80 < config.txt
>>> 5)  now start the command line tool and try to list the Configs column
>>> family:
>>> ./bin/cassandra-cli --host 17.224.109.80
>>> Connected to: "Test Cluster" on 17.224.109.80/9160
>>> Welcome to cassandra CLI.
>>> Type 'help;' or '?' for help. Type 'quit;' or 'exit;' to quit.
>>> [default@unknown] use Test;
>>> Authenticated to keyspace: Test
>>> [default@Test] list Configs;
>>> Using default limit of 100
>>> 0 Row Returned.
>>> [default@Test] get Configs['row-a'];
>>> => (column=key-a, value=31, timestamp=1292970451049000)
>>> => (column=key-b, value=32, timestamp=1292970451099000)
>>> => (column=key-c, value=33, timestamp=1292970451104000)
>>> Returned 3 results.
>>> [default@Test] get Configs['row-b'];
>>> => (column=key-a, value=34, timestamp=1292970451108000)
>>> => (column=key-b, value=35, timestamp=1292970451111000)
>>> => (column=key-c, value=36, timestamp=1292970451116000)
>>> Returned 3 results.
>>> [default@Test] get Configs['row-c'];
>>> => (column=key-a, value=37, timestamp=1292970451120000)
>>> => (column=key-b, value=38, timestamp=1292970451123000)
>>> => (column=key-c, value=39, timestamp=1292970451128000)
>>> Returned 3 results.
>>> note: that the 'list Configs' command doesn't return any results,
>>> but when you 'get' a particular row the data is there.
>>> note: when only using a single node everything works as
>>> expected
>>> note: that if you try to combine schema.txt and config.txt and
>>> load all at once the first data point fails to load and the following
>>> error shows up in the 2nd node's logs:
>>>  INFO [FlushWriter:1] 2010-12-21 12:30:25,701 Memtable.java (line 155)
>>> Writing Memtable-Schema@390276053(2184 bytes, 3 operations)
>>> ERROR [MutationStage:1] 2010-12-21 12:30:25,718 RowMutationVerbHandler.java
>>> (line 83) Error in row mutation
>>> org.apache.cassandra.db.UnserializableColumnFamilyException: Couldn't find
>>> cfId=1000
>>>         at
>>> org.apache.cassandra.db.ColumnFamilySerializer.deserialize(ColumnFamilySerializer.java:117)
>>>         at
>>> org.apache.cassandra.db.RowMutationSerializer.defreezeTheMaps(RowMutation.java:383)
>>>         at
>>> org.apache.cassandra.db.RowMutationSerializer.deserialize(RowMutation.java:393)
>>>         at
>>> org.apache.cassandra.db.RowMutationSerializer.deserialize(RowMutation.java:351)
>>>         at
>>> org.apache.cassandra.db.RowMutationVerbHandler.doVerb(RowMutationVerbHandler.java:52)
>>>         at
>>> org.apache.cassandra.net.MessageDeliveryTask.run(MessageDeliveryTask.java:63)
>>>         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)
>>>  INFO [FlushWriter:1] 2010-12-21 12:30:25,925 Memtable.java (line 162)
>>> Completed flushing /var/lib/cassandra/data/system/Schema-e-1-Data.db (2472
>>> byte
>>> has anyone else seen anything similar or is there something that i'm
>>> missing?
>>> thanks,
>>> -mike
>>> 
>> 
>> 
>> 
>> -- 
>> Jonathan Ellis
>> Project Chair, Apache Cassandra
>> co-founder of Riptano, the source for professional Cassandra support
>> http://riptano.com
> 


Mime
View raw message