Description of problem: I am trying to make connections using PLAIN auth over SSL (port 5671), which works fine with Python. In Ruby, the attempt at connecting simply hangs and eventually times out. We've been able to collect the following info: * The Ruby bindings do not appear to have direct support for SSL, from what I can tell. To make any attempt at all, I've had to wrap the TCPSocket in an SSLSocket, and implement some low-level missing methods that the ruby-qpid calls on plain Socket. * Within read_frame of framer.rb, it is almost always hitting the case: raise FramingError if (flags & 0xF0 > 0) * According to the server side logs, it looks to be attempting a GSSAPI connection despite being set as PLAIN.
Created attachment 467549 [details] Example SSL connect code In this example, the code simply hangs & +then times out at line 35 (conn.start 60). According to the server side logs, it looks to be attempting a GSSAPI connection despite being set as PLAIN.
I've just looked at mixologist.lab.bos.redhat.com. It appears to be configured for *only* GSSAPI: 2010-12-20 13:46:08 trace RECV [48355 mixologist.lab.bos.redhat.com:5672]: Frame[BEbe; channel=0; {ConnectionStartBody: server-properties={qpid.federation_tag:V2:36:str16(a884e76f-cb71-444f-8b0c-fffbcfab920a)}; mechanisms=str16{V2:6:str16(GSSAPI)}; locales=str16{V2:5:str16(en_US)}; }]
This doesn't seem right. Mixologist is configured to use SSL on port 5671, and works fine without any gssapi authentication in other languages, i.e. python. Tim, can you confirm?
If the config is incorrect then I'm having trouble locating where it's broken. The contents of /etc/sasl2/qpidd.conf are: mech_list: gssapi plain pwcheck_method: auxprop auxprop_plugin: sasldb sasldb_path: /var/lib/qpidd/qpidd.sasldb #following line stops spurious 'sql_select option missing' errors when #cyrus-sql-sasl plugin is installed sql_select: dummy select And here's the contents of /etc/qpidd.conf: require-encryption=yes auth=yes realm=XXXXXX.COM # ACL acl-file=/etc/qpid/policy.acl # SSL ssl-port=5671 ssl-use-export-policy=yes ssl-cert-password-file=/var/lib/qpidd/ssl/passwd ssl-cert-db=/var/lib/qpidd/ssl ssl-cert-name=somecertname # Logging log-to-syslog=0 log-to-file=/var/log/qpidd.log log-time=1 log-level=1 log-enable=debug+ # Modules no-module-dir=yes load-module=/usr/lib64/qpid/daemon/acl.so load-module=/usr/lib64/qpid/daemon/ssl.so load-module=/usr/lib64/qpid/daemon/msgstore.so load-module=/usr/lib64/qpid/daemon/xml.so
> * Within read_frame of framer.rb, it is almost always hitting the case: raise > FramingError if (flags & 0xF0 > 0) It appears that the decoding is not working correctly at some level. The first frame after the protocol header is an invalid frame (hence the above framing error, which is not caught meaning the connection processing thread exists and no further reading is done). > * According to the server side logs, it looks to be attempting a GSSAPI > connection despite being set as PLAIN. I don't _think_ this is the case. The mechanism is selected by the client on connection_start. However the test doesn't seem to get this far. Even the protocol header _appears_ to be incorrectly decoded. I suspect that the SSL decoding is not happening (or not happening at the right time) and the client library is consequently trying to decode SSL encrypted data and failing. Unfortunately I don't really know much ruby, or the OpenSSL module. Are we sure the added method does the right thing? Could this be circumventing the SSL decryption? module OpenSSL module SSL module SocketForwarder def recv(size) to_io.recvfrom(size)[0] end end end end
(In reply to comment #6) > I suspect that the SSL decoding is not happening (or not happening at the right > time) and the client library is consequently trying to decode SSL encrypted > data and failing. > > Unfortunately I don't really know much ruby, or the OpenSSL module. Are we sure > the added method does the right thing? Could this be circumventing the SSL > decryption? It is entirely possible that it is doing the wrong thing. It does not appear that the ruby library was tested using SSL in the first place. In ruby, the typical method of using SSL is to open a socket, wrap it with OpenSSL::SSL::SSLSocket, and pass that object in where the socket is used. The qpid libary uses the method recv on TCPSocket, which is not implemented in the SSLSocket class. The code below is consistent with how the rest of the wrapping code is written in the SSL library, but it could be incorrect in this case. > module OpenSSL > module SSL > module SocketForwarder > def recv(size) > to_io.recvfrom(size)[0] > end > end > end > end
We've gotten a little bit further by switching the call in the SocketForwarder: module OpenSSL module SSL module SocketForwarder def recv(size) readpartial(size) end end end end It appears to get a response back from the server and decrypted properly. Trying to authenticate and start the connection times out: ssl_bug_661408.rb OSSL_DEBUG: IS NOW ON! Starting D, [2011-02-25T10:14:48.597517 #25991] DEBUG -- : SENT "AMQP\001\001\000\n" D, [2011-02-25T10:14:48.598503 #25991] DEBUG -- : RECV 8/131 "AMQP\001\001\000\n\017\000\000{\000\000\000\000\000\000\000\000\001\001\a\000\000\000\000?\000\000\000\001\023qpid.federation_tag\225\000$a884e76f-cb71-444f-8b0c-fffbcfab920a\000\000\000\024\225\000\000\000\002\000\006GSSAPI\000\005PLAIN\000\000\000\f\225\000\000\000\001\000\005en_US" D, [2011-02-25T10:14:48.598971 #25991] DEBUG -- : RECV FL 0 0 0 "\001\001\a\000\000\000\000?\000\000\000\001\023qpid.federation_tag\225\000$a884e76f-cb71-444f-8b0c-fffbcfab920a\000\000\000\024\225\000\000\000\002\000\006GSSAPI\000\005PLAIN\000\000\000\f\225\000\000\000\001\000\005en_US" D, [2011-02-25T10:14:48.603387 #25991] DEBUG -- : SENT "\017\000\000\326\000\000\000\000\000\000\000\000\001\002\a\000\000\000\000\247\000\000\000\006\017qpid.client_pid1\000\000\000\000\000\000e\207\bplatform\225\000\tlinux-gnu\aproduct\225\000\022qpid python client\020qpid.client_ppid1\000\000\000\000\000\000eS\aversion\225\000\vdevelopment\023qpid.client_process\225\000\021ssl_bug_661408.rb\005PLAIN\000\000\000\021guest\000guest\000guest" D, [2011-02-25T10:14:48.604266 #25991] DEBUG -- : SENT FL 0 0 0 "\001\002\a\000\000\000\000\247\000\000\000\006\017qpid.client_pid1\000\000\000\000\000\000e\207\bplatform\225\000\tlinux-gnu\aproduct\225\000\022qpid python client\020qpid.client_ppid1\000\000\000\000\000\000eS\aversion\225\000\vdevelopment\023qpid.client_process\225\000\021ssl_bug_661408.rb\005PLAIN\000\000\000\021guest\000guest\000guest" /usr/lib/ruby/site_ruby/1.8/qpid/connection.rb:140:in `start': Qpid::Timeout (Qpid::Timeout) from /usr/lib/ruby/1.8/monitor.rb:242:in `synchronize' from /usr/lib/ruby/site_ruby/1.8/qpid/connection.rb:138:in `start' On the server side, the following appears in the logs: 2011-02-25 10:05:50 debug External ssf=0 and auth= 2011-02-25 10:05:50 debug min_ssf: 10, max_ssf: 256, external_ssf: 0 2011-02-25 10:05:50 info SASL: Mechanism list: GSSAPI 2011-02-25 10:05:50 debug Management object (V1) added: org.apache.qpid.broker:connection:127.0.0.1:5672-127.0.0.1:41953 2011-02-25 10:05:50 trace SENT 127.0.0.1:5672-127.0.0.1:41953 INIT(0-10) 2011-02-25 10:05:50 trace SENT [127.0.0.1:5672-127.0.0.1:41953]: Frame[BEbe; channel=0; {ConnectionStartBody: server-properties={qpid.federation_tag :V2:36:str16(a884e76f-cb71-444f-8b0c-fffbcfab920a)}; mechanisms=str16{V2:6:str16(GSSAPI)}; locales=str16{V2:5:str16(en_US)}; }] 2011-02-25 10:05:50 trace RECV [127.0.0.1:5672-127.0.0.1:41953]: Frame[BEbe; channel=0; {ConnectionCloseBody: reply-code=501; reply-text=internal-er ror: Sasl error: SASL(-1): generic failure: GSSAPI Error: Unspecified GSS failure. Minor code may provide more information (Unknown code krb5 195) (qpid/SaslFactory.cpp:279); }] 2011-02-25 10:05:50 warning Client closed connection with 501: internal-error: Sasl error: SASL(-1): generic failure: GSSAPI Error: Unspecified GSS failure. Minor code may provide more information (Unknown code krb5 195) (qpid/SaslFactory.cpp:279) 2011-02-25 10:05:50 trace SENT [127.0.0.1:5672-127.0.0.1:41953]: Frame[BEbe; channel=0; {ConnectionCloseOkBody: }] 2011-02-25 10:05:50 debug SEND raiseEvent (v1) class=org.apache.qpid.broker.clientDisconnect 2011-02-25 10:05:56 debug RECV [10.16.36.223:5671-10.11.9.178:50551] INIT(0-10) 2011-02-25 10:05:56 debug External ssf=40 and auth= 2011-02-25 10:05:56 debug min_ssf: 0, max_ssf: 0, external_ssf: 40 2011-02-25 10:05:56 info SASL: Mechanism list: GSSAPI PLAIN 2011-02-25 10:05:56 debug Management object (V1) added: org.apache.qpid.broker:connection:10.16.36.223:5671-10.11.9.178:50551 2011-02-25 10:05:56 trace SENT 10.16.36.223:5671-10.11.9.178:50551 INIT(0-10) 2011-02-25 10:05:56 trace SENT [10.16.36.223:5671-10.11.9.178:50551]: Frame[BEbe; channel=0; {ConnectionStartBody: server-properties={qpid.federatio n_tag:V2:36:str16(a884e76f-cb71-444f-8b0c-fffbcfab920a)}; mechanisms=str16{V2:6:str16(GSSAPI), V2:5:str16(PLAIN)}; locales=str16{V2:5:str16(en_US)}; }] 2011-02-25 10:05:57 debug Exception constructed: Framing version unsupported (qpid/framing/AMQFrame.cpp:93) 2011-02-25 10:05:57 error framing-error: Framing version unsupported (qpid/framing/AMQFrame.cpp:93) 2011-02-25 10:05:57 debug SEND raiseEvent (v1) class=org.apache.qpid.broker.clientDisconnect