#5538 vault-archive command sometimes does not work
Closed: Fixed None Opened 5 years ago by mbasti.

With IPA CI I occasionally received this error, it is not 100% reproducible.

[ipa.ipatests.test_integration.host.Host.master.ParamikoTransport] RUN ['ipa', 'vault-archive', 'ci_test_vault_master', '--password', 'password', '--data', 'SSBsb3ZlIENJIHRlc3RzCg==']
[ipa.ipatests.test_integration.host.Host.master.cmd27] RUN ['ipa', 'vault-archive', 'ci_test_vault_master', '--password', 'password', '--data', 'SSBsb3ZlIENJIHRlc3RzCg==']
[ipa.ipatests.test_integration.host.Host.master.cmd27] ipa: ERROR: an internal error has occurred
[ipa.ipatests.test_integration.host.Host.master.cmd27] Exit code: 1




[Thu Dec 10 16:07:53.310049 2015] [wsgi:error] [pid 27825] ipa: INFO: [jsonserver_session] admin@IPA.TEST: vaultconfig_show(all=False, raw=False, version=u'2.161'): SUCCESS
[Thu Dec 10 16:07:56.453009 2015] [wsgi:error] [pid 27824] ipa: ERROR: non-public: PKIException: Unauthorized request.  Recovery request not approved.
[Thu Dec 10 16:07:56.453025 2015] [wsgi:error] [pid 27824] Traceback (most recent call last):
[Thu Dec 10 16:07:56.453027 2015] [wsgi:error] [pid 27824]   File "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py", line 350, in wsgi_execute
[Thu Dec 10 16:07:56.453028 2015] [wsgi:error] [pid 27824]     result = self.Command[name](*args, **options)
[Thu Dec 10 16:07:56.453030 2015] [wsgi:error] [pid 27824]   File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 447, in __call__
[Thu Dec 10 16:07:56.453031 2015] [wsgi:error] [pid 27824]     ret = self.run(*args, **options)
[Thu Dec 10 16:07:56.453033 2015] [wsgi:error] [pid 27824]   File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 764, in run
[Thu Dec 10 16:07:56.453044 2015] [wsgi:error] [pid 27824]     return self.execute(*args, **options)
[Thu Dec 10 16:07:56.453045 2015] [wsgi:error] [pid 27824]   File "/usr/lib/python2.7/site-packages/ipalib/plugins/vault.py", line 2017, in execute
[Thu Dec 10 16:07:56.453046 2015] [wsgi:error] [pid 27824]     wrapped_session_key)
[Thu Dec 10 16:07:56.453048 2015] [wsgi:error] [pid 27824]   File "/usr/lib/python2.7/site-packages/pki/__init__.py", line 298, in handler
[Thu Dec 10 16:07:56.453049 2015] [wsgi:error] [pid 27824]     return fn_call(inst, *args, **kwargs)
[Thu Dec 10 16:07:56.453050 2015] [wsgi:error] [pid 27824]   File "/usr/lib/python2.7/site-packages/pki/key.py", line 914, in retrieve_key
[Thu Dec 10 16:07:56.453051 2015] [wsgi:error] [pid 27824]     key = self.retrieve_key_data(request)
[Thu Dec 10 16:07:56.453053 2015] [wsgi:error] [pid 27824]   File "/usr/lib/python2.7/site-packages/pki/__init__.py", line 317, in handler
[Thu Dec 10 16:07:56.453054 2015] [wsgi:error] [pid 27824]     raise pki_exception
[Thu Dec 10 16:07:56.453055 2015] [wsgi:error] [pid 27824] PKIException: Unauthorized request.  Recovery request not approved.





