Issue #5269: ipa-server-install in a container fails with RemoteRetrieveError: Non-2xx response from CA REST API: 500 Internal Server Error. - freeipa

freeipa

#5269 ipa-server-install in a container fails with RemoteRetrieveError: Non-2xx response from CA REST API: 500 Internal Server Error.

Closed: Fixed None Opened 8 years ago by adelton.

When running ipa-server-install in a container with bits from https://copr.fedoraproject.org/coprs/mkosek/freeipa-4.2/ using the fedora-22-upstream branch of https://github.com/adelton/docker-freeipa, sometimes the ipa-server-install ends with

  [23/25]: Configure HTTP to proxy connections
  [24/25]: restarting certificate server
  [25/25]: Importing IPA certificate profiles
  [error] RemoteRetrieveError: Non-2xx response from CA REST API: 500 Internal Server Error. 
ipa.ipapython.install.cli.install_tool(Server): ERROR    Non-2xx response from CA REST API: 500 Internal Server Error. 
FreeIPA server configuration failed.

The {{{/var/log/ipaserver-install.log}}} then has

2015-08-28T07:36:17Z DEBUG Cipher: TLS_RSA_WITH_AES_128_GCM_SHA256
2015-08-28T07:36:17Z DEBUG request status 204
2015-08-28T07:36:17Z DEBUG request reason_phrase u'No Content'
2015-08-28T07:36:17Z DEBUG request headers {'set-cookie': 'JSESSIONID=7188A372D92D402C949B10AC68333E5E; Path=/ca/; Secure; HttpOnly', 'expires': 'Thu, 01
 Jan 1970 00:00:00 UTC', 'server': 'Apache-Coyote/1.1', 'cache-control': 'private', 'date': 'Fri, 28 Aug 2015 07:36:17 GMT', 'content-type': 'application
/xml'}
2015-08-28T07:36:17Z DEBUG request body ''
2015-08-28T07:36:17Z DEBUG Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/ipaserver/install/service.py", line 416, in start_creation
    run_step(full_msg, method)
  File "/usr/lib/python2.7/site-packages/ipaserver/install/service.py", line 406, in run_step
    method()
  File "/usr/lib/python2.7/site-packages/ipaserver/install/cainstance.py", line 1724, in import_included_profiles
    _create_dogtag_profile(profile_id, profile_data)
  File "/usr/lib/python2.7/site-packages/ipaserver/install/cainstance.py", line 1798, in _create_dogtag_profile
    profile_api.create_profile(profile_data)
  File "/usr/lib/python2.7/site-packages/ipaserver/plugins/dogtag.py", line 2081, in create_profile
    body=profile_data
  File "/usr/lib/python2.7/site-packages/ipaserver/plugins/dogtag.py", line 2061, in _ssldo
    % {'status': status, 'status_text': status_text, 'explanation': explanation}
RemoteRetrieveError: Non-2xx response from CA REST API: 500 Internal Server Error.

2015-08-28T07:36:17Z DEBUG   [error] RemoteRetrieveError: Non-2xx response from CA REST API: 500 Internal Server Error. 
2015-08-28T07:36:17Z 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 308, in run
    cfgr.run()
  File "/usr/lib/python2.7/site-packages/ipapython/install/core.py", line 280, in run
    self.execute()
  File "/usr/lib/python2.7/site-packages/ipapython/install/core.py", line 302, in execute
    for nothing in self._executor():
  File "/usr/lib/python2.7/site-packages/ipapython/install/core.py", line 342, in __runner
    self._handle_exception(exc_info)
  File "/usr/lib/python2.7/site-packages/ipapython/install/core.py", line 364, in _handle_exception
    util.raise_exc_info(exc_info)
  File "/usr/lib/python2.7/site-packages/ipapython/install/core.py", line 332, in __runner
    step()
  File "/usr/lib/python2.7/site-packages/ipapython/install/util.py", line 87, in run_generator_with_yield_from
    raise_exc_info(exc_info)
  File "/usr/lib/python2.7/site-packages/ipapython/install/util.py", line 65, in run_generator_with_yield_from
    value = gen.send(prev_value)
  File "/usr/lib/python2.7/site-packages/ipapython/install/core.py", line 523, in _configure
    executor.next()
  File "/usr/lib/python2.7/site-packages/ipapython/install/core.py", line 342, in __runner
    self._handle_exception(exc_info)
  File "/usr/lib/python2.7/site-packages/ipapython/install/core.py", line 420, in _handle_exception
    self.__parent._handle_exception(exc_info)
  File "/usr/lib/python2.7/site-packages/ipapython/install/core.py", line 364, in _handle_exception
    util.raise_exc_info(exc_info)
  File "/usr/lib/python2.7/site-packages/ipapython/install/core.py", line 417, in _handle_exception
    super(ComponentBase, self)._handle_exception(exc_info)
  File "/usr/lib/python2.7/site-packages/ipapython/install/core.py", line 364, in _handle_exception
    util.raise_exc_info(exc_info)
  File "/usr/lib/python2.7/site-packages/ipapython/install/core.py", line 332, in __runner
    step()
  File "/usr/lib/python2.7/site-packages/ipapython/install/util.py", line 87, in run_generator_with_yield_from
    raise_exc_info(exc_info)
  File "/usr/lib/python2.7/site-packages/ipapython/install/util.py", line 65, in run_generator_with_yield_from
    value = gen.send(prev_value)
    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 1656, in main
    install(self)
  File "/usr/lib/python2.7/site-packages/ipaserver/install/server/install.py", line 262, in decorated
    func(installer)
  File "/usr/lib/python2.7/site-packages/ipaserver/install/server/install.py", line 764, in install
    ca.install_step_0(False, None, options)
  File "/usr/lib/python2.7/site-packages/ipaserver/install/ca.py", line 151, in install_step_0
    ca_signing_algorithm=options.ca_signing_algorithm)
  File "/usr/lib/python2.7/site-packages/ipaserver/install/cainstance.py", line 480, in configure_instance
    self.start_creation(runtime=210)
  File "/usr/lib/python2.7/site-packages/ipaserver/install/service.py", line 416, in start_creation
    run_step(full_msg, method)
  File "/usr/lib/python2.7/site-packages/ipaserver/install/service.py", line 406, in run_step
    method()
  File "/usr/lib/python2.7/site-packages/ipaserver/install/cainstance.py", line 1724, in import_included_profiles
    _create_dogtag_profile(profile_id, profile_data)
  File "/usr/lib/python2.7/site-packages/ipaserver/install/cainstance.py", line 1798, in _create_dogtag_profile
    profile_api.create_profile(profile_data)
  File "/usr/lib/python2.7/site-packages/ipaserver/plugins/dogtag.py", line 2081, in create_profile
    body=profile_data
  File "/usr/lib/python2.7/site-packages/ipaserver/plugins/dogtag.py", line 2061, in _ssldo
    % {'status': status, 'status_text': status_text, 'explanation': explanation}

