Bug 558526 - clustered qpidd shutdowns during start-up with 'Authentication failed: SASL(-1): generic failure: Unable to find a callback: 32775'
Summary: clustered qpidd shutdowns during start-up with 'Authentication failed: SASL(-...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise MRG
Classification: Red Hat
Component: qpid-cpp
Version: 1.2
Hardware: All
OS: Linux
high
high
Target Milestone: 1.3
: ---
Assignee: Alan Conway
QA Contact: Frantisek Reznicek
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2010-01-25 15:32 UTC by Frantisek Reznicek
Modified: 2015-11-16 01:11 UTC (History)
2 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clustered qpidd no longer shuts down during a start-up due to an Authentication failure.
Clone Of:
Environment:
Last Closed: 2010-10-14 16:04:19 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)
The reproducer (8.65 KB, application/x-shellscript)
2010-01-25 15:35 UTC, Frantisek Reznicek 		no flags Details
Another reproducer of the issue (1.65 KB, application/x-shellscript)
2010-04-29 08:36 UTC, Frantisek Reznicek 		no flags Details
View All


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHSA-2010:0773 0 normal SHIPPED_LIVE Moderate: Red Hat Enterprise MRG Messaging and Grid Version 1.3 2010-10-14 15:56:44 UTC

Description Frantisek Reznicek 2010-01-25 15:32:44 UTC 
Description of problem:

On the reproducing path to bug 546271 I created reproducer which starts and stops broker every minute and verifies whether broker started ok. The verification is done using netstat -nlp | grep qpidd and qpid-cluster

This test was run on 4 machines in the cluster with following configurations listed on the bottom of this post.

Test should run indefinitely long and uncover qpidd starting up problems.

After some time (after couble of runs) one broker shutdown with following Authentification message:
...
2010-jan-21 08:35:03 info SASL: Mechanism list: PLAIN ANONYMOUS LOGIN
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) new connection: 192.168.157.11:10033-2(local,catchup)
2010-jan-21 08:35:03 info SASL: Starting authentication with mechanism: ANONYMOUS
2010-jan-21 08:35:03 info SASL: Authentication succeeded for: anonymous@QPID
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) decoded exchange
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) decoded exchange amq.direct
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) decoded exchange amq.failover
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) decoded exchange amq.fanout
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) decoded exchange amq.match
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) decoded exchange amq.topic
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) decoded exchange qpid.cluster-update
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) decoded exchange qpid.management
2010-jan-21 08:35:03 notice Journal "perftest0": Created
2010-jan-21 08:35:03 info SASL: Mechanism list: PLAIN ANONYMOUS LOGIN
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) new connection: 192.168.157.11:10033-3(local,catchup)
2010-jan-21 08:35:03 info SASL: Starting authentication with mechanism: ANONYMOUS
2010-jan-21 08:35:03 info SASL: Authentication succeeded for: anonymous@QPID
.168.157.9:29383-2
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) add shadow connection 192.168.157.9:29383-2
2010-jan-21 08:35:03 info SASL: Mechanism list: PLAIN ANONYMOUS LOGIN
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) new connection: 192.168.157.11:10033-4(local,catchup)
2010-jan-21 08:35:03 info SASL: Starting authentication with mechanism: ANONYMOUS
2010-jan-21 08:35:03 info SASL: Authentication succeeded for: anonymous@QPID
t.com.12394.1
.168.157.10:12351-1
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) add shadow connection 192.168.157.10:12351-1
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) incoming update complete on connection 192.168.157.11:10033-2(local,catchup)
2010-jan-21 08:35:03 info 192.168.157.11:10033(CATCHUP) received update, starting catch-up
2010-jan-21 08:35:03 info SASL: Starting authentication with mechanism: PLAIN
2010-jan-21 08:35:03 info SASL: Authentication failed: SASL(-1): generic failure: Unable to find a callback: 32775
d: Authentication failed (unresolved: 192.168.157.9:29383 192.168.157.10:12351 )
3
2010-jan-21 08:35:03 debug 192.168.157.11:10033(CATCHUP/error) closed update connection 192.168.157.11:10033-0(updated)
2010-jan-21 08:35:03 info 192.168.157.11:10033(CATCHUP/error) error 63 resolved with 192.168.157.11:10033
2010-jan-21 08:35:03 debug 192.168.157.11:10033(CATCHUP/error) deleted connection: 192.168.157.11:10033-0(updated)
2010-jan-21 08:35:03 critical 192.168.157.11:10033(CATCHUP/error) error 63 did not occur on 192.168.157.9:29383
2010-jan-21 08:35:03 error Error delivering frames: Error 63 did not occur on all members (qpid/cluster/ErrorCheck.cpp:90)
2010-jan-21 08:35:03 notice 192.168.157.11:10033(LEFT/error) leaving cluster mrg_pepe_test_cluster
2010-jan-21 08:35:03 debug 192.168.157.11:10033(LEFT/error) deleted connection: 192.168.157.10:12351-1(shadow)
2010-jan-21 08:35:03 debug 192.168.157.11:10033(LEFT/error) deleted connection: 192.168.157.9:29383-2(shadow)
2010-jan-21 08:35:03 debug Shutting down CPG
2010-jan-21 08:35:03 notice Shut down

The test reproducer is able to sweep the gaps between qpidd services start-up, so, which is goot for race condition testing, Usage is:

./bz546271.sh [qpidd start-up gap in ms in between two consecutive brokers] 
              [number of checks before claimed as good startup]
              [max qpidd settle time ms after service qpidd start]

typical case can be: ./bz546271.sh 50 6 100


Version-Release number of selected component (if applicable):
root@mrg-qe-11:~# rpm -qa | grep -E '(qpid|sasl|openai)'| sort
cyrus-sasl-2.1.22-5.el5
cyrus-sasl-lib-2.1.22-5.el5
cyrus-sasl-plain-2.1.22-5.el5
openais-0.80.6-8.el5_4.1
openais-debuginfo-0.80.6-8.el5_4.1
openais-devel-0.80.6-8.el5_4.1
python-qpid-0.5.752581-4.el5
qpidc-0.5.752581-34.el5
qpidc-debuginfo-0.5.752581-34.el5
qpidc-devel-0.5.752581-34.el5
qpidc-perftest-0.5.752581-34.el5
qpidc-rdma-0.5.752581-34.el5
qpidc-ssl-0.5.752581-34.el5
qpidd-0.5.752581-34.el5
qpidd-acl-0.5.752581-34.el5
qpidd-cluster-0.5.752581-34.el5
qpidd-devel-0.5.752581-34.el5
qpid-dotnet-0.4.738274-2.el5
qpidd-rdma-0.5.752581-34.el5
qpidd-ssl-0.5.752581-34.el5
qpidd-xml-0.5.752581-34.el5
qpid-java-client-0.5.751061-9.el5
qpid-java-common-0.5.751061-9.el5

How reproducible:
90%

Steps to Reproduce:
1. set-up openais (config below) all 3-4 nodes
2. set-up qpidd (config below) all 3-4 nodes
3. run the test './bz546271.sh 50 6 100' on all 3-4 nodes
   NOTICE: test is self synchronizing to clock, so it is NEEDED to have synchronized clock on those machines and launch it at once in the range when second count is between 1 to 55.

  
Actual results:
clustered qpidd shutdowns during start-up with Authentication failure.

Expected results:
clustered qpidd should always start-up.


Additional info:
root@mrg-qe-10:~# cat /etc/qpidd.conf

cluster-mechanism=ANONYMOUS
#max-session-rate=10000
cluster-name=mrg_pepe_test_cluster
cluster-cman=no
auth=yes
log-enable=info+
log-enable=debug+:cluster
log-to-file=/tmp/qpidd.log
root@mrg-qe-10:~# cat /etc/ais/openais.conf

