FreeIPA nightly tests failure when installing a CA replica (pki nightly) #3330

pki-bot · 2020-10-03T02:46:21Z

This issue was migrated from Pagure Issue #3213. Originally filed by frenaud (@flo-renaud) on 2020-09-22 03:19:01:

Assigned to nobody

2 nightly tests using pki's nightly copr repo failed in ipa-replica-install, see PR #421:

test_replication_layouts_TestLineTopologyWithCA: report, logs
test_replication_layouts_TestLineTopologyWithCAKRA: report, logs

The replica installation fails in the pkispawn step with the following message:

Installation failed: Command failed: pki -d /etc/pki/pki-tomcat/alias -f /etc/pki/pki-tomcat/password.conf -U https://replica0.ipa.test:443 ca-range-request request --session 3460448776536667421 --output-format json --debug

Please check pkispawn logs in /var/log/pki/pki-ca-spawn.20200921215144.log

and we also see the following in the logs:

INFO: Requesting request range
INFO: HTTP request: POST /ca/admin/ca/updateNumberRange HTTP/1.1
INFO:   Content-Type: application/x-www-form-urlencoded
INFO:   Content-Length: 57
INFO:   Host: replica0.ipa.test:443
INFO:   Connection: Keep-Alive
INFO:   User-Agent: Apache-HttpClient/4.5.10 (Java/1.8.0_265)
INFO: HTTP response: HTTP/1.1 200 200
INFO:   Date: Mon, 21 Sep 2020 21:52:20 GMT
INFO:   Server: Apache/2.4.46 (Fedora) OpenSSL/1.1.1g mod_wsgi/4.6.8 Python/3.8 mod_auth_gssapi/1.6.1
INFO:   Content-Type: application/xml
INFO:   Content-Length: 174
INFO:   Keep-Alive: timeout=30, max=99
INFO:   Connection: Keep-Alive
FINE: Response: <?xml version="1.0" encoding="UTF-8" standalone="no"?><XMLResponse><Status>1</Status><Error>Error: Unable to update number range: Zero length BigInteger</Error></XMLResponse>
FINE: Status: 1
java.io.IOException: Error: Unable to update number range: Zero length BigInteger
	at com.netscape.certsrv.client.SubsystemClient.requestRange(SubsystemClient.java:133)
	at com.netscape.cmstools.range.RangeRequestCLI.execute(RangeRequestCLI.java:62)
	at org.dogtagpki.cli.CommandCLI.execute(CommandCLI.java:57)
	at org.dogtagpki.cli.CLI.execute(CLI.java:352)
	at org.dogtagpki.cli.CLI.execute(CLI.java:352)
	at com.netscape.cmstools.cli.SubsystemCLI.execute(SubsystemCLI.java:76)
	at org.dogtagpki.cli.CLI.execute(CLI.java:352)
	at com.netscape.cmstools.cli.MainCLI.execute(MainCLI.java:688)
	at com.netscape.cmstools.cli.MainCLI.main(MainCLI.java:724)