[10/Dec/2015:16:07:55][ajp-bio-127.0.0.1-8009-exec-5]: MessageFormatInterceptor: KeyRequestResource.approveRequest()
[10/Dec/2015:16:07:55][ajp-bio-127.0.0.1-8009-exec-5]: MessageFormatInterceptor: content-type: application/json
[10/Dec/2015:16:07:55][ajp-bio-127.0.0.1-8009-exec-5]: MessageFormatInterceptor: accept: [application/json]
[10/Dec/2015:16:07:55][ajp-bio-127.0.0.1-8009-exec-5]: MessageFormatInterceptor: request format: application/json
[10/Dec/2015:16:07:55][ajp-bio-127.0.0.1-8009-exec-5]: MessageFormatInterceptor: response format: application/json
[10/Dec/2015:16:07:55][ajp-bio-127.0.0.1-8009-exec-5]: In LdapBoundConnFactory::getConn()
[10/Dec/2015:16:07:55][ajp-bio-127.0.0.1-8009-exec-5]: masterConn is connected: true
[10/Dec/2015:16:07:55][ajp-bio-127.0.0.1-8009-exec-5]: getConn: conn is connected true
[10/Dec/2015:16:07:55][ajp-bio-127.0.0.1-8009-exec-5]: getConn: mNumConns now 2
[10/Dec/2015:16:07:55][ajp-bio-127.0.0.1-8009-exec-5]: returnConn: mNumConns now 3
[10/Dec/2015:16:07:55][ajp-bio-127.0.0.1-8009-exec-5]: In LdapBoundConnFactory::getConn()
[10/Dec/2015:16:07:55][ajp-bio-127.0.0.1-8009-exec-5]: masterConn is connected: true
[10/Dec/2015:16:07:55][ajp-bio-127.0.0.1-8009-exec-5]: getConn: conn is connected true
[10/Dec/2015:16:07:55][ajp-bio-127.0.0.1-8009-exec-5]: getConn: mNumConns now 2
[10/Dec/2015:16:07:55][ajp-bio-127.0.0.1-8009-exec-5]: authorization search base: cn=Data Recovery Manager Agents,ou=groups,o=kra,o=ipaca
[10/Dec/2015:16:07:55][ajp-bio-127.0.0.1-8009-exec-5]: authorization search filter: (uniquemember=uid=ipakra,ou=people,o=kra,o=ipaca)
[10/Dec/2015:16:07:55][ajp-bio-127.0.0.1-8009-exec-5]: authorization result: true
[10/Dec/2015:16:07:55][ajp-bio-127.0.0.1-8009-exec-5]: returnConn: mNumConns now 3
[10/Dec/2015:16:07:55][ajp-bio-127.0.0.1-8009-exec-5]: In LdapBoundConnFactory::getConn()
[10/Dec/2015:16:07:55][ajp-bio-127.0.0.1-8009-exec-5]: masterConn is connected: true
[10/Dec/2015:16:07:55][ajp-bio-127.0.0.1-8009-exec-5]: getConn: conn is connected true
[10/Dec/2015:16:07:55][ajp-bio-127.0.0.1-8009-exec-5]: getConn: mNumConns now 2
[10/Dec/2015:16:07:55][ajp-bio-127.0.0.1-8009-exec-5]: returnConn: mNumConns now 3
[10/Dec/2015:16:07:55][ajp-bio-127.0.0.1-8009-exec-5]: In LdapBoundConnFactory::getConn()
[10/Dec/2015:16:07:55][ajp-bio-127.0.0.1-8009-exec-5]: masterConn is connected: true
[10/Dec/2015:16:07:55][ajp-bio-127.0.0.1-8009-exec-5]: getConn: conn is connected true
[10/Dec/2015:16:07:55][ajp-bio-127.0.0.1-8009-exec-5]: getConn: mNumConns now 2
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: Error: LDAP operation failure - cn=2,ou=kra,ou=requests,o=kra,o=ipaca netscape.ldap.LDAPException: error result (1)
LDAP operation failure - cn=2,ou=kra,ou=requests,o=kra,o=ipaca netscape.ldap.LDAPException: error result (1)
        at com.netscape.cmscore.dbs.DBSSession.modify(DBSSession.java:240)
        at com.netscape.cmscore.request.RequestQueue.modifyRequest(RequestQueue.java:181)
        at com.netscape.cmscore.request.ARequestQueue.updateRequest(ARequestQueue.java:552)
        at com.netscape.kra.KeyRecoveryAuthority.addAgentAsyncKeyRecovery(KeyRecoveryAuthority.java:986)
        at org.dogtagpki.server.kra.rest.KeyRequestService.approveRequest(KeyRequestService.java:270)
        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)
        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.GeneratedMethodAccessor40.invoke(Unknown Source)
        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.GeneratedMethodAccessor39.invoke(Unknown Source)
        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.ajp.AjpProcessor.process(AjpProcessor.java:190)
        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)
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: returnConn: mNumConns now 3
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: SignedAuditEventFactory: create() message=[AuditEvent=SECURITY_DATA_RECOVERY_REQUEST_STATE_CHANGE][SubjectID=ipakra][Outcome=Success][RecoveryID=2][Operation=approve] security data recovery request state change

