Created attachment 405331 [details]
The testing client

You need python-saslwrapper and saslwrapper packages for gssapi with python, and they don't seem to be in the list. Not sure that that is the issue here and indeed the error is a little ungraceful anyway.

I found another case on RHEL 5.5 x86_64 with installed saslwrappers. 

This case is found during SASL PLAIN authentication run, so issue does not have any link kerberos stuff.

Interesting fact is that another run of qpid_ptest_authentication_plain on RHEL 5.5 i386 just passed.

So I analyzed installed packages and all were same except cyrus-sasl-md5 which was not installed on RHEL 5.5 i386.

After installation of cyrus-sasl-md5 package python client started to fail also on RHEL 5.5 i386.


[root@mrg-qe-02 1-1]# rpm -qa | grep -E '(qpid|sasl|^krb5|^python-2)' | sort -u
cyrus-sasl-2.1.22-5.el5_4.3
cyrus-sasl-devel-2.1.22-5.el5_4.3
cyrus-sasl-lib-2.1.22-5.el5_4.3
cyrus-sasl-md5-2.1.22-5.el5_4.3
cyrus-sasl-plain-2.1.22-5.el5_4.3
krb5-auth-dialog-0.7-1
krb5-devel-1.6.1-36.el5_4.1
krb5-libs-1.6.1-36.el5_4.1
krb5-workstation-1.6.1-36.el5_4.1
python-2.4.3-27.el5
python-qpid-0.7.930108-1.el5
python-saslwrapper-0.1.897961-3.el5
qpid-cpp-client-0.7.929717-1.el5
qpid-cpp-client-devel-0.7.929717-1.el5
qpid-cpp-client-devel-docs-0.7.929717-1.el5
qpid-cpp-client-ssl-0.7.929717-1.el5
qpid-cpp-mrg-debuginfo-0.7.929717-1.el5
qpid-cpp-server-0.7.929717-1.el5
qpid-cpp-server-cluster-0.7.929717-1.el5
qpid-cpp-server-devel-0.7.929717-1.el5
qpid-cpp-server-ssl-0.7.929717-1.el5
qpid-cpp-server-store-0.7.929717-1.el5
qpid-cpp-server-xml-0.7.929717-1.el5
qpid-java-client-0.7.918215-1.el5
qpid-java-common-0.7.918215-1.el5
qpid-tools-0.7.930108-1.el5
ruby-qpid-0.7.904654-1.el5
ruby-saslwrapper-0.1.897961-3.el5
saslwrapper-0.1.897961-3.el5
saslwrapper-devel-0.1.897961-3.el5

qc_client.py --conn-auth-mechanism PLAIN -p 14134 --password JwD624dAwVCevVZkBQ --broker localhost --user TzZYm5ufU8a35fiRvtT04
Cannot connect to the broker localhost:14134
Traceback (most recent call last):
  File "/root/MRG/Messaging/qpid_common/clients/python/qc_lib.py", line 210, in connect
    self.connection.start();
  File "/usr/lib/python2.4/site-packages/qpid/connection.py", line 149, in start
    raise ConnectionFailed(*self.close_code)
ConnectionFailed: (None, "(9, 'Bad file descriptor')")
Traceback (most recent call last):
  File "/root/MRG/Messaging/qpid_common/clients/python/qc_client.py", line 30, in ?
    sys.exit(main());
  File "/root/MRG/Messaging/qpid_common/clients/python/qc_client.py", line 18, in main
    qc.connect();
  File "/root/MRG/Messaging/qpid_common/clients/python/qc_lib.py", line 218, in connect
    raise QcException(e);
qc_lib.QcException: <qpid.connection.ConnectionFailed instance at 0x2b0ae614acb0>

Conclusion:
Package cyrus-sasl-md5 (on RHEL 5.5) causes qpid python client to fail when authenticate to broker via SASL.

Python authentication failure case

a] rough log

