freeipa

Clone
Source Code
GIT

#7654 ipa-kra-install fails on DL1
Closed: fixed 5 years ago Opened 6 years ago by ppicka.

Closed: fixed
Reopen Issue

Issue

ipa-kra-install fails with cert caSigningCert cert-pki-ca already exists

Steps to Reproduce

  1. ipa-server-install --setup-ca --setup-kra
  2. ipa-client-install
  3. ipa-replica-install
  4. ipa-ca-install # on that replica
  5. ipa-kra-install

Actual behavior

[1/10]: creating installation admin user
  [2/10]: configuring KRA instance
Failed to configure KRA instance: CalledProcessError(Command ['/usr/sbin/pkispawn', '-s', 'KRA', '-f', '/tmp/tmpb5m3axzr'] returned non-zero exit status 1: 'WARNING: cert caSigningCert cert-pki-ca already exists\n')
See the installation logs and the following files/directories for more information:
  /var/log/pki/pki-tomcat
  [error] RuntimeError: KRA configuration failed.

Expected behavior

install is ok

Version/Release/Distribution

freeipa-server-4.6.90.pre2-3.fc28.x86_64
freeipa-client-4.6.90.pre2-3.fc28.x86_64
389-ds-base-1.4.0.11-2.fc28.x86_64
pki-ca-10.6.1-3.fc28.noarch
pki-kra-10.6.1-3.fc28.noarch

Additional info:

tomcat log

2018-07-27 09:00:23 [https-jsse-nio-8443-exec-9] FINE: Server certificate:
2018-07-27 09:00:23 [https-jsse-nio-8443-exec-9] FINE:  - subject: CN=vm-171-023.abc.idm.lab.eng.brq.redhat.com,O=ABC.IDM.LAB.ENG.BRQ.REDHAT.COM
2018-07-27 09:00:23 [https-jsse-nio-8443-exec-9] FINE:  - issuer: CN=Certificate Authority,O=ABC.IDM.LAB.ENG.BRQ.REDHAT.COM
2018-07-27 09:00:23 [https-jsse-nio-8443-exec-9] WARNING: updateNumberRange: Failed to contact master using admin portjavax.ws.rs.InternalServerErrorException: HTTP 500 Internal Server Error
2018-07-27 09:00:23 [https-jsse-nio-8443-exec-9] WARNING: updateNumberRange: Attempting to contact master using EE port
2018-07-27 09:00:23 [https-jsse-nio-8443-exec-9] INFO: ConfigurationUtils: POST https://vm-171-023.abc.idm.lab.eng.brq.redhat.com:443/kra/ee/kra/updateNumberRange
2018-07-27 09:00:23 [https-jsse-nio-8443-exec-9] SEVERE: Configuration failed: HTTP 404 Not Found
javax.ws.rs.NotFoundException: HTTP 404 Not Found
    at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.handleErrorStatus(ClientInvocation.java:201)
    at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.extractResult(ClientInvocation.java:174)
    at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.invoke(ClientInvocation.java:473)
    at org.jboss.resteasy.client.jaxrs.internal.ClientInvocationBuilder.post(ClientInvocationBuilder.java:201)
    at com.netscape.certsrv.client.PKIConnection.post(PKIConnection.java:509)
    at com.netscape.cms.servlet.csadmin.ConfigurationUtils.post(ConfigurationUtils.java:254)
    at com.netscape.cms.servlet.csadmin.ConfigurationUtils.updateNumberRange(ConfigurationUtils.java:676)
    at com.netscape.cms.servlet.csadmin.ConfigurationUtils.getConfigEntriesFromMaster(ConfigurationUtils.java:573)
    at org.dogtagpki.server.rest.SystemConfigService.configureClone(SystemConfigService.java:833)
    at org.dogtagpki.server.rest.SystemConfigService.configureSubsystem(SystemConfigService.java:981)
    at org.dogtagpki.server.rest.SystemConfigService.configure(SystemConfigService.java:150)
    at org.dogtagpki.server.rest.SystemConfigService.configure(SystemConfigService.java:107)
    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:498)
    at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:139)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:295)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:249)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:236)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:402)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:209)
    at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:221)
    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:742)
    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:498)
    at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:282)
    at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:279)
    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:314)
    at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:170)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:225)
    at org.apache.catalina.core.ApplicationFilterChain.access$000(ApplicationFilterChain.java:47)
    at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:149)
    at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:145)
    at java.security.AccessController.doPrivileged(Native Method)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:144)
    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:498)
    at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:282)
    at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:279)
    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:314)
    at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:253)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:191)
    at org.apache.catalina.core.ApplicationFilterChain.access$000(ApplicationFilterChain.java:47)
    at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:149)
    at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:145)
    at java.security.AccessController.doPrivileged(Native Method)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:144)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:496)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
    at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:650)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
    at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803)
    at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
    at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:790)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1459)
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:748)