[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: SessionContextInterceptor: KeyResource.retrieveKey()
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: SessionContextInterceptor: principal: ipakra
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: AuthMethodInterceptor: KeyResource.retrieveKey()
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: AuthMethodInterceptor: mapping: keys
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: AuthMethodInterceptor: required auth methods: [certUserDBAuthMgr]
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: AuthMethodInterceptor: authentication manager: certUserDBAuthMgr
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: AuthMethodInterceptor: access granted
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: ACLInterceptor: KeyResource.retrieveKey()
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: ACLInterceptor: principal: ipakra
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: ACLInterceptor: mapping: keys
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: ACLInterceptor: ACL: certServer.kra.keys,execute
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: checkACLS(): ACLEntry expressions= group="Data Recovery Manager Agents"
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: evaluating expressions: group="Data Recovery Manager Agents"
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: GroupAccessEvaluator: evaluate: uid=ipakra value="Data Recovery Manager Agents"
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: GroupAccessEvaluator: evaluate: no groups in authToken
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: In LdapBoundConnFactory::getConn()
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: masterConn is connected: true
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: getConn: conn is connected true
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: getConn: mNumConns now 2
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: returnConn: mNumConns now 3
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: UGSubsystem.isMemberOf() using new lookup code
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: In LdapBoundConnFactory::getConn()
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: masterConn is connected: true
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: getConn: conn is connected true
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: getConn: mNumConns now 2
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: authorization search base: cn=Data Recovery Manager Agents,ou=groups,o=kra,o=ipaca
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: authorization search filter: (uniquemember=uid=ipakra,ou=people,o=kra,o=ipaca)
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: authorization result: true
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: returnConn: mNumConns now 3
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: evaluated expression: group="Data Recovery Manager Agents" to be true
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: DirAclAuthz: authorization passed
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: ACLInterceptor: access granted
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: SignedAuditEventFactory: create() message=[AuditEvent=AUTHZ_SUCCESS][SubjectID=ipakra][Outcome=Success][aclResource=certServer.kra.keys][Op=execute][Info=KeyResource.retrieveKey] authorization success

[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: MessageFormatInterceptor: KeyResource.retrieveKey()
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: MessageFormatInterceptor: content-type: application/json
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: MessageFormatInterceptor: accept: [application/json]
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: MessageFormatInterceptor: request format: application/json
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: MessageFormatInterceptor: response format: application/json
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: KeyService.retrieveKey()
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: KeyService: request ID: 2
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: KeyService: key ID: 1
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: In LdapBoundConnFactory::getConn()
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: masterConn is connected: true
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: getConn: conn is connected true
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: getConn: mNumConns now 2
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: returnConn: mNumConns now 3
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: KeyService: request type: securityDataRecovery
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: KeyService.validateRequest: begins.
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: In LdapBoundConnFactory::getConn()
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: masterConn is connected: true
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: getConn: conn is connected true
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: getConn: mNumConns now 2
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: returnConn: mNumConns now 3
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: In LdapBoundConnFactory::getConn()
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: masterConn is connected: true
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: getConn: conn is connected true
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: getConn: mNumConns now 2
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: returnConn: mNumConns now 3
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: Unauthorized request.  Recovery request not approved.
com.netscape.certsrv.base.UnauthorizedException: Unauthorized request.  Recovery request not approved.
        at org.dogtagpki.server.kra.rest.KeyService.validateRequest(KeyService.java:391)
        at org.dogtagpki.server.kra.rest.KeyService.retrieveKey(KeyService.java:162)
        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)
        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.GeneratedMethodAccessor40.invoke(Unknown Source)
        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.GeneratedMethodAccessor39.invoke(Unknown Source)
        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.ajp.AjpProcessor.process(AjpProcessor.java:190)
        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)
[10/Dec/2015:16:07:56][ajp-bio-127.0.0.1-8009-exec-5]: SignedAuditEventFactory: create() message=[AuditEvent=SECURITY_DATA_RETRIEVE_KEY][SubjectID=ipakra][Outcome=Failure][RecoveryID=2][KeyID=1][Info=KeyService.retrieveKey: requestID=2; keyID=1; request type:securityDataRecovery;Unauthorized request.  Recovery request not approved.] security data retrieval request

And another error (same test, same machine, next run):

