#4676 CA did not start in 300.0s after IPA upgrade
Closed: Fixed None Opened 9 years ago by mbasti.

This happens only during first upgrade (reproduced from 4.0.4 to 4.1.0)

2014-10-31T03:08:34Z DEBUG Waiting for CA to start...
2014-10-31T03:08:35Z DEBUG request 'https://vm-026.example.com:443/ca/admin/ca/getStatus'
2014-10-31T03:08:35Z DEBUG request body ''
2014-10-31T03:08:35Z DEBUG The CA status is: check interrupted
2014-10-31T03:08:35Z DEBUG Waiting for CA to start...
2014-10-31T03:08:36Z DEBUG   File "/usr/lib/python2.7/site-packages/ipaserver/install/installutils.py", line 642, in run_script
    return_value = main_function()

  File "/usr/sbin/ipa-upgradeconfig", line 1457, in main
    ca.restart(dogtag.configured_constants().PKI_INSTANCE_NAME)

  File "/usr/lib/python2.7/site-packages/ipaserver/install/service.py", line 282, in restart
    self.service.restart(instance_name, capture_output=capture_output, wait=wait)

  File "/usr/lib/python2.7/site-packages/ipaplatform/redhat/services.py", line 209, in restart
    self.wait_until_running()

  File "/usr/lib/python2.7/site-packages/ipaplatform/redhat/services.py", line 197, in wait_until_running
    raise RuntimeError('CA did not start in %ss' % timeout)

2014-10-31T03:08:36Z DEBUG The ipa-upgradeconfig command failed, exception: RuntimeError: CA did not start in 300.0s

But when I add link to web browser, CA is running.

I removed [dogtag] entries from /var/lib/ipa/sysupgrade/sysupgrade.state and re-run ipa-upgradeconfig.

ipa-upgradeconfig finished successfully:

2014-10-31T03:56:51Z DEBUG wait_for_open_ports: localhost [8080, 8443] timeout 300
2014-10-31T03:56:55Z DEBUG Waiting until the CA is running
2014-10-31T03:56:55Z DEBUG request 'https://vm-026.example.com:443/ca/admin/ca/getStatus'
2014-10-31T03:56:55Z DEBUG request body ''
2014-10-31T03:57:16Z DEBUG request status 200
2014-10-31T03:57:16Z DEBUG request reason_phrase u'OK'
2014-10-31T03:57:16Z DEBUG request headers {'date': 'Fri, 31 Oct 2014 03:56:55 GMT', 'content-length': '168', 'content-type': 'application/xml', 'server': 'Apache/2.4.10 (Fedora) mod_auth_kerb/5.4 m
od_nss/2.4.10 NSS/3.17.1 Basic ECC mod_wsgi/3.5 Python/2.7.8'}
2014-10-31T03:57:16Z DEBUG request body '<?xml version="1.0" encoding="UTF-8" standalone="no"?><XMLResponse><State>1</State><Type>CA</Type><Status>running</Status><Version>10.2.0-3.fc21</Version></X
MLResponse>'
2014-10-31T03:57:16Z DEBUG The CA status is: running
2014-10-31T03:57:16Z INFO The ipa-upgradeconfig command was successful

IMO it is SSL related problem, the same code causes segfault in #4649


Martin is investigating.

Traceback:

Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/ipaplatform/redhat/services.py", line 188, in wait_until_running
    status = dogtag.ca_status(use_proxy=use_proxy)
  File "/usr/lib/python2.7/site-packages/ipapython/dogtag.py", line 210, in ca_status
    ca_host, ca_port, '/ca/admin/ca/getStatus')
  File "/usr/lib/python2.7/site-packages/ipapython/dogtag.py", line 275, in unauthenticated_https_request
    'https', host, port, url, httplib.HTTPSConnection, body)
  File "/usr/lib/python2.7/site-packages/ipapython/dogtag.py", line 306, in _httplib_request
    raise NetworkError(uri=uri, error=str(e))
NetworkError: cannot connect to 'https://ipa.example.com:443/ca/admin/ca/getStatus': _ssl.c:316: Invalid SSL protocol variant specified.

Capture how it should look like (wget used to get status)
tcpdump-test.cap

File tcpdump-error.cap shows, there was no successful connection, no SSL data.

Python raises Invalid SSL protocol variant specified, but there was no SSL.

gdb shows, the protocol version is SSL23

#0  newPySSLObject (ciphers=0x7f38ca0d6eb4 "DEFAULT:!aNULL:!eNULL:!LOW:!EXPORT:!SSLv2", cacerts_file=<optimized out>, proto_version=PY_SSL_VERSION_SSL23, certreq=<optimized out>, socket_type=<optimized out>, cert_file=0x0,
    key_file=0x0, Sock=0x7f38c4c32a50) at /usr/src/debug/Python-2.7.8/Modules/_ssl.c:319
#1  PySSL_sslwrap (self=<optimized out>, args=<optimized out>) at /usr/src/debug/Python-2.7.8/Modules/_ssl.c:453
#2  0x00007f38d88eea4e in call_function (oparg=<optimized out>, pp_stack=0x7fffc06261d0) at /usr/src/debug/Python-2.7.8/Python/ceval.c:4110

...

This is a blocker for Fedora 21.

Root of the error is on line 1819 in file ssl_lib.c
SSL library is unable to load digest function. This is most probably caused by missing call of OpenSSL_add_all_digests(3) function as calling it from GDB fixes this issue.

Full stack: http://fpaste.org/152073/14163897/

workaround to unblock installation

master:

  • 43285b1 Show warning instead of error if CA did not start

ipa-4-1:

  • 3f3f49e Show warning instead of error if CA did not start

master:

  • 337faf5 Using wget to get status of CA

ipa-4-1:

  • 5052af7 Using wget to get status of CA

master:

  • 95becc1 Fix don't check certificate during getting CA status

ipa-4-1:

  • 8440c2e Fix don't check certificate during getting CA status

JFTR workaround has been removed in IPA 4.4:

master:

  • fd7ea2c Remove workaround for CA running check

Metadata Update from @mbasti:
- Issue assigned to mbasti
- Issue set to the milestone: FreeIPA 4.1.3

7 years ago

Login to comment on this ticket.

Metadata