2015-08-28T07:36:17Z DEBUG The ipa-server-install command failed, exception: RemoteRetrieveError: Non-2xx response from CA REST API: 500 Internal Server Error. 
2015-08-28T07:36:17Z ERROR Non-2xx response from CA REST API: 500 Internal Server Error.

{{{/var/log/pki/pki-tomcat/localhost_access_log.2015-08-28.txt}}} contains

172.17.0.12 - - [28/Aug/2015:07:34:32 +0000] "GET /ca/admin/ca/getStatus HTTP/1.1" 200 168
172.17.0.12 - - [28/Aug/2015:07:35:39 +0000] "POST /ca/rest/installer/configure HTTP/1.1" 200 12283
172.17.0.12 - - [28/Aug/2015:07:35:47 +0000] "GET /ca/admin/ca/getStatus HTTP/1.1" 200 168
172.17.0.12 - - [28/Aug/2015:07:35:47 +0000] "GET /ca/ee/ca/getCertChain HTTP/1.1" 200 1414
172.17.0.12 - - [28/Aug/2015:07:35:55 +0000] "GET /ca/admin/ca/getStatus HTTP/1.1" 200 168
172.17.0.12 - - [28/Aug/2015:07:35:55 +0000] "POST /ca/ee/ca/profileSubmit HTTP/1.1" 200 162
172.17.0.12 - - [28/Aug/2015:07:35:55 +0000] "GET /ca/agent/ca/profileReview?requestId=7 HTTP/1.0" 200 29532
172.17.0.12 - - [28/Aug/2015:07:35:56 +0000] "POST /ca/agent/ca/profileProcess HTTP/1.0" 200 13204
172.17.0.12 - - [28/Aug/2015:07:35:59 +0000] "GET /ca/ee/ca/profileList?xml=true HTTP/1.1" 200 23672
172.17.0.12 - - [28/Aug/2015:07:36:02 +0000] "GET /ca/ee/ca/profileList?xml=true HTTP/1.1" 200 23672
172.17.0.12 - - [28/Aug/2015:07:36:16 +0000] "GET /ca/admin/ca/getStatus HTTP/1.1" 200 168
172.17.0.12 - ipara [28/Aug/2015:07:36:16 +0000] "GET /ca/rest/account/login HTTP/1.1" 200 205
172.17.0.12 - ipara [28/Aug/2015:07:36:17 +0000] "POST /ca/rest/profiles/raw HTTP/1.1" 400 148
172.17.0.12 - ipara [28/Aug/2015:07:36:17 +0000] "POST /ca/rest/profiles/caIPAserviceCert?action=disable HTTP/1.1" 204 -
172.17.0.12 - ipara [28/Aug/2015:07:36:17 +0000] "DELETE /ca/rest/profiles/caIPAserviceCert HTTP/1.1" 204 -
172.17.0.12 - ipara [28/Aug/2015:07:36:17 +0000] "POST /ca/rest/profiles/raw HTTP/1.1" 500 6602
172.17.0.12 - ipara [28/Aug/2015:07:36:17 +0000] "GET /ca/rest/account/logout HTTP/1.1" 204 -

