Bug 1717229 - dogtag stopped working after dnf update due to docBase in /etc/pki/pki-tomcat/Catalina/localhost/ca.xml not being updated
Summary: dogtag stopped working after dnf update due to docBase in /etc/pki/pki-tomcat...
Keywords:
Status: POST
Alias: None
Product: Fedora
Classification: Fedora
Component: pki-core
Version: 29
Hardware: All
OS: All
unspecified
urgent
Target Milestone: ---
Assignee: Matthew Harmsen
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
: 1717230 (view as bug list)
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2019-06-05 00:11 UTC by Adam Williamson
Modified: 2019-07-12 22:10 UTC (History)
8 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:


Attachments (Terms of Use)

Description Adam Williamson 2019-06-05 00:11:16 UTC
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.

Comment 1 Adam Williamson 2019-06-05 00:12:29 UTC
*** Bug 1717230 has been marked as a duplicate of this bug. ***

Comment 2 Endi Sukma Dewata 2019-07-08 15:37:05 UTC
The logs in the original bug description said that the pki-base package got
upgraded to 10.7.0-1, but did the other PKI packages (e.g. pki-server) get
upgraded as well? A NoSuchMethodException usually indicates that there are
mismatching packages being installed (since such error would have been
caught at build time), or the packages got upgraded while the server is
still running.

Comment 3 Adam Williamson 2019-07-08 17:48:45 UTC
Yes, these were full system updates/upgrades (I just ran 'dnf update' and 'dnf system-upgrade download / dnf system-upgrade reboot'). All packages would've been updated/upgraded together.

Comment 4 Adam Williamson 2019-07-08 17:52:03 UTC
I was gonna check the logs to confirm this, but unfortunately they seem to have been rotated out of existence :/ I can confirm that right now everything is 10.7.0-1, though:

[root@id adamw]# rpm -qa | grep pki-
pki-base-java-10.7.0-1.fc30.noarch
pki-kra-10.7.0-1.fc30.noarch
python3-pki-10.7.0-1.fc30.noarch
dogtag-pki-server-theme-10.7.0-1.fc30.noarch
pki-ca-10.7.0-1.fc30.noarch
pki-server-10.7.0-1.fc30.noarch
pki-tools-10.7.0-1.fc30.x86_64
pki-base-10.7.0-1.fc30.noarch
pki-symkey-10.7.0-1.fc30.x86_64

Comment 5 Adam Williamson 2019-07-08 17:54:08 UTC
BTW, this is still happening and I have no idea how to fix it; my server has been out of commission for over a month at this point...

Comment 6 Adam Williamson 2019-07-08 18:52:37 UTC
Tomasz Torcz just found something:

<zdzichu> adamw: hey, about https://bugzilla.redhat.com/show_bug.cgi?id=1717229; could you fpaste output of 'grep netscape.security /etc/pki/pki-tomcat/ca/CS.cfg'?
<zdzichu> adamw: I had a problem with freeipa recently, class names weren't updates to correct ones
<adamw> zdzichu: https://paste.fedoraproject.org/paste/mIZl-Ktm0XK7oSyWQS7qng
<zdzichu> yep, seems like the same. It should have org.mozilla.jss in front, like in https://paste.fedoraproject.org/paste/QY9ECyRbHOIWKbHw2ysoKQ
<adamw> oo

so I changed all those to add org.mozilla.jss on the front and rebooted. Then it seemed to blow up on a certificate validity issue. So I tried rewinding time and restarting certmonger...which fails because it can't talk to a KDC. At this point I would like to set the whole thing on fire and go punt it in a freaking lake.

Can I just give you root permissions on the thing and let you go to town with it?

Comment 7 Endi Sukma Dewata 2019-07-08 19:18:27 UTC
About the CMSEngine issue, could you attach a tarball of these folders?
- /etc/pki
- /var/lib/pki
- /var/log/pki

I'm suspecting your machine might contain an older JAR file. Feel free to
exclude the NSS database, passwords, or any other sensitive information.

About the JSS classes, it's a different issue, but there is already an
upgrade script for that:
https://github.com/dogtagpki/pki/blob/master/base/server/upgrade/10.7.0/02-UpdateNetscapeSecurityClasses

Could you check /var/log/pki/pki-server-upgrade-*.log to make sure the upgrade
ran successfully?

Comment 8 Adam Williamson 2019-07-08 19:27:04 UTC
"Could you check /var/log/pki/pki-server-upgrade-*.log to make sure the upgrade ran successfully?"

It doesn't look like it did, no.

The last log that looks successful was /var/log/pki/pki-server-upgrade-10.5.6.log :

===

Upgrading from version 10.5.5 to 10.5.6:
1. Add token profile params for externalRegISEtoken for TPS CS.cfg

Upgrade complete.

---------------
System migrated
---------------

===

After that, there's 10.5.7, 10.5.8, 10.5.9 , which all look like this:

===

