RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 1196455 - ipa-server-install step [8/27]: starting certificate server instance - confusing CA staus message on TLS error
Summary: ipa-server-install step [8/27]: starting certificate server instance - confus...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: ipa
Version: 7.1
Hardware: Unspecified
OS: Unspecified
medium
unspecified
Target Milestone: rc
: ---
Assignee: IPA Maintainers
QA Contact: Namita Soman
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2015-02-26 01:24 UTC by Marc Sauton
Modified: 2015-11-19 12:01 UTC (History)
5 users (show)

Fixed In Version: ipa-4.2.0-0.1.alpha1.el7
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2015-11-19 12:01:37 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2015:2362 0 normal SHIPPED_LIVE ipa bug fix and enhancement update 2015-11-19 10:40:46 UTC

Description Marc Sauton 2015-02-26 01:24:58 UTC
Description of problem:

having errors while running RHEL 7.1 ipa-server-install after the CA restart
this the error described in
 bz  1158410 - ipa-server-install failing with error message - CA did not start in 300.0s

the error message returned by ipa-server-install in step
2015-02-26T00:11:02Z DEBUG   [8/27]: starting certificate server instance
...
2015-02-26T00:16:07Z DEBUG The ipa-server-install command failed, exception: RuntimeError: CA did not start in 300.0s

is confusing
because the CA is perfectly up and running as per the previous step 3/26 until the begining of step8/27
2015-02-26T00:11:00Z DEBUG completed creating ca instance


and manually reading the CA status works:

openssl s_client -connect ipaserver1.example.com:8443
...
GET /ca/admin/ca/getStatus HTTP/1.0

HTTP/1.1 200 OK
Server: Apache-Coyote/1.1
Content-Type: application/xml
Content-Length: 167
Date: Thu, 26 Feb 2015 00:59:13 GMT
Connection: close

<?xml version="1.0" encoding="UTF-8" standalone="no"?><XMLResponse><State>1</State><Type>CA</Type><Status>running</Status><Version>10.1.2-7.el7</Version></XMLResponse>closed


the CA is up and running, the problem is wait_for_open_ports in /usr/lib/python2.7/site-packages/ipapython/ipautil.py seem to fail using the TLS range and TLSv1.2

so the message 
" ipa-server-install command failed, exception: RuntimeError: CA did not start in 300.0s"

is misleading, it is more like the script cold not connect to the CA, for some reason, and timed out.



less /var/log/ipaserver-install.log
...
2015-02-26T00:11:02Z DEBUG   [8/27]: starting certificate server instance
2015-02-26T00:11:02Z DEBUG Starting external process
2015-02-26T00:11:02Z DEBUG args='/bin/systemctl' 'start' 'pki-tomcatd.target'
2015-02-26T00:11:02Z DEBUG Process finished, return code=0
2015-02-26T00:11:02Z DEBUG stdout=
2015-02-26T00:11:02Z DEBUG stderr=
2015-02-26T00:11:02Z DEBUG Starting external process
2015-02-26T00:11:02Z DEBUG args='/bin/systemctl' 'is-active' 'pki-tomcatd.target'
2015-02-26T00:11:02Z DEBUG Process finished, return code=0
2015-02-26T00:11:02Z DEBUG stdout=active

2015-02-26T00:11:02Z DEBUG stderr=
2015-02-26T00:11:02Z DEBUG wait_for_open_ports: localhost [8080, 8443] timeout 300
2015-02-26T00:11:06Z DEBUG The httpd proxy is not installed, wait on local port
2015-02-26T00:11:06Z DEBUG Waiting until the CA is running
2015-02-26T00:11:06Z DEBUG request 'https://ipaserver1-example-com:8443/ca/admin/ca/getStatus'
2015-02-26T00:11:06Z DEBUG request body ''
2015-02-26T00:11:06Z DEBUG The CA status is: check interrupted
2015-02-26T00:11:06Z DEBUG Waiting for CA to start...

and loop until failing:

2015-02-26T00:16:07Z DEBUG The ipa-server-install command failed, exception: RuntimeError: CA did not start in 300.0s
(END)




Version-Release number of selected component (if applicable):