ERROR: CalledProcessError: Command '['pki', '-d', '/etc/pki/pki-tomcat/alias', '-f', '/etc/pki/pki-tomcat/password.conf', '-U', 'https://replica0.ipa.test:443', 'ca-range-request', 'request', '--session', '3460448776536667421', '--output-format', 'json', '--debug']' returned non-zero exit status 255.
  File "/usr/lib/python3.8/site-packages/pki/server/pkispawn.py", line 575, in main
    scriptlet.spawn(deployer)
  File "/usr/lib/python3.8/site-packages/pki/server/deployment/scriptlets/configuration.py", line 821, in spawn
    subsystem.update_ranges(master_url, deployer.install_token)
  File "/usr/lib/python3.8/site-packages/pki/server/subsystem.py", line 991, in update_ranges
    request_range = self.request_range(master_url, 'request', install_token)
  File "/usr/lib/python3.8/site-packages/pki/server/subsystem.py", line 983, in request_range
    output = subprocess.check_output(cmd)
  File "/usr/lib64/python3.8/subprocess.py", line 411, in check_output
    return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
  File "/usr/lib64/python3.8/subprocess.py", line 512, in run
    raise CalledProcessError(retcode, process.args,

The same error can be seen in the server used as source for the CA replication in /var/log/pki/pki-tomcat/ca/debug.2020-09-21.log.gz :

2020-09-21 21:52:21 [ajp-nio-127.0.0.1-8009-exec-5] INFO: UpdateNumberRange: Type: request
2020-09-21 21:52:21 [ajp-nio-127.0.0.1-8009-exec-5] INFO: UpdateNumberRange: Getting request repository
2020-09-21 21:52:21 [ajp-nio-127.0.0.1-8009-exec-5] INFO: UpdateNumberRange: dbs.endRequestNumber: 10000000
2020-09-21 21:52:21 [ajp-nio-127.0.0.1-8009-exec-5] INFO: UpdateNumberRange: dbs.requestCloneTransferNumber: 10000
2020-09-21 21:52:21 [ajp-nio-127.0.0.1-8009-exec-5] INFO: UpdateNumberRange: Begin number: 9990001
2020-09-21 21:52:21 [ajp-nio-127.0.0.1-8009-exec-5] INFO: Configured transfer size: 10000
2020-09-21 21:52:21 [ajp-nio-127.0.0.1-8009-exec-5] INFO: UpdateNumberRange: Current range: 9990003..10000000
2020-09-21 21:52:21 [ajp-nio-127.0.0.1-8009-exec-5] INFO: UpdateNumberRange: Size: 9998
2020-09-21 21:52:21 [ajp-nio-127.0.0.1-8009-exec-5] SEVERE: UpdateNumberRange: Unable to update number range: Zero length BigInteger
java.lang.NumberFormatException: Zero length BigInteger
	at java.math.BigInteger.<init>(BigInteger.java:420)
	at com.netscape.cms.servlet.csadmin.UpdateNumberRange.process(UpdateNumberRange.java:225)
	at com.netscape.cms.servlet.base.CMSServlet.service(CMSServlet.java:494)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:741)
	at sun.reflect.GeneratedMethodAccessor42.invoke(Unknown Source)
	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:53)
	at sun.reflect.GeneratedMethodAccessor41.invoke(Unknown Source)
	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:202)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541)
	at com.netscape.cms.tomcat.ExternalAuthenticationValve.invoke(ExternalAuthenticationValve.java:82)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
	at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:690)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
	at org.apache.coyote.ajp.AjpProcessor.service(AjpProcessor.java:431)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1590)
	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)

Installed packages (full list here):

pki-server-10.10.0-0.1.alpha1.20200921191621UTC.14caa1fe.fc32.noarch
tomcat-9.0.36-1.fc32.noarch
tomcatjss-7.5.0-1.20200917180556UTC.18249585.fc32.noarch
jss-4.8.0-0.1.20200918204253UTC.6c40ee99.fc32.x86_64

The text was updated successfully, but these errors were encountered:

pki-bot · 2020-10-03T02:46:22Z

Comment from frenaud (@flo-renaud) at 2020-09-22 03:19:51

Companion issue logged against FreeIPA: https://pagure.io/freeipa/issue/8509

flo-renaud · 2020-11-26T13:53:53Z

The issue seems to happen when the 2nd replica is created (replica1 is cloned from master and replica2 is cloned from replica1).

cipherboy · 2020-11-26T15:20:30Z

This is probably a regression of #40 then?

In commit e0b2496 the configurePorts() invocation was moved to happen later during server startup process. It's not clear how, but apparently the replica ID range assignment depends on this code so it failed when installing a clone of an existing clone. To fix the problem the configurePorts() has been moved back into its original position. Resolves: dogtagpki#3330

