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
>
