Bug 1717230
| Summary: | dogtag stopped working after dnf update (and continued not to work on upgrade to Fedora 30) | ||
|---|---|---|---|
| Product: | [Fedora] Fedora | Reporter: | Adam Williamson <awilliam> |
| Component: | pki-core | Assignee: | Matthew Harmsen <mharmsen> |
| Status: | CLOSED DUPLICATE | QA Contact: | Fedora Extras Quality Assurance <extras-qa> |
| Severity: | urgent | Docs Contact: | |
| Priority: | unspecified | ||
| Version: | 29 | CC: | alee, ascheel, dmoluguw, edewata, kwright, mharmsen |
| Target Milestone: | --- | ||
| Target Release: | --- | ||
| Hardware: | All | ||
| OS: | All | ||
| Whiteboard: | |||
| Fixed In Version: | Doc Type: | If docs needed, set a value | |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2019-06-05 00:12:29 UTC | Type: | Bug |
| Regression: | --- | Mount Type: | --- |
| Documentation: | --- | CRM: | |
| Verified Versions: | Category: | --- | |
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
| Cloudforms Team: | --- | Target Upstream Version: | |
| Embargoed: | |||
sorry, managed to file this twice... *** This bug has been marked as a duplicate of bug 1717229 *** |
Today I upgraded my FreeIPA server to Fedora 30 and FreeIPA stopped working. At least, that's what I thought happened. On closer inspection it's a bit more complicated. In fact, I started with a Fedora 29 system that wasn't fully up to date. I ran 'dnf update' to update it to latest Fedora 29 before upgrading, as you're supposed to do. That resulted in lots of stuff getting updated - I'll attach a full list, but the highlights: ========= 2019-06-04T19:31:59Z DEBUG ---> Package 389-ds-base.x86_64 1.4.0.16-1.fc29 will be upgraded 2019-06-04T19:31:59Z DEBUG ---> Package 389-ds-base.x86_64 1.4.0.22-1.fc29 will be an upgrade 2019-06-04T19:31:59Z DEBUG ---> Package bind-libs.x86_64 32:9.11.4-10.P2.fc29 will be upgraded 2019-06-04T19:31:59Z DEBUG ---> Package bind-libs.x86_64 32:9.11.5-4.P4.fc29 will be an upgrade 2019-06-04T19:31:59Z DEBUG ---> Package certmonger.x86_64 0.79.6-3.fc29 will be upgraded 2019-06-04T19:31:59Z DEBUG ---> Package certmonger.x86_64 0.79.7-1.fc29 will be an upgrade 2019-06-04T19:31:59Z DEBUG ---> Package freeipa-server.x86_64 4.7.0-3.fc29 will be upgraded 2019-06-04T19:31:59Z DEBUG ---> Package freeipa-server.x86_64 4.7.2-1.1.fc29 will be an upgrade 2019-06-04T19:31:59Z DEBUG ---> Package java-1.8.0-openjdk.x86_64 1:1.8.0.191.b12-11.fc29 will be upgraded 2019-06-04T19:31:59Z DEBUG ---> Package java-1.8.0-openjdk.x86_64 1:1.8.0.212.b04-0.fc29 will be an upgrade 2019-06-04T19:31:59Z DEBUG ---> Package krb5-libs.x86_64 1.16.1-21.fc29 will be upgraded 2019-06-04T19:31:59Z DEBUG ---> Package krb5-libs.x86_64 1.16.1-25.fc29 will be an upgrade 019-06-04T19:31:59Z DEBUG ---> Package openldap.x86_64 2.4.46-9.fc29 will be upgraded 2019-06-04T19:31:59Z DEBUG ---> Package openldap.x86_64 2.4.46-10.fc29 will be an upgrade 2019-06-04T19:31:59Z DEBUG ---> Package pki-base.noarch 10.6.6-2.fc29 will be upgraded 2019-06-04T19:31:59Z DEBUG ---> Package pki-base.noarch 10.7.0-1.fc29 will be an upgrade 2019-06-04T19:32:00Z DEBUG ---> Package sssd.x86_64 2.0.0-4.fc29 will be upgraded 2019-06-04T19:32:00Z DEBUG ---> Package sssd.x86_64 2.1.0-2.fc29 will be an upgrade 2019-06-04T19:32:00Z DEBUG ---> Package tomcat.noarch 1:9.0.10-1.fc29 will be upgraded 2019-06-04T19:32:00Z DEBUG ---> Package tomcat.noarch 1:9.0.13-1.fc29 will be an upgrade ======= Stupidly, after doing this, I didn't check that FreeIPA was still working. I just went right ahead and upgraded to Fedora 30, and found that on the upgraded system...it wasn't working. The first obvious problem was that httpd wouldn't start because mod_nss was installed and both tomcat and mod_nss wanted port 8443. So I removed mod_nss, but then found things still weren't working. ipa.service does not start, because it tries to run ipa-server-upgrade, and that doesn't work. It fails at this point: ==== pki-tomcat configuration changed, restart pki-tomcat [Ensuring CA is using LDAPProfileSubsystem] [Migrating certificate profiles to LDAP] IPA server upgrade failed: Inspect /var/log/ipaupgrade.log and run command ipa-server-upgrade manually. ==== The ipaupgrade.log shows this: ==== 2019-06-04T21:36:09Z DEBUG response body (decoded): b'<!doctype html><html lang="en"><head><title>HTTP Status 500 \xe2\x80\x93 Internal Server Error</title><style type="text/css">h1 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:22px;} h2 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:16px;} h3 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:14px;} body {font-family:Tahoma,Arial,sans-serif;color:black;background-color:white;} b {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;} p {font-family:Tahoma,Arial,sans-serif;background:white;color:black;font-size:12px;} a {color:black;} a.name {color:black;} .line {height:1px;background-color:#525D76;border:none;}</style></head><body><h1>HTTP Status 500 \xe2\x80\x93 Internal Server Error</h1><hr class="line" /><p><b>Type</b> Exception Report</p><p><b>Message</b> Subsystem unavailable</p><p><b>Description</b> The server encountered an unexpected condition that prevented it from fulfilling the request.</p><p><b>Exception</b></p><pre>javax.ws.rs.ServiceUnavailableException: Subsystem unavailable\n\tcom.netscape.cms.tomcat.ProxyRealm.findSecurityConstraints(ProxyRealm.java:150)\n\torg.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:479)\n\torg.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)\n\torg.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)\n\torg.apache.coyote.http11.Http11Processor.service(Http11Processor.java:408)\n\torg.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)\n\torg.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:791)\n\torg.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1417)\n\torg.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)\n\tjava.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)\n\tjava.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)\n\torg.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)\n\tjava.lang.Thread.run(Thread.java:748)\n</pre><p><b>Note</b> The full stack trace of the root cause is available in the server logs.</p><hr class="line" /><h3>Apache Tomcat/9.0.13</h3></body></html>' 2019-06-04T21:36:09Z ERROR IPA server upgrade failed: Inspect /var/log/ipaupgrade.log and run command ipa-server-upgrade manually. ... 2019-06-04T21:36:09Z DEBUG The ipa-server-upgrade command failed, exception: RemoteRetrieveError: Failed to authenticate to CA REST API ==== Which points to 'CA REST API', i.e. dogtag. Looking at dogtag logs, we see this: ==== 04-Jun-2019 14:35:55.508 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version: Apache Tomcat/9.0.13 04-Jun-2019 14:35:55.511 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built: Feb 3 2019 10:05:35 UTC 04-Jun-2019 14:35:55.513 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server number: 9.0.13.0 04-Jun-2019 14:35:55.516 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name: Linux 04-Jun-2019 14:35:55.519 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version: 5.1.5-300.fc30.x86_64 04-Jun-2019 14:35:55.522 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Architecture: amd64 04-Jun-2019 14:35:55.526 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Java Home: /usr/lib/jvm/java-1.8.0-openjdk-1.8.0.212.b04-0.fc30.x86_64/jre 04-Jun-2019 14:35:55.530 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version: 1.8.0_212-b04 04-Jun-2019 14:35:55.534 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor: Oracle Corporation 04-Jun-2019 14:35:55.535 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE: /var/lib/pki/pki-tomcat 04-Jun-2019 14:35:55.538 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME: /usr/share/tomcat 04-Jun-2019 14:35:55.540 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -DRESTEASY_LIB=/usr/share/java/resteasy 04-Jun-2019 14:35:55.542 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.base=/var/lib/pki/pki-tomcat 04-Jun-2019 14:35:55.545 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.home=/usr/share/tomcat 04-Jun-2019 14:35:55.548 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.endorsed.dirs= 04-Jun-2019 14:35:55.548 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.io.tmpdir=/var/lib/pki/pki-tomcat/temp 04-Jun-2019 14:35:55.552 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.config.file=/var/lib/pki/pki-tomcat/conf/logging.properties 04-Jun-2019 14:35:55.553 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager 04-Jun-2019 14:35:55.558 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.security.manager 04-Jun-2019 14:35:55.571 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.security.policy==/var/lib/pki/pki-tomcat/conf/catalina.policy 04-Jun-2019 14:35:55.787 INFO [main] org.dogtagpki.tomcat.JSSListener.initJSS JSSListener: Initializing JSS 04-Jun-2019 14:35:55.791 INFO [main] org.dogtagpki.tomcat.JSSListener.initJSS JSSListener: Config: null 04-Jun-2019 14:35:55.914 INFO [main] org.apache.tomcat.util.net.jss.TomcatJSS.init TomcatJSS: initialization 04-Jun-2019 14:35:55.937 INFO [main] org.mozilla.jss.CryptoManager.<clinit> CryptoManager: loading JSS library 04-Jun-2019 14:35:55.949 INFO [main] org.mozilla.jss.CryptoManager.<clinit> CryptoManager: loaded JSS library from /usr/lib64/jss/libjss4.so 04-Jun-2019 14:35:55.951 INFO [main] org.mozilla.jss.CryptoManager.initialize CryptoManager: initializing NSS database at /var/lib/pki/pki-tomcat/alias 04-Jun-2019 14:35:56.055 INFO [main] org.apache.tomcat.util.net.jss.TomcatJSS.configureOCSP configuring OCSP 04-Jun-2019 14:35:56.086 INFO [main] org.apache.tomcat.util.net.jss.TomcatJSS.init TomcatJSS: initialization complete 04-Jun-2019 14:35:56.260 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-nio-8080"] 04-Jun-2019 14:35:56.308 INFO [main] org.apache.tomcat.util.net.NioSelectorPool.getSharedSelector Using a shared selector for servlet write/read 04-Jun-2019 14:35:56.327 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["https-jsse-nio-8443"] 04-Jun-2019 14:35:56.863 INFO [main] org.apache.tomcat.util.net.NioSelectorPool.getSharedSelector Using a shared selector for servlet write/read 04-Jun-2019 14:35:56.868 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["ajp-nio-127.0.0.1-8009"] 04-Jun-2019 14:35:56.874 INFO [main] org.apache.tomcat.util.net.NioSelectorPool.getSharedSelector Using a shared selector for servlet write/read 04-Jun-2019 14:35:56.885 INFO [main] org.apache.catalina.startup.Catalina.load Initialization processed in 2891 ms 04-Jun-2019 14:35:57.015 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service [Catalina] 04-Jun-2019 14:35:57.024 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet Engine: Apache Tomcat/9.0.13 04-Jun-2019 14:35:57.072 INFO [main] org.apache.catalina.startup.HostConfig.deployDescriptor Deploying deployment descriptor [/etc/pki/pki-tomcat/Catalina/localhost/ROOT.xml] 04-Jun-2019 14:36:00.989 INFO [main] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time. 04-Jun-2019 14:36:01.081 INFO [main] org.apache.catalina.startup.HostConfig.deployDescriptor Deployment of deployment descriptor [/etc/pki/pki-tomcat/Catalina/localhost/ROOT.xml] has finished in [4,003] ms 04-Jun-2019 14:36:01.084 INFO [main] org.apache.catalina.startup.HostConfig.deployDescriptor Deploying deployment descriptor [/etc/pki/pki-tomcat/Catalina/localhost/ca.xml] 04-Jun-2019 14:36:01.106 INFO [main] com.netscape.cms.tomcat.AbstractPKIAuthenticator.<init> PKIAuthenticator: Creating SSLAuthenticatorWithFallback 04-Jun-2019 14:36:04.990 INFO [main] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time. 04-Jun-2019 14:36:05.520 SEVERE [main] com.netscape.cms.servlet.base.CMSStartServlet.init Unable to create CMS engine: com.netscape.cmscore.apps.CMSEngine java.lang.InstantiationException: com.netscape.cmscore.apps.CMSEngine at java.lang.Class.newInstance(Class.java:427) at com.netscape.cms.servlet.base.CMSStartServlet.init(CMSStartServlet.java:138) at javax.servlet.GenericServlet.init(GenericServlet.java:158) 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:1112) at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1079) at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:971) at org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:4829) at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5143) at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:743) at org.apache.catalina.core.ContainerBase.access$000(ContainerBase.java:131) at org.apache.catalina.core.ContainerBase$PrivilegedAddChild.run(ContainerBase.java:152) at org.apache.catalina.core.ContainerBase$PrivilegedAddChild.run(ContainerBase.java:142) at java.security.AccessController.doPrivileged(Native Method) at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:717) at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:695) at org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:630) at org.apache.catalina.startup.HostConfig$DeployDescriptor.run(HostConfig.java:1840) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75) at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:112) at org.apache.catalina.startup.HostConfig.deployDescriptors(HostConfig.java:525) at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:424) at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1585) at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:308) at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:123) at org.apache.catalina.util.LifecycleBase.setStateInternal(LifecycleBase.java:424) at org.apache.catalina.util.LifecycleBase.setState(LifecycleBase.java:367) at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:972) at org.apache.catalina.core.StandardHost.startInternal(StandardHost.java:831) at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1432) at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1422) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75) at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:134) at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:944) at org.apache.catalina.core.StandardEngine.startInternal(StandardEngine.java:261) at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) at org.apache.catalina.core.StandardService.startInternal(StandardService.java:422) at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) at org.apache.catalina.core.StandardServer.startInternal(StandardServer.java:801) at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) at org.apache.catalina.startup.Catalina.start(Catalina.java:695) 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.startup.Bootstrap.start(Bootstrap.java:350) at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:492) Caused by: java.lang.NoSuchMethodException: com.netscape.cmscore.apps.CMSEngine.<init>() at java.lang.Class.getConstructor0(Class.java:3082) at java.lang.Class.newInstance(Class.java:412) ... 61 more 04-Jun-2019 14:36:05.549 INFO [main] org.apache.catalina.startup.HostConfig.deployDescriptor Deployment of deployment descriptor [/etc/pki/pki-tomcat/Catalina/localhost/ca.xml] has finished in [4,466] ms 04-Jun-2019 14:36:05.550 INFO [main] org.apache.catalina.startup.HostConfig.deployDescriptor Deploying deployment descriptor [/etc/pki/pki-tomcat/Catalina/localhost/pki.xml] 04-Jun-2019 14:36:08.596 INFO [main] org.apache.catalina.startup.HostConfig.deployDescriptor Deployment of deployment descriptor [/etc/pki/pki-tomcat/Catalina/localhost/pki.xml] has finished in [3,046] ms 04-Jun-2019 14:36:08.608 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"] 04-Jun-2019 14:36:08.693 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["https-jsse-nio-8443"] 04-Jun-2019 14:36:08.751 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["ajp-nio-127.0.0.1-8009"] 04-Jun-2019 14:36:08.796 INFO [main] com.netscape.cms.tomcat.PKIListener.verifySubsystems PKIListener: Subsystem CA is running. 04-Jun-2019 14:36:08.809 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 11920 ms 04-Jun-2019 14:36:18.613 WARNING [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.core.ContainerBase.backgroundProcess Exception processing realm [com.netscape.cms.tomcat.ProxyRealm@4fb7ce8a] background process javax.ws.rs.ServiceUnavailableException: Subsystem unavailable at com.netscape.cms.tomcat.ProxyRealm.backgroundProcess(ProxyRealm.java:142) at org.apache.catalina.core.ContainerBase.backgroundProcess(ContainerBase.java:1165) at org.apache.catalina.core.StandardContext.backgroundProcess(StandardContext.java:5501) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1401) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1405) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1405) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1373) at java.lang.Thread.run(Thread.java:748) ==== and that's about as far as I've got. Now, ascheel asked me some good questions that led me to check the logs from *before* the F30 upgrade, and it turns out this problem actually started with the F29 update I ran before the F30 upgrade. That update started at 2019-06-04T19:31:51Z and finished at 2019-06-04T19:43:53Z , and in the system journal we see where this error showed up for the first time: ==== Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.catalina.startup.VersionLoggerListener log Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: Server version: Apache Tomcat/9.0.13 Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.catalina.startup.VersionLoggerListener log Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: Server built: Dec 13 2018 16:06:34 UTC Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.catalina.startup.VersionLoggerListener log Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: Server number: 9.0.13.0 Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.catalina.startup.VersionLoggerListener log Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: OS Name: Linux Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.catalina.startup.VersionLoggerListener log Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: OS Version: 4.19.5-300.fc29.x86_64 Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.catalina.startup.VersionLoggerListener log Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: Architecture: amd64 Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.catalina.startup.VersionLoggerListener log Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: Java Home: /usr/lib/jvm/java-1.8.0-openjdk-1.8.0.212.b04-0.fc29.x86_64/jre Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.catalina.startup.VersionLoggerListener log Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: JVM Version: 1.8.0_212-b04 Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.catalina.startup.VersionLoggerListener log Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: JVM Vendor: Oracle Corporation Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.catalina.startup.VersionLoggerListener log Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: CATALINA_BASE: /var/lib/pki/pki-tomcat Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.catalina.startup.VersionLoggerListener log Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: CATALINA_HOME: /usr/share/tomcat Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.catalina.startup.VersionLoggerListener log Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: Command line argument: -DRESTEASY_LIB=/usr/share/java/resteasy Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.catalina.startup.VersionLoggerListener log Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: Command line argument: -Dcatalina.base=/var/lib/pki/pki-tomcat Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.catalina.startup.VersionLoggerListener log Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: Command line argument: -Dcatalina.home=/usr/share/tomcat Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.catalina.startup.VersionLoggerListener log Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: Command line argument: -Djava.endorsed.dirs= Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.catalina.startup.VersionLoggerListener log Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: Command line argument: -Djava.io.tmpdir=/var/lib/pki/pki-tomcat/temp Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.catalina.startup.VersionLoggerListener log Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: Command line argument: -Djava.util.logging.config.file=/var/lib/pki/pki-tomcat/conf/logging.properties Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.catalina.startup.VersionLoggerListener log Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.catalina.startup.VersionLoggerListener log Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: Command line argument: -Djava.security.manager Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.catalina.startup.VersionLoggerListener log Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: Command line argument: -Djava.security.policy==/var/lib/pki/pki-tomcat/conf/catalina.policy Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.dogtagpki.tomcat.JSSListener initJSS Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: JSSListener: Initializing JSS Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.dogtagpki.tomcat.JSSListener initJSS Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: JSSListener: Config: null Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.tomcat.util.net.jss.TomcatJSS init Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: TomcatJSS: initialization Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.mozilla.jss.CryptoManager <clinit> Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: CryptoManager: loading JSS library Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.mozilla.jss.CryptoManager <clinit> Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: CryptoManager: loaded JSS library from /usr/lib64/jss/libjss4.so Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.mozilla.jss.CryptoManager initialize Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: CryptoManager: initializing NSS database at /var/lib/pki/pki-tomcat/alias Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.tomcat.util.net.jss.TomcatJSS configureOCSP Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: configuring OCSP Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.tomcat.util.net.jss.TomcatJSS init Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: TomcatJSS: initialization complete Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.coyote.AbstractProtocol init Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: Initializing ProtocolHandler ["http-nio-8080"] Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.tomcat.util.net.NioSelectorPool getSharedSelector Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: Using a shared selector for servlet write/read Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.coyote.AbstractProtocol init Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: Initializing ProtocolHandler ["https-jsse-nio-8443"] Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.tomcat.util.net.NioSelectorPool getSharedSelector Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: Using a shared selector for servlet write/read Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.coyote.AbstractProtocol init Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: Initializing ProtocolHandler ["ajp-nio-127.0.0.1-8009"] Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.tomcat.util.net.NioSelectorPool getSharedSelector Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: Using a shared selector for servlet write/read Jun 04 19:38:46 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:46 PM org.apache.catalina.startup.Catalina load Jun 04 19:38:46 id.happyassassin.net server[14907]: INFO: Initialization processed in 1353 ms Jun 04 19:38:47 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:47 PM org.apache.catalina.core.StandardService startInternal Jun 04 19:38:47 id.happyassassin.net server[14907]: INFO: Starting service [Catalina] Jun 04 19:38:47 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:47 PM org.apache.catalina.core.StandardEngine startInternal Jun 04 19:38:47 id.happyassassin.net server[14907]: INFO: Starting Servlet Engine: Apache Tomcat/9.0.13 Jun 04 19:38:47 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:47 PM org.apache.catalina.startup.HostConfig deployDescriptor Jun 04 19:38:47 id.happyassassin.net server[14907]: INFO: Deploying deployment descriptor [/etc/pki/pki-tomcat/Catalina/localhost/ROOT.xml] Jun 04 19:38:48 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:48 PM org.apache.jasper.servlet.TldScanner scanJars Jun 04 19:38:48 id.happyassassin.net server[14907]: INFO: At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time. Jun 04 19:38:48 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:48 PM org.apache.catalina.startup.HostConfig deployDescriptor Jun 04 19:38:48 id.happyassassin.net server[14907]: INFO: Deployment of deployment descriptor [/etc/pki/pki-tomcat/Catalina/localhost/ROOT.xml] has finished in [1,838] ms Jun 04 19:38:48 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:48 PM org.apache.catalina.startup.HostConfig deployDescriptor Jun 04 19:38:48 id.happyassassin.net server[14907]: INFO: Deploying deployment descriptor [/etc/pki/pki-tomcat/Catalina/localhost/ca.xml] Jun 04 19:38:48 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:48 PM com.netscape.cms.tomcat.AbstractPKIAuthenticator <init> Jun 04 19:38:48 id.happyassassin.net server[14907]: INFO: PKIAuthenticator: Creating SSLAuthenticatorWithFallback Jun 04 19:38:49 id.happyassassin.net ns-slapd[14731]: [04/Jun/2019:12:38:49.437519397 -0700] - ERR - schema-compat-plugin - warning: no entries set up under cn=computers, cn=compat,dc=happyassassin,dc=net Jun 04 19:38:49 id.happyassassin.net ns-slapd[14731]: [04/Jun/2019:12:38:49.440167773 -0700] - ERR - schema-compat-plugin - Finished plugin initialization. Jun 04 19:38:50 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:50 PM org.apache.jasper.servlet.TldScanner scanJars Jun 04 19:38:50 id.happyassassin.net server[14907]: INFO: At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time. Jun 04 19:38:50 id.happyassassin.net server[14907]: Jun 04, 2019 12:38:50 PM com.netscape.cms.servlet.base.CMSStartServlet init Jun 04 19:38:50 id.happyassassin.net server[14907]: SEVERE: Unable to create CMS engine: com.netscape.cmscore.apps.CMSEngine Jun 04 19:38:50 id.happyassassin.net server[14907]: java.lang.InstantiationException: com.netscape.cmscore.apps.CMSEngine Jun 04 19:38:50 id.happyassassin.net server[14907]: at java.lang.Class.newInstance(Class.java:427) Jun 04 19:38:50 id.happyassassin.net server[14907]: at com.netscape.cms.servlet.base.CMSStartServlet.init(CMSStartServlet.java:138) Jun 04 19:38:50 id.happyassassin.net server[14907]: at javax.servlet.GenericServlet.init(GenericServlet.java:158) Jun 04 19:38:50 id.happyassassin.net server[14907]: at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) Jun 04 19:38:50 id.happyassassin.net server[14907]: at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) Jun 04 19:38:50 id.happyassassin.net server[14907]: at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) Jun 04 19:38:50 id.happyassassin.net server[14907]: at java.lang.reflect.Method.invoke(Method.java:498) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:282) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:279) Jun 04 19:38:50 id.happyassassin.net server[14907]: at java.security.AccessController.doPrivileged(Native Method) Jun 04 19:38:50 id.happyassassin.net server[14907]: at javax.security.auth.Subject.doAsPrivileged(Subject.java:549) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:314) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:170) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:123) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:1112) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1079) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:971) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:4829) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5143) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:743) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.core.ContainerBase.access$000(ContainerBase.java:131) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.core.ContainerBase$PrivilegedAddChild.run(ContainerBase.java:152) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.core.ContainerBase$PrivilegedAddChild.run(ContainerBase.java:142) Jun 04 19:38:50 id.happyassassin.net server[14907]: at java.security.AccessController.doPrivileged(Native Method) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:717) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:695) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:630) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.startup.HostConfig$DeployDescriptor.run(HostConfig.java:1840) Jun 04 19:38:50 id.happyassassin.net server[14907]: at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) Jun 04 19:38:50 id.happyassassin.net server[14907]: at java.util.concurrent.FutureTask.run(FutureTask.java:266) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75) Jun 04 19:38:50 id.happyassassin.net server[14907]: at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:112) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.startup.HostConfig.deployDescriptors(HostConfig.java:525) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:424) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1585) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:308) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:123) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.util.LifecycleBase.setStateInternal(LifecycleBase.java:424) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.util.LifecycleBase.setState(LifecycleBase.java:367) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:972) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.core.StandardHost.startInternal(StandardHost.java:831) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1432) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1422) Jun 04 19:38:50 id.happyassassin.net server[14907]: at java.util.concurrent.FutureTask.run(FutureTask.java:266) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75) Jun 04 19:38:50 id.happyassassin.net server[14907]: at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:134) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:944) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.core.StandardEngine.startInternal(StandardEngine.java:261) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.core.StandardService.startInternal(StandardService.java:422) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.core.StandardServer.startInternal(StandardServer.java:801) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.startup.Catalina.start(Catalina.java:695) Jun 04 19:38:50 id.happyassassin.net server[14907]: at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) Jun 04 19:38:50 id.happyassassin.net server[14907]: at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) Jun 04 19:38:50 id.happyassassin.net server[14907]: at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) Jun 04 19:38:50 id.happyassassin.net server[14907]: at java.lang.reflect.Method.invoke(Method.java:498) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:350) Jun 04 19:38:50 id.happyassassin.net server[14907]: at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:492) Jun 04 19:38:50 id.happyassassin.net server[14907]: Caused by: java.lang.NoSuchMethodException: com.netscape.cmscore.apps.CMSEngine.<init>() Jun 04 19:38:50 id.happyassassin.net server[14907]: at java.lang.Class.getConstructor0(Class.java:3082) Jun 04 19:38:50 id.happyassassin.net server[14907]: at java.lang.Class.newInstance(Class.java:412) Jun 04 19:38:50 id.happyassassin.net server[14907]: ... 61 more ==== So it seems the update detailed at the start of the description - from pki 10.6.6 and freeipa 4.7.0 to 4.7.2 - somehow started this problem, and it has persisted across the upgrade to Fedora 30. I think this problem is *somehow* specific to my system: it started out as Fedora 18 or Fedora 19 and has been constantly upgraded since, so it tends to expose odd bugs due to very old config cruft which don't show up in CI or openQA tests. But I don't know how to debug it further and figure out what's wrong.