I did some test on this issue, and it turns out the problem caused by local time stamp. In our traffic, the update and delete happened very fast, within 1 seconds, even within 100ms. And at that time, the ntp service seems not work well, the offset is same times even larger then 1 second.
Then the some delete time stamp is before the create time stamp, so when do mismatch resolve, the result is not correct. 2012/7/4 aaron morton <aa...@thelastpickle.com> > Jason, > Are you able document the steps to reproduce this on a clean install ? > > Is so do you have time to create an issue on > https://issues.apache.org/jira/browse/CASSANDRA > > Thanks > > > ----------------- > Aaron Morton > Freelance Developer > @aaronmorton > http://www.thelastpickle.com > > On 2/07/2012, at 1:49 AM, Jason Tang wrote: > > For the create/update/deleteColumn/deleteRow test case, for Quorum > consistency level, 6 nodes, replicate factor 3, for one thread around 1/100 > round, I can have this reproduced. > > And if I have 20 client threads to run the test client, the ratio is > bigger. > > And the test group will be executed by one thread, and the client time > stamp is unique and sequenced, guaranteed by Hector. > > And client only access the data from local Cassandra. > > And the query only use the row key which is unique. The column name is not > unique, in my case, eg, "status". > > And the row have around 7 columns, which are all not big, eg > "status:true", "userName:Jason" ... > > BRs > //Ares > > 2012/7/1 Jonathan Ellis <jbel...@gmail.com> > >> Is this Cassandra 1.1.1? >> >> How often do you observe this? How many columns are in the row? Can >> you reproduce when querying by column name, or only when "slicing" the >> row? >> >> On Thu, Jun 28, 2012 at 7:24 AM, Jason Tang <ares.t...@gmail.com> wrote: >> > Hi >> > >> > First I delete one column, then I delete one row. Then try to read >> all >> > columns from the same row, all operations from same client app. >> > >> > The consistency level is read/write quorum. >> > >> > Check the Cassandra log, the local node don't perform the delete >> > operation but send the mutation to other nodes (192.168.0.6, >> 192.168.0.1) >> > >> > After delete, I try to read all columns from the row, I found the >> node >> > found "Digest mismatch" due to Quorum consistency configuration, but the >> > result is not correct. >> > >> > From the log, I can see the delete mutation already accepted >> > by 192.168.0.6, 192.168.0.1, but when 192.168.0.5 read response from >> 0.6 >> > and 0.1, and then it merge the data, but finally 0.5 shows the result >> which >> > is the dirty data. >> > >> > Following logs shows the change of column "737461747573" , >> 192.168.0.5 >> > try to read from 0.1 and 0.6, it should be deleted, but finally it >> shows it >> > has the data. >> > >> > log: >> > 192.168.0.5 >> > DEBUG [Thrift:17] 2012-06-28 15:59:42,198 StorageProxy.java (line 653) >> > Command/ConsistencyLevel is SliceByNamesReadCommand(table='drc', >> > key=7878323239537570657254616e67307878, >> > columnParent='QueryPath(columnFamilyName='queue', >> superColumnName='null', >> > columnName='null')', >> > >> columns=[6578656375746554696d65,6669726554696d65,67726f75705f6964,696e517565756554696d65,6c6f67526f6f744964,6d6f54797065,706172746974696f6e,7265636569766554696d65,72657175657374,7265747279,7365727669636550726f7669646572,737461747573,757365724e616d65,])/QUORUM >> > DEBUG [Thrift:17] 2012-06-28 15:59:42,198 ReadCallback.java (line 79) >> > Blockfor is 2; setting up requests to /192.168.0.6,/192.168.0.1 >> > DEBUG [Thrift:17] 2012-06-28 15:59:42,198 StorageProxy.java (line 674) >> > reading data from /192.168.0.6 >> > DEBUG [Thrift:17] 2012-06-28 15:59:42,198 StorageProxy.java (line 694) >> > reading digest from /192.168.0.1 >> > DEBUG [RequestResponseStage:2] 2012-06-28 15:59:42,199 >> > ResponseVerbHandler.java (line 44) Processing response on a callback >> from >> > 6556@/192.168.0.6 >> > DEBUG [RequestResponseStage:2] 2012-06-28 15:59:42,199 >> > AbstractRowResolver.java (line 66) Preprocessed data response >> > DEBUG [RequestResponseStage:6] 2012-06-28 15:59:42,199 >> > ResponseVerbHandler.java (line 44) Processing response on a callback >> from >> > 6557@/192.168.0.1 >> > DEBUG [RequestResponseStage:6] 2012-06-28 15:59:42,199 >> > AbstractRowResolver.java (line 66) Preprocessed digest response >> > DEBUG [Thrift:17] 2012-06-28 15:59:42,199 RowDigestResolver.java (line >> 65) >> > resolving 2 responses >> > DEBUG [Thrift:17] 2012-06-28 15:59:42,200 StorageProxy.java (line 733) >> > Digest mismatch: org.apache.cassandra.service.DigestMismatchException: >> > Mismatch for key DecoratedKey(100572974179274741747356988451225858264, >> > 7878323239537570657254616e67307878) (b725ab25696111be49aaa7c4b7afa52d vs >> > d41d8cd98f00b204e9800998ecf8427e) >> > DEBUG [RequestResponseStage:9] 2012-06-28 15:59:42,201 >> > ResponseVerbHandler.java (line 44) Processing response on a callback >> from >> > 6558@/192.168.0.6 >> > DEBUG [RequestResponseStage:7] 2012-06-28 15:59:42,201 >> > ResponseVerbHandler.java (line 44) Processing response on a callback >> from >> > 6559@/192.168.0.1 >> > DEBUG [RequestResponseStage:9] 2012-06-28 15:59:42,201 >> > AbstractRowResolver.java (line 66) Preprocessed data response >> > DEBUG [RequestResponseStage:7] 2012-06-28 15:59:42,201 >> > AbstractRowResolver.java (line 66) Preprocessed data response >> > DEBUG [Thrift:17] 2012-06-28 15:59:42,201 RowRepairResolver.java (line >> 63) >> > resolving 2 responses >> > DEBUG [Thrift:17] 2012-06-28 15:59:42,201 SliceQueryFilter.java (line >> 123) >> > collecting 0 of 2147483647: 6669726554696d65:false:13@1340870382109004 >> > DEBUG [Thrift:17] 2012-06-28 15:59:42,201 SliceQueryFilter.java (line >> 123) >> > collecting 1 of 2147483647: 67726f75705f6964:false:10@1340870382109014 >> > DEBUG [Thrift:17] 2012-06-28 15:59:42,201 SliceQueryFilter.java (line >> 123) >> > collecting 2 of 2147483647: >> 696e517565756554696d65:false:13@1340870382109005 >> > DEBUG [Thrift:17] 2012-06-28 15:59:42,201 SliceQueryFilter.java (line >> 123) >> > collecting 3 of 2147483647: 6c6f67526f6f744964:false:7@1340870382109015 >> > DEBUG [Thrift:17] 2012-06-28 15:59:42,202 SliceQueryFilter.java (line >> 123) >> > collecting 4 of 2147483647: 6d6f54797065:false:6@1340870382109009 >> > DEBUG [Thrift:17] 2012-06-28 15:59:42,202 SliceQueryFilter.java (line >> 123) >> > collecting 5 of 2147483647: 706172746974696f6e:false:2@1340870382109001 >> > DEBUG [Thrift:17] 2012-06-28 15:59:42,202 SliceQueryFilter.java (line >> 123) >> > collecting 6 of 2147483647: >> 7265636569766554696d65:false:13@1340870382109003 >> > DEBUG [Thrift:17] 2012-06-28 15:59:42,202 SliceQueryFilter.java (line >> 123) >> > collecting 7 of 2147483647: 72657175657374:false:300@1340870382109013 >> > DEBUG [RequestResponseStage:5] 2012-06-28 15:59:42,202 >> > ResponseVerbHandler.java (line 44) Processing response on a callback >> from >> > 6552@/192.168.0.1 >> > DEBUG [Thrift:17] 2012-06-28 15:59:42,202 SliceQueryFilter.java (line >> 123) >> > collecting 8 of 2147483647: 7265747279:false:1@1340870382109006 >> > DEBUG [Thrift:17] 2012-06-28 15:59:42,202 SliceQueryFilter.java (line >> 123) >> > collecting 9 of 2147483647: >> > 7365727669636550726f7669646572:false:4@1340870382109007 >> > DEBUG [Thrift:17] 2012-06-28 15:59:42,203 SliceQueryFilter.java (line >> 123) >> > collecting 10 of 2147483647: 737461747573:false:8@1340870382152000 >> > DEBUG [Thrift:17] 2012-06-28 15:59:42,203 SliceQueryFilter.java (line >> 123) >> > collecting 11 of 2147483647: 757365724e616d65:false:4@1340870382109000 >> > DEBUG [Thrift:17] 2012-06-28 15:59:42,203 RowRepairResolver.java (line >> 89) >> > versions merged >> > DEBUG [Thrift:17] 2012-06-28 15:59:42,203 RowRepairResolver.java (line >> 102) >> > resolve: 2 ms. >> > DEBUG [Thrift:18] 2012-06-28 15:59:42,204 ClientState.java (line 123) >> logged >> > in: #<User casadm groups=[]> >> > DEBUG [Thrift:18] 2012-06-28 15:59:42,204 CassandraServer.java (line >> 305) >> > get_slice >> > >> > 192.168.0.1: >> > DEBUG [MutationStage:21] 2012-06-28 15:59:42,177 >> RowMutationVerbHandler.java >> > (line 44) Applying RowMutation(keyspace='drc', >> > key='7878323239537570657254616e67307878', >> modifications=[ColumnFamily(queue >> > [737461747573:true:4@1340870382175000,])]) >> > DEBUG [MutationStage:21] 2012-06-28 15:59:42,178 Table.java (line 391) >> > applying mutation of row 7878323239537570657254616e67307878 >> > DEBUG [MutationStage:23] 2012-06-28 15:59:42,187 >> RowMutationVerbHandler.java >> > (line 44) Applying RowMutation(keyspace='drc', >> > key='7878323239537570657254616e67307878', >> modifications=[ColumnFamily(queue >> > -deleted at 1340870382185000- [])]) >> > DEBUG [MutationStage:23] 2012-06-28 15:59:42,187 Table.java (line 391) >> > applying mutation of row 7878323239537570657254616e67307878 >> > DEBUG [MutationStage:20] 2012-06-28 15:59:42,189 Table.java (line 425) >> > mutating indexed column 737461747573 value 4445515545554544 >> > DEBUG [MutationStage:20] 2012-06-28 15:59:42,189 >> CollationController.java >> > (line 77) collectTimeOrderedData >> > DEBUG [MutationStage:20] 2012-06-28 15:59:42,190 Table.java (line 449) >> > Pre-mutation index row is ColumnFamily(queue >> > [737461747573:false:8@1340870382152000,]) >> > DEBUG [MutationStage:20] 2012-06-28 15:59:42,190 Table.java (line 500) >> > skipping index update for obsolete mutation of 737461747573 >> > DEBUG [ReadStage:5] 2012-06-28 15:59:42,199 CollationController.java >> (line >> > 77) collectTimeOrderedData >> > DEBUG [ReadStage:5] 2012-06-28 15:59:42,199 ReadVerbHandler.java (line >> 73) >> > digest is b725ab25696111be49aaa7c4b7afa52d >> > DEBUG [ReadStage:5] 2012-06-28 15:59:42,199 ReadVerbHandler.java (line >> 58) >> > Read key 7878323239537570657254616e67307878; sending response to >> > 6557@/192.168.0.3 >> > DEBUG [ReadStage:6] 2012-06-28 15:59:42,200 CollationController.java >> (line >> > 77) collectTimeOrderedData >> > DEBUG [ReadStage:6] 2012-06-28 15:59:42,201 ReadVerbHandler.java (line >> 58) >> > Read key 7878323239537570657254616e67307878; sending response to >> > 6559@/192.168.0.3 >> > DEBUG [MutationStage:23] 2012-06-28 15:59:42,201 Table.java (line 425) >> > mutating indexed column 6669726554696d65 value null >> > DEBUG [MutationStage:21] 2012-06-28 15:59:42,201 Table.java (line 425) >> > mutating indexed column 737461747573 value 4fec0eee >> > DEBUG [MutationStage:23] 2012-06-28 15:59:42,201 Table.java (line 425) >> > mutating indexed column 6669726554696d65536c696365 value null >> > DEBUG [MutationStage:21] 2012-06-28 15:59:42,201 >> CollationController.java >> > (line 77) collectTimeOrderedData >> > DEBUG [MutationStage:23] 2012-06-28 15:59:42,202 Table.java (line 425) >> > mutating indexed column 696e517565756554696d65 value null >> > DEBUG [MutationStage:21] 2012-06-28 15:59:42,202 Table.java (line 449) >> > Pre-mutation index row is ColumnFamily(queue >> > [737461747573:false:8@1340870382152000,]) >> > DEBUG [MutationStage:23] 2012-06-28 15:59:42,202 Table.java (line 425) >> > mutating indexed column 696e517565756554696d65536c696365 value null >> > DEBUG [MutationStage:23] 2012-06-28 15:59:42,202 Table.java (line 425) >> > mutating indexed column 6d6f54797065 value null >> > DEBUG [MutationStage:21] 2012-06-28 15:59:42,202 KeysIndex.java (line >> 103) >> > removed index entry for cleaned-up value DecoratedKey(DEQUEUED, >> > 4445515545554544):ColumnFamily(queue.idxStatus >> > [7878323239537570657254616e67307878:true:4@1340870382152000,]) >> > DEBUG [MutationStage:23] 2012-06-28 15:59:42,202 Table.java (line 425) >> > mutating indexed column 706172746974696f6e value null >> > DEBUG [MutationStage:21] 2012-06-28 15:59:42,202 >> RowMutationVerbHandler.java >> > (line 56) RowMutation(keyspace='drc', >> > key='7878323239537570657254616e67307878', >> modifications=[ColumnFamily(queue >> > [737461747573:true:4@1340870382175000,])]) applied. Sending response >> to >> > 6552@/192.168.0.3 >> > >> > 192.168.0.6: >> > DEBUG [MutationStage:6] 2012-06-28 15:59:42,177 >> RowMutationVerbHandler.java >> > (line 44) Applying RowMutation(keyspace='drc', >> > key='7878323239537570657254616e67307878', >> modifications=[ColumnFamily(queue >> > [737461747573:true:4@1340870382175000,])]) >> > DEBUG [MutationStage:6] 2012-06-28 15:59:42,177 Table.java (line 391) >> > applying mutation of row 7878323239537570657254616e67307878 >> > DEBUG [MutationStage:6] 2012-06-28 15:59:42,184 Table.java (line 425) >> > mutating indexed column 737461747573 value 4fec0eee >> > DEBUG [MutationStage:6] 2012-06-28 15:59:42,184 CollationController.java >> > (line 77) collectTimeOrderedData >> > DEBUG [MutationStage:6] 2012-06-28 15:59:42,184 Table.java (line 449) >> > Pre-mutation index row is ColumnFamily(queue >> > [737461747573:false:8@1340870382152000,]) >> > DEBUG [MutationStage:6] 2012-06-28 15:59:42,184 KeysIndex.java (line >> 103) >> > removed index entry for cleaned-up value DecoratedKey(DEQUEUED, >> > 4445515545554544):ColumnFamily(queue.idxStatus >> > [7878323239537570657254616e67307878:true:4@1340870382152000,]) >> > DEBUG [MutationStage:6] 2012-06-28 15:59:42,184 >> RowMutationVerbHandler.java >> > (line 56) RowMutation(keyspace='drc', >> > key='7878323239537570657254616e67307878', >> modifications=[ColumnFamily(queue >> > [737461747573:true:4@1340870382175000,])]) applied. Sending response >> to >> > 6550@/192.168.0.3 >> > DEBUG [MutationStage:10] 2012-06-28 15:59:42,187 >> RowMutationVerbHandler.java >> > (line 44) Applying RowMutation(keyspace='drc', >> > key='7878323239537570657254616e67307878', >> modifications=[ColumnFamily(queue >> > -deleted at 1340870382185000- [])]) >> > DEBUG [MutationStage:10] 2012-06-28 15:59:42,187 Table.java (line 391) >> > applying mutation of row 7878323239537570657254616e67307878 >> > DEBUG [MutationStage:10] 2012-06-28 15:59:42,190 Table.java (line 425) >> > mutating indexed column 6669726554696d65 value null >> > DEBUG [MutationStage:10] 2012-06-28 15:59:42,190 Table.java (line 425) >> > mutating indexed column 6669726554696d65536c696365 value null >> > DEBUG [MutationStage:10] 2012-06-28 15:59:42,190 Table.java (line 425) >> > mutating indexed column 696e517565756554696d65 value null >> > DEBUG [MutationStage:10] 2012-06-28 15:59:42,190 Table.java (line 425) >> > mutating indexed column 696e517565756554696d65536c696365 value null >> > DEBUG [MutationStage:10] 2012-06-28 15:59:42,190 Table.java (line 425) >> > mutating indexed column 6d6f54797065 value null >> > DEBUG [MutationStage:10] 2012-06-28 15:59:42,190 Table.java (line 425) >> > mutating indexed column 706172746974696f6e value null >> > DEBUG [MutationStage:10] 2012-06-28 15:59:42,190 Table.java (line 425) >> > mutating indexed column 7265636569766554696d65 value null >> > DEBUG [MutationStage:10] 2012-06-28 15:59:42,190 Table.java (line 425) >> > mutating indexed column 7265636569766554696d65536c696365 value null >> > DEBUG [MutationStage:10] 2012-06-28 15:59:42,191 Table.java (line 425) >> > mutating indexed column 7365727669636550726f7669646572 value null >> > DEBUG [MutationStage:10] 2012-06-28 15:59:42,191 Table.java (line 425) >> > mutating indexed column 737461747573 value null >> > DEBUG [MutationStage:10] 2012-06-28 15:59:42,191 >> CollationController.java >> > (line 77) collectTimeOrderedData >> > DEBUG [MutationStage:10] 2012-06-28 15:59:42,191 Table.java (line 449) >> > Pre-mutation index row is ColumnFamily(queue >> > [6669726554696d65:false:13@1340870382109004 >> ,6669726554696d65536c696365:false:13@1340870382109011 >> ,696e517565756554696d65:false:13@1340870382109005 >> ,696e517565756554696d65536c696365:false:13@1340870382109012 >> ,6d6f54797065:false:6@1340870382109009 >> ,706172746974696f6e:false:2@1340870382109001 >> ,7265636569766554696d65:false:13@1340870382109003 >> ,7265636569766554696d65536c696365:false:13@1340870382109010 >> ,7365727669636550726f7669646572:false:4@1340870382109007 >> ,737461747573:true:4@1340870382175000,]) >> > DEBUG [MutationStage:10] 2012-06-28 15:59:42,191 Table.java (line 500) >> > skipping index update for obsolete mutation of 737461747573 >> > DEBUG [MutationStage:10] 2012-06-28 15:59:42,191 KeysIndex.java (line >> 103) >> > removed index entry for cleaned-up value >> > DecoratedKey(3898026790553046681950927403065, >> > 31333430383730333531373839):ColumnFamily(queue.idxFireTime >> > [7878323239537570657254616e67307878:true:4@1340870382109004,]) >> > DEBUG [MutationStage:10] 2012-06-28 15:59:42,192 KeysIndex.java (line >> 103) >> > removed index entry for cleaned-up value >> > DecoratedKey(3898026790552830793920833138736, >> > 31333430383431363030303030):ColumnFamily(queue.idxFireTimeRange >> > [7878323239537570657254616e67307878:true:4@1340870382109011,]) >> > DEBUG [MutationStage:10] 2012-06-28 15:59:42,192 KeysIndex.java (line >> 103) >> > removed index entry for cleaned-up value >> > DecoratedKey(3898026790553046681950927403065, >> > 31333430383730333531373839):ColumnFamily(queue.idxInQueueTime >> > [7878323239537570657254616e67307878:true:4@1340870382109005,]) >> > DEBUG [MutationStage:10] 2012-06-28 15:59:42,192 KeysIndex.java (line >> 103) >> > removed index entry for cleaned-up value >> > DecoratedKey(3898026790552830793920833138736, >> > 31333430383431363030303030):ColumnFamily(queue.idxInQueueTimeRange >> > [7878323239537570657254616e67307878:true:4@1340870382109012,]) >> > DEBUG [MutationStage:10] 2012-06-28 15:59:42,192 KeysIndex.java (line >> 103) >> > removed index entry for cleaned-up value DecoratedKey(TestMo, >> > 546573744d6f):ColumnFamily(queue.idxMoType >> > [7878323239537570657254616e67307878:true:4@1340870382109009,]) >> > DEBUG [MutationStage:10] 2012-06-28 15:59:42,193 KeysIndex.java (line >> 103) >> > removed index entry for cleaned-up value DecoratedKey(32, >> > 3332):ColumnFamily(queue.idxPartitionId >> > [7878323239537570657254616e67307878:true:4@1340870382109001,]) >> > DEBUG [MutationStage:10] 2012-06-28 15:59:42,193 KeysIndex.java (line >> 103) >> > removed index entry for cleaned-up value >> > DecoratedKey(3898026790553046681950927403065, >> > 31333430383730333531373839):ColumnFamily(queue.idxRecvTime >> > [7878323239537570657254616e67307878:true:4@1340870382109003,]) >> > DEBUG [MutationStage:10] 2012-06-28 15:59:42,193 KeysIndex.java (line >> 103) >> > removed index entry for cleaned-up value >> > DecoratedKey(3898026790552830793920833138736, >> > 31333430383431363030303030):ColumnFamily(queue.idxRecvTimeRange >> > [7878323239537570657254616e67307878:true:4@1340870382109010,]) >> > DEBUG [MutationStage:10] 2012-06-28 15:59:42,193 KeysIndex.java (line >> 103) >> > removed index entry for cleaned-up value DecoratedKey(test, >> > 74657374):ColumnFamily(queue.idxServiceProvider >> > [7878323239537570657254616e67307878:true:4@1340870382109007,]) >> > DEBUG [MutationStage:10] 2012-06-28 15:59:42,193 >> RowMutationVerbHandler.java >> > (line 56) RowMutation(keyspace='drc', >> > key='7878323239537570657254616e67307878', >> modifications=[ColumnFamily(queue >> > -deleted at 1340870382185000- [])]) applied. Sending response to >> > 6553@/192.168.0.3 >> > DEBUG [ReadStage:17] 2012-06-28 15:59:42,198 CollationController.java >> (line >> > 77) collectTimeOrderedData >> > DEBUG [ReadStage:17] 2012-06-28 15:59:42,199 ReadVerbHandler.java (line >> 58) >> > Read key 7878323239537570657254616e67307878; sending response to >> > 6556@/192.168.0.3 >> > >> > BRs >> > //Ares >> >> >> >> -- >> Jonathan Ellis >> Project Chair, Apache Cassandra >> co-founder of DataStax, the source for professional Cassandra support >> http://www.datastax.com >> > > >