[Thu Dec 10 17:08:21.949267 2015] [wsgi:error] [pid 12112] ipa: ERROR: non-public: PKIException: LDAP operation failure - cn=9,ou=keyRepository,ou=kra,o=kra,o=ipaca netscape.ldap.LDAPException: error result (1)
[Thu Dec 10 17:08:21.949281 2015] [wsgi:error] [pid 12112] Traceback (most recent call last):
[Thu Dec 10 17:08:21.949283 2015] [wsgi:error] [pid 12112]   File "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py", line 350, in wsgi_execute
[Thu Dec 10 17:08:21.949285 2015] [wsgi:error] [pid 12112]     result = self.Command[name](*args, **options)
[Thu Dec 10 17:08:21.949286 2015] [wsgi:error] [pid 12112]   File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 447, in __call__
[Thu Dec 10 17:08:21.949287 2015] [wsgi:error] [pid 12112]     ret = self.run(*args, **options)
[Thu Dec 10 17:08:21.949289 2015] [wsgi:error] [pid 12112]   File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 764, in run
[Thu Dec 10 17:08:21.949290 2015] [wsgi:error] [pid 12112]     return self.execute(*args, **options)
[Thu Dec 10 17:08:21.949291 2015] [wsgi:error] [pid 12112]   File "/usr/lib/python2.7/site-packages/ipalib/plugins/vault.py", line 1746, in execute
[Thu Dec 10 17:08:21.949293 2015] [wsgi:error] [pid 12112]     pki.key.KeyClient.KEY_STATUS_INACTIVE)
[Thu Dec 10 17:08:21.949294 2015] [wsgi:error] [pid 12112]   File "/usr/lib/python2.7/site-packages/pki/__init__.py", line 317, in handler
[Thu Dec 10 17:08:21.949296 2015] [wsgi:error] [pid 12112]     raise pki_exception
[Thu Dec 10 17:08:21.949297 2015] [wsgi:error] [pid 12112] PKIException: LDAP operation failure - cn=9,ou=keyRepository,ou=kra,o=kra,o=ipaca netscape.ldap.LDAPException: error result (1)
[Thu Dec 10 17:08:21.949534 2015] [wsgi:error] [pid 12112] ipa: INFO: [jsonserver_session] admin@IPA.TEST: vault_archive_internal(u'ci_test_vault_master3', shared=False, session_key="[\\xe6.\\xc7b\\xfe\\xee\\xd6\\xbd\\xae\\xc4D\\xf2\\x07P\\x9b\\xa5u:\\x0e\\x19s8\\x06a\\xaf\\xdf\\xa4Y\\x00\\xcfo'K\\x04\\xedJA!h\\xccY\\xa6\\x98*\\xbcK\\xbeI^\\xfc\\x03H>(L](\\x1c\\x9e\\x1b\\x98\\x9b\\xa9T\\x80\\x8a\\x14\\x9c\\x0c'G\\x89\\xcd\\x84\\x10\\x1e\\r\\x93\\x89B\\x9e2\\xb6\\xf0I\\xac\\xfb\\x80r%\\xd3l\\x8cB%\\x15\\xfb\\xec5Ta(F\\x15\\xa9\\xe1\\x06G\\x0c5,\\x0bG\\xbb\\x85S\\xafg\\rE\\x0c\\xe0--w\\x14fj1\\xa2\\xa9\\x96\\xbb\\x85\\xe6h\\x863R\\xfd\\x1c\\xad\\xffUq\\xee\\xc2z@|\\x97\\xfa8\\x11M\\xde\\xa1\\xd8a\\x82\\xaa\\xb6\\x9eQ\\xc7\\xfb\\n+\\x88\\xa4\\xeb\\xe8\\xcd\\xa9\\x19\\x0c\\x88\\xc7\\x88\\x8b\\x17d\\xcfv\\x0b\\x1d\\xb4\\xeb\\xbbn\\x8f\\xb8/\\xdey\\xa1>\\x10\\x9b\\x14\\xae\\xa1\\x1bY\\xc4\\x0f\\xd87\\xc3\\xa0\\xb2\\xdf\\x06<\\x98\\x98\\xfcJ\\xa9\\xd4O\\x06\\x07G\\xa6f}P\\xc9\\xca\\x03\\x9ff<R\\x03\\x88\\xddp\\xa5\\x11\\x16\\x1a\\xb1\\xfdI&\\xd3\\xb9\\xb8[\\xab\\x1b\\x8b\\x15", vault_data='\\\\\\xbe\\xe1\\x0f\\x8a\\xa4\\xfa\\xe9\\xa0*\\x9b\\x11N\\xe7\\xcbs\\x876\\xd7-\\x86\\xe2\\r\\xb7\\xfd@w\\x12\\xc4\\x08)Zl\\xfc\\xdfZ5\\xf7<\\xe0\\xab~Px\\xc2\\x9c\\xfa\\x1d\\xf4"a\\xf7\\xde\\xde\\xb4\\x186\\x18\\xaa&\\xf6\\xb7$V\\xc6\\x1e\\xa6n8M\\x94-gx\\x16\\x03\\xdc\\xb2\\xa4e\\xa8\\x0cy\\xbb\\xb1r\\x91\\xe0\\xd1\\x875\\xdd\\xd4\\xf4\\xdd\\x9a0\\x07?\\xbcotW\\x80\\xf6"w\\x86\\x83\\'\\x13\\x98|\\xda\\x01\\xed\\xa7]+\\x97\\x1c\\xd5QG3\\x9a\\xa5\\xc9D\\xb6\\x8e\\x08\\xe7\\x1d\\xbf\\x89\\xfc\\xd4"{(Q\\xb3\\x1b\\xb1,hd\\xb2\\xbf\\xc1\\r\\xb8\\xe9\\xbdd\\x1b\\xb6\\xb5X;\\xd0\\x17\\xe7\\xcfDG\\xef[\\xcd\\xba\\x82\\xad\\xf7J\\x06', nonce='\\xb0\\xbeV\\xe0\\xbc\\xcf\\x0c\\x87', all=False, raw=False, version=u'2.161'): PKIException




