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")
Also seen in PR #358, report, logs.
@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.
ipa-server-install
pkispawn
Endi has a similar error that manifested after I merged some v10.9 patches for JDK11 support, but his are on F31 running JDK8:
v10.9
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.
journalctl
/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
(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.
This is identical to https://pagure.io/dogtagpki/issue/3208
@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.
Subscribe
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)
Login to comment on this ticket.