#3182 Nightly test failure in freeipa during ipa-replica-install
Closed: migrated 3 years ago by dmoluguw. Opened 3 years ago by frenaud.

The nightly tests for freeipa (using the repo updates-testing) failed in ipa-ca-install on the replica, in the pkispawn step.
See the PR 262 with the logs for test_clrgen_manage test.

Logs on the replica for pki-ca-spawn :

2020-06-28 04:53:16 ERROR: CalledProcessError: Command '['pki', '-d', '/etc/pki/pki-tomcat/alias', '-U', 'https://master.ipa.test:443', 'ca-range-request', 'request', '--session', '7410956800213774495', '--output-format', 'json']' returned non-zero exit status 255.
  File "/usr/lib/python3.8/site-packages/pki/server/pkispawn.py", line 569, in main
    scriptlet.spawn(deployer)
  File "/usr/lib/python3.8/site-packages/pki/server/deployment/scriptlets/configuration.py", line 854, in spawn
    subsystem.update_ranges(master_url, deployer.install_token)
  File "/usr/lib/python3.8/site-packages/pki/server/subsystem.py", line 971, 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 963, 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,

Logs on the master for the corresponding call pki/pki-tomcat/pki/debug:

2020-06-28 04:53:16 [ajp-nio-127.0.0.1-8009-exec-9] SEVERE: Servlet.init() for servlet [Resteasy] threw exception
java.lang.RuntimeException: RESTEASY003325: Failed to construct public org.dogtagpki.server.rest.PKIApplication()
    at org.jboss.resteasy.core.ConstructorInjectorImpl.construct(ConstructorInjectorImpl.java:162)
    at org.jboss.resteasy.spi.ResteasyProviderFactory.createProviderInstance(ResteasyProviderFactory.java:2300)
    at org.jboss.resteasy.spi.ResteasyDeployment.createApplication(ResteasyDeployment.java:341)
    at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.init(ServletContainerDispatcher.java:103)
    at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.init(HttpServletDispatcher.java:36)
    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.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:123)
    at org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:1122)
    at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1089)
    at org.apache.catalina.core.StandardWrapper.allocate(StandardWrapper.java:761)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:135)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541)
    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)
Caused by: java.lang.ExceptionInInitializerError
    at org.dogtagpki.server.rest.PKIApplication.<init>(PKIApplication.java:41)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
    at org.jboss.resteasy.core.ConstructorInjectorImpl.construct(ConstructorInjectorImpl.java:150)
    ... 35 more
Caused by: java.lang.IllegalStateException: Unexpected initialization failure
    at org.slf4j.LoggerFactory.bind(LoggerFactory.java:175)
    at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:124)
    at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:417)
    at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:362)
    at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:388)
    at org.dogtagpki.server.rest.MessageFormatInterceptor.<clinit>(MessageFormatInterceptor.java:41)
    ... 41 more
Caused by: java.security.AccessControlException: access denied ("java.io.FilePermission" "/usr/share/pki/server/webapps/pki/WEB-INF/lib/slf4j-jdk14.jar" "read")
    at java.security.AccessControlContext.checkPermission(AccessControlContext.java:472)
    at java.security.AccessController.checkPermission(AccessController.java:886)
    at java.lang.SecurityManager.checkPermission(SecurityManager.java:549)
    at java.lang.SecurityManager.checkRead(SecurityManager.java:888)
    at java.util.zip.ZipFile.<init>(ZipFile.java:216)
    at java.util.zip.ZipFile.<init>(ZipFile.java:155)
    at java.util.jar.JarFile.<init>(JarFile.java:166)
    at java.util.jar.JarFile.<init>(JarFile.java:130)
    at org.apache.tomcat.util.compat.JreCompat.jarFileNewInstance(JreCompat.java:221)
    at org.apache.tomcat.util.compat.JreCompat.jarFileNewInstance(JreCompat.java:206)
    at org.apache.catalina.webresources.AbstractArchiveResourceSet.openJarFile(AbstractArchiveResourceSet.java:307)
    at org.apache.catalina.webresources.AbstractSingleArchiveResourceSet.getArchiveEntry(AbstractSingleArchiveResourceSet.java:97)
    at org.apache.catalina.webresources.AbstractArchiveResourceSet.getResource(AbstractArchiveResourceSet.java:256)
    at org.apache.catalina.webresources.StandardRoot.getResourcesInternal(StandardRoot.java:327)
    at org.apache.catalina.webresources.CachedResource.validateResources(CachedResource.java:158)
    at org.apache.catalina.webresources.Cache.getResources(Cache.java:147)
    at org.apache.catalina.webresources.StandardRoot.getResources(StandardRoot.java:315)
    at org.apache.catalina.webresources.StandardRoot.getClassLoaderResources(StandardRoot.java:231)
    at org.apache.catalina.loader.WebappClassLoaderBase.findResources(WebappClassLoaderBase.java:991)
    at org.apache.catalina.loader.WebappClassLoaderBase.getResources(WebappClassLoaderBase.java:1086)
    at org.slf4j.LoggerFactory.findPossibleStaticLoggerBinderPathSet(LoggerFactory.java:308)
    at org.slf4j.LoggerFactory.bind(LoggerFactory.java:146)
    ... 46 more