[10/Dec/2015:17:08:21][ajp-bio-127.0.0.1-8009-exec-10]: MessageFormatInterceptor: KeyResource.modifyKeyStatus()
[10/Dec/2015:17:08:21][ajp-bio-127.0.0.1-8009-exec-10]: MessageFormatInterceptor: content-type: application/json
[10/Dec/2015:17:08:21][ajp-bio-127.0.0.1-8009-exec-10]: MessageFormatInterceptor: accept: [application/json]
[10/Dec/2015:17:08:21][ajp-bio-127.0.0.1-8009-exec-10]: MessageFormatInterceptor: request format: application/json
[10/Dec/2015:17:08:21][ajp-bio-127.0.0.1-8009-exec-10]: MessageFormatInterceptor: response format: application/json
[10/Dec/2015:17:08:21][ajp-bio-127.0.0.1-8009-exec-10]: KeyService.modifyKeyStatus: begins.
[10/Dec/2015:17:08:21][ajp-bio-127.0.0.1-8009-exec-10]: In LdapBoundConnFactory::getConn()
[10/Dec/2015:17:08:21][ajp-bio-127.0.0.1-8009-exec-10]: masterConn is connected: true
[10/Dec/2015:17:08:21][ajp-bio-127.0.0.1-8009-exec-10]: getConn: conn is connected true
[10/Dec/2015:17:08:21][ajp-bio-127.0.0.1-8009-exec-10]: getConn: mNumConns now 2
[10/Dec/2015:17:08:21][ajp-bio-127.0.0.1-8009-exec-10]: returnConn: mNumConns now 3
[10/Dec/2015:17:08:21][ajp-bio-127.0.0.1-8009-exec-10]: KeyService.createKeyDataInfo: begins.
[10/Dec/2015:17:08:21][ajp-bio-127.0.0.1-8009-exec-10]: In LdapBoundConnFactory::getConn()
[10/Dec/2015:17:08:21][ajp-bio-127.0.0.1-8009-exec-10]: masterConn is connected: true
[10/Dec/2015:17:08:21][ajp-bio-127.0.0.1-8009-exec-10]: getConn: conn is connected true
[10/Dec/2015:17:08:21][ajp-bio-127.0.0.1-8009-exec-10]: getConn: mNumConns now 2
[10/Dec/2015:17:08:21][ajp-bio-127.0.0.1-8009-exec-10]: returnConn: mNumConns now 3
[10/Dec/2015:17:08:21][ajp-bio-127.0.0.1-8009-exec-10]: KeyService.modifyKeyStatus:LDAP operation failure - cn=9,ou=keyRepository,ou=kra,o=kra,o=ipaca netscape.ldap.LDAPException: error result (1)
[10/Dec/2015:17:08:21][ajp-bio-127.0.0.1-8009-exec-10]: SignedAuditEventFactory: create() message=[AuditEvent=KEY_STATUS_CHANGE][SubjectID=ipakra][Outcome=Failure][KeyID=9][OldStatus=active][NewStatus=inactive][Info=KeyService.modifyKeyStatus:LDAP operation failure - cn=9,ou=keyRepository,ou=kra,o=kra,o=ipaca netscape.ldap.LDAPException: error result (1)] Key Status Change

and now with the same test suite, I just changed domain level to 0, and this happened to almost latest test, others passed.
It is vault-retrieve command