snipped from KRA debug log:

2018-07-27 10:59:06 [https-jsse-nio-8443-exec-20] INFO: ConfigurationUtils: POST https://replica0.ipa.test:443/kra/admin/kra/updateNumberRange
2018-07-27 10:59:06 [https-jsse-nio-8443-exec-20] FINE: Server certificate:
2018-07-27 10:59:06 [https-jsse-nio-8443-exec-20] FINE: - subject: CN=replica0.ipa.test,O=IPA.TEST
2018-07-27 10:59:06 [https-jsse-nio-8443-exec-20] FINE: - issuer: CN=Certificate Authority,O=IPA.TEST
2018-07-27 10:59:06 [https-jsse-nio-8443-exec-20] FINE: content from admin interface =<?xml version="1.0" encoding="UTF-8" standalone="no"?><XMLResponse><Status>1</Status><Error>Error: Failed to update number range.</Error></XMLResponse>
2018-07-27 10:59:07 [https-jsse-nio-8443-exec-20] FINE: updateNumberRange(): status=1
2018-07-27 10:59:07 [https-jsse-nio-8443-exec-20] SEVERE: Configuration failed: Error: Failed to update number range.
java.io.IOException: Error: Failed to update number range.

I think we need input from @ftweedal or @edewata

I'll try and reproduce tomorrow, and if successful pursue the fix.

Was not able to reproduce. I will now have a closer look at logs. It may be a replication race
caused by slow CI environment.

On further investigation it doesn't seem to be a race. Rather we see in the log for replica0.ipa.test (the master the clone-in-progress is contacting):

2018-07-27 10:59:06 [ajp-nio-127.0.0.1-8009-exec-1] FINE: Repository:In getTheSerialNumber 
2018-07-27 10:59:06 [ajp-nio-127.0.0.1-8009-exec-1] FINE: UpdateNumberRange: Failed to update number range: java.lang.NullPointerException
2018-07-27 10:59:06 [ajp-nio-127.0.0.1-8009-exec-1] WARNING: java.lang.NullPointerException
    at java.math.BigInteger.compareTo(BigInteger.java:3519)
    at com.netscape.cms.servlet.csadmin.UpdateNumberRange.process(UpdateNumberRange.java:190)

From reading the code, the only way I can see how this would arise is when
the master's request range configuration is messed up, with "last serial number" >=
"max serial number". The logs do not support this, but then again, the logs do
not necessarily tell the whole story. I have a theory about how this is happening.
I need to test the theory, and if substantiated it would be a complex issue to fix.

The theory is:

  • the updateNumberRange procedure consumes part of the contacted master's request range. The size of the "gifted" range is fixed.
  • the original master has sufficient range that it can gift to many replicas with no operational impact
  • but because the size of the gifted range is fixed, creating a clone from a clone steals its entire range.
  • therefore, if B clones from A, then C clones from B, B's range is fully depleted. Attempting to create another clone from B fails.
  • side note: the logs don't reveal this fact because, although initial ranges are logged at startup, range adjustments during runtime (e.g. as result of servicing an updateNumberRange request) are not logged.

