[2016-07-18T21:46:02Z ipa.ipatests.test_integration.host.Host.vm-058-228.ParamikoTransport] <INFO>: RUN ['ipa', 'domainlevel-get'] [2016-07-18T21:46:02Z ipa.ipatests.test_integration.host.Host.vm-058-228.cmd35] <DEBUG>: RUN ['ipa', 'domainlevel-get'] [2016-07-18T21:46:06Z ipa.ipatests.test_integration.host.Host.vm-058-228.cmd35] <DEBUG>: ----------------------- [2016-07-18T21:46:06Z ipa.ipatests.test_integration.host.Host.vm-058-228.cmd35] <DEBUG>: Current domain level: 1 [2016-07-18T21:46:06Z ipa.ipatests.test_integration.host.Host.vm-058-228.cmd35] <DEBUG>: ----------------------- [2016-07-18T21:46:06Z ipa.ipatests.test_integration.host.Host.vm-058-228.cmd35] <DEBUG>: Exit code: 0 [2016-07-18T21:46:06Z ipa.ipatests.test_integration.host.Host.vm-058-228.ParamikoTransport] <INFO>: RUN ['ipa-kra-install', '-U', '-p', 'Secret123'] [2016-07-18T21:46:06Z ipa.ipatests.test_integration.host.Host.vm-058-228.cmd36] <DEBUG>: RUN ['ipa-kra-install', '-U', '-p', 'Secret123'] [2016-07-18T21:46:13Z ipa.ipatests.test_integration.host.Host.vm-058-228.cmd36] <DEBUG>: [2016-07-18T21:46:13Z ipa.ipatests.test_integration.host.Host.vm-058-228.cmd36] <DEBUG>: =================================================================== [2016-07-18T21:46:13Z ipa.ipatests.test_integration.host.Host.vm-058-228.cmd36] <DEBUG>: This program will setup Dogtag KRA for the FreeIPA Server. [2016-07-18T21:46:13Z ipa.ipatests.test_integration.host.Host.vm-058-228.cmd36] <DEBUG>: [2016-07-18T21:46:13Z ipa.ipatests.test_integration.host.Host.vm-058-228.cmd36] <DEBUG>: [2016-07-18T21:46:13Z ipa.ipatests.test_integration.host.Host.vm-058-228.cmd36] <DEBUG>: Configuring KRA server (pki-tomcatd). Estimated time: 2 minutes 6 seconds [2016-07-18T21:46:13Z ipa.ipatests.test_integration.host.Host.vm-058-228.cmd36] <DEBUG>: [1/8]: creating installation admin user [2016-07-18T21:46:16Z ipa.ipatests.test_integration.host.Host.vm-058-228.cmd36] <DEBUG>: [2/8]: configuring KRA instance [2016-07-18T21:48:28Z ipa.ipatests.test_integration.host.Host.vm-058-228.cmd36] <DEBUG>: Failed to configure KRA instance: Command '/usr/sbin/pkispawn -s KRA -f /tmp/tmpiqVY1i' returned non-zero exit status 1 [2016-07-18T21:48:28Z ipa.ipatests.test_integration.host.Host.vm-058-228.cmd36] <DEBUG>: See the installation logs and the following files/directories for more information: [2016-07-18T21:48:28Z ipa.ipatests.test_integration.host.Host.vm-058-228.cmd36] <DEBUG>: /var/log/pki/pki-tomcat [2016-07-18T21:48:28Z ipa.ipatests.test_integration.host.Host.vm-058-228.cmd36] <DEBUG>: [error] RuntimeError: KRA configuration failed. [2016-07-18T21:48:28Z ipa.ipatests.test_integration.host.Host.vm-058-228.cmd36] <DEBUG>: [2016-07-18T21:48:28Z ipa.ipatests.test_integration.host.Host.vm-058-228.cmd36] <DEBUG>: Your system may be partly configured. [2016-07-18T21:48:28Z ipa.ipatests.test_integration.host.Host.vm-058-228.cmd36] <DEBUG>: Run ipa-kra-install --uninstall to clean up. [2016-07-18T21:48:28Z ipa.ipatests.test_integration.host.Host.vm-058-228.cmd36] <DEBUG>: [2016-07-18T21:48:28Z ipa.ipatests.test_integration.host.Host.vm-058-228.cmd36] <DEBUG>: KRA configuration failed. [2016-07-18T21:48:28Z ipa.ipatests.test_integration.host.Host.vm-058-228.cmd36] <DEBUG>: The ipa-kra-install command failed. See /var/log/ipaserver-kra-install.log for more information ipa: ERROR: Exit code: 1 [2016-07-18T21:48:28Z ipa.ipatests.test_integration.host.Host.vm-058-228.cmd36] <ERROR>: Exit code: 1
Version: pki-kra 10.3.3-3 (works with 10.3.4 provided by Fraser in our copr repo)
Additional details:
More details:
2016-07-27T06:00:29Z DEBUG Starting external process 2016-07-27T06:00:29Z DEBUG args=/usr/sbin/pkispawn -s KRA -f /tmp/tmpZrYbNE 2016-07-27T06:00:54Z DEBUG Process finished, return code=1 2016-07-27T06:00:54Z DEBUG stdout=Log file: /var/log/pki/pki-kra-spawn.20160727080029.log Loading deployment configuration from /tmp/tmpZrYbNE. Installing KRA into /var/lib/pki/pki-tomcat. Storing deployment configuration into /etc/sysconfig/pki/tomcat/pki-tomcat/kra/deployment.cfg. WARNING: cert caSigningCert cert-pki-ca already exists Installation failed: mismatched tag: line 76, column 165 2016-07-27T06:00:54Z DEBUG stderr=pkispawn : ERROR ....... Exception from Java Configuration Servlet: 500 Server Error: Internal Server Error for url: https://vm-204.abc.idm.lab.eng.brq.redhat.com:8443/kra/rest/installer/configure pkispawn : ERROR ....... ParseError: mismatched tag: line 76, column 165: <!DOCTYPE html><html><head><title>Apache Tomcat/8.0.32 - 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 - java.io.IOException: Error: Failed to update number range.</h1><div class="line"></div><p><b>type</b> Exception report</p><p><b>message</b> <u>java.io.IOException: Error: Failed to update number range.</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>org.jboss.resteasy.spi.UnhandledException: java.io.IOException: Error: Failed to update number range. org.jboss.resteasy.core.ExceptionHandler.handleApplicationException(ExceptionHandler.java:76) org.jboss.resteasy.core.ExceptionHandler.handleException(ExceptionHandler.java:212) org.jboss.resteasy.core.SynchronousDispatcher.writeException(SynchronousDispatcher.java:149) org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:372) org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:179) org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:220) org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56) org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51) javax.servlet.http.HttpServlet.service(HttpServlet.java:729) sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) java.lang.reflect.Method.invoke(Method.java:498) org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:286) org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:283) java.security.AccessController.doPrivileged(Native Method) javax.security.auth.Subject.doAsPrivileged(Subject.java:549) org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:318) org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:173) java.security.AccessController.doPrivileged(Native Method) org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) java.lang.reflect.Method.invoke(Method.java:498) org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:286) org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:283) java.security.AccessController.doPrivileged(Native Method) javax.security.auth.Subject.doAsPrivileged(Subject.java:549) org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:318) org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:258) </pre><p><b>root cause</b></p><pre>java.io.IOException: Error: Failed to update number range. com.netscape.cms.servlet.csadmin.ConfigurationUtils.updateNumberRange(ConfigurationUtils.java:683) com.netscape.cms.servlet.csadmin.ConfigurationUtils.getConfigEntriesFromMaster(ConfigurationUtils.java:548) org.dogtagpki.server.rest.SystemConfigService.configureClone(SystemConfigService.java:881) org.dogtagpki.server.rest.SystemConfigService.configureSubsystem(SystemConfigService.java:1018) org.dogtagpki.server.rest.SystemConfigService.configure(SystemConfigService.java:164) org.dogtagpki.server.rest.SystemConfigService.configure(SystemConfigService.java:121) sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) java.lang.reflect.Method.invoke(Method.java:498) org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:137) org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:280) org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:234) org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:221) org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:356) org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:179) org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:220) org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56) org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51) javax.servlet.http.HttpServlet.service(HttpServlet.java:729) sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) java.lang.reflect.Method.invoke(Method.java:498) org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:286) org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:283) java.security.AccessController.doPrivileged(Native Method) javax.security.auth.Subject.doAsPrivileged(Subject.java:549) org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:318) org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:173) java.security.AccessController.doPrivileged(Native Method) org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) java.lang.reflect.Method.invoke(Method.java:498) org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:286) org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:283) java.security.AccessController.doPrivileged(Native Method) javax.security.auth.Subject.doAsPrivileged(Subject.java:549) org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:318) org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:258) </pre><p><b>note</b> <u>The full stack trace of the root cause is available in the Apache Tomcat/8.0.32 logs.</u></p><hr class="line"><h3>Apache Tomcat/8.0.32</h3></body></html> 2016-07-27T06:00:54Z CRITICAL Failed to configure KRA instance: Command '/usr/sbin/pkispawn -s KRA -f /tmp/tmpZrYbNE' returned non-zero exit status 1 2016-07-27T06:00:54Z CRITICAL See the installation logs and the following files/directories for more information: 2016-07-27T06:00:54Z CRITICAL /var/log/pki/pki-tomcat 2016-07-27T06:00:54Z DEBUG Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/ipaserver/install/service.py", line 448, in start_creation run_step(full_msg, method) File "/usr/lib/python2.7/site-packages/ipaserver/install/service.py", line 438, in run_step method() File "/usr/lib/python2.7/site-packages/ipaserver/install/krainstance.py", line 258, in __spawn_instance DogtagInstance.spawn_instance(self, cfg_file) File "/usr/lib/python2.7/site-packages/ipaserver/install/dogtaginstance.py", line 181, in spawn_instance self.handle_setup_error(e) File "/usr/lib/python2.7/site-packages/ipaserver/install/dogtaginstance.py", line 420, in handle_setup_error raise RuntimeError("%s configuration failed." % self.subsystem) RuntimeError: KRA configuration failed. 2016-07-27T06:00:54Z DEBUG [error] RuntimeError: KRA configuration failed. 2016-07-27T06:00:54Z ERROR Your system may be partly configured. Run ipa-kra-install --uninstall to clean up.
KRA spawn log pki-kra-spawn.20160727080029.log
Update: it looks like now it is failing installation of KRA on replica if master has KRA too
PKI ticket created, we will see if this is dogtag issue: https://fedorahosted.org/pki/ticket/2434
Another seemingly unrelated failure of pki-spawn was encountered during KRA installation on replica. See attached ipaserver-kra-install.log for details
attachment ipaserver-kra-install.log
Please use PKI 10.3.5. The problem cannot be reproduced with that version. The PKI ticket 2434 has been closed.
ofayans, if that is a different issue please open a separate ticket. Thanks.
Steps to reproduce:
* [master] ipa-server-install --setup-dns * [master] ipa-kra-install * [replica0] ipa-replica-install (against master) * [replica0] ipa-ca-install * [replica0] ipa-kra-install * [replica0] ipa-dns-install * [replica1] ipa-replica-install --setup-ca (against master) * [replica1] ipa-kra-install <-----failed here
I was able to reproduce it manually, but I dont know if this is 100% reproducible, please note that replica0 must be installed too, without that I couldn't reproduce it.
This should be fixed on IPA side, plese refer to comment https://fedorahosted.org/pki/ticket/2434#comment:15
Metadata Update from @mbasti: - Issue assigned to mbasti - Issue set to the milestone: FreeIPA 4.5 backlog
Metadata Update from @mbasti: - Assignee reset
I'm seeing this issue and my problem seems unrelated to 2434. I have one master with a working CA and KRA. Installing a replica fails (after waiting for quite a while on "configuring KRA instance") with:
WARNING: updateNumberRange: Failed to contact master using admin portjavax.ws.rs.InternalServerErrorDescription: HTTP 500 Internal Server Error
I can see the access log entry on the master for that request but I can't see any details about the error. There isn't even a log file since the 16th.
The KRA on the master seems to work (at least ipa vault-* commands work.
ipa vault-*
Seems that the same issue randonly happens on nightly test. See PR 4163 and its logs.
Metadata Update from @frenaud: - Issue close_status updated to: None - Issue set to the milestone: None (was: FreeIPA 4.5 backlog)
Metadata Update from @frenaud: - Issue tagged with: test-failure
Login to comment on this ticket.