Upgrading PKI server configuration at Fri Jun 22 09:47:10 PDT 2018.
pki-tomcat instance:
  Configuration version: 10.5.6

pki-tomcat/ca subsystem:
  Configuration version: 10.5.6

Upgrade incomplete.

---------------
System migrated
---------------

===

(just with different dates). Then 10.6.6.log looks like this:

===

Upgrading PKI server configuration at Mon Dec  3 12:14:48 PST 2018.
Upgrading from version 10.5.6 to 10.6.0:
No upgrade scriptlets.
Tracker has been set to version 10.6.0.

Upgrading from version 10.6.0 to 10.6.5:
1. Remove NSS_DEFAULT_DB_TYPE from instance sysconfig
2. Fix server configuration
ERROR: [Errno 2] No such file or directory: '/etc/pki/pki-tomcat/ciphers.info'
Failed upgrading pki-tomcat instance.

Upgrade failed in pki-tomcat: [Errno 2] No such file or directory: '/etc/pki/pki-tomcat/ciphers.info'

Continue (Yes/No) [Y]? Traceback (most recent call last):
  File "/usr/lib/python3.7/site-packages/pki/server/upgrade.py", line 91, in upgrade
    self.upgrade_instance(instance)
  File "/usr/share/pki/server/upgrade/10.6.0/02-FixServerConfiguration", line 41, in upgrade_instance
    '/usr/share/pki/server/conf/ciphers.info')
  File "/usr/share/pki/server/upgrade/10.6.0/02-FixServerConfiguration", line 62, in replace_with_link
    os.remove(source)
FileNotFoundError: [Errno 2] No such file or directory: '/etc/pki/pki-tomcat/ciphers.info'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.7/site-packages/pki/upgrade.py", line 593, in upgrade_version
    scriptlet.upgrade()
  File "/usr/lib/python3.7/site-packages/pki/server/upgrade.py", line 113, in upgrade
    'Upgrade failed in %s: %s' % (instance, e), e, instance)
pki.server.PKIServerException: Upgrade failed in pki-tomcat: [Errno 2] No such file or directory: '/etc/pki/pki-tomcat/ciphers.info'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib64/python3.7/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/usr/lib64/python3.7/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/usr/lib/python3.7/site-packages/pki/server/cli/upgrade.py", line 210, in <module>
    main(sys.argv)
  File "/usr/lib/python3.7/site-packages/pki/server/cli/upgrade.py", line 203, in main
    upgrader.upgrade()
  File "/usr/lib/python3.7/site-packages/pki/upgrade.py", line 623, in upgrade
    self.upgrade_version(version)
  File "/usr/lib/python3.7/site-packages/pki/upgrade.py", line 613, in upgrade_version
    case_sensitive=False).lower()
  File "/usr/lib/python3.7/site-packages/pki/__init__.py", line 142, in read_text
    value = input(message)
EOFError: EOF when reading a line

===

Then 10.7.0.log looks basically the same: errors about /etc/pki/pki-tomcat/ciphers.info not existing.

Comment 9 Adam Williamson 2019-07-08 19:44:14 UTC
So I just tried doing 'touch /etc/pki/pki-tomcat/ciphers.info' and running pki-server-upgrade , and that completed successfully, but it doesn't seem to help the original problem unfortunately. ipa-server-upgrade is still blowing up.

I just found this thread from December:

https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahosted.org/thread/J257R4GFYIEG64JU5TO7Z2S6GVZZBHFK/

which looks a lot like my problem. But I cannot quite understand Arjen's mail saying 'this is solved':

https://lists.fedorahosted.org/archives/list/freeipa-users@lists.fedorahosted.org/message/PTXTMW6XZUY5FEYO2AO5T4W4O5AR3KOC/

what does he mean about those two files? What did he have to change to 'solve' it? I don't get it. Here's those two files on my system:

[root@id ca]# rpm -qf /usr/share/pki/ca/webapps/ca/WEB-INF/lib/pki-cmscore.jar
pki-ca-10.7.0-1.fc30.noarch
[root@id ca]# rpm -qf /usr/share/java/pki/pki-cmscore.jar
pki-server-10.7.0-1.fc30.noarch
[root@id ca]# ls -l /usr/share/pki/ca/webapps/ca/WEB-INF/lib/pki-cmscore.jar
lrwxrwxrwx. 1 root root 35 May  7 09:58 /usr/share/pki/ca/webapps/ca/WEB-INF/lib/pki-cmscore.jar -> /usr/share/java/pki/pki-cmscore.jar
[root@id ca]# 

so, is there something wrong there?

Comment 10 Endi Sukma Dewata 2019-07-08 20:06:33 UTC
There might be several issues here. I've fixed the JSS upgrade issue here (not merged yet):
https://github.com/edewata/pki/commit/9cf2be94943ad9be8a4603969291381320bd0746

I was suspecting there might be an old JAR file (or a link to it) in one of the instance
folders here:
- /etc/pki
- /var/lib/pki
- /var/log/pki

If you could post a tarball of those directories I'd be able to take a look at it.

