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 [email protected]:
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 [email protected]:
sender marked completed: { [293,629] }
2009-nov-17 17:22:29 debug Exception constructed:
[email protected]: confirmed< (630+0) but only
sent< (629+0) (qpid/SessionState.cpp:163)
2009-nov-17 17:22:29 error Execution exception: invalid-argument:
[email protected]: 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:
[email protected]: 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:[email protected]