The workaround implied by this theory is to create all clones from the original master.
Of course, we must support creating clones from clones and that is what this test is
checking, so we still have to fix it.
Edited 6 years ago by ftweedal

Metadata Update from @ftweedal:
- Issue assigned to ftweedal
6 years ago

I'm pushing this to 4.7 backlog unless you'll be able to solve it in upcoming week(s).

Metadata Update from @abbra:
- Issue set to the milestone: FreeIPA 4.7 backlog
6 years ago

@abbra: I'm working on it; hold off a couple of days and we'll see how I go.

Metadata Update from @ftweedal:
- Custom field blockedby adjusted to https://pagure.io/dogtagpki/issue/3055
6 years ago

master:

  • 2488813 ipatests: mark known failures as xfail

ipa-4-7:

  • 9564fff ipatests: mark known failures as xfail

Metadata Update from @tdudlak:
- Issue close_status updated to: fixed
- Issue status updated to: Closed (was: Open)
6 years ago

I am re-opening the issue as the above commit only marks the tests as known failure. We are still waiting for a fix on dogtag side and will need to bump pki version when the fix is available.

Metadata Update from @frenaud:
- Issue status updated to: Open (was: Closed)
6 years ago

Fix was pushed to Dogtag master:

* 128628693d51adf753750f7ac1307ec246822db9 Add missing synchronisation for range management
* 44be5837503efa4b2b44718379ebaebcebd805ab UpdateNumberRange: improve logging, add commentary
* 925ef2637f01d5aff0306d9b70c8a6b916d8b74e checkRange: small refactor and add commentary
* 3b57d324ed9eea61b828aea4801ac7abe8139859 rename method getTheSerialNumber -> peekNextSerialNumber
* 8011d2d74ad40142b1762e514d3db58d69fb89b0 Repository: handle depleted range in initCache()
* b5ddac86a266bbb9dbd3cb70c70c9de0b2dcc0e7 getTheSerialNumber: only return null if next range not available

After we cut a Dogtag release with these fixes we can bump the dep, restore the test, and close this issue.

Dogtag v10.6.7 was tagged (ee92a50f47652b56320a5faf78a3f443faef3b15) but no build yet.

pki-core-10.6.7-1 is now in updates-testing for f28 and f29.
PR: https://github.com/freeipa/freeipa/pull/2436

Metadata Update from @ftweedal:
- Custom field on_review adjusted to https://github.com/freeipa/freeipa/pull/2436
6 years ago

@ftweedal What's the status of the update? https://bodhi.fedoraproject.org/updates/FEDORA-2018-83e180a755 is blocked by a failing integration test.

I have build 10.6.7 on COPR and ran into https://pagure.io/dogtagpki/issue/3073. I have now removed the 10.6.7 build and gave negative Karma to the update. We have to wait for 10.6.8.

Thanks for the update (and the Dogtag patch!) @cheimes.

master:

  • 4b920df Restore KRA clone installation integration test
  • ec208e9 Require Dogtag 10.6.7-3

ipa-4-7:

  • 0344354 Restore KRA clone installation integration test
  • 795fe62 Require Dogtag 10.6.7-3

Metadata Update from @cheimes:
- Issue close_status updated to: fixed
- Issue status updated to: Closed (was: Open)
5 years ago

master:

  • 07e6d51 Require Dogtag PKI 10.6.8-3

ipa-4-7:

  • 8d746c8 Require Dogtag PKI 10.6.8-3

Log in to comment on this ticket.

Metadata

test-failure

None
None
important
None
None
None
None
None
https://pagure.io/dogtagpki/issue/3055
None
None
None
https://github.com/freeipa/freeipa/pull/2436
None
None
None
None
None
None
None
None
Powered by Pagure 5.14.1
Documentation • File an Issue • About • SSH Hostkey/Fingerprint
© Red Hat, Inc. and others.