pki
pki copied to clipboard
dogtagpki
Nightly test failure in freeipa during ipa-replica-install
This issue was migrated from Pagure Issue #3182. Originally filed by frenaud (@flo-renaud) on 2020-06-29 10:39:14:
- Assigned to nobody
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
Comment from frenaud (@flo-renaud) at 2020-07-02 03:31:24
Also happened in PR #268 using fedora 32 + updates repo. Logs availble here
Comment from frenaud (@flo-renaud) at 2020-08-01 08:08:27
Also in PR #319 during the KRA installation. Logs available here
Comment from frenaud (@flo-renaud) at 2020-08-10 03:35:55
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")
Comment from frenaud (@flo-renaud) at 2020-08-26 13:39:30
@SilleBille @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?
Comment from cipherboy (@cipherboy) at 2020-08-27 11:12:24
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.
Comment from cipherboy (@cipherboy) at 2020-08-27 11:12:25
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
Comment from cipherboy (@cipherboy) at 2020-08-27 11:14:50
(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+).
Comment from frenaud (@flo-renaud) at 2020-08-28 04:20:03
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.
Comment from fcami (@fcami) at 2020-09-03 04:07:04
This is identical to https://pagure.io/dogtagpki/issue/3208
Comment from edewata (@edewata) at 2020-09-03 10:11:23
@csutherl, have you seen this intermittent AccessControlException when loading web application libraries? Any idea what might have caused it?
Comment from csutherl at 2020-09-03 14:52:19
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.
Comment from frenaud (@flo-renaud) at 2020-09-17 05:55:14
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.
@csutherl @cipherboy if you want us to temporarily change the JRE stanza in /usr/share/pki/server/conf/tomcat.conf from:
JAVA_OPTS="-Dcom.redhat.fips=false"
to:
JAVA_OPTS="-Dcom.redhat.fips=false -Djava.security.debug=access:failure"
Let me know.
This issue hasn't been seen in a while, you can close it. We will reopen if needed.