However I'm able to sucessfully get vault manually, so it looks like timing issue.
Note: after every vault-add there is 30sec sleep in test to gave replication time to process data. Is this sleep too short?

[Thu Dec 10 18:14:09.768356 2015] [wsgi:error] [pid 19414] ipa: INFO: [jsonserver_session] admin@IPA.TEST: vaultconfig_show(all=False, raw=False, version=u'2.161'): SUCCESS
[Thu Dec 10 18:14:10.285866 2015] [wsgi:error] [pid 19415] ipa: ERROR: non-public: HTTPError: 500 Server Error: Internal Server Error
[Thu Dec 10 18:14:10.285885 2015] [wsgi:error] [pid 19415] Traceback (most recent call last):
[Thu Dec 10 18:14:10.285887 2015] [wsgi:error] [pid 19415]   File "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py", line 350, in wsgi_execute
[Thu Dec 10 18:14:10.285889 2015] [wsgi:error] [pid 19415]     result = self.Command[name](*args, **options)
[Thu Dec 10 18:14:10.285890 2015] [wsgi:error] [pid 19415]   File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 447, in __call__
[Thu Dec 10 18:14:10.285892 2015] [wsgi:error] [pid 19415]     ret = self.run(*args, **options)
[Thu Dec 10 18:14:10.285893 2015] [wsgi:error] [pid 19415]   File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 764, in run
[Thu Dec 10 18:14:10.285894 2015] [wsgi:error] [pid 19415]     return self.execute(*args, **options)
[Thu Dec 10 18:14:10.285896 2015] [wsgi:error] [pid 19415]   File "/usr/lib/python2.7/site-packages/ipalib/plugins/vault.py", line 2017, in execute
[Thu Dec 10 18:14:10.285897 2015] [wsgi:error] [pid 19415]     wrapped_session_key)
[Thu Dec 10 18:14:10.285899 2015] [wsgi:error] [pid 19415]   File "/usr/lib/python2.7/site-packages/pki/__init__.py", line 298, in handler
[Thu Dec 10 18:14:10.285900 2015] [wsgi:error] [pid 19415]     return fn_call(inst, *args, **kwargs)
[Thu Dec 10 18:14:10.285901 2015] [wsgi:error] [pid 19415]   File "/usr/lib/python2.7/site-packages/pki/key.py", line 906, in retrieve_key
[Thu Dec 10 18:14:10.285903 2015] [wsgi:error] [pid 19415]     self.approve_request(request_id)
[Thu Dec 10 18:14:10.285904 2015] [wsgi:error] [pid 19415]   File "/usr/lib/python2.7/site-packages/pki/__init__.py", line 298, in handler
[Thu Dec 10 18:14:10.285905 2015] [wsgi:error] [pid 19415]     return fn_call(inst, *args, **kwargs)
[Thu Dec 10 18:14:10.285906 2015] [wsgi:error] [pid 19415]   File "/usr/lib/python2.7/site-packages/pki/key.py", line 528, in approve_request
[Thu Dec 10 18:14:10.285908 2015] [wsgi:error] [pid 19415]     self.connection.post(url, None, self.headers)
[Thu Dec 10 18:14:10.285909 2015] [wsgi:error] [pid 19415]   File "/usr/lib/python2.7/site-packages/pki/client.py", line 41, in wrapper
[Thu Dec 10 18:14:10.285910 2015] [wsgi:error] [pid 19415]     return func(self, *args, **kwargs)
[Thu Dec 10 18:14:10.285912 2015] [wsgi:error] [pid 19415]   File "/usr/lib/python2.7/site-packages/pki/client.py", line 163, in post
[Thu Dec 10 18:14:10.285913 2015] [wsgi:error] [pid 19415]     r.raise_for_status()
[Thu Dec 10 18:14:10.285914 2015] [wsgi:error] [pid 19415]   File "/usr/lib/python2.7/site-packages/requests/models.py", line 851, in raise_for_status
[Thu Dec 10 18:14:10.285916 2015] [wsgi:error] [pid 19415]     raise HTTPError(http_error_msg, response=self)
[Thu Dec 10 18:14:10.285922 2015] [wsgi:error] [pid 19415] HTTPError: 500 Server Error: Internal Server Error
[Thu Dec 10 18:14:10.286179 2015] [wsgi:error] [pid 19415] ipa: INFO: [jsonserver_session] admin@IPA.TEST: vault_retrieve_internal(u'ci_test_vault_master', shared=False, session_key='\\x18n`\\x8eL\\xb7\\xd8\\xce\\xafHP\\xc1H\\xe3s\\x99\\x98\\xc4"Y\\xe0\\x10\\xf5\\x16\\xe4\\xcd\\xd1B\\xed*\\x95WnJF=\\x0e\\x13\\xad\\xcd\\xbba\\xcc\\x03-\\x05\\x11\\xc6\\x0cYgba\\x82\\xb2\\xbc\\x16\\x04\\x19\\x97\\xe7\\xd7\\x13\\xa2Tu\\xfa\\xceF\\t\\xea\\xfd\\x9c\\x14+\\xc4sBc\\x8f\\x05\\x05\\xfd}\\x85X\\xa8\\xeeW\\x06\\xcfA\\x02Ov\\x7f\\xff\\x89\\x98\\x04\\xb6\\xa0l\\xb9\\xf6\\xf0\\xcc\\x18p\\x88\\xbd\\x91\\xdaK\\x10\\xf4\\x82{c@\\xbaov\\x93}\\x07\\xded`j\\xd5\\xd8\\x95\\xab\\\\*\\x15\\xc1\\x1a\\xb3\\x03(\\xf1\\xf9F?\\xcesG\\x91C\\x9d\\xc9\\xd7*\\x1b;\\xfcL\\xcd\\xfe\\xd1\\x10(\\xba\\xf70T\\xda\\xa7\\xf3T\\xd2\\x13g\\x88\\xc2\\xd8Q\\xbdCQc\\xdbP\\xb2!\\x98\\x8c\\xbe\\x92{\\xfe\\xc1x\\x97ZZ\\xd2\\xf1\\xe4\\xacI\\tN\\xbc\\xd6\\xf7\\xeb\\xd9\\x19\\xa7\\x85Y\\xd5\\x0fo\\x14\\xd2\\x14\\x14\\x9a\\xfb\\x1a;Or\\xb2\\xcdh\\xf3-\\x1b@\\x05[\\xc1!\\xb4\\xfc7\\xb8p\\x10\\xe1[>\\x9d78)E\\xfa\\xc8\\xcdX', all=False, raw=False, version=u'2.161'): HTTPError





