Re: cli 'list' command not returning all data, get_range_slices bug?

[mike dooley]

hi, i wrote a little test program to duplicate the problem and eliminate pelops (attached)

CClient.java
Description: Binary data

. 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:6...@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:6...@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:6...@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:6...@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:6...@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:6...@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:6...@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:6...@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:6...@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:6...@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:6...@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:6...@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:6...@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:6...@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 <doo...@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. [defa...@unknown] use Test; Authenticated to keyspace: Test [defa...@test] list Configs; Using default limit of 100 0 Row Returned. [defa...@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. [defa...@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. [defa...@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-sch...@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