Bug 661408

Summary:

Unable to use SSL connections

Product:

Red Hat Enterprise MRG

Reporter:

Jon Orris <jorris>

Component:

qpid-sdk

Assignee:

messaging-bugs <messaging-bugs>

Status:

NEW ---

QA Contact:

MRG Quality Engineering <mrgqe-bugs>

Severity:

medium

Docs Contact:

Priority:

low

Version:

1.3

CC:

gsim

Target Milestone:

---

Target Release:

---

Hardware:

Unspecified

OS:

Unspecified

Whiteboard:

Fixed In Version:

Doc Type:

Bug Fix

Doc Text:

Story Points:

---

Clone Of:

Environment:

Last Closed:

Type:

---

Regression:

---

Mount Type:

---

Documentation:

---

CRM:

Verified Versions:

Category:

---

oVirt Team:

---

RHEL 7.3 requirements from Atomic Host:

Cloudforms Team:

---

Target Upstream Version:

Embargoed:

Attachments:

Description	Flags
Example SSL connect code	none

Description Jon Orris 2010-12-08 18:54:24 UTC

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.

Comment 1 Jon Orris 2010-12-08 18:58:06 UTC

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.

Comment 3 Ted Ross 2010-12-20 18:52:59 UTC

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)}; }]

Comment 4 Jon Orris 2011-01-04 15:44:40 UTC

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?

Comment 5 Tim Powers 2011-01-05 07:58:54 UTC

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

Comment 6 Gordon Sim 2011-01-24 10:44:46 UTC

> * 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

Comment 7 Jon Orris 2011-01-26 15:21:22 UTC

(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

Comment 8 Jon Orris 2011-02-25 16:22:14 UTC

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