Description of problem: Running ipa-server-install in a container fails to start CA. Version-Release number of selected component (if applicable): freeipa-server-4.3.2-2.fc24.x86_64 How reproducible: Deterministic. Steps to Reproduce: 1. Have freeipa/Dockerfile file: FROM fedora:24 MAINTAINER Jan Pazdziora RUN dnf install -y freeipa-server freeipa-server-dns freeipa-server-trust-ad && dnf clean all ENV container docker ENTRYPOINT [ "/usr/sbin/init" ] 2. Run systemd container: docker run -h ipa.example.test --rm -ti --name freeipa-master freeipa 3. From another terminal, start shell in that container: docker exec -ti freeipa-master bash 4. Run ipa-server-install in the container: [root@ipa /]# ipa-server-install -r EXAMPLE.TEST -p Secret123 -a Secret123 -U Actual results: [26/28]: importing IPA certificate profiles [27/28]: adding default CA ACL [28/28]: updating IPA configuration Done configuring certificate server (pki-tomcatd). Configuring directory server (dirsrv). Estimated time: 10 seconds [1/3]: configuring ssl for ds instance [2/3]: restarting directory server [3/3]: adding CA certificate entry Done configuring directory server (dirsrv). ipa.ipapython.install.cli.install_tool(Server): ERROR CA did not start in 300.0s ipa.ipapython.install.cli.install_tool(Server): ERROR The ipa-server-install command failed. See /var/log/ipaserver-install.log for more information The ipaserver-install.log ends with 2016-11-09T12:45:05Z DEBUG The CA status is: check interrupted due to error: mismatched tag: line 14, column 165 2016-11-09T12:45:05Z DEBUG Waiting for CA to start... 2016-11-09T12:45:06Z DEBUG Starting external process 2016-11-09T12:45:06Z DEBUG args=/usr/bin/curl -o - --connect-timeout 30 -k https://ipa.example.test:8443/ca/admin/ca/getStatus 2016-11-09T12:45:06Z DEBUG Process finished, return code=0 2016-11-09T12:45:06Z DEBUG stdout=<!DOCTYPE html><html><head><title>Apache Tomcat/8.0.36 - Error report</title><style type="text/css">H1 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:22px;} H2 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:16px;} H3 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:14px;} BODY {font-family:Tahoma,Arial,sans-serif;color:black;background-color:white;} B {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;} P {font-family:Tahoma,Arial,sans-serif;background:white;color:black;font-size:12px;}A {color : black;}A.name {color : black;}.line {height: 1px; background-color: #525D76; border: none;}</style> </head><body><h1>HTTP Status 500 - Subsystem unavailable</h1><div class="line"></div><p><b>type</b> Exception report</p><p><b>message</b> <u>Subsystem unavailable</u></p><p><b>description</b> <u>The server encountered an internal error that prevented it from fulfilling this request.</u></p><p><b>exception</b></p><pre>javax.ws.rs.ServiceUnavailableException: Subsystem unavailable com.netscape.cms.tomcat.ProxyRealm.findSecurityConstraints(ProxyRealm.java:138) org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:496) org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79) org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:616) org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:528) org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1099) org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:670) org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:283) java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) java.lang.Thread.run(Thread.java:745) </pre><p><b>note</b> <u>The full stack trace of the root cause is available in the Apache Tomcat/8.0.36 logs.</u></p><hr class="line"><h3>Apache Tomcat/8.0.36</h3></body></html> 2016-11-09T12:45:06Z DEBUG stderr= % Total % Received % Xferd Average Speed Time Time Time Current Dload Upload Total Spent Left Speed 100 2265 100 2265 0 0 36416 0 --:--:-- --:--:-- --:--:-- 36532 2016-11-09T12:45:06Z DEBUG The CA status is: check interrupted due to error: mismatched tag: line 14, column 165 2016-11-09T12:45:06Z DEBUG Waiting for CA to start... 2016-11-09T12:45:08Z DEBUG File "/usr/lib/python2.7/site-packages/ipapython/admintool.py", line 171, in execute return_value = self.run() File "/usr/lib/python2.7/site-packages/ipapython/install/cli.py", line 318, in run cfgr.run() File "/usr/lib/python2.7/site-packages/ipapython/install/core.py", line 310, in run self.execute() File "/usr/lib/python2.7/site-packages/ipapython/install/core.py", line 332, in execute for nothing in self._executor(): File "/usr/lib/python2.7/site-packages/ipapython/install/core.py", line 372, in __runner self._handle_exception(exc_info) File "/usr/lib/python2.7/site-packages/ipapython/install/core.py", line 394, in _handle_exception six.reraise(*exc_info) File "/usr/lib/python2.7/site-packages/ipapython/install/core.py", line 362, in __runner step() File "/usr/lib/python2.7/site-packages/ipapython/install/core.py", line 359, in <lambda> step = lambda: next(self.__gen) File "/usr/lib/python2.7/site-packages/ipapython/install/util.py", line 81, in run_generator_with_yield_from six.reraise(*exc_info) File "/usr/lib/python2.7/site-packages/ipapython/install/util.py", line 59, in run_generator_with_yield_from value = gen.send(prev_value) File "/usr/lib/python2.7/site-packages/ipapython/install/core.py", line 586, in _configure next(executor) File "/usr/lib/python2.7/site-packages/ipapython/install/core.py", line 372, in __runner self._handle_exception(exc_info) File "/usr/lib/python2.7/site-packages/ipapython/install/core.py", line 449, in _handle_exception self.__parent._handle_exception(exc_info) File "/usr/lib/python2.7/site-packages/ipapython/install/core.py", line 394, in _handle_exception six.reraise(*exc_info) File "/usr/lib/python2.7/site-packages/ipapython/install/core.py", line 446, in _handle_exception super(ComponentBase, self)._handle_exception(exc_info) File "/usr/lib/python2.7/site-packages/ipapython/install/core.py", line 394, in _handle_exception six.reraise(*exc_info) File "/usr/lib/python2.7/site-packages/ipapython/install/core.py", line 362, in __runner step() File "/usr/lib/python2.7/site-packages/ipapython/install/core.py", line 359, in <lambda> step = lambda: next(self.__gen) File "/usr/lib/python2.7/site-packages/ipapython/install/util.py", line 81, in run_generator_with_yield_from six.reraise(*exc_info) File "/usr/lib/python2.7/site-packages/ipapython/install/util.py", line 59, in run_generator_with_yield_from value = gen.send(prev_value) File "/usr/lib/python2.7/site-packages/ipapython/install/common.py", line 63, in _install for nothing in self._installer(self.parent): File "/usr/lib/python2.7/site-packages/ipaserver/install/server/install.py", line 1519, in main install(self) File "/usr/lib/python2.7/site-packages/ipaserver/install/server/install.py", line 268, in decorated func(installer) File "/usr/lib/python2.7/site-packages/ipaserver/install/server/install.py", line 925, in install ca.install_step_1(False, None, options) File "/usr/lib/python2.7/site-packages/ipaserver/install/ca.py", line 196, in install_step_1 ca.enable_client_auth_to_db(paths.CA_CS_CFG_PATH) File "/usr/lib/python2.7/site-packages/ipaserver/install/dogtaginstance.py", line 252, in enable_client_auth_to_db 'internaldb', None) File "/usr/lib64/python2.7/contextlib.py", line 24, in __exit__ self.gen.next() File "/usr/lib/python2.7/site-packages/ipaserver/install/installutils.py", line 981, in stopped_service service_obj.start(instance_name) File "/usr/lib/python2.7/site-packages/ipaplatform/redhat/services.py", line 241, in start self.wait_until_running() File "/usr/lib/python2.7/site-packages/ipaplatform/redhat/services.py", line 235, in wait_until_running raise RuntimeError('CA did not start in %ss' % timeout) 2016-11-09T12:45:08Z DEBUG The ipa-server-install command failed, exception: RuntimeError: CA did not start in 300.0s 2016-11-09T12:45:08Z ERROR CA did not start in 300.0s 2016-11-09T12:45:08Z ERROR The ipa-server-install command failed. See /var/log/ipaserver-install.log for more information The /var/log/pki/pki-tomcat/catalina.2016-11-09.log ends with 09-Nov-2016 12:40:15.275 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDescriptor Deploying configuration descriptor /etc/pki/pki-tomcat/Catalina/localhost/ca.xml 09-Nov-2016 12:40:18.187 INFO [localhost-startStop-1] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time. 09-Nov-2016 12:40:19.308 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDescriptor Deployment of configuration descriptor /etc/pki/pki-tomcat/Catalina/localhost/ca.xml has finished in 4,033 ms 09-Nov-2016 12:40:19.323 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"] 09-Nov-2016 12:40:19.331 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-bio-8443"] 09-Nov-2016 12:40:19.338 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["ajp-nio-127.0.0.1-8009"] 09-Nov-2016 12:40:19.340 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 11999 ms 09-Nov-2016 12:40:29.361 WARNING [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.core.ContainerBase.backgroundProcess Exception processing realm com.netscape.cms.tomcat.ProxyRealm@3efeddd9 background process javax.ws.rs.ServiceUnavailableException: Subsystem unavailable at com.netscape.cms.tomcat.ProxyRealm.backgroundProcess(ProxyRealm.java:130) at org.apache.catalina.core.ContainerBase.backgroundProcess(ContainerBase.java:1126) at org.apache.catalina.core.StandardContext.backgroundProcess(StandardContext.java:5686) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1376) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1380) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1380) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1348) at java.lang.Thread.run(Thread.java:745) 09-Nov-2016 12:40:39.382 WARNING [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.core.ContainerBase.backgroundProcess Exception processing realm com.netscape.cms.tomcat.ProxyRealm@3efeddd9 background process javax.ws.rs.ServiceUnavailableException: Subsystem unavailable at com.netscape.cms.tomcat.ProxyRealm.backgroundProcess(ProxyRealm.java:130) at org.apache.catalina.core.ContainerBase.backgroundProcess(ContainerBase.java:1126) at org.apache.catalina.core.StandardContext.backgroundProcess(StandardContext.java:5686) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1376) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1380) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1380) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1348) at java.lang.Thread.run(Thread.java:745) [...] 09-Nov-2016 12:48:49.615 WARNING [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.core.ContainerBase.backgroundProcess Exception processing realm com.netscape.cms.tomcat.ProxyRealm@3efeddd9 background process javax.ws.rs.ServiceUnavailableException: Subsystem unavailable at com.netscape.cms.tomcat.ProxyRealm.backgroundProcess(ProxyRealm.java:130) at org.apache.catalina.core.ContainerBase.backgroundProcess(ContainerBase.java:1126) at org.apache.catalina.core.StandardContext.backgroundProcess(StandardContext.java:5686) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1376) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1380) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1380) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1348) at java.lang.Thread.run(Thread.java:745) 09-Nov-2016 12:48:59.619 WARNING [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.core.ContainerBase.backgroundProcess Exception processing realm com.netscape.cms.tomcat.ProxyRealm@3efeddd9 background process javax.ws.rs.ServiceUnavailableException: Subsystem unavailable at com.netscape.cms.tomcat.ProxyRealm.backgroundProcess(ProxyRealm.java:130) at org.apache.catalina.core.ContainerBase.backgroundProcess(ContainerBase.java:1126) at org.apache.catalina.core.StandardContext.backgroundProcess(StandardContext.java:5686) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1376) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1380) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1380) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1348) at java.lang.Thread.run(Thread.java:745) Expected results: No error, IPA server configured. Additional info:
Actually, I see the same bug with freeipa-server-4.4.2-1.fc24.x86_64 from https://copr.fedorainfracloud.org/coprs/g/freeipa/freeipa-4-4/ as well. To reproduce that, put RUN cd /etc/yum.repos.d && curl -LksO https://copr.fedorainfracloud.org/coprs/g/freeipa/freeipa-4-4/repo/fedora-24/group_freeipa-freeipa-4-4-fedora-24.repo line to the Dockerfile before that RUN dnf install line.
(In reply to Jan Pazdziora from comment #1) > Actually, I see the same bug with freeipa-server-4.4.2-1.fc24.x86_64 from > https://copr.fedorainfracloud.org/coprs/g/freeipa/freeipa-4-4/ as well. To > reproduce that, put > > RUN cd /etc/yum.repos.d && curl -LksO > https://copr.fedorainfracloud.org/coprs/g/freeipa/freeipa-4-4/repo/fedora-24/ > group_freeipa-freeipa-4-4-fedora-24.repo > > line to the Dockerfile before that RUN dnf install line. Actually, with 4.4, the error message is shown in different place of the ipa-server-install output: [28/31]: importing IPA certificate profiles [29/31]: adding default CA ACL [30/31]: adding 'ipa' CA entry [31/31]: updating IPA configuration Done configuring certificate server (pki-tomcatd). Configuring directory server (dirsrv). Estimated time: 10 seconds [1/3]: configuring ssl for ds instance [2/3]: restarting directory server [3/3]: adding CA certificate entry Done configuring directory server (dirsrv). Configuring Kerberos KDC (krb5kdc). Estimated time: 30 seconds [1/9]: adding kerberos container to the directory [2/9]: configuring KDC [3/9]: initialize kerberos container WARNING: Your system is running out of entropy, you may experience long delays [4/9]: adding default ACIs [5/9]: creating a keytab for the directory [6/9]: creating a keytab for the machine [7/9]: adding the password extension to the directory [8/9]: starting the KDC [9/9]: configuring KDC to start on boot Done configuring Kerberos KDC (krb5kdc). Configuring kadmin [1/2]: starting kadmin [2/2]: configuring kadmin to start on boot Done configuring kadmin. ipa.ipapython.install.cli.install_tool(Server): ERROR CA did not start in 300.0s ipa.ipapython.install.cli.install_tool(Server): ERROR The ipa-server-install command failed. See /var/log/ipaserver-install.log for more information
On host, outside container, ipa-server-install on Fedora 24 passes.
I see this same error on a f24 host with master. I don't see it on a f25 host. I think it is a dogtag issue on f24, but it is not 100% reproducible, must depend on something else on the platform that is not always there.
Forcing installation of Fedora 24 GA pki-server-10.3.1-1.fc24.noarch in the container does not fix the problem.
Works for me with pki-ca-10.3.5-8.fc24.noarch which is in updates testing
And also it works with pki-ca-10.3.5-7.fc24.noarch for me Hello, dogtag team, could you please help us to investigate what can be possible issue why dogtag subsystem is not available?
I've seen it fail, with pki-ca upgraded to pki-ca-10.3.5-8.fc24.noarch.
I just hit this bug on VM as with pki-ca-10.3.5-8.fc24.noarch, so it is not related to containers for sure.
I found out that upgrading of NSS resolves this issue. Before: nss-softokn-3.25.0-1.0.fc24.x86_64 nss-softokn-devel-3.25.0-1.0.fc24.x86_64 nss-softokn-freebl-devel-3.25.0-1.0.fc24.x86_64 nss-util-devel-3.25.0-1.0.fc24.x86_64 nss-util-3.25.0-1.0.fc24.x86_64 nss-sysinit-3.25.0-1.2.fc24.x86_64 nss-devel-3.25.0-1.2.fc24.x86_64 nss-softokn-freebl-3.25.0-1.0.fc24.x86_64 nss-3.25.0-1.2.fc24.x86_64 nss-tools-3.25.0-1.2.fc24.x86_64 After: nss-softokn-3.27.0-1.0.fc24.x86_64 nss-devel-3.27.0-1.2.fc24.x86_64 nss-util-devel-3.27.0-1.0.fc24.x86_64 nss-3.27.0-1.2.fc24.x86_64 nss-tools-3.27.0-1.2.fc24.x86_64 nss-softokn-freebl-3.27.0-1.0.fc24.x86_64 nss-softokn-freebl-devel-3.27.0-1.0.fc24.x86_64 nss-util-3.27.0-1.0.fc24.x86_64 nss-softokn-devel-3.27.0-1.0.fc24.x86_64 nss-sysinit-3.27.0-1.2.fc24.x86_64 After NSS upgrade I was able to install master without issues, nss-3.27 is in fedora updates repo.
Should IPA or PKI raise NSS dependencies?
Preferably PKI, at least as fedora downstream patch
(In reply to Martin Bašti from comment #11) > I found out that upgrading of NSS resolves this issue. Amazing. I confirm that prepending RUN dnf upgrade -y nss to my Dockerfile fixes the issue in container as well, upgrading from 3.23.0-1.2.fc24 to 3.27.0-1.0.fc24. Do we know what in the pki* land is upset about the older versions? Things used to work in the past ... If it's just a matter of newer pki* packages built against newer sources causing it ABI-incompatilibity, we likely need some better checks in place for these situations.
Any updates from dogtag team?
Hi, Could you attach the debug and selftest log files from /var/log/pki/pki-tomcat/ca folder? If NSS returns any error message, it should be in those log files.
In comment 0, step 1.5: docker build -t freeipa freeipa is missing.
Created attachment 1223224 [details] Providing requested log files
Thanks for the logs. According to the debug log PKI server failed to access the DS during startup: Could not connect to LDAP server host ipa.example.test port 636 Error netscape.ldap.LDAPException: Authentication failed (48) It looks like the error happens at the same location shown in this unresolved ticket: https://fedorahosted.org/pki/ticket/2226 It's still unclear why the problem is happening, but if it's fixed by upgrading NSS and without changing PKI, it's likely that it's not a PKI issue. So we can update PKI to require NSS 3.27, which hopefully fixes the problem, but if you need someone to further investigate the exact cause of this problem please reassign the ticket to NSS.
Created attachment 1227059 [details] pki-edewata-0879-Updated-NSS-dependency-on-Fedora.patch
Comment on attachment 1227059 [details] pki-edewata-0879-Updated-NSS-dependency-on-Fedora.patch ACK -- after was informed that this patch was for DOGTAG_10_3_BRANCH.
Thanks for the review! Fixed in master: * f7b69b0804ddb1c80250616fff601e3573602eae Fixed in 10.3 branch: * 12921f2270d66beb6f2cbaf5ed12127ae2ac65bd
Was the fix released in updates? What was the errata in bodhi?
If the fix is already out via https://bodhi.fedoraproject.org/updates/FEDORA-2016-346c2e1366, the status of this bugzilla should likely no longer be MODIFIED. The problem is, the bodhi update did not have this bugzilla listed, so it did not autoclose it.
This message is a reminder that Fedora 24 is nearing its end of life. Approximately 2 (two) weeks from now Fedora will stop maintaining and issuing updates for Fedora 24. It is Fedora's policy to close all bug reports from releases that are no longer maintained. At that time this bug will be closed as EOL if it remains open with a Fedora 'version' of '24'. Package Maintainer: If you wish for this bug to remain open because you plan to fix it in a currently maintained version, simply change the 'version' to a later Fedora version. Thank you for reporting this issue and we are sorry that we were not able to fix it before Fedora 24 is end of life. If you would still like to see this bug fixed and are able to reproduce it against a later version of Fedora, you are encouraged change the 'version' to a later Fedora version prior this bug is closed as described in the policy above. Although we aim to fix as many bugs as possible during every release's lifetime, sometimes those efforts are overtaken by events. Often a more recent Fedora release includes newer upstream software that fixes bugs or makes them obsolete.
Per comment 25, could you please update the status of this bugzilla?
Fedora 24 changed to end-of-life (EOL) status on 2017-08-08. Fedora 24 is no longer maintained, which means that it will not receive any further security or bug fix updates. As a result we are closing this bug. If you can reproduce this bug against a currently maintained version of Fedora please feel free to reopen this bug against that version. If you are unable to reopen this bug, please file a new report against the current release. If you experience problems, please add a comment to this bug. Thank you for reporting this bug and we are sorry it could not be fixed.
(In reply to Jan Pazdziora from comment #27) > Per comment 25, could you please update the status of this bugzilla? Per Comment #28 -- Fedora End Of Life appears to have done this before I got to it.