and {{{/var/log/pki/pki-tomcat/localhost.2015-08-28.log}}} contains

Aug 28, 2015 7:35:40 AM org.apache.catalina.core.ApplicationContext log
SEVERE: Servlet castart threw unload() exception
javax.servlet.ServletException: Servlet.destroy() for servlet castart threw exception
        at org.apache.catalina.core.StandardWrapper.unload(StandardWrapper.java:1508)
        at org.apache.catalina.core.StandardWrapper.stopInternal(StandardWrapper.java:1847)
        at org.apache.catalina.util.LifecycleBase.stop(LifecycleBase.java:232)
        at org.apache.catalina.core.StandardContext.stopInternal(StandardContext.java:5707)
        at org.apache.catalina.util.LifecycleBase.stop(LifecycleBase.java:232)
        at org.apache.catalina.core.ContainerBase$StopChild.call(ContainerBase.java:1591)
        at org.apache.catalina.core.ContainerBase$StopChild.call(ContainerBase.java:1580)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.NullPointerException
        at com.netscape.cmscore.profile.LDAPProfileSubsystem.forgetAllProfiles(LDAPProfileSubsystem.java:254)
        at com.netscape.cmscore.profile.LDAPProfileSubsystem.shutdown(LDAPProfileSubsystem.java:250)
        at com.netscape.cmscore.apps.CMSEngine.shutdownSubsystems(CMSEngine.java:1859)
        at com.netscape.cmscore.apps.CMSEngine.shutdown(CMSEngine.java:1797)
        at com.netscape.certsrv.apps.CMS.shutdown(CMS.java:233)
        at com.netscape.cms.servlet.base.CMSStartServlet.destroy(CMSStartServlet.java:144)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:497)
        at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:276)
        at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:273)
        at java.security.AccessController.doPrivileged(Native Method)
        at javax.security.auth.Subject.doAsPrivileged(Subject.java:549)
        at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:308)
        at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:168)
        at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:100)
        at org.apache.catalina.core.StandardWrapper.unload(StandardWrapper.java:1480)
        ... 10 more