[10/Dec/2015:18:14:10][ajp-bio-127.0.0.1-8009-exec-11]: MessageFormatInterceptor: response format: application/json
[10/Dec/2015:18:14:10][ajp-bio-127.0.0.1-8009-exec-11]: In LdapBoundConnFactory::getConn()
[10/Dec/2015:18:14:10][ajp-bio-127.0.0.1-8009-exec-11]: masterConn is connected: true
[10/Dec/2015:18:14:10][ajp-bio-127.0.0.1-8009-exec-11]: getConn: conn is connected true
[10/Dec/2015:18:14:10][ajp-bio-127.0.0.1-8009-exec-11]: getConn: mNumConns now 2
[10/Dec/2015:18:14:10][ajp-bio-127.0.0.1-8009-exec-11]: returnConn: mNumConns now 3
[10/Dec/2015:18:14:10][ajp-bio-127.0.0.1-8009-exec-11]: In LdapBoundConnFactory::getConn()
[10/Dec/2015:18:14:10][ajp-bio-127.0.0.1-8009-exec-11]: masterConn is connected: true
[10/Dec/2015:18:14:10][ajp-bio-127.0.0.1-8009-exec-11]: getConn: conn is connected true
[10/Dec/2015:18:14:10][ajp-bio-127.0.0.1-8009-exec-11]: getConn: mNumConns now 2
[10/Dec/2015:18:14:10][ajp-bio-127.0.0.1-8009-exec-11]: authorization search base: cn=Data Recovery Manager Agents,ou=groups,o=kra,o=ipaca
[10/Dec/2015:18:14:10][ajp-bio-127.0.0.1-8009-exec-11]: authorization search filter: (uniquemember=uid=ipakra,ou=people,o=kra,o=ipaca)
[10/Dec/2015:18:14:10][ajp-bio-127.0.0.1-8009-exec-11]: authorization result: true
[10/Dec/2015:18:14:10][ajp-bio-127.0.0.1-8009-exec-11]: returnConn: mNumConns now 3
[10/Dec/2015:18:14:10][ajp-bio-127.0.0.1-8009-exec-11]: In LdapBoundConnFactory::getConn()
[10/Dec/2015:18:14:10][ajp-bio-127.0.0.1-8009-exec-11]: masterConn is connected: true
[10/Dec/2015:18:14:10][ajp-bio-127.0.0.1-8009-exec-11]: getConn: conn is connected true
[10/Dec/2015:18:14:10][ajp-bio-127.0.0.1-8009-exec-11]: getConn: mNumConns now 2
[10/Dec/2015:18:14:10][ajp-bio-127.0.0.1-8009-exec-11]: Error: Record not found
Record not found
        at com.netscape.cmscore.dbs.DBSSession.read(DBSSession.java:180)
        at com.netscape.cmscore.dbs.DBSSession.read(DBSSession.java:135)
        at com.netscape.cmscore.request.RequestQueue.readRequest(RequestQueue.java:72)
        at com.netscape.cmscore.request.ARequestQueue.findRequest(ARequestQueue.java:325)
        at com.netscape.kra.KeyRecoveryAuthority.addAgentAsyncKeyRecovery(KeyRecoveryAuthority.java:956)
        at org.dogtagpki.server.kra.rest.KeyRequestService.approveRequest(KeyRequestService.java:270)
        at sun.reflect.GeneratedMethodAccessor98.invoke(Unknown Source)
        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)
        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.GeneratedMethodAccessor40.invoke(Unknown Source)
        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.GeneratedMethodAccessor39.invoke(Unknown Source)
        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.ajp.AjpProcessor.process(AjpProcessor.java:190)
        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)