[06:31:50] mrg_install_packages_yum:Installation succeeded
[06:31:50] ========================TEST started========================
[06:31:50] -TEST-CASE:V.MRG.M.0005-TEST-CASE-DESC:qpidd broker authentication SASL Plain----------------
[06:31:56] run 1/3--------------------------------------[err_cnt:0]-
[06:31:56] .create identities (cnt:5)
[06:31:57] .start broker (realm:QPID)
[06:31:57] .running qpidd broker (see log/1-1)...  running
[06:31:58] .running auth. clients (LFOvf6FChecz54ZPufg2CW:jwwDvepECo9LW@localhost mode:success)
[06:31:58] ..brief summary (perftest|qc_client|qc_client.py|qc_client.rb, ecode:0 0 1 0)
[06:31:58] ..ecode:0
[06:31:58] ..ecode:0
[06:31:58] ..ERROR:ecode:1
[06:31:58] ..ecode:0
[06:31:58] ./root/MRG/Messaging/qpid_ptest_authentication_plain/log/1-1/qpidd.log password check
[06:31:58] ..passed
[06:31:58] .running auth. clients (LFOvf6FChecz54ZPufg2CW:_I_jwwDvepECo9LW_I_@localhost mode:failure)

b] python client stdout/err

qc_client.py --conn-auth-mechanism PLAIN -p 5749 --password jwwDvepECo9LW --broker localhost --user LFOvf6FChecz54ZPufg2CW
Cannot connect to the broker localhost:5749
Traceback (most recent call last):
  File "/root/MRG/Messaging/qpid_common/clients/python/qc_lib.py", line 210, in connect
    self.connection.start();
  File "/usr/lib/python2.4/site-packages/qpid/connection.py", line 149, in start
    raise ConnectionFailed(*self.close_code)
ConnectionFailed: (None, "(9, 'Bad file descriptor')")
Traceback (most recent call last):
  File "/root/MRG/Messaging/qpid_common/clients/python/qc_client.py", line 30, in ?
    sys.exit(main());
  File "/root/MRG/Messaging/qpid_common/clients/python/qc_client.py", line 18, in main
    qc.connect();
  File "/root/MRG/Messaging/qpid_common/clients/python/qc_lib.py", line 218, in connect
    raise QcException(e);
qc_lib.QcException: <qpid.connection.ConnectionFailed instance at 0x2aaac10cccb0>
Exception qc_lib.QcException: <qc_lib.QcException instance at 0x2aaac10ccd40> in <bound method qc_client.__del__ of <qc_lib.qc_client object at 0x2aaac
10c6d10>> ignored
qc_client.py --conn-auth-mechanism PLAIN -p 5749 --password _I_jwwDvepECo9LW_I_ --broker localhost --user LFOvf6FChecz54ZPufg2CW
Cannot connect to the broker localhost:5749
Traceback (most recent call last):
  File "/root/MRG/Messaging/qpid_common/clients/python/qc_lib.py", line 210, in connect
    self.connection.start();
  File "/usr/lib/python2.4/site-packages/qpid/connection.py", line 149, in start
    raise ConnectionFailed(*self.close_code)
ConnectionFailed: (None, "(9, 'Bad file descriptor')")
Traceback (most recent call last):
  File "/root/MRG/Messaging/qpid_common/clients/python/qc_client.py", line 30, in ?
    sys.exit(main());
  File "/root/MRG/Messaging/qpid_common/clients/python/qc_client.py", line 18, in main
    qc.connect();
  File "/root/MRG/Messaging/qpid_common/clients/python/qc_lib.py", line 218, in connect
    raise QcException(e);
qc_lib.QcException: <qpid.connection.ConnectionFailed instance at 0x2ab418fbccb0>
Exception qc_lib.QcException: <qc_lib.QcException instance at 0x2ab418fbcd40> in <bound method qc_client.__del__ of <qc_lib.qc_client object at 0x2ab41
8fb7d50>> ignored


c] broker log (debug+)

see 
  Authentication failed (no username available):SASL(-6): can't request info until later in exchange: Information that was requested is not yet available.
lower

