Bug 713419

Jeff - Looks like an API call out of gofer/qpid, can you take a look?

Sachin - What version of gofer?

Here is the gofer version. I'm using same 0.39 both on rhua and cds.

[root@dhcp193-163 yum.repos.d]# rpm -qa | grep gofer
python-gofer-0.39-1.el6.noarch
gofer-0.39-1.el6.noarch
[root@dhcp193-163 yum.repos.d]#

(In reply to comment #1)
> Jeff - Looks like an API call out of gofer/qpid, can you take a look?

Sure.

Wow, this trace is a nightmare.

> 
> Sachin - What version of gofer?

Can this be an SELinux issue?

<snip>
[Wed Jun 15 16:34:39 2011] [notice] SELinux policy enabled; httpd running as
context unconfined_u:system_r:httpd_t:s0
</snip>

Sachin downgraded gofer to 0.38 with no improvement so we can assume this has nothing to do with the 0.39 upgrade.

Looks like el6 has moved to qpid 0.10 and the Transport API has changed since 0.8.

[root@dhcp193-163 ~]# rpm -qa|grep qpid
qpid-cpp-server-0.10-3.el6.x86_64
qpid-cpp-client-ssl-0.10-3.el6.x86_64
qpid-cpp-client-0.10-3.el6.x86_64
python-qpid-0.10-1.el6.noarch
qpid-cpp-server-ssl-0.10-3.el6.x86_64

I monkey patched the installed suds to match the Transport API change in python-qpid 0.10 and everything seems good.  I can register/unregister a CDS.

I'll fix in gofer 0.4 shortly but it will change the 'requires' to python-qpid 0.10.

(In reply to comment #7)
> I monkey patched the installed suds to match the Transport API change in

Er, 'gofer' not 'suds'

> python-qpid 0.10 and everything seems good.  I can register/unregister a CDS.
> 
> I'll fix in gofer 0.4 shortly but it will change the 'requires' to python-qpid
> 0.10.

Refiled upstream: 713758

Looks like python-qpid 0.10 in F14/F15 API has not changed but python-qpid 0.10 in EL6 has changed.  Ted Ross (qpid) will look into why the API does not match in EL6.  For now, I'll fix in a way that tolerates either signature for Transport.__init__().

Fixed in gofer 0.41.

I updated the gofer on rhua and CDS. Now I can register CDS. Thanks Jeff.


rhua node:
=======
[root@dhcp193-163 mongodb]# rpm -qa | grep gofer
gofer-0.41-1.el6.noarch
python-gofer-0.41-1.el6.noarch
[root@dhcp193-163 mongodb]# 


CDS node:
============
[root@dhcp193-115 ~]# rpm -qa | grep gofer
python-gofer-0.41-1.el6.noarch
gofer-0.41-1.el6.noarch
[root@dhcp193-115 ~]# 




------------------------------------------------------------------------------
             -= Red Hat Update Infrastructure Management Tool =-


-= Content Delivery Server (CDS) Management =-

   l   list all CDS instances registered to the RHUI
   a   register (add) a new CDS instance
   d   unregister (delete) a CDS instance from the RHUI

                                         Connected: dhcp193-163.pnq.redhat.com
------------------------------------------------------------------------------
rhui (cds) => a

Prior to registering a CDS, the CDS must be configured and running.

Hostname of the CDS to register:
dhcp193-163.pnq.redhat.com

Display name for the CDS [dhcp193-163.pnq.redhat.com]:
cdss0115^C  

------------------------------------------------------------------------------
rhui (cds) => a       

Prior to registering a CDS, the CDS must be configured and running.

Hostname of the CDS to register:
dhcp193-115.pnq.redhat.com

Display name for the CDS [dhcp193-115.pnq.redhat.com]:
cdss00115


The following CDS instance will be registered:
  Hostname: dhcp193-115.pnq.redhat.com
  Name:     cdss00115
Proceed? (y/n) y


Successfully registered cdss00115

------------------------------------------------------------------------------
rhui (cds) => l

-= RHUI Content Delivery Servers =-

  cds0021
  cdss00115

------------------------------------------------------------------------------
rhui (cds) =>

strange, I did a new install and facing this issue again with, not sure may be the setup was tweaked. 

I have done two different setups one at amazon and one locally.

[root@dhcp201-115 pulp]# rpm -qav | grep -ie python-qpid -e pulp -e gofer  -e python-gofer
pulp-client-0.0.190-1.el6.noarch
pulp-common-0.0.190-1.el6.noarch
python-qpid-0.10-1.el6.noarch
gofer-0.41-1.el6.noarch
python-gofer-0.41-1.el6.noarch
pulp-0.0.190-1.el6.noarch


------------------------------------------------------------------------------
             -= Red Hat Update Infrastructure Management Tool =-


-= Content Delivery Server (CDS) Management =-

   l   list all CDS instances registered to the RHUI
   a   register (add) a new CDS instance
   d   unregister (delete) a CDS instance from the RHUI

                                  Connected: dhcp201-115.englab.pnq.redhat.com
------------------------------------------------------------------------------
rhui (cds) => a

Prior to registering a CDS, the CDS must be configured and running.

Hostname of the CDS to register:
dhcp201-225.englab.pnq.redhat.com

Display name for the CDS [dhcp201-225.englab.pnq.redhat.com]:
cds1-225


The following CDS instance will be registered:
  Hostname: dhcp201-225.englab.pnq.redhat.com
  Name:     cds1-225
Proceed? (y/n) y


Error registering cds1-225, check the log file for more information

------------------------------------------------------------------------------
rhui (cds) => logout




Connecting to RHUA [dhcp201-115.englab.pnq.redhat.com]...
Successfully connected to [dhcp201-115.englab.pnq.redhat.com]
Exception attempting to register CDS [dhcp201-225.englab.pnq.redhat.com]
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/rhui/tools/pulp_api.py", line 501, in register_cds
    self.cds_api.register(hostname, name=display_name, description='RHUI CDS', sync_schedule=schedule, cluster_id=CDS_CLUSTER_NAME)
  File "/usr/lib/python2.6/site-packages/pulp/client/api/cds.py", line 32, in register
    return self.server.POST(path, data)[1]
  File "/usr/lib/python2.6/site-packages/pulp/client/server.py", line 301, in POST
    return self._request('POST', path, body=body)
  File "/usr/lib/python2.6/site-packages/pulp/client/server.py", line 265, in _request
    raise ServerRequestError(response.status, message, traceback)
ServerRequestError: (500, u"PulpException: 'Timeout occurred attempting to initialize CDS [dhcp201-225.englab.pnq.redhat.com]'", u'Traceback (most recent call last):\n  File "/usr/lib/python2.6/site-packages/pulp/server/webservices/controllers/base.py", line 53, in report_error\n    return method(self, *args, **kwargs)\n  File "/usr/lib/python2.6/site-packages/pulp/server/webservices/controllers/base.py", line 132, in _auth_decorator\n    value = method(self, *args, **kwargs)\n  File "/usr/lib/python2.6/site-packages/pulp/server/webservices/controllers/cds.py", line 73, in POST\n    cds = cds_api.register(hostname, name, description, sync_schedule=sync_schedule, cluster_id=cluster_id)\n  File "/usr/lib/python2.6/site-packages/pulp/server/auditing.py", line 197, in _audit\n    result = method(*args, **kwargs)\n  File "/usr/lib/python2.6/site-packages/pulp/server/api/cds.py", line 120, in register\n    secret = self.dispatcher.init_cds(cds)\n  File "/usr/lib/python2.6/site-packages/pulp/server/cds/dispatcher.py", line 93, in init_cds\n    secret = self._send(self._cds_stub(cds).initialize)\n  File "/usr/lib/python2.6/site-packages/pulp/server/cds/dispatcher.py", line 170, in _send\n    result = func(*args)\n  File "/usr/lib/python2.6/site-packages/gofer/messaging/stub.py", line 71, in __call__\n    return self.stub._send(request, opts)\n  File "/usr/lib/python2.6/site-packages/gofer/messaging/stub.py", line 142, in _send\n    any=opts.any)\n  File "/usr/lib/python2.6/site-packages/gofer/messaging/policy.py", line 120, in send\n    self.__getstarted(sn, reader)\n  File "/usr/lib/python2.6/site-packages/gofer/messaging/policy.py", line 158, in __getstarted\n    raise RequestTimeout(sn)')

I don't see anything in the log to suggest this is the same issue.  I see the RequestTimeout registering hostname= dhcp201-225.englab.pnq.redhat.com.  Is this the correct hostname?  Is goferd running on this CDS?  Please attach the /var/log/gofer/agent.log.

Also, I'd be glad to poke around if you want to email me credentials.  I tried to ssh to dhcp201-115.englab.pnq.redhat.com and dhcp201-225.englab.pnq.redhat.com but can't resolve the hostnames.

Nevermind the log and credentials.  I was able to ssh onto dhcp201-225.englab.pnq.redhat.com
 and gofer can't connect to the qpid broker:

2011-06-21 00:38:22,185 [WARNING][Thread-1] close_engine() @ driver.py:444 - recoverable error[attempt 171]: [Errno 1] _ssl.c:480: error:14090086:SSL routines:SSL3_GET_SERVER_CERTIFICATE:certificate verify failed

Looks like the server certificate is not yet valid.

[root@dhcp201-225 cds]# openssl s_client -connect dhcp201-115.englab.pnq.redhat.com:5674 -CAfile /etc/pki/cds/qpid-ca.crt
CONNECTED(00000003)
depth=1 C = US, ST = Alabama, O = pulp, CN = rhua
verify error:num=9:certificate is not yet valid
notBefore=Jun 20 22:59:57 2011 GMT
verify return:0
140019511711560:error:14094412:SSL routines:SSL3_READ_BYTES:sslv3 alert bad certificate:s3_pkt.c:1193:SSL alert number 42
140019511711560:error:140790E5:SSL routines:SSL23_WRITE:ssl handshake failure:s23_lib.c:184:
---
Certificate chain
 0 s:/C=US/ST=Alabama/O=pulp/CN=dhcp201-115.englab.pnq.redhat.com
   i:/C=US/ST=Alabama/O=pulp/CN=rhua
 1 s:/C=US/ST=Alabama/O=pulp/CN=rhua
   i:/C=US/ST=Alabama/O=pulp/CN=rhua
---
Server certificate
-----BEGIN CERTIFICATE-----
MIICCzCCAXSgAwIBAgIBATANBgkqhkiG9w0BAQUFADA9MQswCQYDVQQGEwJVUzEQ
MA4GA1UECBMHQWxhYmFtYTENMAsGA1UEChMEcHVscDENMAsGA1UEAxMEcmh1YTAe
Fw0xMTA2MjAyMjU5NTdaFw0xMjA2MjAyMjU5NTdaMFoxCzAJBgNVBAYTAlVTMRAw
DgYDVQQIEwdBbGFiYW1hMQ0wCwYDVQQKEwRwdWxwMSowKAYDVQQDEyFkaGNwMjAx
LTExNS5lbmdsYWIucG5xLnJlZGhhdC5jb20wgZ8wDQYJKoZIhvcNAQEBBQADgY0A
MIGJAoGBALRYwyqygDWG4Xlksmpai7qraB9BB6tbGYlDTFKObttW8sY0aZ+Ye9ws
R8Fa6uNs58iT5bdaV81kt002AJleXeW0HiDsZLbW/JqOadqyv7O6acOmXFYsrqZc
4w18U+LYEsOIhi0F+7NHk/6V9+5MQzcT6a5wWYZZl1NoRH/Cfzq7AgMBAAEwDQYJ
KoZIhvcNAQEFBQADgYEAUlFea6pOZhHNi7qJqTBWI/MoOwUX/OsK5CrfLSYsCyEF
GUP0auL2dq+bG6UV90lm9Xd1Jx7FcwYXxrhnSvLI4BaJPvcJ9rnf7JU4OI2p4RLL
w6+G5Lmrf7HrD+xLZxnCm1/F1YOUnDnJ9OPDAGJ3UUvv8+6Zo/13YyTt7VPpNOE=
-----END CERTIFICATE-----
subject=/C=US/ST=Alabama/O=pulp/CN=dhcp201-115.englab.pnq.redhat.com
issuer=/C=US/ST=Alabama/O=pulp/CN=rhua
---
Acceptable client certificate CA names
/C=US/ST=Alabama/O=pulp/CN=rhua
---
SSL handshake has read 1213 bytes and written 194 bytes
---
New, TLSv1/SSLv3, Cipher is RC4-MD5
Server public key is 1024 bit
Secure Renegotiation IS supported
Compression: NONE
Expansion: NONE
SSL-Session:
    Protocol  : TLSv1
    Cipher    : RC4-MD5
    Session-ID: 59DC475F50E37FEA02411AD3A7D3497178B27660188D850C6AD9032D89BC8848
    Session-ID-ctx: 
    Master-Key: 2176C36D8835C938FD66D35802215B24A6B896D59B94CE7650C7ACE4E5AF715775A6041F034901744EFEB82D968BAEA9
    Key-Arg   : None
    Krb5 Principal: None
    PSK identity: None
    PSK identity hint: None
    Start Time: 1308597550
    Timeout   : 300 (sec)
    Verify return code: 9 (certificate is not yet valid)

Server cert text:
Certificate:
    Data:
        Version: 3 (0x2)
        Serial Number: 1 (0x1)
        Signature Algorithm: sha1WithRSAEncryption
        Issuer: C=US, ST=Alabama, O=pulp, CN=rhua
        Validity
            Not Before: Jun 20 22:59:57 2011 GMT
            Not After : Jun 20 22:59:57 2012 GMT
        Subject: C=US, ST=Alabama, O=pulp, CN=dhcp201-115.englab.pnq.redhat.com
        Subject Public Key Info:
            Public Key Algorithm: rsaEncryption
                Public-Key: (1024 bit)
                Modulus:
                    00:b4:58:c3:2a:b2:80:35:86:e1:79:64:b2:6a:5a:
                    8b:ba:ab:68:1f:41:07:ab:5b:19:89:43:4c:52:8e:
                    6e:db:56:f2:c6:34:69:9f:98:7b:dc:2c:47:c1:5a:
                    ea:e3:6c:e7:c8:93:e5:b7:5a:57:cd:64:b7:4d:36:
                    00:99:5e:5d:e5:b4:1e:20:ec:64:b6:d6:fc:9a:8e:
                    69:da:b2:bf:b3:ba:69:c3:a6:5c:56:2c:ae:a6:5c:
                    e3:0d:7c:53:e2:d8:12:c3:88:86:2d:05:fb:b3:47:
                    93:fe:95:f7:ee:4c:43:37:13:e9:ae:70:59:86:59:
                    97:53:68:44:7f:c2:7f:3a:bb
                Exponent: 65537 (0x10001)
    Signature Algorithm: sha1WithRSAEncryption
        52:51:5e:6b:aa:4e:66:11:cd:8b:ba:89:a9:30:56:23:f3:28:
        3b:05:17:fc:eb:0a:e4:2a:df:2d:26:2c:0b:21:05:19:43:f4:
        6a:e2:f6:76:af:9b:1b:a5:15:f7:49:66:f5:77:75:27:1e:c5:
        73:06:17:c6:b8:67:4a:f2:c8:e0:16:89:3e:f7:09:f6:b9:df:
        ec:95:38:38:8d:a9:e1:12:cb:c3:af:86:e4:b9:ab:7f:b1:eb:
        0f:ec:4b:67:19:c2:9b:5f:c5:d5:83:94:9c:39:c9:f4:e3:c3:
        00:62:77:51:4b:ef:f3:ee:99:a3:fd:77:63:24:ed:ed:53:e9:
        34:e1

Current date: Tue Jun 21 01:02:31 IST 2011 
IST = GMT +5:30 so the certificate wont be valid until: Jun 21 03:59:57 which is almost 3 hours in the future.

So, the question is: why does the QPID server certificate have a future valid date?

Looks like nss-db-gen (AKA nss certutil) is generating certificates with a valid date of 4 hours in the future in IST.  I'm digging further.

The CDS succeeded to connect to the qpid broker at 2011-06-21 04:31:00 because the certificate became valid.  You should be able to register your CDS now.

yes it works now, I should be more careful, it was for 2 different reasons that I got the same error in pulp.log file for setups at 1) amazon and 2) local vm's

The issue with 2) local vm's has been resolved, the main reason being the time zones, my mistake , I just checked pulp-server is EDT and pulp-cds is IST. certs were created on pulp-server.

But the issue still persists with the amazon setup.

The cds register issue with the amazon setup solved. 
Needs to use the output of the command 'hostname' , while registering for the cds node.

with the new gofer 0.41 and python-qpid-0.10, this issue is no longer observed.

moving to release pending

closing out, product released