Red Hat Enterprise Linux Server release 7.1 (Maipo)
Linux ipaserver1.example.com 3.10.0-229.el7.x86_64 #1 SMP Thu Jan 29 18:37:38 EST 2015 x86_64 x86_64 x86_64 GNU/Linux
389-ds-base-1.3.3.1-13.el7.x86_64
ipa-server-4.1.0-18.el7.x86_64
sssd-1.12.2-58.el7.x86_64
krb5-server-1.12.2-14.el7.x86_64
nss-3.16.2.3-5.el7.x86_64
nspr-4.10.6-3.el7.x86_64
pki-ca-10.1.2-7.el7.noarch
bind-dyndb-ldap-6.0-2.el7.x86_64
httpd-2.4.6-31.el7.x86_64
jss-4.2.6-35.el7.x86_64

from
http://download.devel.redhat.com/rel-eng/latest-RHEL-7/compose/Server/x86_64/os/
on 
Wed Feb 25 17:15:10 PST 2015

How reproducible:


Steps to Reproduce:
1.
2.
3.

Actual results:


Expected results:


Additional info:

Comment 1 Marc Sauton 2015-02-26 01:28:31 UTC
have
tomcatjss-7.1.0-5.el7.noarch

Comment 3 Petr Vobornik 2015-03-02 12:25:28 UTC
Hello Marc, 

I see two issues here. 

First, that it may report invalid message. Second, that it actually failed. 