[root@mrg-qe-02 1-1]# head -250 qpidd.log
2010-04-09 06:31:57 info Loaded Module: /usr/lib64/qpid/daemon/acl.so
2010-04-09 06:31:57 info Loaded Module: /usr/lib64/qpid/daemon/xml.so
2010-04-09 06:31:57 info SSL connector not enabled, you must set QPID_SSL_CERT_DB to enable it.
2010-04-09 06:31:57 info Loaded Module: /usr/lib64/qpid/client/sslconnector.so
2010-04-09 06:31:57 info Loaded Module: /usr/lib64/qpid/daemon/cluster.so
2010-04-09 06:31:57 info Loaded Module: /usr/lib64/qpid/daemon/msgstore.so
2010-04-09 06:31:57 info Loaded Module: /usr/lib64/qpid/daemon/ssl.so
2010-04-09 06:31:57 info Loaded Module: /usr/lib64/qpid/daemon/watchdog.so
2010-04-09 06:31:57 info Loaded Module: /usr/lib64/qpid/daemon/replication_exchange.so
2010-04-09 06:31:57 info Loaded Module: /usr/lib64/qpid/daemon/replicating_listener.so
2010-04-09 06:31:57 info No message store configured, persistence is disabled.
2010-04-09 06:31:57 info Management enabled
2010-04-09 06:31:57 info ManagementAgent generated broker ID: 93f90bf2-6bf6-4a75-9582-27e4590469cb
2010-04-09 06:31:57 debug ManagementAgent boot sequence: 1
2010-04-09 06:31:57 debug ManagementAgent added package org.apache.qpid.broker
2010-04-09 06:31:57 debug ManagementAgent added class org.apache.qpid.broker:system
2010-04-09 06:31:57 debug ManagementAgent added class org.apache.qpid.broker:broker
2010-04-09 06:31:57 debug ManagementAgent added class org.apache.qpid.broker:agent
2010-04-09 06:31:57 debug ManagementAgent added class org.apache.qpid.broker:vhost
2010-04-09 06:31:57 debug ManagementAgent added class org.apache.qpid.broker:queue
2010-04-09 06:31:57 debug ManagementAgent added class org.apache.qpid.broker:exchange
2010-04-09 06:31:57 debug ManagementAgent added class org.apache.qpid.broker:binding
2010-04-09 06:31:57 debug ManagementAgent added class org.apache.qpid.broker:subscription
2010-04-09 06:31:57 debug ManagementAgent added class org.apache.qpid.broker:connection
2010-04-09 06:31:57 debug ManagementAgent added class org.apache.qpid.broker:link
2010-04-09 06:31:57 debug ManagementAgent added class org.apache.qpid.broker:bridge
2010-04-09 06:31:57 debug ManagementAgent added class org.apache.qpid.broker:session
2010-04-09 06:31:57 debug ManagementAgent added class org.apache.qpid.broker:managementsetupstate
2010-04-09 06:31:57 debug ManagementAgent added class org.apache.qpid.broker:clientConnect
2010-04-09 06:31:57 debug ManagementAgent added class org.apache.qpid.broker:clientConnectFail
2010-04-09 06:31:57 debug ManagementAgent added class org.apache.qpid.broker:clientDisconnect
2010-04-09 06:31:57 debug ManagementAgent added class org.apache.qpid.broker:brokerLinkUp
2010-04-09 06:31:57 debug ManagementAgent added class org.apache.qpid.broker:brokerLinkDown
2010-04-09 06:31:57 debug ManagementAgent added class org.apache.qpid.broker:queueDeclare
2010-04-09 06:31:57 debug ManagementAgent added class org.apache.qpid.broker:queueDelete
2010-04-09 06:31:57 debug ManagementAgent added class org.apache.qpid.broker:exchangeDeclare
2010-04-09 06:31:57 debug ManagementAgent added class org.apache.qpid.broker:exchangeDelete
2010-04-09 06:31:57 debug ManagementAgent added class org.apache.qpid.broker:bind
2010-04-09 06:31:57 debug ManagementAgent added class org.apache.qpid.broker:unbind
2010-04-09 06:31:57 debug ManagementAgent added class org.apache.qpid.broker:subscribe
2010-04-09 06:31:57 debug ManagementAgent added class org.apache.qpid.broker:unsubscribe
2010-04-09 06:31:57 info Registered xml exchange
2010-04-09 06:31:57 notice Journal "TplStore": Created
2010-04-09 06:31:57 debug Journal "TplStore": Journal directory = "/root/MRG/Messaging/qpid_ptest_authentication_plain/log/1-1/datadir/rhm/tpl/"; Base file name = "tpl"
2010-04-09 06:31:57 notice Store module initialized; store-dir=/root/MRG/Messaging/qpid_ptest_authentication_plain/log/1-1/datadir
2010-04-09 06:31:57 info > Default files per journal: 8
2010-04-09 06:31:57 info > Default journal file size: 24 (wpgs)
2010-04-09 06:31:57 info > Default write cache page size: 32 (Kib)
2010-04-09 06:31:57 info > Default number of write cache pages: 32
2010-04-09 06:31:57 info > TPL files per journal: 8
2010-04-09 06:31:57 info > TPL journal file size: 24 (wpgs)
2010-04-09 06:31:57 info > TPL write cache page size: 4 (Kib)
2010-04-09 06:31:57 info > TPL number of write cache pages: 64
2010-04-09 06:31:57 info Registered replication exchange
2010-04-09 06:31:57 info Most recent persistence id found: 0x0
2010-04-09 06:31:57 info SASL enabled
2010-04-09 06:31:57 notice Listening on TCP port 5749
2010-04-09 06:31:57 info Policy file not specified. ACL Disabled, no ACL checking being done!
2010-04-09 06:31:57 debug ManagementAgent added package com.redhat.rhm.store
2010-04-09 06:31:57 debug ManagementAgent added class com.redhat.rhm.store:store
2010-04-09 06:31:57 debug ManagementAgent added class com.redhat.rhm.store:journal
2010-04-09 06:31:57 debug ManagementAgent added class com.redhat.rhm.store:enqThresholdExceeded
2010-04-09 06:31:57 debug ManagementAgent added class com.redhat.rhm.store:created
2010-04-09 06:31:57 debug ManagementAgent added class com.redhat.rhm.store:full
2010-04-09 06:31:57 debug ManagementAgent added class com.redhat.rhm.store:recovered
2010-04-09 06:31:57 info SSL plugin not enabled, you must set --ssl-cert-db to enable it.
2010-04-09 06:31:57 notice Broker running
2010-04-09 06:31:58 debug RECV [127.0.0.1:38732] INIT(0-10)
2010-04-09 06:31:58 debug External ssf=0 and auth=
2010-04-09 06:31:58 debug min_ssf: 0, max_ssf: 256, external_ssf: 0
2010-04-09 06:31:58 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS CRAM-MD5 DIGEST-MD5
2010-04-09 06:31:58 debug SASL: Starting authentication with mechanism: PLAIN
2010-04-09 06:31:58 info SASL: Authentication succeeded for: LFOvf6FChecz54ZPufg2CW@QPID
2010-04-09 06:31:58 debug SessionState::SessionState LFOvf6FChecz54ZPufg2CW: 0x2aaaac004d30
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: attached on broker.
2010-04-09 06:31:58 debug Attached channel 1 to LFOvf6FChecz54ZPufg2CW
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: ready to send, activating output.
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver command-point set to: (0+0)
2010-04-09 06:31:58 debug Configured queue perftest_pub_start with no-local=0
2010-04-09 06:31:58 debug Configured queue perftest_pub_start with qpid.trace.id='' and qpid.trace.exclude='' i.e. 0 elements
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 0 incomplete: { } unknown-completed: { [0,0] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 1 incomplete: { } unknown-completed: { [0,1] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 2 incomplete: { } unknown-completed: { [0,2] }
2010-04-09 06:31:58 debug Configured queue perftest_pub_done with no-local=0
2010-04-09 06:31:58 debug Configured queue perftest_pub_done with qpid.trace.id='' and qpid.trace.exclude='' i.e. 0 elements
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 3 incomplete: { } unknown-completed: { [0,3] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 4 incomplete: { } unknown-completed: { [0,4] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 5 incomplete: { } unknown-completed: { [0,5] }
2010-04-09 06:31:58 debug Configured queue perftest_sub_ready with no-local=0
2010-04-09 06:31:58 debug Configured queue perftest_sub_ready with qpid.trace.id='' and qpid.trace.exclude='' i.e. 0 elements
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 6 incomplete: { } unknown-completed: { [0,6] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 7 incomplete: { } unknown-completed: { [0,7] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 8 incomplete: { } unknown-completed: { [0,8] }
2010-04-09 06:31:58 debug Configured queue perftest_sub_done with no-local=0
2010-04-09 06:31:58 debug Configured queue perftest_sub_done with qpid.trace.id='' and qpid.trace.exclude='' i.e. 0 elements
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 9 incomplete: { } unknown-completed: { [0,9] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 10 incomplete: { } unknown-completed: { [0,10] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 11 incomplete: { } unknown-completed: { [0,11] }
2010-04-09 06:31:58 debug Configured queue perftest0 with no-local=0
2010-04-09 06:31:58 debug Configured queue perftest0 with qpid.trace.id='' and qpid.trace.exclude='' i.e. 0 elements
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 12 incomplete: { } unknown-completed: { [0,12] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 13 incomplete: { } unknown-completed: { [0,13] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 14 incomplete: { } unknown-completed: { [0,14] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: detached on broker.
2010-04-09 06:31:58 debug RECV [127.0.0.1:38733] INIT(0-10)
2010-04-09 06:31:58 debug External ssf=0 and auth=
2010-04-09 06:31:58 debug min_ssf: 0, max_ssf: 256, external_ssf: 0
2010-04-09 06:31:58 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS CRAM-MD5 DIGEST-MD5
2010-04-09 06:31:58 debug SASL: Starting authentication with mechanism: PLAIN
2010-04-09 06:31:58 info SASL: Authentication succeeded for: LFOvf6FChecz54ZPufg2CW@QPID
2010-04-09 06:31:58 debug SessionState::SessionState LFOvf6FChecz54ZPufg2CW: 0x2aaaac004d30
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: attached on broker.
2010-04-09 06:31:58 debug Attached channel 1 to LFOvf6FChecz54ZPufg2CW
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: ready to send, activating output.
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver command-point set to: (0+0)
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 0 incomplete: { } unknown-completed: { [0,0] }
2010-04-09 06:31:58 debug RECV [127.0.0.1:38734] INIT(0-10)
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 1 incomplete: { } unknown-completed: { [0,1] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 2 incomplete: { } unknown-completed: { [0,2] }
2010-04-09 06:31:58 debug External ssf=0 and auth=
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 3 incomplete: { } unknown-completed: { [0,3] }
2010-04-09 06:31:58 debug min_ssf: 0, max_ssf: 256, external_ssf: 0
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 4 incomplete: { } unknown-completed: { [0,4] }
2010-04-09 06:31:58 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS CRAM-MD5 DIGEST-MD5
2010-04-09 06:31:58 debug No messages to dispatch on queue 'perftest_pub_start'
2010-04-09 06:31:58 debug SASL: Starting authentication with mechanism: PLAIN
2010-04-09 06:31:58 info SASL: Authentication succeeded for: LFOvf6FChecz54ZPufg2CW@QPID
2010-04-09 06:31:58 debug SessionState::SessionState LFOvf6FChecz54ZPufg2CW: 0x2aaaac0019b0
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: attached on broker.
2010-04-09 06:31:58 debug Attached channel 1 to LFOvf6FChecz54ZPufg2CW
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: ready to send, activating output.
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver command-point set to: (0+0)
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 0 incomplete: { } unknown-completed: { [0,0] }
2010-04-09 06:31:58 debug RECV [127.0.0.1:38735] INIT(0-10)
2010-04-09 06:31:58 debug External ssf=0 and auth=
2010-04-09 06:31:58 debug min_ssf: 0, max_ssf: 256, external_ssf: 0
2010-04-09 06:31:58 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS CRAM-MD5 DIGEST-MD5
2010-04-09 06:31:58 debug SASL: Starting authentication with mechanism: PLAIN
2010-04-09 06:31:58 info SASL: Authentication succeeded for: LFOvf6FChecz54ZPufg2CW@QPID
2010-04-09 06:31:58 debug SessionState::SessionState LFOvf6FChecz54ZPufg2CW: 0x1feba190
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: attached on broker.
2010-04-09 06:31:58 debug Attached channel 1 to LFOvf6FChecz54ZPufg2CW
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: ready to send, activating output.
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver command-point set to: (0+0)
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 0 incomplete: { } unknown-completed: { [0,0] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 1 incomplete: { } unknown-completed: { [0,1] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 2 incomplete: { } unknown-completed: { [0,2] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 3 incomplete: { } unknown-completed: { [0,3] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 4 incomplete: { } unknown-completed: { [0,4] }
2010-04-09 06:31:58 debug No messages to dispatch on queue 'perftest_sub_ready'
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 1 incomplete: { } unknown-completed: { [0,1] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 2 incomplete: { } unknown-completed: { [0,2] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 3 incomplete: { } unknown-completed: { [0,3] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 4 incomplete: { } unknown-completed: { [0,4] }
2010-04-09 06:31:58 debug No messages to dispatch on queue 'perftest0'
2010-04-09 06:31:58 debug Message 0x1feb9ed0 enqueued on perftest_sub_ready
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 5 incomplete: { } unknown-completed: { [0,5] }
2010-04-09 06:31:58 debug Sufficient credit for perftest_sub_ready on LFOvf6FChecz54ZPufg2CW, have bytes: 4294967295 msgs: 1, need 49 bytes
2010-04-09 06:31:58 debug Credit allocated for perftest_sub_ready on LFOvf6FChecz54ZPufg2CW, was  bytes: 4294967295 msgs: 1 now bytes: 4294967295 msgs: 0
2010-04-09 06:31:58 debug DeliveryRecord::setEnded() id=0
2010-04-09 06:31:58 debug Accepted 0
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 5 incomplete: { } unknown-completed: { [0,5] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: sender marked completed: { [0,0] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: sender confirmed point moved to (1+0)
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 6 incomplete: { } unknown-completed: { [0,6] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 7 incomplete: { } unknown-completed: { [0,7] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 8 incomplete: { } unknown-completed: { [0,8] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 9 incomplete: { } unknown-completed: { [0,9] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 10 incomplete: { } unknown-completed: { [0,10] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 11 incomplete: { } unknown-completed: { [0,11] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 12 incomplete: { } unknown-completed: { [0,12] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 13 incomplete: { } unknown-completed: { [0,13] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 14 incomplete: { } unknown-completed: { [0,14] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 15 incomplete: { } unknown-completed: { [0,15] }
2010-04-09 06:31:58 debug Message 0x1febb1a0 enqueued on perftest_pub_start
2010-04-09 06:31:58 debug Sufficient credit for perftest_pub_start on LFOvf6FChecz54ZPufg2CW, have bytes: 4294967295 msgs: 1, need 49 bytes
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 16 incomplete: { } unknown-completed: { [0,16] }
2010-04-09 06:31:58 debug Credit allocated for perftest_pub_start on LFOvf6FChecz54ZPufg2CW, was  bytes: 4294967295 msgs: 1 now bytes: 4294967295 msgs: 0
2010-04-09 06:31:58 debug DeliveryRecord::setEnded() id=0
2010-04-09 06:31:58 debug Accepted 0
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 5 incomplete: { } unknown-completed: { [0,5] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: sender marked completed: { [0,0] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: sender confirmed point moved to (1+0)
2010-04-09 06:31:58 debug Message 0x2aaaac089a40 enqueued on perftest0
2010-04-09 06:31:58 debug Sufficient credit for perftest0 on LFOvf6FChecz54ZPufg2CW, have bytes: 4294967295 msgs: 1, need 1059 bytes
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 6 incomplete: { } unknown-completed: { [0,6] }
2010-04-09 06:31:58 debug Credit allocated for perftest0 on LFOvf6FChecz54ZPufg2CW, was  bytes: 4294967295 msgs: 1 now bytes: 4294967295 msgs: 0
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 7 incomplete: { } unknown-completed: { [0,7] }
2010-04-09 06:31:58 debug DeliveryRecord::setEnded() id=0
2010-04-09 06:31:58 debug No messages to dispatch on queue 'perftest_pub_start'
2010-04-09 06:31:58 debug Message 0x1febb1a0 enqueued on perftest_pub_done
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 8 incomplete: { } unknown-completed: { [0,8] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: detached on broker.
2010-04-09 06:31:58 debug Message 0x2aaaac004280 enqueued on perftest_sub_done
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 6 incomplete: { } unknown-completed: { [0,6] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: detached on broker.
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 17 incomplete: { } unknown-completed: { [0,17] }
2010-04-09 06:31:58 debug Sufficient credit for perftest_pub_done on LFOvf6FChecz54ZPufg2CW, have bytes: 4294967295 msgs: 1, need 59 bytes
2010-04-09 06:31:58 debug Credit allocated for perftest_pub_done on LFOvf6FChecz54ZPufg2CW, was  bytes: 4294967295 msgs: 1 now bytes: 4294967295 msgs: 0
2010-04-09 06:31:58 debug DeliveryRecord::setEnded() id=1
2010-04-09 06:31:58 debug Accepted 1
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 18 incomplete: { } unknown-completed: { [0,18] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: sender marked completed: { [0,1] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: sender confirmed point moved to (2+0)
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 19 incomplete: { } unknown-completed: { [0,19] }
2010-04-09 06:31:58 debug Sufficient credit for perftest_sub_done on LFOvf6FChecz54ZPufg2CW, have bytes: 4294967295 msgs: 1, need 60 bytes
2010-04-09 06:31:58 debug Credit allocated for perftest_sub_done on LFOvf6FChecz54ZPufg2CW, was  bytes: 4294967295 msgs: 1 now bytes: 4294967295 msgs: 0
2010-04-09 06:31:58 debug DeliveryRecord::setEnded() id=2
2010-04-09 06:31:58 debug Accepted 2
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver marked completed: 20 incomplete: { } unknown-completed: { [0,20] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: sender marked completed: { [0,2] }
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: sender confirmed point moved to (3+0)
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: detached on broker.
2010-04-09 06:31:58 debug RECV [127.0.0.1:38736] INIT(0-10)
2010-04-09 06:31:58 debug External ssf=0 and auth=
2010-04-09 06:31:58 debug min_ssf: 0, max_ssf: 256, external_ssf: 0
2010-04-09 06:31:58 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS CRAM-MD5 DIGEST-MD5
2010-04-09 06:31:58 debug SASL: Starting authentication with mechanism: PLAIN
2010-04-09 06:31:58 info SASL: Authentication succeeded for: LFOvf6FChecz54ZPufg2CW@QPID
2010-04-09 06:31:58 debug SessionState::SessionState LFOvf6FChecz54ZPufg2CW: 0x2aaaac001830
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: attached on broker.
2010-04-09 06:31:58 debug Attached channel 1 to LFOvf6FChecz54ZPufg2CW
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: ready to send, activating output.
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: receiver command-point set to: (0+0)
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: detached on broker.
2010-04-09 06:31:58 debug RECV [127.0.0.1:38737] INIT(0-10)
2010-04-09 06:31:58 debug External ssf=0 and auth=
2010-04-09 06:31:58 debug min_ssf: 0, max_ssf: 256, external_ssf: 0
2010-04-09 06:31:58 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS CRAM-MD5 DIGEST-MD5
2010-04-09 06:31:58 debug SASL: Starting authentication with mechanism: DIGEST-MD5
2010-04-09 06:31:58 debug SASL: sending challenge to client
2010-04-09 06:31:58 warning Failed to retrieve sasl username
2010-04-09 06:31:58 info SASL: Authentication failed (no username available):SASL(-6): can't request info until later in exchange: Information that was requested is not yet available.
2010-04-09 06:31:58 debug Exception constructed: Authentication failed
2010-04-09 06:31:58 warning Failed to retrieve sasl username
2010-04-09 06:31:58 debug DISCONNECTED [127.0.0.1:38737]
2010-04-09 06:31:58 debug RECV [127.0.0.1:38738] INIT(0-10)
2010-04-09 06:31:58 debug External ssf=0 and auth=
2010-04-09 06:31:58 debug min_ssf: 0, max_ssf: 256, external_ssf: 0
2010-04-09 06:31:58 info SASL: Mechanism list: LOGIN PLAIN ANONYMOUS CRAM-MD5 DIGEST-MD5
2010-04-09 06:31:58 debug SASL: Starting authentication with mechanism: PLAIN
2010-04-09 06:31:58 info SASL: Authentication succeeded for: LFOvf6FChecz54ZPufg2CW@QPID
2010-04-09 06:31:58 debug SessionState::SessionState LFOvf6FChecz54ZPufg2CW: 0x2aaaac04abb0
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: attached on broker.
2010-04-09 06:31:58 debug Attached channel 0 to LFOvf6FChecz54ZPufg2CW
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: ready to send, activating output.
2010-04-09 06:31:58 debug LFOvf6FChecz54ZPufg2CW: detached on broker.
2010-04-09 06:31:58 debug RECV [127.0.0.1:38739] INIT(0-10)
2010-04-09 06:31:58 debug External ssf=0 and auth=
2010-04-09 06:31:58 debug min_ssf: 0, max_ssf: 256, external_ssf: 0

I believe the issue here is that if the authentication fails (regardless of mechanism and apparently whether or not you have saslwrapper installed), you get the following exception:

Traceback (most recent call last):
  File "./declare_queues.py", line 65, in ?
    connection.start()
  File "/usr/lib/python2.4/site-packages/qpid/connection.py", line 149, in start
    raise ConnectionFailed(*self.close_code)
qpid.connection.ConnectionFailed: (None, "(9, 'Bad file descriptor')")

Frantisek is that an accurate statement of the bug?

I should have added that the issue I describe above is not so much the exception (which can be caught), but that it does not describe the problem, namely an authentication failure.

Fixed by r938815 (the exception now given should be correct).

I do confirm the description from comment #6.
I can see 
'qpid.connection.ConnectionFailed: (None, "(9, 'Bad file descriptor')")'
message when authentication fails (PLAIN mechanism) regardless whether or not  saslwrapper is installed.

In the GSSAPI case I can see this message if authentication fails:

qc_client.py --conn-auth-mechanism GSSAPI -p 33309 --user _^_mXyvuWhg6TKK2NyG2z_^_ --broker dell-pe2850-04.rhts.eng.bos.redhat.com 
Exception in thread Thread-1:
Traceback (most recent call last):
  File "/usr/lib64/python2.4/threading.py", line 442, in __bootstrap
    self.run()
  File "/usr/lib64/python2.4/threading.py", line 422, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/usr/lib/python2.4/site-packages/qpid/connection.py", line 179, in run
    self.delegate.received(op)
  File "/usr/lib/python2.4/site-packages/qpid/delegates.py", line 52, in received
    getattr(self, op.NAME)(ch, op)
  File "/usr/lib/python2.4/site-packages/qpid/delegates.py", line 213, in connection_start
    raise Closed("SASL error: %s" % self.sasl.getError())
Closed: SASL error: Error in sasl_client_start (-1) SASL(-1): generic failure: GSSAPI Error: Unspecified GSS failure.  Minor code may provide more information (Unknown code krb5 195)

Frantisek, is it safe to say this is verified?