totem {
        version: 2
        secauth: off
        threads: 0
        interface {
                ringnumber: 0
                bindnetaddr: 192.168.157.0
                mcastaddr: 225.0.10.12
                mcastport: 54051
        }
}

logging {
        to_file: yes
        logfile: /tmp/openais.log
        debug: on
        timestamp: on
}


amf {
        mode: disabled
}

qpidd.log of machine which shutdown:
2010-jan-21 08:34:46 notice Shut down
2010-jan-21 08:35:01 info Loaded Module: /usr/lib/qpid/daemon/acl.so
2010-jan-21 08:35:01 info Loaded Module: /usr/lib/qpid/daemon/replication_exchange.so
2010-jan-21 08:35:01 info Loaded Module: /usr/lib/qpid/daemon/xml.so
2010-jan-21 08:35:01 info SSL connector not enabled, you must set QPID_SSL_CERT_DB to enable it.
2010-jan-21 08:35:01 info Loaded Module: /usr/lib/qpid/client/sslconnector.so
2010-jan-21 08:35:01 info Loaded Module: /usr/lib/qpid/client/rdmaconnector.so
2010-jan-21 08:35:01 info Loaded Module: /usr/lib/qpid/daemon/cluster.so
2010-jan-21 08:35:01 info Loaded Module: /usr/lib/qpid/daemon/ssl.so
2010-jan-21 08:35:01 info Loaded Module: /usr/lib/qpid/daemon/msgstore.so
2010-jan-21 08:35:01 info Loaded Module: /usr/lib/qpid/daemon/replicating_listener.so
2010-jan-21 08:35:01 info Loaded Module: /usr/lib/qpid/daemon/rdma.so
2010-jan-21 08:35:01 info Management enabled
2010-jan-21 08:35:01 info Initializing CPG
157.11:10033(joined) )
2010-jan-21 08:35:01 notice Journal "TplStore": Created
2010-jan-21 08:35:01 notice Store module initialized; dir=/var/lib/qpidd
2010-jan-21 08:35:01 info > Default files per journal: 8
2010-jan-21 08:35:01 info > Default journal file size: 24 (wpgs)
2010-jan-21 08:35:01 info > Default write cache page size: 32 (Kib)
2010-jan-21 08:35:01 info > Default number of write cache pages: 32
2010-jan-21 08:35:01 info > TPL files per journal: 8
2010-jan-21 08:35:01 info > TPL journal file size: 24 (wpgs)
2010-jan-21 08:35:01 info > TPL write cache page size: 4 (Kib)
2010-jan-21 08:35:01 info > TPL number of write cache pages: 64
2010-jan-21 08:35:01 notice Cluster recovery: recovered journal data discarded and journal files pushed down
2010-jan-21 08:35:02 notice Journal "TplStore": Created
2010-jan-21 08:35:02 info SASL enabled
2010-jan-21 08:35:02 notice Listening on TCP port 5672
2010-jan-21 08:35:02 info Policy file not specified. ACL Disabled, no ACL checking being done!
2010-jan-21 08:35:02 info Registered replication exchange
2010-jan-21 08:35:02 info Registered xml exchange
92.168.157.11:5672
2010-jan-21 08:35:02 info SSL plugin not enabled, you must set --qpid-ssl-cert-db to enable it.
2010-jan-21 08:35:02 info Rdma: Disabled: no rdma devices found
2010-jan-21 08:35:02 notice Broker running
33 (joined: 192.168.157.9:29383(joined) )
33 192.168.157.12:9693 (joined: 192.168.157.12:9693(joined) )
wn)
2010-jan-21 08:35:02 info 192.168.157.11:10033(JOINER) joining cluster: 192.168.157.10:12351(unknown) 192.168.157.11:10033(unknown)
own) 192.168.157.11:10033(unknown)
2010-jan-21 08:35:02 debug 192.168.157.11:10033(JOINER) stall for update offer from 192.168.157.10:12351 to 192.168.157.9:29383
2010-jan-21 08:35:02 info Loaded Module: /usr/lib/qpid/daemon/acl.so
2010-jan-21 08:35:02 info Loaded Module: /usr/lib/qpid/daemon/replication_exchange.so
own) 192.168.157.11:10033(unknown) 192.168.157.12:9693(unknown)
2010-jan-21 08:35:02 info Loaded Module: /usr/lib/qpid/daemon/xml.so
2010-jan-21 08:35:02 debug 192.168.157.11:10033(JOINER) unstall, ignore update 192.168.157.10:12351 to 192.168.157.9:29383
2010-jan-21 08:35:02 info SSL connector not enabled, you must set QPID_SSL_CERT_DB to enable it.
2010-jan-21 08:35:02 info Loaded Module: /usr/lib/qpid/client/sslconnector.so
2010-jan-21 08:35:02 info Loaded Module: /usr/lib/qpid/client/rdmaconnector.so
2010-jan-21 08:35:02 info Loaded Module: /usr/lib/qpid/daemon/cluster.so
2010-jan-21 08:35:02 info Loaded Module: /usr/lib/qpid/daemon/ssl.so
2010-jan-21 08:35:02 info Loaded Module: /usr/lib/qpid/daemon/msgstore.so
2010-jan-21 08:35:02 info Loaded Module: /usr/lib/qpid/daemon/replicating_listener.so
2010-jan-21 08:35:02 info Loaded Module: /usr/lib/qpid/daemon/rdma.so
2010-jan-21 08:35:02 info SASL: Mechanism list: PLAIN ANONYMOUS LOGIN
2010-jan-21 08:35:02 debug 192.168.157.11:10033(JOINER) new connection: 192.168.157.11:10033-1(local)
2010-jan-21 08:35:02 debug 192.168.157.11:10033(JOINER) add local connection 192.168.157.11:10033-1
68.157.11:10033(joiner) 192.168.157.12:9693(joiner)
2010-jan-21 08:35:03 debug 192.168.157.11:10033(JOINER) stall for update offer from 192.168.157.10:12351 to 192.168.157.11:10033
2010-jan-21 08:35:03 debug 192.168.157.11:10033(JOINER) cluster-id = 89a20fa5-3fb8-49a1-950f-f4cbec9502f2
2010-jan-21 08:35:03 info 192.168.157.11:10033(UPDATEE) receiving update from 192.168.157.10:12351
2010-jan-21 08:35:03 info SASL: Mechanism list: PLAIN ANONYMOUS LOGIN
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) new connection: 192.168.157.11:10033-2(local,catchup)
2010-jan-21 08:35:03 info SASL: Starting authentication with mechanism: ANONYMOUS
2010-jan-21 08:35:03 info SASL: Authentication succeeded for: anonymous@QPID
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) decoded exchange
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) decoded exchange amq.direct
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) decoded exchange amq.failover
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) decoded exchange amq.fanout
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) decoded exchange amq.match
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) decoded exchange amq.topic
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) decoded exchange qpid.cluster-update
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) decoded exchange qpid.management
2010-jan-21 08:35:03 notice Journal "perftest0": Created
2010-jan-21 08:35:03 info SASL: Mechanism list: PLAIN ANONYMOUS LOGIN
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) new connection: 192.168.157.11:10033-3(local,catchup)
2010-jan-21 08:35:03 info SASL: Starting authentication with mechanism: ANONYMOUS
2010-jan-21 08:35:03 info SASL: Authentication succeeded for: anonymous@QPID
.168.157.9:29383-2
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) add shadow connection 192.168.157.9:29383-2
2010-jan-21 08:35:03 info SASL: Mechanism list: PLAIN ANONYMOUS LOGIN
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) new connection: 192.168.157.11:10033-4(local,catchup)
2010-jan-21 08:35:03 info SASL: Starting authentication with mechanism: ANONYMOUS
2010-jan-21 08:35:03 info SASL: Authentication succeeded for: anonymous@QPID
t.com.12394.1
.168.157.10:12351-1
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) add shadow connection 192.168.157.10:12351-1
2010-jan-21 08:35:03 debug 192.168.157.11:10033(UPDATEE) incoming update complete on connection 192.168.157.11:10033-2(local,catchup)
2010-jan-21 08:35:03 info 192.168.157.11:10033(CATCHUP) received update, starting catch-up
2010-jan-21 08:35:03 info SASL: Starting authentication with mechanism: PLAIN
2010-jan-21 08:35:03 info SASL: Authentication failed: SASL(-1): generic failure: Unable to find a callback: 32775
d: Authentication failed (unresolved: 192.168.157.9:29383 192.168.157.10:12351 )
3
2010-jan-21 08:35:03 debug 192.168.157.11:10033(CATCHUP/error) closed update connection 192.168.157.11:10033-0(updated)
2010-jan-21 08:35:03 info 192.168.157.11:10033(CATCHUP/error) error 63 resolved with 192.168.157.11:10033
2010-jan-21 08:35:03 debug 192.168.157.11:10033(CATCHUP/error) deleted connection: 192.168.157.11:10033-0(updated)
2010-jan-21 08:35:03 critical 192.168.157.11:10033(CATCHUP/error) error 63 did not occur on 192.168.157.9:29383
2010-jan-21 08:35:03 error Error delivering frames: Error 63 did not occur on all members (qpid/cluster/ErrorCheck.cpp:90)
2010-jan-21 08:35:03 notice 192.168.157.11:10033(LEFT/error) leaving cluster mrg_pepe_test_cluster
2010-jan-21 08:35:03 debug 192.168.157.11:10033(LEFT/error) deleted connection: 192.168.157.10:12351-1(shadow)
2010-jan-21 08:35:03 debug 192.168.157.11:10033(LEFT/error) deleted connection: 192.168.157.9:29383-2(shadow)
2010-jan-21 08:35:03 debug Shutting down CPG
2010-jan-21 08:35:03 notice Shut down
Comment 1 Frantisek Reznicek 2010-01-25 15:35:30 UTC 
Created attachment 386651 [details]
The reproducer
Comment 2 Frantisek Reznicek 2010-01-25 15:38:38 UTC 
Curently reproduced at least 4 times on mrg-qe-09 ... 12.

