Bug 1717229
| Summary: | dogtag stopped working after dnf update due to docBase in /etc/pki/pki-tomcat/Catalina/localhost/ca.xml not being updated | ||
|---|---|---|---|
| Product: | [Fedora] Fedora | Reporter: | Adam Williamson <awilliam> |
| Component: | pki-core | Assignee: | Matthew Harmsen <mharmsen> |
| Status: | CLOSED CURRENTRELEASE | QA Contact: | Fedora Extras Quality Assurance <extras-qa> |
| Severity: | urgent | Docs Contact: | |
| Priority: | unspecified | ||
| Version: | 29 | CC: | alee, ascheel, dmoluguw, edewata, kwright, mharmsen, rcritten, tomek |
| Target Milestone: | --- | ||
| Target Release: | --- | ||
| Hardware: | All | ||
| OS: | All | ||
| Whiteboard: | |||
| Fixed In Version: | pki-core-10.7.3-3.fc29 | Doc Type: | If docs needed, set a value |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2019-10-31 19:48:53 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: | |||
*** Bug 1717230 has been marked as a duplicate of this bug. *** 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. 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. 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 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... 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? 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? "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.
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? 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. I'll email them to you. Thanks. 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. > 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.
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. 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. 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! 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...) 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. 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! 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. 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! This message is a reminder that Fedora 29 is nearing its end of life. Fedora will stop maintaining and issuing updates for Fedora 29 on 2019-11-26. It is Fedora's policy to close all bug reports from releases that are no longer maintained. At that time this bug will be closed as EOL if it remains open with a Fedora 'version' of '29'. Package Maintainer: If you wish for this bug to remain open because you plan to fix it in a currently maintained version, simply change the 'version' to a later Fedora version. Thank you for reporting this issue and we are sorry that we were not able to fix it before Fedora 29 is end of life. If you would still like to see this bug fixed and are able to reproduce it against a later version of Fedora, you are encouraged change the 'version' to a later Fedora version prior this bug is closed as described in the policy above. Although we aim to fix as many bugs as possible during every release's lifetime, sometimes those efforts are overtaken by events. Often a more recent Fedora release includes newer upstream software that fixes bugs or makes them obsolete. |
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.