Comment 11 Adam Williamson 2019-07-08 23:01:05 UTC
I'll email them to you. Thanks.

Comment 12 Endi Sukma Dewata 2019-07-09 00:12:43 UTC
Thanks. Here's what I found.

The docBase in your /etc/pki/pki-tomcat/Catalina/localhost/ca.xml is pointing
to /var/lib/pki/pki-tomcat/ca/webapps/ca folder which contains an old copy of
PKI CA web application, including old JAR files (see WEB-INF/lib subfolder).

In the past the PKI installer used to copy the web application files into the
instance folder, allowing the admin to customize the files (e.g. changing the
HTML templates, adding custom JAR files). However, this meant that the admin
would be responsible to update the web application manually when the PKI
packages are upgraded.

In newer PKI the installer sets the docBase to /usr/share/pki/ca/webapps/ca
which is part of the package so it will be updated automatically by default.

To fix the issue in older instances, assuming there was no customization,
simply change the docBase to /usr/share/pki/ca/webapps/ca, then remove the
old /var/lib/pki/pki-tomcat/ca/webapps/ca folder.

Since it may be difficult to automatically determine whether there was any
customization, I don't think PKI should automatically update the docBase and
remove the old web application. However, since IPA has a more strict usage
of PKI (i.e. IPA users do not access PKI CA web application directly), it's
probably safe to assume that there is no customization in PKI instances
installed as part of IPA. In that case I'd suggest that IPA should perform
this change as part of IPA upgrade, either automatically with a script or
manually by providing the above instruction.

Comment 13 Tomasz Torcz 2019-07-09 05:57:28 UTC
> However, this meant that the admin would be responsible to update the web application manually when the PKI packages are upgraded.

This is first time I heard about such requirement, and I'm running my home FreeIPA for 6 years now…
This should certainly be automated and path should be corrected during packages upgrade.

Comment 14 Adam Williamson 2019-07-09 15:30:49 UTC
Thanks Endi! That was exactly the problem; with that plus a date dodge to get certificates re-issued by certmonger, I'm *finally* back up and running.

This should definitely be handled on upgrade by Tomcat or FreeIPA, though, I'd say.

Comment 15 Endi Sukma Dewata 2019-07-09 18:28:16 UTC
Just to clarify, the problem happened because there was a change in WEB-INF/web.xml
in PKI 10.7 that affected how the CMSEngine is created. Had the docBase been pointing
to /usr/share/pki/ca/webapps/ca as in newer instances, there wouldn't be any problem
since the file would have been updated automatically. However, since in old instances
the web.xml was copied into /var/lib/pki/pki-tomcat/ca/webapps/ca, it is not updated
automatically during upgrade, causing the NoSuchMethodException exception.

Comment 16 Endi Sukma Dewata 2019-07-09 21:08:47 UTC
Please take a look at this page and let me know what you think:
https://www.dogtagpki.org/wiki/Upgrading_Custom_PKI_Subsystem

It will determine how this ticket will be resolved. Thanks!

Comment 17 Adam Williamson 2019-07-09 21:27:53 UTC
I don't think I have a sufficient understanding of the components to provide a useful opinion. The only opinion I'd venture is that /etc/pki/pki-tomcat/Catalina/localhost/ca.xml , being in /etc , is a *config* file, yes? We already have a substantial body of knowledge about handling config files in RPM: are we not using the %config mechanism, such that RPM would replace the file if it was unmodified, but preserve it if it was modified? If not, why not?

(Also, perhaps you could consider using the config file fragment approach, which is I think pretty well established by now as a superior approach to shipping a config file you expect to possibly be modified...)

Comment 18 Adam Williamson 2019-07-09 21:29:12 UTC
Further thought: if the case here is that the config file is marked as %config in the tomcat package but FreeIPA deployment modifies it, I'd say that makes this pretty clearly a problem for FreeIPA to handle on upgrade.

Comment 19 Endi Sukma Dewata 2019-07-09 22:13:39 UTC
The files in /etc/pki/<instance> are configuration files created when that particular PKI server instance was created using pkispawn (which was invoked by IPA installer). They are not part of the RPM packages so I don't think we will be able to use the %config on them, but thanks for your feedback!

Comment 20 Adam Williamson 2019-07-09 22:38:09 UTC
Ah, I see, that explains it. So unless tomcat invents its own mechanism for doing it, there's no possibility to tell whether they've been modified from "stock" or not, I guess.

Comment 21 Endi Sukma Dewata 2019-07-12 22:10:03 UTC
We decided to fix this issue in PKI and replace the "custom" webapps
with the default ones. This should avoid similar issues in the future.

Here are the changes in master branch:
* https://github.com/dogtagpki/pki/commit/f24ec55923ee01981954e41c64d7a7304707d41d
* https://github.com/dogtagpki/pki/commit/f4275bfcf1bd7f6e9ef008d264d76928f3a19e99

Thanks!


Note You need to log in before you can comment on or make changes to this bug.