Another case looked similarly:
...
2010-jan-25 10:31:01 debug 192.168.157.10:28366(UPDATEE) decoded exchange amq.fanout
2010-jan-25 10:31:01 debug 192.168.157.10:28366(UPDATEE) decoded exchange amq.match
2010-jan-25 10:31:01 debug 192.168.157.10:28366(UPDATEE) decoded exchange amq.topic
2010-jan-25 10:31:01 debug 192.168.157.10:28366(UPDATEE) decoded exchange qpid.cluster-update
2010-jan-25 10:31:01 debug 192.168.157.10:28366(UPDATEE) decoded exchange qpid.management
2010-jan-25 10:31:01 notice Journal "perftest0": Created
2010-jan-25 10:31:01 info SASL: Mechanism list: PLAIN ANONYMOUS LOGIN
2010-jan-25 10:31:01 debug 192.168.157.10:28366(UPDATEE) new connection: 192.168.157.10:28366-3(local)
2010-jan-25 10:31:01 debug 192.168.157.10:28366(UPDATEE) add local connection 192.168.157.10:28366-3
2010-jan-25 10:31:01 info SASL: Mechanism list: PLAIN ANONYMOUS LOGIN
2010-jan-25 10:31:01 debug 192.168.157.10:28366(UPDATEE) new connection: 192.168.157.10:28366-4(local,catchup)
2010-jan-25 10:31:01 info SASL: Starting authentication with mechanism: ANONYMOUS
2010-jan-25 10:31:01 info SASL: Authentication succeeded for: anonymous@QPID
2010-jan-25 10:31:01 debug 192.168.157.10:28366(UPDATEE) catch-up connection 192.168.157.10:28366-4(local,catchup) becomes shadow 192.168.157.9:10505-100 info > Default files per journal: 8
2010-jan-25 10:31:01 debug 192.168.157.10:28366(UPDATEE) add shadow connection 192.168.157.9:10505-1
2010-jan-25 10:31:02 debug 192.168.157.10:28366(UPDATEE) incoming update complete on connection 192.168.157.10:28366-1(local,catchup)
2010-jan-25 10:31:02 info 192.168.157.10:28366(CATCHUP) received update, starting catch-up
2010-jan-25 10:31:02 info SASL: Starting authentication with mechanism: PLAIN
2010-jan-25 10:31:02 info SASL: Authentication failed: SASL(-1): generic failure: Unable to find a callback: 32775
2010-jan-25 10:31:02 debug 192.168.157.10:28366(CATCHUP) closed update connection 192.168.157.10:28366-0(updated)
2010-jan-25 10:31:02 debug 192.168.157.10:28366(CATCHUP) deleted connection: 192.168.157.10:28366-0(updated)
2010-jan-25 10:31:02 error 192.168.157.10:28366(CATCHUP/error) connection error 2 on 192.168.157.9:10505-1(shadow): connection-forced: Authentication failed (unresolved: 192.168.157.9:10505 )bership change: 192.168.157.9:6236 192.168.157.10:26918 (joined: 192.168.152010-jan-25 10:31:02 info 192.168.157.10:28366(CATCHUP/error) error 2 resolved with 192.168.157.10:28366
2010-jan-25 10:31:02 info 192.168.157.10:28366(CATCHUP/error) error 2 must be resolved with 192.168.157.9:10505
2010-jan-25 10:31:02 debug 192.168.157.10:28366(CATCHUP/error) stall for update offer from 192.168.157.9:10505 to 192.168.157.11:23257010-jan-25 10:23:01 info SASL enabled
2010-jan-25 10:31:02 critical 192.168.157.10:28366(CATCHUP/error) error 2 did not occur on 192.168.157.9:10505
2010-jan-25 10:31:02 error Error delivering frames: Error 2 did not occur on all members (qpid/cluster/ErrorCheck.cpp:90)
2010-jan-25 10:31:02 notice 192.168.157.10:28366(LEFT/error) leaving cluster mrg_pepe_test_cluster
2010-jan-25 10:31:02 debug 192.168.157.10:28366(LEFT/error) deleted connection: 192.168.157.9:10505-1(shadow)
2010-jan-25 10:31:02 debug Shutting down CPG
2010-jan-25 10:31:02 notice Shut down

The only node is down, the remaining ones are alive and operational.
Comment 3 Frantisek Reznicek 2010-01-26 12:46:04 UTC 
Another slightly different case (qpidd.log of the shutdown broker):
...
2010-jan-26 04:25:02 info SASL: Authentication succeeded for: anonymous@QPID
2010-jan-26 04:25:02 info Passivating links
2010-jan-26 04:25:03 debug 192.168.157.11:16296(UPDATEE) received session state update for anonymous.lab.eng.brq.redhat.com.6384.104:05:00 info SSL connector not enabled, you must set QPID_SSL_CERT_DB to enable it.
2010-jan-26 04:25:03 debug 192.168.157.11:16296(UPDATEE) catch-up connection 192.168.157.11:16296-4(local,catchup) becomes shadow 192.168.157.9:6347-2:00 info Loaded Module: /usr/lib/qpid/client/rdmaconnector.so
2010-jan-26 04:25:03 debug 192.168.157.11:16296(UPDATEE) add shadow connection 192.168.157.9:6347-2
2010-jan-26 04:25:03 info SASL: Mechanism list: PLAIN ANONYMOUS LOGIN
2010-jan-26 04:25:03 debug 192.168.157.11:16296(UPDATEE) new connection: 192.168.157.11:16296-5(local,catchup)
2010-jan-26 04:25:03 info SASL: Starting authentication with mechanism: ANONYMOUS
2010-jan-26 04:25:03 info SASL: Authentication succeeded for: anonymous@QPID
2010-jan-26 04:25:03 debug 192.168.157.11:16296(UPDATEE) catch-up connection 192.168.157.11:16296-5(local,catchup) becomes shadow 192.168.157.10:26738-20 info Initializing CPG
2010-jan-26 04:25:03 debug 192.168.157.11:16296(UPDATEE) add shadow connection 192.168.157.10:26738-2
2010-jan-26 04:25:03 debug 192.168.157.11:16296(UPDATEE) incoming update complete on connection 192.168.157.11:16296-1(local,catchup)
2010-jan-26 04:25:03 info 192.168.157.11:16296(CATCHUP) received update, starting catch-up
2010-jan-26 04:25:03 info SASL: Starting authentication with mechanism: PLAIN
2010-jan-26 04:25:03 info SASL: Authentication failed: SASL(-1): generic failure: Unable to find a callback: 32775
2010-jan-26 04:25:03 error 192.168.157.11:16296(CATCHUP/error) connection error 48 on 192.168.157.10:26738-2(shadow): connection-forced: Authentication failed (unresolved: 192.168.157.9:6347 192.168.157.10:26738 )
2010-jan-26 04:25:03 debug 192.168.157.11:16296(CATCHUP/error) apply config change to error 48: 192.168.157.9:6347 192.168.157.10:26738 192.168.157.11:16296 192.168.157.12:15488 rnal: 8
2010-jan-26 04:25:03 info 192.168.157.11:16296(CATCHUP/error) error 48 must be resolved with 192.168.157.9:6347 192.168.157.10:26738
2010-jan-26 04:25:03 info 192.168.157.11:16296(CATCHUP/error) error 48 resolved with 192.168.157.11:16296
2010-jan-26 04:25:03 info 192.168.157.11:16296(CATCHUP/error) error 48 must be resolved with 192.168.157.9:6347 192.168.157.10:26738
2010-jan-26 04:25:03 critical 192.168.157.11:16296(CATCHUP/error) error 48 did not occur on 192.168.157.9:6347
2010-jan-26 04:25:03 error Error delivering frames: Error 48 did not occur on all members (qpid/cluster/ErrorCheck.cpp:90)
2010-jan-26 04:25:03 notice 192.168.157.11:16296(LEFT/error) leaving cluster mrg_pepe_test_cluster
2010-jan-26 04:25:03 debug 192.168.157.11:16296(LEFT/error) deleted connection: 192.168.157.10:26738-2(shadow)
2010-jan-26 04:25:03 debug 192.168.157.11:16296(LEFT/error) deleted connection: 192.168.157.9:6347-2(shadow)
2010-jan-26 04:25:03 debug 192.168.157.11:16296(LEFT/error) deleted connection: 192.168.157.9:6347-1(shadow)
2010-jan-26 04:25:03 debug 192.168.157.11:16296(LEFT/error) closed update connection 192.168.157.11:16296-0(updated)
2010-jan-26 04:25:03 debug Shutting down CPG
2010-jan-26 04:25:03 notice Shut down

Other three brokers are operational, 
all openais services are operational w/o any problem in log file.
Comment 4 Frantisek Reznicek 2010-04-29 08:33:18 UTC 
The issue is still present on:
python-qpid-0.7.934605-1.el5
qpid-cpp-client-0.7.935473-1.el5
qpid-cpp-client-devel-0.7.935473-1.el5
qpid-cpp-client-devel-docs-0.7.935473-1.el5
qpid-cpp-client-ssl-0.7.935473-1.el5
qpid-cpp-mrg-debuginfo-0.7.935473-1.el5
qpid-cpp-server-0.7.935473-1.el5
qpid-cpp-server-cluster-0.7.935473-1.el5
qpid-cpp-server-devel-0.7.935473-1.el5
qpid-cpp-server-ssl-0.7.935473-1.el5
qpid-cpp-server-store-0.7.935473-1.el5
qpid-cpp-server-xml-0.7.935473-1.el5
qpid-java-client-0.7.934605-1.el5
qpid-java-common-0.7.934605-1.el5
qpid-tests-0.7.930108-1.el5
qpid-tools-0.7.934605-2.el5
ruby-qpid-0.7.935473-1.el5


I succeeded to trigger this issue during cluster stress test attached below.


First broker starts up well and work under perftest stress, the second cluster node comes up when first is already under load, starts up and after few tens of operations leaves cluster with authentication error + Unable to find callback.
The first broker survives the problem of the second node.

second node log:
  2010-04-29 04:11:55 info Loaded Module: /usr/lib64/qpid/daemon/acl.so
  2010-04-29 04:11:55 info Loaded Module: /usr/lib64/qpid/daemon/xml.so
  2010-04-29 04:11:55 info SSL connector not enabled, you must set QPID_SSL_CERT_DB to enable it.
  2010-04-29 04:11:55 info Loaded Module: /usr/lib64/qpid/client/sslconnector.so
  2010-04-29 04:11:55 info Loaded Module: /usr/lib64/qpid/daemon/cluster.so
  2010-04-29 04:11:55 info Loaded Module: /usr/lib64/qpid/daemon/msgstore.so
  2010-04-29 04:11:55 info Loaded Module: /usr/lib64/qpid/daemon/ssl.so
  2010-04-29 04:11:55 info Loaded Module: /usr/lib64/qpid/daemon/watchdog.so
  2010-04-29 04:11:55 info Loaded Module: /usr/lib64/qpid/daemon/replication_exchange.so
  2010-04-29 04:11:55 info Loaded Module: /usr/lib64/qpid/daemon/replicating_listener.so
  2010-04-29 04:11:55 info No message store configured, persistence is disabled.
  2010-04-29 04:11:55 info Management enabled
  2010-04-29 04:11:55 info Registered xml exchange
  2010-04-29 04:11:55 notice Store directory /var/lib/qpidd/rhm was truncated.
  2010-04-29 04:11:55 notice Journal "TplStore": Created
  2010-04-29 04:11:55 notice Store module initialized; store-dir=/var/lib/qpidd
  2010-04-29 04:11:55 info > Default files per journal: 8
  2010-04-29 04:11:55 info > Default journal file size: 24 (wpgs)
  2010-04-29 04:11:55 info > Default write cache page size: 32 (Kib)
  2010-04-29 04:11:55 info > Default number of write cache pages: 32
  2010-04-29 04:11:55 info > TPL files per journal: 8
  2010-04-29 04:11:55 info > TPL journal file size: 24 (wpgs)
  2010-04-29 04:11:55 info > TPL write cache page size: 4 (Kib)
  2010-04-29 04:11:55 info > TPL number of write cache pages: 64
  2010-04-29 04:11:55 info Registered replication exchange
  2010-04-29 04:11:55 notice Initializing CPG
  2010-04-29 04:11:55 notice Cluster store state: empty
  2010-04-29 04:11:55 notice cluster(10.34.45.2:13840 PRE_INIT) Membership update: 10.34.45.1:19120 10.34.45.2:13840
  2010-04-29 04:11:55 notice cluster(10.34.45.2:13840 PRE_INIT) Members joined: 10.34.45.2:13840
  2010-04-29 04:11:55 debug cluster(10.34.45.2:13840 PRE_INIT) received initial status from 10.34.45.2:13840
  2010-04-29 04:11:56 debug cluster(10.34.45.2:13840 PRE_INIT) received initial status from 10.34.45.1:19120
  2010-04-29 04:11:56 debug cluster(10.34.45.2:13840 PRE_INIT) initial status map complete.
  2010-04-29 04:11:56 info Most recent persistence id found: 0x0
  2010-04-29 04:11:56 info SASL enabled
  2010-04-29 04:11:56 notice Listening on TCP port 5672
  2010-04-29 04:11:56 info Policy file not specified. ACL Disabled, no ACL checking being done!
  2010-04-29 04:11:56 info SSL plugin not enabled, you must set --ssl-cert-db to enable it.
  2010-04-29 04:11:56 debug cluster(10.34.45.2:13840 INIT) initial status map complete.
  2010-04-29 04:11:56 debug cluster(10.34.45.2:13840 INIT) elders: 10.34.45.1:19120
  2010-04-29 04:11:56 info cluster(10.34.45.2:13840 INIT) not active for links.
  2010-04-29 04:11:56 debug cluster(10.34.45.2:13840 INIT) cluster-uuid = 8848bbb1-9a2b-431f-aa57-a9cf912d75ca
  2010-04-29 04:11:56 notice cluster(10.34.45.2:13840 JOINER) joining cluster xyz
  2010-04-29 04:11:56 notice Broker running
  2010-04-29 04:11:56 info Loaded Module: /usr/lib64/qpid/daemon/acl.so
  2010-04-29 04:11:56 info Loaded Module: /usr/lib64/qpid/daemon/xml.so
  2010-04-29 04:11:56 info SSL connector not enabled, you must set QPID_SSL_CERT_DB to enable it.
  2010-04-29 04:11:56 info Loaded Module: /usr/lib64/qpid/client/sslconnector.so
  2010-04-29 04:11:56 info Loaded Module: /usr/lib64/qpid/daemon/cluster.so
  2010-04-29 04:11:56 info Loaded Module: /usr/lib64/qpid/daemon/msgstore.so
  2010-04-29 04:11:56 info Loaded Module: /usr/lib64/qpid/daemon/ssl.so
  2010-04-29 04:11:56 info Loaded Module: /usr/lib64/qpid/daemon/watchdog.so
  2010-04-29 04:11:56 info Loaded Module: /usr/lib64/qpid/daemon/replication_exchange.so
  2010-04-29 04:11:56 info Loaded Module: /usr/lib64/qpid/daemon/replicating_listener.so
  2010-04-29 04:11:56 info new client connection 10.34.45.2:13840-1(local)
  2010-04-29 04:11:56 info cluster(10.34.45.2:13840 JOINER) stall for update offer from 10.34.45.1:19120 to 10.34.45.2:13840
  2010-04-29 04:11:56 notice cluster(10.34.45.2:13840 UPDATEE) receiving update from 10.34.45.1:19120
  2010-04-29 04:11:57 info new catch-up connection 10.34.45.2:13840-2(local,catchup)
  2010-04-29 04:11:57 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:11:57 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-2(local,catchup) ssf=0
  2010-04-29 04:11:57 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:11:57 debug Running managementsetup state handler, new objectnum 348 seq 2424
  2010-04-29 04:11:57 debug cluster(10.34.45.2:13840 UPDATEE) updated exchange
  2010-04-29 04:11:57 info Passivating links
  2010-04-29 04:11:57 debug cluster(10.34.45.2:13840 UPDATEE) updated exchange amq.direct
  2010-04-29 04:11:57 debug cluster(10.34.45.2:13840 UPDATEE) updated exchange amq.failover
  2010-04-29 04:11:57 debug cluster(10.34.45.2:13840 UPDATEE) updated exchange amq.fanout
  2010-04-29 04:11:57 debug cluster(10.34.45.2:13840 UPDATEE) updated exchange amq.match
  2010-04-29 04:11:57 debug cluster(10.34.45.2:13840 UPDATEE) updated exchange amq.topic
  2010-04-29 04:11:57 debug cluster(10.34.45.2:13840 UPDATEE) updated exchange qmf.default.direct
  2010-04-29 04:11:57 debug cluster(10.34.45.2:13840 UPDATEE) updated exchange qmf.default.topic
  2010-04-29 04:11:57 debug cluster(10.34.45.2:13840 UPDATEE) updated exchange qpid.cluster-update
  2010-04-29 04:11:57 debug cluster(10.34.45.2:13840 UPDATEE) updated exchange qpid.management
  2010-04-29 04:11:57 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_000__pub_done": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:57 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_000__pub_start": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:57 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_000__sub_done": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:57 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_000__sub_ready": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:57 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_001__pub_done": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:57 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_001__pub_start": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:57 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_001__sub_done": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:57 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_001__sub_ready": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:57 notice Journal "mrg-qe-01.lab.eng.brq.redhat.com_perftest_002_0": Created
  2010-04-29 04:11:57 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_002__pub_done": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:57 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_002__pub_start": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:57 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_002__sub_done": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:57 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_002__sub_ready": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:57 notice Journal "mrg-qe-01.lab.eng.brq.redhat.com_perftest_003_0": Created
  2010-04-29 04:11:58 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_003__pub_done": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:58 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_003__pub_start": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:58 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_003__sub_done": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:58 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_003__sub_ready": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:58 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_004__pub_done": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:58 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_004__pub_start": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:58 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_004__sub_done": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:58 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_004__sub_ready": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:58 notice Journal "mrg-qe-01.lab.eng.brq.redhat.com_perftest_005_0": Created
  2010-04-29 04:11:58 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_005__pub_done": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:58 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_005__pub_start": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:58 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_005__sub_done": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:58 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_005__sub_ready": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:58 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_006__pub_done": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:58 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_006__pub_start": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:58 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_006__sub_done": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:58 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_006__sub_ready": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:58 notice Journal "mrg-qe-01.lab.eng.brq.redhat.com_perftest_007_0": Created
  2010-04-29 04:11:58 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_007__pub_done": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:58 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_007__pub_start": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:58 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_007__sub_done": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:58 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_007__sub_ready": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:59 notice Journal "mrg-qe-01.lab.eng.brq.redhat.com_perftest_008_0": Created
  2010-04-29 04:11:59 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_008__pub_done": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:59 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_008__pub_start": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:59 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_008__sub_done": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:59 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_008__sub_ready": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:59 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_009__pub_done": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:59 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_009__pub_start": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:59 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_009__sub_done": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:59 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_009__sub_ready": Policy created: type=reject; maxCount=0; maxSize=10485
  7600
  2010-04-29 04:11:59 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_010__pub_done": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:59 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_010__pub_start": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:59 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_010__sub_done": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:59 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_010__sub_ready": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:59 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_011__pub_done": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:59 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_011__pub_start": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:59 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_011__sub_done": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:59 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_011__sub_ready": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:59 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_012__pub_done": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:59 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_012__pub_start": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:59 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_012__sub_done": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:59 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_012__sub_ready": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:59 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_013__pub_done": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:59 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_013__pub_start": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:59 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_014__pub_start": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:59 info Queue "qpid.cluster-update": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:11:59 info new catch-up connection 10.34.45.2:13840-3(local,catchup)
  2010-04-29 04:11:59 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:11:59 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-3(local,catchup) ssf=0
  2010-04-29 04:11:59 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:00 debug cluster(10.34.45.2:13840 UPDATEE) received session state update for anonymous
  2010-04-29 04:12:00 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-3(local,catchup) becomes shadow 10.34.45.1:19120-6
  2010-04-29 04:12:00 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-6
  2010-04-29 04:12:00 info new catch-up connection 10.34.45.2:13840-4(local,catchup)
  2010-04-29 04:12:00 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:00 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-4(local,catchup) ssf=0
  2010-04-29 04:12:00 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:00 debug cluster(10.34.45.2:13840 UPDATEE) received session state update for anonymous
  2010-04-29 04:12:00 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-4(local,catchup) becomes shadow 10.34.45.1:19120-7
  2010-04-29 04:12:00 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-7
  2010-04-29 04:12:00 info new catch-up connection 10.34.45.2:13840-5(local,catchup)
  2010-04-29 04:12:00 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:00 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-5(local,catchup) ssf=0
  2010-04-29 04:12:00 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:00 debug cluster(10.34.45.2:13840 UPDATEE) received session state update for anonymous
  2010-04-29 04:12:00 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-5(local,catchup) becomes shadow 10.34.45.1:19120-8
  2010-04-29 04:12:00 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-8
  2010-04-29 04:12:00 info new catch-up connection 10.34.45.2:13840-6(local,catchup)
  2010-04-29 04:12:00 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:00 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-6(local,catchup) ssf=0
  2010-04-29 04:12:00 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:00 debug cluster(10.34.45.2:13840 UPDATEE) received session state update for anonymous
  2010-04-29 04:12:00 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-6(local,catchup) becomes shadow 10.34.45.1:19120-11
  2010-04-29 04:12:00 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-11
  2010-04-29 04:12:00 info new catch-up connection 10.34.45.2:13840-7(local,catchup)
  2010-04-29 04:12:00 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:00 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-7(local,catchup) ssf=0
  2010-04-29 04:12:00 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:00 debug cluster(10.34.45.2:13840 UPDATEE) received session state update for anonymous
  2010-04-29 04:12:00 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-7(local,catchup) becomes shadow 10.34.45.1:19120-12
  2010-04-29 04:12:00 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-12
  2010-04-29 04:12:00 info new catch-up connection 10.34.45.2:13840-8(local,catchup)
  2010-04-29 04:12:00 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:00 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-8(local,catchup) ssf=0
  2010-04-29 04:12:00 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:00 debug cluster(10.34.45.2:13840 UPDATEE) received session state update for anonymous
  2010-04-29 04:12:00 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-8(local,catchup) becomes shadow 10.34.45.1:19120-13
  2010-04-29 04:12:00 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-13
  2010-04-29 04:12:00 info new catch-up connection 10.34.45.2:13840-9(local,catchup)
  2010-04-29 04:12:00 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:00 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-9(local,catchup) ssf=0
  2010-04-29 04:12:00 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:00 debug cluster(10.34.45.2:13840 UPDATEE) received session state update for anonymous
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-9(local,catchup) becomes shadow 10.34.45.1:19120-16
  2010-04-29 04:12:01 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-16
  2010-04-29 04:12:01 info new catch-up connection 10.34.45.2:13840-10(local,catchup)
  2010-04-29 04:12:01 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-10(local,catchup) ssf=0
  2010-04-29 04:12:01 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) received session state update for anonymous
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-10(local,catchup) becomes shadow 10.34.45.1:19120-17
  2010-04-29 04:12:01 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-17
  2010-04-29 04:12:01 info new catch-up connection 10.34.45.2:13840-11(local,catchup)
  2010-04-29 04:12:01 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-11(local,catchup) ssf=0
  2010-04-29 04:12:01 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) received session state update for anonymous
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-11(local,catchup) becomes shadow 10.34.45.1:19120-18
  2010-04-29 04:12:01 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-18
  2010-04-29 04:12:01 info new catch-up connection 10.34.45.2:13840-12(local,catchup)
  2010-04-29 04:12:01 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-12(local,catchup) ssf=0
  2010-04-29 04:12:01 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) received session state update for anonymous
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-12(local,catchup) becomes shadow 10.34.45.1:19120-20
  2010-04-29 04:12:01 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-20
  2010-04-29 04:12:01 info new catch-up connection 10.34.45.2:13840-13(local,catchup)
  2010-04-29 04:12:01 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-13(local,catchup) ssf=0
  2010-04-29 04:12:01 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) received session state update for anonymous
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-13(local,catchup) becomes shadow 10.34.45.1:19120-22
  2010-04-29 04:12:01 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-22
  2010-04-29 04:12:01 info new catch-up connection 10.34.45.2:13840-14(local,catchup)
  2010-04-29 04:12:01 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-14(local,catchup) ssf=0
  2010-04-29 04:12:01 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) received session state update for anonymous
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-14(local,catchup) becomes shadow 10.34.45.1:19120-23
  2010-04-29 04:12:01 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-23
  2010-04-29 04:12:01 info new catch-up connection 10.34.45.2:13840-15(local,catchup)
  2010-04-29 04:12:01 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-15(local,catchup) ssf=0
  2010-04-29 04:12:01 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) received session state update for anonymous
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-15(local,catchup) becomes shadow 10.34.45.1:19120-24
  2010-04-29 04:12:01 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-24
  2010-04-29 04:12:01 info new catch-up connection 10.34.45.2:13840-16(local,catchup)
  2010-04-29 04:12:01 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-16(local,catchup) ssf=0
  2010-04-29 04:12:01 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) received session state update for anonymous
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-16(local,catchup) becomes shadow 10.34.45.1:19120-27
  2010-04-29 04:12:01 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-27
  2010-04-29 04:12:01 info new catch-up connection 10.34.45.2:13840-17(local,catchup)
  2010-04-29 04:12:01 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-17(local,catchup) ssf=0
  2010-04-29 04:12:01 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) received session state update for anonymous
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-17(local,catchup) becomes shadow 10.34.45.1:19120-28
  2010-04-29 04:12:01 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-28
  2010-04-29 04:12:01 info new catch-up connection 10.34.45.2:13840-18(local,catchup)
  2010-04-29 04:12:01 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-18(local,catchup) ssf=0
  2010-04-29 04:12:01 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:01 info Queue "reply-mrg-qe-01.lab.eng.brq.redhat.com.19265.1": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:12:01 info Queue "topic-mrg-qe-01.lab.eng.brq.redhat.com.19265.1": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:12:01 info Queue "qmfc-v2-mrg-qe-01.lab.eng.brq.redhat.com.19265.1": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) received session state update for anonymous.lab.eng.brq.redhat.com.19265.1
  2010-04-29 04:12:01 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-18(local,catchup) becomes shadow 10.34.45.1:19120-29
  2010-04-29 04:12:02 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-29
  2010-04-29 04:12:02 info new catch-up connection 10.34.45.2:13840-19(local,catchup)
  2010-04-29 04:12:02 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:02 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-19(local,catchup) ssf=0
  2010-04-29 04:12:02 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:02 debug cluster(10.34.45.2:13840 UPDATEE) received session state update for anonymous
  2010-04-29 04:12:02 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-19(local,catchup) becomes shadow 10.34.45.1:19120-31
  2010-04-29 04:12:02 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-31
  2010-04-29 04:12:02 info new catch-up connection 10.34.45.2:13840-20(local,catchup)
  2010-04-29 04:12:02 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:02 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-20(local,catchup) ssf=0
  2010-04-29 04:12:02 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:02 debug cluster(10.34.45.2:13840 UPDATEE) received session state update for anonymous
  2010-04-29 04:12:02 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-20(local,catchup) becomes shadow 10.34.45.1:19120-32
  2010-04-29 04:12:02 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-32
  2010-04-29 04:12:02 info new catch-up connection 10.34.45.2:13840-21(local,catchup)
  2010-04-29 04:12:02 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:02 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-21(local,catchup) ssf=0
  2010-04-29 04:12:02 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:02 debug cluster(10.34.45.2:13840 UPDATEE) received session state update for anonymous
  2010-04-29 04:12:02 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-21(local,catchup) becomes shadow 10.34.45.1:19120-35
  2010-04-29 04:12:02 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-35
  2010-04-29 04:12:02 info new catch-up connection 10.34.45.2:13840-22(local,catchup)
  2010-04-29 04:12:02 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:02 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-22(local,catchup) ssf=0
  2010-04-29 04:12:02 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:02 debug cluster(10.34.45.2:13840 UPDATEE) received session state update for anonymous
  2010-04-29 04:12:02 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-22(local,catchup) becomes shadow 10.34.45.1:19120-36
  2010-04-29 04:12:02 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-36
  2010-04-29 04:12:02 info new catch-up connection 10.34.45.2:13840-23(local,catchup)
  2010-04-29 04:12:02 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:02 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-23(local,catchup) ssf=0
  2010-04-29 04:12:02 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:02 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-23(local,catchup) becomes shadow 10.34.45.1:19120-37
  2010-04-29 04:12:02 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-37
  2010-04-29 04:12:02 info new catch-up connection 10.34.45.2:13840-24(local,catchup)
  2010-04-29 04:12:02 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:02 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-24(local,catchup) ssf=0
  2010-04-29 04:12:02 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:02 debug cluster(10.34.45.2:13840 UPDATEE) received session state update for anonymous
  2010-04-29 04:12:02 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-24(local,catchup) becomes shadow 10.34.45.1:19120-38
  2010-04-29 04:12:02 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-38
  2010-04-29 04:12:02 info new catch-up connection 10.34.45.2:13840-25(local,catchup)
  2010-04-29 04:12:02 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:02 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-25(local,catchup) ssf=0
  2010-04-29 04:12:02 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:02 debug cluster(10.34.45.2:13840 UPDATEE) received session state update for anonymous
  2010-04-29 04:12:02 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-25(local,catchup) becomes shadow 10.34.45.1:19120-39
  2010-04-29 04:12:02 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-39
  2010-04-29 04:12:02 info new catch-up connection 10.34.45.2:13840-26(local,catchup)
  2010-04-29 04:12:02 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:02 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-26(local,catchup) ssf=0
  2010-04-29 04:12:02 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:02 debug cluster(10.34.45.2:13840 UPDATEE) received session state update for anonymous
  2010-04-29 04:12:02 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-26(local,catchup) becomes shadow 10.34.45.1:19120-40
  2010-04-29 04:12:02 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-40
  2010-04-29 04:12:02 info new catch-up connection 10.34.45.2:13840-27(local,catchup)
  2010-04-29 04:12:02 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:02 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-27(local,catchup) ssf=0
  2010-04-29 04:12:02 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:02 debug cluster(10.34.45.2:13840 UPDATEE) received session state update for anonymous
  2010-04-29 04:12:03 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-27(local,catchup) becomes shadow 10.34.45.1:19120-41
  2010-04-29 04:12:03 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-41
  2010-04-29 04:12:03 info new catch-up connection 10.34.45.2:13840-28(local,catchup)
  2010-04-29 04:12:03 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:03 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-28(local,catchup) ssf=0
  2010-04-29 04:12:03 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:03 debug cluster(10.34.45.2:13840 UPDATEE) received session state update for anonymous
  2010-04-29 04:12:03 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-28(local,catchup) becomes shadow 10.34.45.1:19120-42
  2010-04-29 04:12:03 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-42
  2010-04-29 04:12:03 info new catch-up connection 10.34.45.2:13840-29(local,catchup)
  2010-04-29 04:12:03 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:03 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-29(local,catchup) ssf=0
  2010-04-29 04:12:03 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:03 debug cluster(10.34.45.2:13840 UPDATEE) received session state update for anonymous
  2010-04-29 04:12:03 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-29(local,catchup) becomes shadow 10.34.45.1:19120-43
  2010-04-29 04:12:03 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-43
  2010-04-29 04:12:03 info new catch-up connection 10.34.45.2:13840-30(local,catchup)
  2010-04-29 04:12:03 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:03 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-30(local,catchup) ssf=0
  2010-04-29 04:12:03 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:03 debug cluster(10.34.45.2:13840 UPDATEE) received session state update for anonymous
  2010-04-29 04:12:03 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-30(local,catchup) becomes shadow 10.34.45.1:19120-44
  2010-04-29 04:12:03 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-44
  2010-04-29 04:12:03 info new catch-up connection 10.34.45.2:13840-31(local,catchup)
  2010-04-29 04:12:03 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:03 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-31(local,catchup) ssf=0
  2010-04-29 04:12:03 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:03 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-31(local,catchup) becomes shadow 10.34.45.1:19120-45
  2010-04-29 04:12:03 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-45
  2010-04-29 04:12:03 info new catch-up connection 10.34.45.2:13840-32(local,catchup)
  2010-04-29 04:12:03 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:03 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-32(local,catchup) ssf=0
  2010-04-29 04:12:03 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:03 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-32(local,catchup) becomes shadow 10.34.45.1:19120-46
  2010-04-29 04:12:03 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-46
  2010-04-29 04:12:03 info new catch-up connection 10.34.45.2:13840-33(local,catchup)
  2010-04-29 04:12:03 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:03 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-33(local,catchup) ssf=0
  2010-04-29 04:12:03 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:03 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-33(local,catchup) becomes shadow 10.34.45.1:19120-47
  2010-04-29 04:12:03 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-47
  2010-04-29 04:12:03 info new catch-up connection 10.34.45.2:13840-34(local,catchup)
  2010-04-29 04:12:03 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:03 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-34(local,catchup) ssf=0
  2010-04-29 04:12:03 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:03 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-34(local,catchup) becomes shadow 10.34.45.1:19120-48
  2010-04-29 04:12:03 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-48
  2010-04-29 04:12:03 info new catch-up connection 10.34.45.2:13840-35(local,catchup)
  2010-04-29 04:12:03 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:03 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-35(local,catchup) ssf=0
  2010-04-29 04:12:03 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:03 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-35(local,catchup) becomes shadow 10.34.45.1:19120-49
  2010-04-29 04:12:03 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-49
  2010-04-29 04:12:03 info new catch-up connection 10.34.45.2:13840-36(local,catchup)
  2010-04-29 04:12:03 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:03 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-36(local,catchup) ssf=0
  2010-04-29 04:12:03 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-36(local,catchup) becomes shadow 10.34.45.1:19120-50
  2010-04-29 04:12:04 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-50
  2010-04-29 04:12:04 info new catch-up connection 10.34.45.2:13840-37(local,catchup)
  2010-04-29 04:12:04 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 UPDATEE) initialized connection: 10.34.45.2:13840-37(local,catchup) ssf=0
  2010-04-29 04:12:04 info SASL: Authentication succeeded for: anonymous@QPID
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 UPDATEE) catch-up connection 10.34.45.2:13840-37(local,catchup) becomes shadow 10.34.45.1:19120-51
  2010-04-29 04:12:04 info cluster(10.34.45.2:13840 UPDATEE) new shadow connection 10.34.45.1:19120-51
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 UPDATEE) updated management schemas
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 UPDATEE) updated management agents
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 UPDATEE) incoming update complete on connection 10.34.45.2:13840-2(local,catchup)
  2010-04-29 04:12:04 notice cluster(10.34.45.2:13840 CATCHUP) update complete, starting catch-up.
  2010-04-29 04:12:04 debug queue snapshot at 319274: mrg-qe-01.lab.eng.brq.redhat.com_perftest_000_0=574 mrg-qe-01.lab.eng.brq.redhat.com_perftest_000__pub_done=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_000__pub_start=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_000__sub_done=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_000__sub_ready=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_001_0=517 mrg-qe-01.lab.eng.brq.redhat.com_perftest_001__pub_done=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_001__pub_start=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_001__sub_done=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_001__sub_ready=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_002_0=574 mrg-qe-01.lab.eng.brq.redhat.com_perftest_002__pub_done=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_002__pub_start=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_002__sub_done=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_002__sub_ready=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_003_0=574 mrg-qe-01.lab.eng.brq.redhat.com_perftest_003__pub_done=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_003__pub_start=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_003__sub_done=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_003__sub_ready=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_004_0=460 mrg-qe-01.lab.eng.brq.redhat.com_perftest_004__pub_done=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_004__pub_start=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_004__sub_done=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_004__sub_ready=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_005_0=316 mrg-qe-01.lab.eng.brq.redhat.com_perftest_005__pub_done=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_005__pub_start=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_005__sub_done=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_005__sub_ready=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_006_0=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_006__pub_done=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_006__pub_start=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_006__sub_done=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_006__sub_ready=1 mrg-qe-01.lab.eng.brq.redhat.com_perftest_007_0=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_007__pub_done=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_007__pub_start=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_007__sub_done=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_007__sub_ready=1 mrg-qe-01.lab.eng.brq.redhat.com_perftest_008_0=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_008__pub_done=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_008__pub_start=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_008__sub_done=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_008__sub_ready=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_009_0=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_009__pub_done=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_009__pub_start=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_009__sub_done=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_009__sub_ready=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_010_0=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_010__pub_done=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_010__pub_start=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_010__sub_done=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_010__sub_ready=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_011_0=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_011__pub_done=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_011__pub_start=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_011__sub_done=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_011__sub_ready=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_012__pub_done=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_012__pub_start=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_012__sub_done=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_012__sub_ready=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_013__pub_done=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_013__pub_start=0 mrg-qe-01.lab.eng.brq.redhat.com_perftest_014__pub_start=0 qmfc-v2-mrg-qe-01.lab.eng.brq.redhat.com.19265.1=0 reply-mrg-qe-01.lab.eng.brq.redhat.com.19265.1=0 topic-mrg-qe-01.lab.eng.brq.redhat.com.19265.1=0
  2010-04-29 04:12:04 debug cluster update  management snapshot: packages: 3 objects: 0 new objects: 263
  2010-04-29 04:12:04 info Queue "mrg-qe-01.lab.eng.brq.redhat.com_perftest_013__sub_ready": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 CATCHUP) closed update connection 10.34.45.2:13840-0(updated)
  2010-04-29 04:12:04 notice Journal "mrg-qe-01.lab.eng.brq.redhat.com_perftest_012_0": Created
  2010-04-29 04:12:04 info SASL: Authentication failed for anonymous@QPID:SASL(-1): generic failure: Unable to find a callback: 32775
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 CATCHUP/error) connection error 323592 on 10.34.45.1:19120-50(shadow) must be resolved with: 10.34.45.1:19120 : connection-forced: Authentication failed
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 CATCHUP/error) error 323592 resolved with 10.34.45.2:13840
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 CATCHUP/error) error 323592 must be resolved with 10.34.45.1:19120
  2010-04-29 04:12:04 critical cluster(10.34.45.2:13840 CATCHUP/error) local error 323592 did not occur on member 10.34.45.1:19120: connection-forced: Authentication failed
  2010-04-29 04:12:04 critical Error delivering frames: local error did not occur on all cluster members : connection-forced: Authentication failed (qpid/cluster/ErrorCheck.cpp:89)
  2010-04-29 04:12:04 notice cluster(10.34.45.2:13840 LEFT/error) leaving cluster xyz
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.2:13840-0(updated)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-51(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-50(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-49(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-48(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-47(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-46(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-45(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-44(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-43(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-42(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-41(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-40(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-39(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-38(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-37(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-36(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-35(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-32(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-31(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-29(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-28(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-27(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-24(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-23(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-22(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-20(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-18(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-17(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-16(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-13(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-12(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-11(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-8(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-7(shadow)
  2010-04-29 04:12:04 debug cluster(10.34.45.2:13840 LEFT/error) deleted connection: 10.34.45.1:19120-6(shadow)
  2010-04-29 04:12:04 debug Shutting down CPG
  2010-04-29 04:12:04 notice Shut down

broker config files:
cluster-mechanism=ANONYMOUS
#auth=no
log-enable=info+
log-enable=debug+:cluster
log-to-file=/tmp/qpidd.log
cluster-name=xyz
truncate=yes
data-dir=/tmp/dd
Comment 5 Frantisek Reznicek 2010-04-29 08:36:01 UTC 
Created attachment 410033 [details]
Another reproducer of the issue

How to run?
1] run on first node:
  ./run.sh 20 1 0 ANONYMOUS; while true; do ./run.sh $(( $((${RANDOM}%4)) + 4)) 0 0 ANONYMOUS|| break; done
2] wait about 30 secs and do it for every other node:
  ./run.sh 20 1 0 ANONYMOUS; while true; do ./run.sh $(( $((${RANDOM}%4)) + 4)) 0 0 ANONYMOUS|| break; done
Comment 6 Alan Conway 2010-05-19 20:47:39 UTC 
Please check this against the beta build, there have been some fixes to authentication that might address this issue.
Comment 7 Alan Conway 2010-05-28 13:56:39 UTC 
Fixed on trunk r48967,r48969. Merged to release repository:

http://mrg1.lab.bos.redhat.com/git/?p=qpid.git;a=commit;h=939a12c7d1f3fc56f328a23e496a87514f7bd42d
http://mrg1.lab.bos.redhat.com/git/?p=qpid.git;a=commit;h=20d5d896b2ae01b717fc8c70ce67a95e6fb2c737
Comment 8 Frantisek Reznicek 2010-08-25 15:26:17 UTC 
Retested with reproducer at comment #5, no issue found.

Going to be retested with original reproducer. Update soon.
Comment 10 Frantisek Reznicek 2010-09-15 07:44:08 UTC 
The bug is being retested once more using original reproducer. So far no luck, because other qpid-tools bugs are preventing the issue repetition on old package set...
Comment 11 Frantisek Reznicek 2010-10-05 11:30:02 UTC 
The issue has been fixed, tested on RHEL 5.5 i386 / x86_64 on packages:
python-qpid-0.7.946106-14.el5
qpid-cpp-client-0.7.946106-17.el5
qpid-cpp-client-devel-0.7.946106-17.el5
qpid-cpp-client-devel-docs-0.7.946106-17.el5
qpid-cpp-client-ssl-0.7.946106-17.el5
qpid-cpp-server-0.7.946106-17.el5
qpid-cpp-server-cluster-0.7.946106-17.el5
qpid-cpp-server-devel-0.7.946106-17.el5
qpid-cpp-server-ssl-0.7.946106-17.el5
qpid-cpp-server-store-0.7.946106-17.el5
qpid-cpp-server-xml-0.7.946106-17.el5
qpid-java-client-0.7.946106-10.el5
qpid-java-common-0.7.946106-10.el5
qpid-tools-0.7.946106-11.el5


-> VERIFIED
Comment 12 Martin Prpič 2010-10-08 13:09:50 UTC 
    Technical note added. If any revisions are required, please edit the "Technical Notes" field
    accordingly. All revisions will be proofread by the Engineering Content Services team.
    
    New Contents:
Clustered qpidd no longer shuts down during a start-up due to an Authentication failure.
Comment 14 errata-xmlrpc 2010-10-14 16:04:19 UTC 
An advisory has been issued which should help the problem
described in this bug report. This report is therefore being
closed with a resolution of ERRATA. For more information
on therefore solution and/or where to find the updated files,
please follow the link below. You may reopen this bug report
if the solution does not work for you.

http://rhn.redhat.com/errata/RHSA-2010-0773.html
Note You need to log in before you can comment on or make changes to this bug.