[10/Dec/2015:18:14:10][ajp-bio-127.0.0.1-8009-exec-11]: returnConn: mNumConns now 3

Workaround for tests to unblock testing has been pushed.

master:

  • 8112ac6 test: Temporarily increase timeout in vault test.

ipa-4-2:

  • ac0999e test: Temporarily increase timeout in vault test.

These commits should be removed when this issue is fixed.

From looking at the logs and discussion on IRC it looks like the core of the problem is that in DS the writing of the retro changelog fails and an error (err=1) is returned to the client.

There are two problems:
1] DS should succeed in writing the retro changelog and if not do a better logging (and eventually return another error)
2] The client ( dogtag ) should handle the returned error and eventually retry the failed operation.

further investigation of 1] is ongoing, but with more error logging the problem did not reoccur, and also 2] will not be available very soon.

There is already a workaround in place by increasing the timeout, but anothe rway to prevent this problem could be to disable writing the retro changelog for th ipaca backend.
In my understanding it is not needed (it is used for syncrepl and dns ), so it would als reduce the write load for the retro CL.

could the following change be tested ?
In the config entry for the retro CL disable writing ipaca:

dn: cn=Retro Changelog Plugin,cn=plugins,cn=config
....
nsslapd-exclude-suffix: o=ipaca

RetroCL was added in #3967 for bind-dyndb-ldap. At the moment the plugin targets the entire LDAP tree. If it is used required for DNS then the plugin can be limited to the dns subtree cn=dns,$SUFFIX.

http://directory.fedoraproject.org/docs/389ds/design/retrocl-scoping.html

The change of scope recommended in https://fedorahosted.org/freeipa/ticket/5538#comment:6

dn: cn=Retro Changelog Plugin,cn=plugins,cn=config
....
nsslapd-exclude-suffix: o=ipaca

Is required (Content Synchronization was enabled so retroCL). A similar deadlock occurs while updating "cn=5,ou=kra,ou=requests,o=kra,o=ipaca"
https://fedorahosted.org/389/ticket/48181#comment:10. tests done git version of freeipa-server-4.3.90.

Removed o=ipaca from syncrepl

master:

  • 54a91c3 Exclude o=ipaca subtree from Retro Changelog (syncrepl)

ipa-4-3:

  • 89c32f2 Exclude o=ipaca subtree from Retro Changelog (syncrepl)

freeipa has two backends (domain, ipaca) and updates in those backends will add entries in a third backend retroCL (cn=changelog). It is prone to create deadlock scenario.

Filling retroCL with ipaca updates is useless, so we can prevent deadlocks with the workaround in https://fedorahosted.org/freeipa/ticket/5538#comment:9.

A long term solution to prevent those deadlocks will be implemented with https://fedorahosted.org/389/ticket/48297

master:

  • a14d687 Revert "test: Temporarily increase timeout in vault test."

ipa-4-3:

  • 390f634 Revert "test: Temporarily increase timeout in vault test."

Revert changes in tests, workaround works.

Ticket can be closed.

47931 is fixed in 1.3.4.0-9. Currently freeipa.spec.in defines '389-ds-base >= 1.3.4.6 so' it already covers the need of 47931 fix.

Metadata Update from @mbasti:
- Issue assigned to someone
- Issue set to the milestone: FreeIPA 4.3.1

4 years ago

Login to comment on this ticket.

Metadata