From users-return-2250-apmail-qpid-users-archive=qpid.apache.org@qpid.apache.org Fri Nov 27 15:52:24 2009 Return-Path: Delivered-To: apmail-qpid-users-archive@www.apache.org Received: (qmail 78717 invoked from network); 27 Nov 2009 15:52:24 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (140.211.11.3) by minotaur.apache.org with SMTP; 27 Nov 2009 15:52:24 -0000 Received: (qmail 94047 invoked by uid 500); 27 Nov 2009 15:52:24 -0000 Delivered-To: apmail-qpid-users-archive@qpid.apache.org Received: (qmail 93983 invoked by uid 500); 27 Nov 2009 15:52:23 -0000 Mailing-List: contact users-help@qpid.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: users@qpid.apache.org Delivered-To: mailing list users@qpid.apache.org Received: (qmail 93973 invoked by uid 99); 27 Nov 2009 15:52:23 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 27 Nov 2009 15:52:23 +0000 X-ASF-Spam-Status: No, hits=-4.0 required=10.0 tests=RCVD_IN_DNSWL_MED,SPF_HELO_PASS,SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (nike.apache.org: domain of aconway@redhat.com designates 209.132.183.28 as permitted sender) Received: from [209.132.183.28] (HELO mx1.redhat.com) (209.132.183.28) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 27 Nov 2009 15:52:15 +0000 Received: from int-mx02.intmail.prod.int.phx2.redhat.com (int-mx02.intmail.prod.int.phx2.redhat.com [10.5.11.12]) by mx1.redhat.com (8.13.8/8.13.8) with ESMTP id nARFpqRF019757 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-SHA bits=256 verify=OK) for ; Fri, 27 Nov 2009 10:51:52 -0500 Received: from [10.11.9.16] (vpn-9-16.rdu.redhat.com [10.11.9.16]) by int-mx02.intmail.prod.int.phx2.redhat.com (8.13.8/8.13.8) with ESMTP id nARFppl5010103 for ; Fri, 27 Nov 2009 10:51:52 -0500 Message-ID: <4B0FF5AF.4040801@redhat.com> Date: Fri, 27 Nov 2009 10:52:15 -0500 From: Alan Conway Organization: Red Hat User-Agent: Mozilla/5.0 (X11; U; Linux x86_64; en-US; rv:1.9.1.4pre) Gecko/20091014 Fedora/3.0-2.8.b4.fc11 Thunderbird/3.0b4 MIME-Version: 1.0 To: users@qpid.apache.org Subject: Re: Qpid Cluster Errors References: <4B02CE3A.5050003@redhat.com> <4B02FC3C.7010700@redhat.com> In-Reply-To: Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit X-Scanned-By: MIMEDefang 2.67 on 10.5.11.12 X-Virus-Checked: Checked by ClamAV on apache.org On 11/17/2009 08:33 PM, Sandy Pratt wrote: > I managed to capture a log today while trace was on. Broker1 and broker2 are in a cluster, and broker1 is pulling messages from federated_broker1 when the error occurred: > > 2009-nov-17 17:22:29 debug DeliveryRecord::setEnded() id=840 > 2009-nov-17 17:22:29 debug Accepted 840 > 2009-nov-17 17:22:29 debug user1@QPID.5d051ed2-74fc-49bc-91ba-144d594b863c: receiver marked completed: 18 incomplete: { } unknown-completed: { [1,18] } > 2009-nov-17 17:22:29 trace broker1:3193(READY) DLVR 838300: Frame[BEbe; channel=0; {SessionCompletedBody: commands={ [293,629] }; }] data broker2:21467-85 > 2009-nov-17 17:22:29 debug user1@QPID.8d28476a-f279-44b2-ae04-37410bc344b5: sender marked completed: { [293,629] } > 2009-nov-17 17:22:29 debug Exception constructed: user1@QPID.8d28476a-f279-44b2-ae04-37410bc344b5: confirmed< (630+0) but only sent< (629+0) (qpid/SessionState.cpp:163) > 2009-nov-17 17:22:29 error Execution exception: invalid-argument: user1@QPID.8d28476a-f279-44b2-ae04-37410bc344b5: confirmed< (630+0) but only sent< (629+0) (qpid/SessionState.cpp:163) > 2009-nov-17 17:22:29 error broker1:3193(READY/error) channel error 838300 on broker2:21467-85(shadow): invalid-argument: user1@QPID.8d28476a-f279-44b2-ae04-37410bc344b5: confirmed< (630+0) but only sent< (629+0) (qpid/SessionState.cpp:163) (unresolved: broker1:3193 broker2:21467 ) > 2009-nov-17 17:22:29 trace MCAST broker2:21467-0: {ClusterErrorCheckBody: type=1; frame-seq=838300; } > 2009-nov-17 17:22:29 trace broker1:3193(READY/error) DLVR: Event[broker1:3193-0 Frame[BEbe; channel=0; {ClusterErrorCheckBody: type=1; frame-seq=838300; }]] > 2009-nov-17 17:22:29 debug broker1:3193(READY/error) error 838300 outcome agrees with broker1:3193 > 2009-nov-17 17:22:29 debug broker1:3193(READY/error) Error 838300 still unresolved: broker2:21467 > 2009-nov-17 17:22:29 trace broker1:3193(READY/error) DLVR: Event[broker2:21467-90 Frame[BEbe; channel=0; {ClusterConnectionDeliverDoOutputBody: limit=64; }]] > 2009-nov-17 17:22:29 trace broker1:3193(READY/error) DLVR: Event[broker2:21467-85 Frame[BEbe; channel=0; {ClusterConnectionDeliverDoOutputBody: limit=96; }]] > 2009-nov-17 17:22:29 trace broker1:3193(READY/error) DLVR: Event[broker2:21467-84 data 26 bytes] > 2009-nov-17 17:22:29 trace broker1:3193(READY/error) DLVR: Event[broker2:21467-88 Frame[BEbe; channel=0; {ClusterConnectionDeliverDoOutputBody: limit=512; }]] > 2009-nov-17 17:22:29 trace broker1:3193(READY/error) DLVR: Event[broker2:21467-88 data 26 bytes] > 2009-nov-17 17:22:29 trace broker1:3193(READY/error) DLVR: Event[broker2:21467-90 data 26 bytes] > 2009-nov-17 17:22:29 trace broker1:3193(READY/error) DLVR: Event[broker2:21467-86 Frame[BEbe; channel=0; {ClusterConnectionDeliverDoOutputBody: limit=128; }]] > 2009-nov-17 17:22:30 trace broker1:3193(READY/error) DLVR: Event[broker2:21467-83 Frame[BEbe; channel=0; {ClusterConnectionDeliverDoOutputBody: limit=128; }]] > 2009-nov-17 17:22:30 trace broker1:3193(READY/error) DLVR: Event[broker2:21467-89 Frame[BEbe; channel=0; {ClusterConnectionDeliverDoOutputBody: limit=32; }]] > 2009-nov-17 17:22:30 trace broker1:3193(READY/error) DLVR: Event[broker2:21467-87 Frame[BEbe; channel=0; {ClusterConnectionDeliverDoOutputBody: limit=32; }]] > 2009-nov-17 17:22:30 trace broker1:3193(READY/error) DLVR: Event[broker2:21467-91 data 26 bytes] > 2009-nov-17 17:22:30 trace broker1:3193(READY/error) DLVR: Event[broker2:21467-92 Frame[BEbe; channel=0; {ClusterConnectionDeliverDoOutputBody: limit=256; }]] > 2009-nov-17 17:22:30 trace broker1:3193(READY/error) DLVR: Event[broker2:21467-91 Frame[BEbe; channel=0; {ClusterConnectionDeliverDoOutputBody: limit=62; }]] > 2009-nov-17 17:22:30 trace broker1:3193(READY/error) DLVR: Event[broker2:21467-86 data 26 bytes] > 2009-nov-17 17:22:30 trace broker1:3193(READY/error) DLVR: Event[broker2:21467-0 Frame[BEbe; channel=0; {ClusterErrorCheckBody: type=0; frame-seq=838300; }]] > 2009-nov-17 17:22:30 critical broker1:3193(READY/error) error 838300 did not occur on broker2:21467 > 2009-nov-17 17:22:30 debug Exception constructed: Aborted by local failure that did not occur on all replicas > 2009-nov-17 17:22:30 error Error delivering frames: Aborted by local failure that did not occur on all replicas > 2009-nov-17 17:22:30 notice broker1:3193(LEFT/error) leaving cluster renga-qpid-dev > 2009-nov-17 17:22:30 debug broker1:3193(LEFT/error) deleted connection: broker2:21467-92(shadow) > 2009-nov-17 17:22:30 debug broker1:3193(LEFT/error) deleted connection: broker2:21467-91(shadow) > 2009-nov-17 17:22:30 debug broker1:3193(LEFT/error) deleted connection: broker2:21467-90(shadow) > 2009-nov-17 17:22:30 debug broker1:3193(LEFT/error) deleted connection: broker2:21467-89(shadow) > 2009-nov-17 17:22:30 debug broker1:3193(LEFT/error) deleted connection: broker2:21467-88(shadow) > 2009-nov-17 17:22:30 debug broker1:3193(LEFT/error) deleted connection: broker2:21467-87(shadow) > 2009-nov-17 17:22:30 debug broker1:3193(LEFT/error) deleted connection: broker2:21467-86(shadow) > 2009-nov-17 17:22:30 debug broker1:3193(LEFT/error) deleted connection: broker2:21467-85(shadow) > 2009-nov-17 17:22:30 debug broker1:3193(LEFT/error) deleted connection: broker2:21467-84(shadow) > 2009-nov-17 17:22:30 debug broker1:3193(LEFT/error) deleted connection: broker2:21467-83(shadow) > 2009-nov-17 17:22:30 debug Shutting down CPG > 2009-nov-17 17:22:30 notice Shut down > 2009-nov-17 17:22:30 error Connection federated_broker1:5672 closed by error: closed by management(320) > 2009-nov-17 17:22:30 debug Journal "test": Destroyed > 2009-nov-17 17:22:30 debug Journal "coreToNode": Destroyed > 2009-nov-17 17:22:30 debug Journal "TplStore": Destroyed > I think this is an instance of one of the following two bugs, probably the first one: (1) https://bugzilla.redhat.com/show_bug.cgi?id=516501 (2) http://svn.apache.org/viewvc?view=revision&revision=834026 Both are fixed for the next release. --------------------------------------------------------------------- Apache Qpid - AMQP Messaging Implementation Project: http://qpid.apache.org Use/Interact: mailto:users-subscribe@qpid.apache.org