You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@cassandra.apache.org by Jason Tang <ar...@gmail.com> on 2012/06/28 14:24:06 UTC
Failed to solve Digest mismatch
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
Re: Failed to solve Digest mismatch
Posted by Jason Tang <ar...@gmail.com>.
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 <jb...@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 <ar...@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
>>
>
>
>
Re: Failed to solve Digest mismatch
Posted by 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 <jb...@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 <ar...@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
>
Re: Failed to solve Digest mismatch
Posted by Jason Tang <ar...@gmail.com>.
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 <jb...@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 <ar...@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
>
Re: Failed to solve Digest mismatch
Posted by Jonathan Ellis <jb...@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 <ar...@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