Return-Path: X-Original-To: apmail-cassandra-user-archive@www.apache.org Delivered-To: apmail-cassandra-user-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 087E59DFD for ; Sun, 1 Jul 2012 13:49:44 +0000 (UTC) Received: (qmail 77280 invoked by uid 500); 1 Jul 2012 13:49:41 -0000 Delivered-To: apmail-cassandra-user-archive@cassandra.apache.org Received: (qmail 77042 invoked by uid 500); 1 Jul 2012 13:49:41 -0000 Mailing-List: contact user-help@cassandra.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: user@cassandra.apache.org Delivered-To: mailing list user@cassandra.apache.org Received: (qmail 77028 invoked by uid 99); 1 Jul 2012 13:49:40 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Sun, 01 Jul 2012 13:49:40 +0000 X-ASF-Spam-Status: No, hits=1.5 required=5.0 tests=FSL_RCVD_USER,HTML_MESSAGE,NORMAL_HTTP_TO_IP,RCVD_IN_DNSWL_LOW,SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (nike.apache.org: domain of ares.tang@gmail.com designates 209.85.161.172 as permitted sender) Received: from [209.85.161.172] (HELO mail-gg0-f172.google.com) (209.85.161.172) by apache.org (qpsmtpd/0.29) with ESMTP; Sun, 01 Jul 2012 13:49:33 +0000 Received: by ggnc4 with SMTP id c4so4023475ggn.31 for ; Sun, 01 Jul 2012 06:49:12 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=mime-version:in-reply-to:references:date:message-id:subject:from:to :content-type; bh=yEB4uneEoJva8rE6l73zX2V+sktZNv1x51w7uTSsRtg=; b=IDsSn9c1mJdZgDNzY0BYZbLpluNdgJgwppSiXSMWqgXSrDM0ed0co1QfSlYpe8f0tD LRz5sMoN6LbEridTwoKgk2FnqD2T4edjNkQolOTSP283ktsyo5g+sWOxh+FERkouWNCb k7Py+s4A8J9qMRpPltGrQjgGx7iGFMdh8SDbjAaryNZzbI73gPn1pAEYbwB7azlVZ6t1 j5HmZJ0eu08m2Pt9w2m1Q6BX2cDZYgC2S4Bn0KLmyweo2HBhWwHohfBrMvt2TKYCFwRZ FJxwrC24/jOm0Ayj9a8vOgzecDo3HqtW3z2N9EbY+/5Qc45+CZ966nYlaG7ips9fRIzS sbHg== MIME-Version: 1.0 Received: by 10.50.242.101 with SMTP id wp5mr3218090igc.12.1341150551957; Sun, 01 Jul 2012 06:49:11 -0700 (PDT) Received: by 10.50.178.69 with HTTP; Sun, 1 Jul 2012 06:49:11 -0700 (PDT) In-Reply-To: References: Date: Sun, 1 Jul 2012 21:49:11 +0800 Message-ID: Subject: Re: Failed to solve Digest mismatch From: Jason Tang To: user@cassandra.apache.org Content-Type: multipart/alternative; boundary=f46d044787613d627204c3c4f27c --f46d044787613d627204c3c4f27c Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: quoted-printable 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 > 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 wrote: > > Hi > > > > First I delete one column, then I delete one row. Then try to read a= ll > > 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 no= de > > found "Digest mismatch" due to Quorum consistency configuration, but th= e > > 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 show= s > 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=3D'drc', > > key=3D7878323239537570657254616e67307878, > > columnParent=3D'QueryPath(columnFamilyName=3D'queue', superColumnName= =3D'null', > > columnName=3D'null')', > > > columns=3D[6578656375746554696d65,6669726554696d65,67726f75705f6964,696e5= 17565756554696d65,6c6f67526f6f744964,6d6f54797065,706172746974696f6e,726563= 6569766554696d65,72657175657374,7265747279,7365727669636550726f7669646572,7= 37461747573,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 fr= om > > 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 fr= om > > 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 v= s > > d41d8cd98f00b204e9800998ecf8427e) > > DEBUG [RequestResponseStage:9] 2012-06-28 15:59:42,201 > > ResponseVerbHandler.java (line 44) Processing response on a callback fr= om > > 6558@/192.168.0.6 > > DEBUG [RequestResponseStage:7] 2012-06-28 15:59:42,201 > > ResponseVerbHandler.java (line 44) Processing response on a callback fr= om > > 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 fr= om > > 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: # > > DEBUG [Thrift:18] 2012-06-28 15:59:42,204 CassandraServer.java (line 30= 5) > > get_slice > > > > 192.168.0.1: > > DEBUG [MutationStage:21] 2012-06-28 15:59:42,177 > RowMutationVerbHandler.java > > (line 44) Applying RowMutation(keyspace=3D'drc', > > key=3D'7878323239537570657254616e67307878', > modifications=3D[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=3D'drc', > > key=3D'7878323239537570657254616e67307878', > modifications=3D[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.ja= va > > (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.ja= va > > (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=3D'drc', > > key=3D'7878323239537570657254616e67307878', > modifications=3D[ColumnFamily(queue > > [737461747573:true:4@1340870382175000,])]) applied. Sending response t= o > > 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=3D'drc', > > key=3D'7878323239537570657254616e67307878', > modifications=3D[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.jav= a > > (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 10= 3) > > 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=3D'drc', > > key=3D'7878323239537570657254616e67307878', > modifications=3D[ColumnFamily(queue > > [737461747573:true:4@1340870382175000,])]) applied. Sending response t= o > > 6550@/192.168.0.3 > > DEBUG [MutationStage:10] 2012-06-28 15:59:42,187 > RowMutationVerbHandler.java > > (line 44) Applying RowMutation(keyspace=3D'drc', > > key=3D'7878323239537570657254616e67307878', > modifications=3D[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.ja= va > > (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=3D'drc', > > key=3D'7878323239537570657254616e67307878', > modifications=3D[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 > --f46d044787613d627204c3c4f27c Content-Type: text/html; charset=ISO-8859-1 Content-Transfer-Encoding: quoted-printable For the create/update/deleteColumn/deleteRow test case, for Quorum consiste= ncy level, 6 nodes,=A0replicate=A0factor 3, for one thread around 1/100 rou= nd, 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,=A0guaranteed=A0by 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".
<= br>
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? =A0How many columns are in the row? =A0Can 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
>
> =A0 =A0First I delete one column, then I delete one row. Then try to r= ead all
> columns from the same row, all operations from same client app.
>
> =A0 =A0The consistency level is read/write quorum.
>
> =A0 =A0Check the Cassandra log, the local node don't perform the d= elete
> operation but send the mutation to other nodes (192.168.0.6, 192.168.0= .1)
>
> =A0 =A0After delete, I try to read all columns from the row, I found t= he node
> found "Digest mismatch" due to Quorum consistency configurat= ion, but the
> result is not correct.
>
> =A0 =A0From the log, I can see the delete mutation already accepted > by=A0192.168.0.6, 192.168.0.1, =A0but when 192.168.0.5 read response f= rom 0.6
> and 0.1, and then it merge the data, but finally 0.5 shows the result = which
> is the dirty data.
>
> =A0 =A0Following logs shows the change of column "737461747573&qu= ot; , 192.168.0.5
> try to read from 0.1 and 0.6, it should be deleted, but finally it sho= ws 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=3D'drc&#= 39;,
> key=3D7878323239537570657254616e67307878,
> columnParent=3D'QueryPath(columnFamilyName=3D'queue', supe= rColumnName=3D'null',
> columnName=3D'null')',
> columns=3D[6578656375746554696d65,6669726554696d65,67726f75705f6964,69= 6e517565756554696d65,6c6f67526f6f744964,6d6f54797065,706172746974696f6e,726= 5636569766554696d65,72657175657374,7265747279,7365727669636550726f766964657= 2,737461747573,757365724e616d65,])/QUORUM
> DEBUG [Thrift:17] 2012-06-28 15:59:42,198 ReadCallback.java (line 79)<= br> > 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 /19= 2.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 f= rom
> 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 f= rom
> 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 f= rom
> 6558@/192.168.0.6=
> DEBUG [RequestResponseStage:7] 2012-06-28 15:59:42,201
> ResponseVerbHandler.java (line 44) Processing response on a callback f= rom
> 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@1340870382= 109005
> DEBUG [Thrift:17] 2012-06-28 15:59:42,201 SliceQueryFilter.java (line = 123)
> collecting 3 of 2147483647: 6c6f67526f6f744964:false:7@134087038210901= 5
> 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@134087038210900= 1
> DEBUG [Thrift:17] 2012-06-28 15:59:42,202 SliceQueryFilter.java (line = 123)
> collecting 6 of 2147483647: 7265636569766554696d65:false:13@1340870382= 109003
> DEBUG [Thrift:17] 2012-06-28 15:59:42,202 SliceQueryFilter.java (line = 123)
> collecting 7 of 2147483647: 72657175657374:false:300@1340870382109013<= br> > DEBUG [RequestResponseStage:5] 2012-06-28 15:59:42,202
> ResponseVerbHandler.java (line 44) Processing response on a callback f= rom
> 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=3D[]>
> DEBUG [Thrift:18] 2012-06-28 15:59:42,204 CassandraServer.java (line 3= 05)
> get_slice
>
> 192.168.0.1:
> DEBUG [MutationStage:21] 2012-06-28 15:59:42,177 RowMutationVerbHandle= r.java
> (line 44) Applying RowMutation(keyspace=3D'drc',
> key=3D'7878323239537570657254616e67307878', modifications=3D[C= olumnFamily(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 RowMutationVerbHandle= r.java
> (line 44) Applying RowMutation(keyspace=3D'drc',
> key=3D'7878323239537570657254616e67307878', modifications=3D[C= olumnFamily(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.j= ava
> (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.j= ava
> (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 RowMutationVerbHandle= r.java
> (line 56) RowMutation(keyspace=3D'drc',
> key=3D'7878323239537570657254616e67307878', modifications=3D[C= olumnFamily(queue
> [737461747573:true:4@1340870382175000,])]) applied. =A0Sending respons= e 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=3D'drc',
> key=3D'7878323239537570657254616e67307878', modifications=3D[C= olumnFamily(queue
> [737461747573:true:4@1340870382175000,])])
> DEBUG [MutationStage:6] 2012-06-28 15:59:42,177 Table.java (line 391)<= br> > applying mutation of row 7878323239537570657254616e67307878
> DEBUG [MutationStage:6] 2012-06-28 15:59:42,184 Table.java (line 425)<= br> > mutating indexed column 737461747573 value 4fec0eee
> DEBUG [MutationStage:6] 2012-06-28 15:59:42,184 CollationController.ja= va
> (line 77) collectTimeOrderedData
> DEBUG [MutationStage:6] 2012-06-28 15:59:42,184 Table.java (line 449)<= br> > Pre-mutation index row is ColumnFamily(queue
> [737461747573:false:8@1340870382152000,])
> DEBUG [MutationStage:6] 2012-06-28 15:59:42,184 KeysIndex.java (line 1= 03)
> 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=3D'drc',
> key=3D'7878323239537570657254616e67307878', modifications=3D[C= olumnFamily(queue
> [737461747573:true:4@1340870382175000,])]) applied. =A0Sending respons= e to
> 6550@/192.168.0.3=
> DEBUG [MutationStage:10] 2012-06-28 15:59:42,187 RowMutationVerbHandle= r.java
> (line 44) Applying RowMutation(keyspace=3D'drc',
> key=3D'7878323239537570657254616e67307878', modifications=3D[C= olumnFamily(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.j= ava
> (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:fa= lse:6@1340870382109009,706172746974696f6e:false:2@1340870382109001,72656365= 69766554696d65:false:13@1340870382109003,7265636569766554696d65536c696365:f= alse:13@1340870382109010,7365727669636550726f7669646572:false:4@13408703821= 09007,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 RowMutationVerbHandle= r.java
> (line 56) RowMutation(keyspace=3D'drc',
> key=3D'7878323239537570657254616e67307878', modifications=3D[C= olumnFamily(queue
> -deleted at 1340870382185000- [])]) applied. =A0Sending 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 (lin= e 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.c= om

--f46d044787613d627204c3c4f27c--