In commit e0b2496 the configurePorts() invocation was moved to happen later during server startup process. It's not clear how, but apparently the cert number range assignment depends on this code so it failed when installing a clone of an existing clone. To fix the problem the configurePorts() has been moved back into its original position. Resolves: dogtagpki#3330

In commit e0b2496 the CMSEngine.configurePorts() invocation was moved later during server startup process. It's not clear how, but apparently the cert number range assignment depends on this code so it failed when installing a clone of an existing clone. To fix the problem the invocation has been moved back into its original position. Resolves: dogtagpki#3330

In commit e0b2496 the CMSEngine.configurePorts() invocation was moved later during server startup process. It's not clear how, but apparently the cert number range assignment depends on this code so it failed when installing a clone of an existing clone. To fix the problem the invocation has been moved back into its original position. Resolves: #3330

In commit e0b2496 the CMSEngine.configurePorts() invocation was moved later during server startup process. It's not clear how, but apparently the cert number range assignment depends on this code so it failed when installing a clone of an existing clone. To fix the problem the invocation has been moved back into its original position. Resolves: dogtagpki#3330

In commit e0b2496 the CMSEngine.configurePorts() invocation was moved later during server startup process. It's not clear how, but apparently the cert number range assignment depends on this code so it failed when installing a clone of an existing clone. To fix the problem the invocation has been moved back into its original position. Resolves: #3330

In commit e0b2496 the CMSEngine.configurePorts() invocation was moved later during server startup process. It's not clear how, but apparently the cert number range assignment depends on this code so it failed when installing a clone of an existing clone. To fix the problem the invocation has been moved back into its original position. Resolves: dogtagpki#3330

flo-renaud mentioned this issue Oct 7, 2020

[testing_master_pki] Nightly PR freeipa-pr-ci2/freeipa#455

Closed

This was referenced Oct 23, 2020

[testing_master_pki] Nightly PR freeipa-pr-ci2/freeipa#483

Closed

[testing_master_pki] Nightly PR freeipa-pr-ci2/freeipa#498

Closed

This was referenced Nov 2, 2020

[testing_master_pki] Nightly PR freeipa-pr-ci2/freeipa#511

Closed

[testing_master_pki] Nightly PR freeipa-pr-ci2/freeipa#523

Closed

This was referenced Nov 15, 2020

[testing_master_389ds] Nightly PR freeipa-pr-ci2/freeipa#532

Closed

[testing_master_testing] Nightly PR freeipa-pr-ci2/freeipa#533

Closed

This was referenced Nov 18, 2020

[testing_master_pki] Nightly PR freeipa-pr-ci2/freeipa#535

Closed

[testing_master_pki] Nightly PR freeipa-pr-ci2/freeipa#548

Closed

amore17 mentioned this issue Nov 30, 2020

[testing_master_pki] Nightly PR freeipa-pr-ci2/freeipa#560

Closed

This was referenced Jan 12, 2021

[testing_master_pki] Nightly PR freeipa-pr-ci2/freeipa#641

Closed

[testing_master_pki] Nightly PR freeipa-pr-ci2/freeipa#653

Closed

amore17 mentioned this issue Jan 27, 2021

[testing_master_pki] Nightly PR freeipa-pr-ci2/freeipa#671

Closed

edewata mentioned this issue Jan 29, 2021

Fix clone of clone installation #3447

Merged

edewata closed this as completed in #3447 Jan 29, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

FreeIPA nightly tests failure when installing a CA replica (pki nightly) #3330

FreeIPA nightly tests failure when installing a CA replica (pki nightly) #3330

pki-bot commented Oct 3, 2020

pki-bot commented Oct 3, 2020

flo-renaud commented Nov 26, 2020

cipherboy commented Nov 26, 2020

FreeIPA nightly tests failure when installing a CA replica (pki nightly) #3330

FreeIPA nightly tests failure when installing a CA replica (pki nightly) #3330

Comments

pki-bot commented Oct 3, 2020

pki-bot commented Oct 3, 2020

flo-renaud commented Nov 26, 2020

cipherboy commented Nov 26, 2020