incubator-cassandra-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Jason Tang <ares.t...@gmail.com>
Subject Re: Failed to solve Digest mismatch
Date Thu, 10 Oct 2013 03:07:32 GMT
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 <aaron@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 <jbellis@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.tang@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
>>
>
>
>

Mime
View raw message