Please note the exception also reported in the master's journal:

java.security.AccessControlException: access denied ("java.io.FilePermission" "/usr/share/pki/server/webapps/pki/WEB-INF/lib/slf4j-jdk14.jar" "read")

Installed versions:
- pki-base-10.9.0-0.2.fc32.noarch
- tomcatjss-7.5.0-0.1.fc32.noarch
- tomcat-9.0.36-1.fc32.noarch
- slf4j-1.7.30-2.fc32.noarch
- java-1.8.0-openjdk-headless-1.8.0.252.b09-1.fc32.x86_64


Also happened in PR #268 using fedora 32 + updates repo. Logs availble here

And also in PR #278. Logs available here

Also in PR #319 during the KRA installation. Logs available here

Similar issue seen in PR #335 during ipa-kra-install (setup of a clone KRA), using ipa-4-8 on fedora32 with the following logs:

java.security.AccessControlException: access denied ("java.io.FilePermission" "/usr/share/pki/server/webapps/pki/WEB-INF/lib/pki-cmsbundle.jar" "read")

@dmoluguw @cipherboy
the issue is not always happening but has been seen multiple times over the last 2 months. Do you have any idea what could be the root cause?

No; I've looked out for it when trying ipa-server-install and pkispawn across F31, F32, F32->F33 upgrades, and clean rawhide (F33/F34) installs as well. I've not been able to reproduce it on any of my virtual machines. They all start from a "clean" base image I keep with a minimal set of packages and users installed to allow me to run ansible scripts against them.

Endi has a similar error that manifested after I merged some v10.9 patches for JDK11 support, but his are on F31 running JDK8:

2020-08-24 09:49:24 [main] WARNING: Failed to scan [file:/usr/share/java/glassfish-jaxb/txw2-2.2.11.jar] from classloader hierarchy
java.io.FileNotFoundException: /usr/share/java/glassfish-jaxb/txw2-2.2.11.jar (No such file or directory)
        at java.util.zip.ZipFile.open(Native Method)
        at java.util.zip.ZipFile.<init>(ZipFile.java:225)
        at java.util.zip.ZipFile.<init>(ZipFile.java:155)
        at java.util.jar.JarFile.<init>(JarFile.java:166)
        at java.util.jar.JarFile.<init>(JarFile.java:130)
        ...

This is because we now include an intentionally broken symlink on F31/F32:

lrwxrwxrwx.  1 root root system_u:object_r:lib_t:s0   22 Aug 27 10:00 jaxb-impl.jar -> JAXB_IMPL_JAR-NOTFOUND

However, I haven't been able to reproduce his issue either; all I get on my machines is:

Aug 27 10:44:00 fedora31-base server[47022]: WARNING: Problem with JAR file [/usr/share/pki/server/common/lib/jaxb-impl.jar], exists: [false], canRead: [false]

And there is no associated stack trace. The above message shows up in journalctl, and no related messages show up under /var/log/pki.


If either of you can get a VM with this issue reproducible, I'd be happy to take a look.

Metadata Update from @cipherboy:
- Custom field component adjusted to None
- Custom field feature adjusted to None
- Custom field origin adjusted to None
- Custom field proposedmilestone adjusted to None
- Custom field proposedpriority adjusted to None
- Custom field reviewer adjusted to None
- Custom field type adjusted to None
- Custom field version adjusted to None

3 years ago

(To clarify, by "now include ... on F31/F32" -- this is in upstream COPR; I have intentions of pushing a build to F31->F34 with these changes once we fix the upgrade path from {F31,F32} -> F33+).

Please see an additional failure in https://pagure.io/freeipa/issue/8476 with initial investigations. This time, the permission issue is reported on /usr/share/pki/server/webapps/pki/WEB-INF/lib/pki-cmsbundle.jar.

@csutherl, have you seen this intermittent AccessControlException when loading web application libraries? Any idea what might have caused it?

I don't think I've ever seen an intermittent AccessControlException. In my experience as long as the java security policy allows the file to be read it works :) Maybe there is something going on in the classloading that's causing that to be missed somehow though; I'll look into it a bit and see what I can find.

Also happened inPR #410 on fedora32, see the report and logs.

The failure happens in ipa-replica-install in the step configuring the KRA with pkispawn.

Dogtag PKI is moving from Pagure issues to GitHub issues. This means that existing or new
issues will be reported and tracked through Dogtag PKI's GitHub Issue tracker.

This issue has been cloned to GitHub and is available here:
https://github.com/dogtagpki/pki/issues/3299

If you want to receive further updates on the issue, please navigate to the
GitHub issue and click on Subscribe button.

Thank you for understanding, and we apologize for any inconvenience.

Metadata Update from @dmoluguw:
- Issue close_status updated to: migrated
- Issue status updated to: Closed (was: Open)

3 years ago

Login to comment on this ticket.

Metadata