1. could be linked to upstream ticket 4885 [https://fedorahosted.org/freeipa/ticket/4885]

2. The mentioned BZ #1158410 should have fixed that. I'm not able to reproduce the issue with the versions of components you stated. Do you know that the failure was indeed because of "TLS range and TLSv1.2"? Do you have a log with the crash (CA or some other)? Are you able to reproduce the issue?

Comment 4 Marc Sauton 2015-03-04 19:59:52 UTC
So in upstream 4885, one problem may be if there is some sort of network issue, the CA is seen as down, while it may be up and running.

In my case, there is no CA crash, the CA instance is up and running, and OK:
systemctl status pki-tomcatd
pki-tomcatd - PKI Tomcat Server pki-tomcat
   Loaded: loaded (/lib/systemd/system/pki-tomcatd@.service; enabled)
   Active: active (running) since Wed 2015-02-25 16:11:02 PST; 6 days ago
  Process: 1594 ExecStartPre=/usr/bin/pkidaemon start tomcat %i (code=exited, status=0/SUCCESS)
 Main PID: 1739 (java)
   CGroup: /system.slice/system-pki\x2dtomcatd.slice/pki-tomcatd
           └─1739 java -DRESTEASY_LIB=/usr/share/java/resteasy-base -classpath /usr/share/tomcat/bin/bootstrap.jar:/usr/share/tomcat/bin/tomcat-juli.jar:/usr/share/java/commons-daemon.jar -Dcatalina.base=/var/lib/pki/pki-tomcat -Dcatalina.home=/usr/share/tomcat -Djava.endorsed.dirs= -Djava.io.tmpdir=/var/lib/pki/pki-tomcat/temp -Djava.util.logging.config.file=/var/lib/pki/pki-tomcat/conf/logging.properties -Djava.ut...

Feb 25 16:11:33 ipaserver1.example.com server[1739]: Feb 25, 2015 4:11:33 PM org.apache.catalina.startup.HostConfig deployDescriptor
Feb 25 16:11:33 ipaserver1.example.com server[1739]: INFO: Deployment of configuration descriptor /etc/pki/pki-tomcat/Catalina/localhost/ca.xml has finished in 18,262 ms
Feb 25 16:11:33 ipaserver1.example.com server[1739]: Feb 25, 2015 4:11:33 PM org.apache.coyote.AbstractProtocol start
Feb 25 16:11:33 ipaserver1.example.com server[1739]: INFO: Starting ProtocolHandler ["http-bio-8080"]
Feb 25 16:11:33 ipaserver1.example.com server[1739]: Feb 25, 2015 4:11:33 PM org.apache.coyote.AbstractProtocol start
Feb 25 16:11:33 ipaserver1.example.com server[1739]: INFO: Starting ProtocolHandler ["http-bio-8443"]
Feb 25 16:11:34 ipaserver1.example.com server[1739]: Feb 25, 2015 4:11:34 PM org.apache.coyote.AbstractProtocol start
Feb 25 16:11:34 ipaserver1.example.com server[1739]: INFO: Starting ProtocolHandler ["ajp-bio-127.0.0.1-8009"]
Feb 25 16:11:34 ipaserver1.example.com server[1739]: Feb 25, 2015 4:11:34 PM org.apache.catalina.startup.Catalina start
Feb 25 16:11:34 ipaserver1.example.com server[1739]: INFO: Server startup in 28330 ms
[root@ipaserver1-example-com ~]# 

I can use openssl s_client to use the CA, no apparent problems on it.

It is possible that VM may not have have the newer rpm, and I could not solve this problem for some other testing I needed, so I opened this report.

I till have the VM available, was about to scratch it for another test, so I will wait until you are done with it (and use another one for my other testing)

ssh root.5.175
redhat123

other passwords should be 
pasword

Comment 5 Petr Vobornik 2015-03-05 09:49:29 UTC
the issue is that it tries to connect to
  'https://ipaserver1-example-com:8443/ca/admin/ca/getStatus' (dashes instead of dots)

and not to 
   'https://ipaserver1.example.com:8443/ca/admin/ca/getStatus'


The probable cause is initial hostname of the machine - I assume: ipaserver1-example-com

Indicator:
2015-02-26T00:08:49Z DEBUG stderr=AH00557: httpd: apr_sockaddr_info_get() failed for ipaserver1-example-com
AH00558: httpd: Could not reliably determine the server's fully qualified domain name, using 127.0.0.1. Set the 'ServerName' directive globally to suppress this message

The CA check code wants to contact ca stored in api.env.ca_host, which is initialized upon api initialization. 

constants.py:
   FQDN = socket.getfqdn()

('ca_host', FQDN),  # Set in Env._finalize_core()

ipa-server-install notices that the hostname differs and sets the correct one:

    if host_name != system_hostname:
        root_logger.debug("Chosen hostname (%s) differs from system hostname (%s) - change it" \
                      % (host_name, system_hostname))
        # configure /etc/sysconfig/network to contain the custom hostname
        tasks.backup_and_replace_hostname(fstore, sstore, host_name)

but it doesn't update the information used by the dogtag check which then leads to the failure.

Workaround is to set correct hostname before installation.

Summary:
- There is a bug in ipa-server-install that it internally uses wrong hostname after it sets the new one.
- In this case, the error message is correct.

I'll create upstream bug for the hostname issue.

Comment 6 Petr Vobornik 2015-03-05 15:41:08 UTC
Upstream ticket:
https://fedorahosted.org/freeipa/ticket/4936

Comment 7 Petr Vobornik 2015-05-07 14:04:53 UTC
Fixed upstream
master:
https://fedorahosted.org/freeipa/changeset/825d4fc9e7fc80e07a68daf35b5eb0c171e821af

Comment 9 Abhijeet Kasurde 2015-10-09 09:20:17 UTC
# less /var/log/ipaserver-install.log

2015-10-09T06:25:39Z DEBUG Waiting until the CA is running
2015-10-09T06:25:39Z DEBUG Starting external process
2015-10-09T06:25:39Z DEBUG args='/usr/bin/wget' '-S' '-O' '-' '--timeout=30' '--no-check-certificate' 'https://ipaserver.testrelm.test:8443/ca/admin/ca/getStatus'
2015-10-09T06:25:52Z DEBUG Process finished, return code=0
2015-10-09T06:25:52Z DEBUG stdout=<?xml version="1.0" encoding="UTF-8" standalone="no"?><XMLResponse><State>1</State><Type>CA</Type><Status>running</Status><Version>10.2.5-6.el7</Version></XMLResponse>
2015-10-09T06:25:52Z DEBUG stderr=--2015-10-09 11:55:39--  https://ipaserver.testrelm.test:8443/ca/admin/ca/getStatus
Resolving ipaserver.testrelm.test (ipaserver.testrelm.test)... 10.65.201.22
Connecting to ipaserver.testrelm.test (ipaserver.testrelm.test)|10.65.201.22|:8443... connected.
WARNING: cannot verify ipaserver.testrelm.test's certificate, issued by ‘/O=TESTRELM.TEST/CN=Certificate Authority’:
  Self-signed certificate encountered.
HTTP request sent, awaiting response...
  HTTP/1.1 200 OK
  Server: Apache-Coyote/1.1
  Content-Type: application/xml
  Content-Length: 167
  Date: Fri, 09 Oct 2015 06:25:52 GMT
Length: 167 [application/xml]
Saving to: ‘STDOUT’

     0K                                                       100% 62.7M=0s
2015-10-09 11:55:52 (62.7 MB/s) - written to stdout [167/167]


2015-10-09T06:25:52Z DEBUG The CA status is: running
...


Verified.

IPA server version ::

ipa-server-4.2.0-13.el7.x86_64

Comment 10 errata-xmlrpc 2015-11-19 12:01:37 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHBA-2015-2362.html


Note You need to log in before you can comment on or make changes to this bug.