Aug 28, 2015 7:36:17 AM org.apache.catalina.core.StandardWrapperValve invoke
SEVERE: Servlet.service() for servlet [Resteasy] in context with path [/ca] threw exception
org.jboss.resteasy.spi.UnhandledException: java.lang.NullPointerException
        at org.jboss.resteasy.core.ExceptionHandler.handleApplicationException(ExceptionHandler.java:76)
        at org.jboss.resteasy.core.ExceptionHandler.handleException(ExceptionHandler.java:212)
        at org.jboss.resteasy.core.SynchronousDispatcher.writeException(SynchronousDispatcher.java:149)
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:372)
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:179)
        at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:220)
        at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56)
        at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:497)
        at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:276)
        at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:273)
        at java.security.AccessController.doPrivileged(Native Method)
        at javax.security.auth.Subject.doAsPrivileged(Subject.java:549)
        at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:308)
        at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:168)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:297)
        at org.apache.catalina.core.ApplicationFilterChain.access$000(ApplicationFilterChain.java:55)
        at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:191)
        at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:187)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:186)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:497)
        at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:276)
        at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:273)
        at java.security.AccessController.doPrivileged(Native Method)
        at javax.security.auth.Subject.doAsPrivileged(Subject.java:549)
        at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:308)
        at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:248)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:238)
        at org.apache.catalina.core.ApplicationFilterChain.access$000(ApplicationFilterChain.java:55)
        at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:191)
        at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:187)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:186)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:221)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:613)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
        at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:421)
        at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1074)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611)
        at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:314)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.NullPointerException
        at com.netscape.cmscore.profile.AbstractProfileSubsystem.disableProfile(AbstractProfileSubsystem.java:119)
        at org.dogtagpki.server.ca.rest.ProfileService.createProfileRaw(ProfileService.java:590)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:497)
        at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:137)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:280)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:234)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:221)
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:356)
        ... 53 more

It is not deterministic.

pvoborni commented 8 years ago

FreeIPA 4.2.1 was released, moving to 4.2.x.

pvoborni commented 8 years ago

Jan, how often do you experience it? What versions of PKI and IPA?

adelton commented 8 years ago

Replying to [comment:4 pvoborni]:

Jan, how often do you experience it?

In about 60 per cent of installations.

What versions of PKI and IPA?

freeipa-server-4.2.3-1.fc23, pki-server-10.2.6-12.fc23

jcholast commented 8 years ago

Linked to Bugzilla bug: https://bugzilla.redhat.com/show_bug.cgi?id=1283429 (Red Hat Enterprise Linux 7)

jcholast commented 8 years ago

master:

2be8d2d TLS and Dogtag HTTPS request logging improvements
5136cd6 Avoid race condition caused by profile delete and recreate

ipa-4-2:

1874ccf TLS and Dogtag HTTPS request logging improvements
a8a6664 Avoid race condition caused by profile delete and recreate

adelton commented 8 years ago

Replying to [comment:9 jcholast]:

master:
2be8d2d TLS and Dogtag HTTPS request logging improvements
5136cd6 Avoid race condition caused by profile delete and recreate

Can I assume that only the second commit is actually needed to fix this ticket?

adelton commented 8 years ago

I believe the linked bugzilla https://bugzilla.redhat.com/show_bug.cgi?id=1283429 is not correct -- I've seen this on non-replica installations as well.

ftweedal commented 8 years ago

Replying to [comment:10 adelton]:

Replying to [comment:9 jcholast]:

master:
2be8d2d TLS and Dogtag HTTPS request logging improvements
5136cd6 Avoid race condition caused by profile delete and recreate

Can I assume that only the second commit is actually needed to fix this ticket?

That's correct.

Metadata Update from @adelton:
- Issue assigned to ftweedal
- Issue set to the milestone: FreeIPA 4.2.4

7 years ago

Metadata

Assignee

ftweedal

Tags

None

Blocking

None

Depending on

None

Priority

important

Milestone

FreeIPA 4.2.4

None

affects_doc

None

source

None

knownissue

None

type

defect

blockedby

None

test_case

None

component

IPA

blocking

None

on_review

keywords

None

test_coverage

None

reviewer

None

external_tracker

None

rhbz

https://bugzilla.redhat.com/show_bug.cgi?id=1283429

tester

None

changelog

None

design

None

freeipa

Source Code

#5269 ipa-server-install in a container fails with RemoteRetrieveError: Non-2xx response from CA REST API: 500 Internal Server Error. Closed: Fixed None Opened 8 years ago by adelton.

Metadata

#5269 ipa-server-install in a container fails with RemoteRetrieveError: Non-2xx response from CA REST API: 500 Internal Server Error.

Closed: Fixed None Opened 8 years ago by adelton.