In FreeIPA nightly tests using copr @pki/master, ipa-server-install sometimes fails in the pkispawn step with the error CA subsystem did not start after 60s.
CA subsystem did not start after 60s
See for instance PR #219, in the test dns_locations with logs:
dns_locations
ipa-server-install logs:
[ipatests.pytest_ipa.integration.host.Host.master.cmd29] Configuring ipa-custodia [ipatests.pytest_ipa.integration.host.Host.master.cmd29] [1/5]: Making sure custodia container exists [ipatests.pytest_ipa.integration.host.Host.master.cmd29] [2/5]: Generating ipa-custodia config file [ipatests.pytest_ipa.integration.host.Host.master.cmd29] [3/5]: Generating ipa-custodia keys [ipatests.pytest_ipa.integration.host.Host.master.cmd29] [4/5]: starting ipa-custodia [ipatests.pytest_ipa.integration.host.Host.master.cmd29] [5/5]: configuring ipa-custodia to start on boot [ipatests.pytest_ipa.integration.host.Host.master.cmd29] Done configuring ipa-custodia. [ipatests.pytest_ipa.integration.host.Host.master.cmd29] Configuring certificate server (pki-tomcatd). Estimated time: 3 minutes [ipatests.pytest_ipa.integration.host.Host.master.cmd29] [1/30]: configuring certificate server instance [ipatests.pytest_ipa.integration.host.Host.master.cmd29] Failed to configure CA instance: CalledProcessError(Command ['/usr/sbin/pkispawn', '-s', 'CA', '-f', '/tmp/tmp5uqbfugh'] returned non-zero exit status 1: 'Notice: Trust flag u is set automatically if the private key is present.\nERROR: Exception: CA subsystem did not start after 60s\n File "/usr/lib/python3.8/site-packages/pki/server/pkispawn.py", line 569, in main\n scriptlet.spawn(deployer)\n File "/usr/lib/python3.8/site-packages/pki/server/deployment/scriptlets/configuration.py", line 886, in spawn\n deployer.instance.wait_for_startup(\n File "/usr/lib/python3.8/site-packages/pki/server/deployment/pkihelper.py", line 919, in wait_for_startup\n raise Exception(\'%s subsystem did not start after %ds\' %\n\n') [ipatests.pytest_ipa.integration.host.Host.master.cmd29] See the installation logs and the following files/directories for more information: [ipatests.pytest_ipa.integration.host.Host.master.cmd29] /var/log/pki/pki-tomcat [ipatests.pytest_ipa.integration.host.Host.master.cmd29] [error] RuntimeError: CA configuration failed. [ipatests.pytest_ipa.integration.host.Host.master.cmd29] CA configuration failed. [ipatests.pytest_ipa.integration.host.Host.master.cmd29] The ipa-server-install command failed. See /var/log/ipaserver-install.log for more information [ipatests.pytest_ipa.integration.host.Host.master.cmd29] Exit code: 1
In the journal:
Jun 01 06:31:07 master.ipa.test server[28737]: Java virtual machine used: /usr/lib/jvm/jre-1.8.0-openjdk/bin/java Jun 01 06:31:07 master.ipa.test server[28737]: classpath used: /usr/share/tomcat/bin/bootstrap.jar:/usr/share/tomcat/bin/tomcat-juli.jar:/usr/lib/java/commons-daemon.jar Jun 01 06:31:07 master.ipa.test server[28737]: main class used: org.apache.catalina.startup.Bootstrap Jun 01 06:31:07 master.ipa.test server[28737]: flags used: Jun 01 06:31:07 master.ipa.test server[28737]: options used: -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.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Djava.security.manager -Djava.security.policy==/var/lib/pki/pki-tomcat/conf/catalina.policy Jun 01 06:31:07 master.ipa.test server[28737]: arguments used: start Jun 01 06:31:11 master.ipa.test java[28737]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock Jun 01 06:31:12 master.ipa.test server[28737]: SEVERE: Failed to initialize component [Connector[org.dogtagpki.tomcat.Http11NioProtocol-8443]] Jun 01 06:31:12 master.ipa.test server[28737]: java.lang.NoSuchFieldError: ENABLE_JSSENGINE Jun 01 06:31:12 master.ipa.test server[28737]: at org.dogtagpki.tomcat.JSSContext.init(JSSContext.java:48) Jun 01 06:31:12 master.ipa.test server[28737]: at org.dogtagpki.tomcat.JSSUtil.init(JSSUtil.java:71) Jun 01 06:31:12 master.ipa.test server[28737]: at org.dogtagpki.tomcat.JSSUtil.getImplementedProtocols(JSSUtil.java:122) Jun 01 06:31:12 master.ipa.test server[28737]: at org.apache.tomcat.util.net.SSLUtilBase.<init>(SSLUtilBase.java:93) Jun 01 06:31:12 master.ipa.test server[28737]: at org.apache.tomcat.util.net.SSLUtilBase.<init>(SSLUtilBase.java:83) Jun 01 06:31:12 master.ipa.test server[28737]: at org.dogtagpki.tomcat.JSSUtil.<init>(JSSUtil.java:58) Jun 01 06:31:12 master.ipa.test server[28737]: at org.dogtagpki.tomcat.JSSImplementation.getSSLUtil(JSSImplementation.java:59) Jun 01 06:31:12 master.ipa.test server[28737]: at org.apache.tomcat.util.net.AbstractJsseEndpoint.createSSLContext(AbstractJsseEndpoint.java:88) Jun 01 06:31:12 master.ipa.test server[28737]: at org.apache.tomcat.util.net.AbstractJsseEndpoint.initialiseSsl(AbstractJsseEndpoint.java:71) Jun 01 06:31:12 master.ipa.test server[28737]: at org.apache.tomcat.util.net.NioEndpoint.bind(NioEndpoint.java:216) Jun 01 06:31:12 master.ipa.test server[28737]: at org.apache.tomcat.util.net.AbstractEndpoint.bindWithCleanup(AbstractEndpoint.java:1141) Jun 01 06:31:12 master.ipa.test server[28737]: at org.apache.tomcat.util.net.AbstractEndpoint.init(AbstractEndpoint.java:1154) Jun 01 06:31:12 master.ipa.test server[28737]: at org.apache.coyote.AbstractProtocol.init(AbstractProtocol.java:581) Jun 01 06:31:12 master.ipa.test server[28737]: at org.apache.coyote.http11.AbstractHttp11Protocol.init(AbstractHttp11Protocol.java:74) Jun 01 06:31:12 master.ipa.test server[28737]: at org.apache.catalina.connector.Connector.initInternal(Connector.java:1038) Jun 01 06:31:12 master.ipa.test server[28737]: at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:136) Jun 01 06:31:12 master.ipa.test server[28737]: at org.apache.catalina.core.StandardService.initInternal(StandardService.java:533) Jun 01 06:31:12 master.ipa.test server[28737]: at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:136) Jun 01 06:31:12 master.ipa.test server[28737]: at org.apache.catalina.core.StandardServer.initInternal(StandardServer.java:1057) Jun 01 06:31:12 master.ipa.test server[28737]: at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:136) Jun 01 06:31:12 master.ipa.test server[28737]: at org.apache.catalina.startup.Catalina.load(Catalina.java:584) Jun 01 06:31:12 master.ipa.test server[28737]: at org.apache.catalina.startup.Catalina.load(Catalina.java:607) Jun 01 06:31:12 master.ipa.test server[28737]: at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) Jun 01 06:31:12 master.ipa.test server[28737]: at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) Jun 01 06:31:12 master.ipa.test server[28737]: at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) Jun 01 06:31:12 master.ipa.test server[28737]: at java.lang.reflect.Method.invoke(Method.java:498) Jun 01 06:31:12 master.ipa.test server[28737]: at org.apache.catalina.startup.Bootstrap.load(Bootstrap.java:303) Jun 01 06:31:12 master.ipa.test server[28737]: at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:473)
Note the message usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock that appears multiple times in the journal and looks similar to what was seen in 3130
usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Hi @frenaud -- I'm actually out of the office until next week.
To me this looks like a mismatch between TomcatJSS and JSS versions. In particular, the field above should always be present if JSS is new enough. See:
https://github.com/dogtagpki/jss/blob/master/org/mozilla/jss/JSSProvider.java#L12
and
https://github.com/dogtagpki/tomcatjss/blob/master/./tomcat-8.5/src/org/dogtagpki/tomcat/JSSContext.java#L48
What versions of both are you running?
Metadata Update from @cipherboy: - Custom field component adjusted to None - Custom field feature adjusted to None - Custom field origin adjusted to None - Custom field proposedmilestone adjusted to None - Custom field proposedpriority adjusted to None - Custom field reviewer adjusted to None - Custom field type adjusted to None - Custom field version adjusted to None
Hi @cipherboy
the versions can be found here: - jss-4.7.0-1.20200428204938.03afe804.fc32.x86_64 - tomcat-9.0.34-2.fc32.noarch - tomcatjss-7.5.0-0.1.20200527024937.ea539175.fc32.noarch
@frenaud Could you try removing jss-4.7.0-1.xxx and and reinstalling the latest JSS from @pki/master repo which is 4.7.0-0.1.xxx?
@cipherboy Sorry, I had to revert the release number from -1 to -0.1 since JSS 4.7 is still beta.
@frenaud -- I'm back. Any update on this? This JSS version is wrong and the correct version needs to be pulled in by PR-CI. In other words, this isn't a Dogtag issue and this should be closed.
@cipherboy unfortunately we had an infra issue over the week-end and the tests were not launched. I manually launched a single test in https://github.com/freeipa/freeipa/pull/4790 and will let you know the outcome as soon as the result is available.
@frenaud Can this be closed? I see you closed the associated PR and opened a new one that also passed AFAICT.
@cipherboy, yes, we can close this issue. Nightly tests are still running here but most of them are already successful.
Metadata Update from @frenaud: - Issue close_status updated to: fixed - Issue status updated to: Closed (was: Open)
Dogtag PKI is moving from Pagure issues to GitHub issues. This means that existing or new issues will be reported and tracked through Dogtag PKI's GitHub Issue tracker.
This issue has been cloned to GitHub and is available here: https://github.com/dogtagpki/pki/issues/3294
If you want to receive further updates on the issue, please navigate to the GitHub issue and click on Subscribe button.
Subscribe
Thank you for understanding, and we apologize for any inconvenience.
Log in to comment on this ticket.