Bug 1655808

   Hi Adam, I'm getting exactly this error as well, although I'm upgrading from fedora 27 to 28. I tried using the "Listener" line but no matter where I place it, the service fails to start the connector on port 8443.

   Can you post details on where this line needs to sit in the server.xml please?

   Thanks in advance...

@jonny,

You need to add it to:

<Server port="8005" shutdown="SHUTDOWN">
   <Listener className="org.apache.catalina.startup.VersionLoggerListener"/>
   ...
   <Listener className="org.apache.catalina.core.JreMemoryLeakPreventionListener"/>
   <Listener className="org.apache.catalina.mbeans.GlobalResourcesLifecycleListener"/>
   <Listener className="org.apache.catalina.core.ThreadLocalLeakPreventionListener"/>
   <Listener className="com.netscape.cms.tomcat.PKIListener"/>
   ...
</Server>

Hope this helps.

   Hi Dinesh, thank you for the prompt reply...I rolled back the server and went through the OS upgrade again from 27 to 28. This time, after the new fedora 28 OS booted up, I checked the pki-tomcatd and the Mozilla-JSS was present. I put the listener line in and restarted the service. This time I got further and received a new error which I will include with preceding startup entries:-

09-Jan-2019 11:07:08.367 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version:        Apache Tomcat/8.5.32
09-Jan-2019 11:07:08.371 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built:          Aug 1 2018 01:30:11 UTC
09-Jan-2019 11:07:08.373 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server number:         8.5.32.0
09-Jan-2019 11:07:08.375 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name:               Linux
09-Jan-2019 11:07:08.378 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version:            4.19.13-200.fc28.x86_64
09-Jan-2019 11:07:08.382 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Architecture:          amd64
09-Jan-2019 11:07:08.384 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Java Home:             /usr/lib/jvm/java-1.8.0-openjdk-1.8.0.191.b12-11.fc28.x86_64/jre
09-Jan-2019 11:07:08.389 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version:           1.8.0_191-b12
09-Jan-2019 11:07:08.390 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor:            Oracle Corporation
09-Jan-2019 11:07:08.392 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE:         /var/lib/pki/pki-tomcat
09-Jan-2019 11:07:08.394 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME:         /usr/share/tomcat
09-Jan-2019 11:07:08.396 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -DRESTEASY_LIB=/usr/share/java/resteasy
09-Jan-2019 11:07:08.397 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.base=/var/lib/pki/pki-tomcat
09-Jan-2019 11:07:08.405 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.home=/usr/share/tomcat
09-Jan-2019 11:07:08.410 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.endorsed.dirs=
09-Jan-2019 11:07:08.414 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.io.tmpdir=/var/lib/pki/pki-tomcat/temp
09-Jan-2019 11:07:08.419 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.config.file=/var/lib/pki/pki-tomcat/conf/logging.properties
09-Jan-2019 11:07:08.422 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
09-Jan-2019 11:07:08.427 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.security.manager
09-Jan-2019 11:07:08.430 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.security.policy==/var/lib/pki/pki-tomcat/conf/catalina.policy
09-Jan-2019 11:07:08.688 INFO [main] com.netscape.cms.tomcat.PKIListener.lifecycleEvent PKIListener: org.apache.catalina.core.StandardServer [before_init]
09-Jan-2019 11:07:08.711 INFO [main] com.netscape.cms.tomcat.PKIListener.lifecycleEvent PKIListener: Initializing TomcatJSS
09-Jan-2019 11:07:08.828 INFO [main] org.apache.tomcat.util.net.jss.TomcatJSS.init TomcatJSS: initialization
09-Jan-2019 11:07:08.840 INFO [main] org.mozilla.jss.CryptoManager.<clinit> CryptoManager: loading JSS library
09-Jan-2019 11:07:08.849 INFO [main] org.mozilla.jss.CryptoManager.<clinit> CryptoManager: loaded JSS library from /usr/lib64/jss/libjss4.so
09-Jan-2019 11:07:08.854 INFO [main] org.mozilla.jss.CryptoManager.initialize CryptoManager: initializing NSS database at /var/lib/pki/pki-tomcat/alias
09-Jan-2019 11:07:08.983 INFO [main] org.apache.tomcat.util.net.jss.TomcatJSS.configureOCSP configuring OCSP
09-Jan-2019 11:07:09.129 WARNING [main] org.apache.tomcat.util.net.jss.TomcatJSS.setSSLCiphers Unable to set SSL cipher preference: org.mozilla.jss.ssl.SSLSocketException: Failed to enable cipher 0xc02d
: (-12266) An unknown SSL cipher suite has been requested.
09-Jan-2019 11:07:09.132 WARNING [main] org.apache.tomcat.util.net.jss.TomcatJSS.setSSLCiphers SSL ECC cipher "TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256" unsupported by NSS. This is probably O.K. unless ECC support has been installed.
09-Jan-2019 11:07:09.136 WARNING [main] org.apache.tomcat.util.net.jss.TomcatJSS.setSSLCiphers Unable to set SSL cipher preference: org.mozilla.jss.ssl.SSLSocketException: Failed to enable cipher 0xc031
: (-12266) An unknown SSL cipher suite has been requested.
09-Jan-2019 11:07:09.138 WARNING [main] org.apache.tomcat.util.net.jss.TomcatJSS.setSSLCiphers SSL ECC cipher "TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256" unsupported by NSS. This is probably O.K. unless ECC support has been installed.
09-Jan-2019 11:07:09.140 INFO [main] org.apache.tomcat.util.net.jss.TomcatJSS.init TomcatJSS: initialization complete
09-Jan-2019 11:07:09.352 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-nio-8080"]
09-Jan-2019 11:07:09.410 INFO [main] org.apache.tomcat.util.net.NioSelectorPool.getSharedSelector Using a shared selector for servlet write/read
09-Jan-2019 11:07:09.495 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["https-jsse-nio-8443"]
09-Jan-2019 11:07:10.217 INFO [main] org.apache.tomcat.util.net.NioSelectorPool.getSharedSelector Using a shared selector for servlet write/read
09-Jan-2019 11:07:10.221 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["ajp-nio-127.0.0.1-8009"]
09-Jan-2019 11:07:10.236 INFO [main] org.apache.tomcat.util.net.NioSelectorPool.getSharedSelector Using a shared selector for servlet write/read
09-Jan-2019 11:07:10.242 INFO [main] com.netscape.cms.tomcat.PKIListener.lifecycleEvent PKIListener: org.apache.catalina.core.StandardServer [after_init]
09-Jan-2019 11:07:10.243 INFO [main] org.apache.catalina.startup.Catalina.load Initialization processed in 3851 ms
09-Jan-2019 11:07:10.244 INFO [main] com.netscape.cms.tomcat.PKIListener.lifecycleEvent PKIListener: org.apache.catalina.core.StandardServer [before_start]
09-Jan-2019 11:07:10.286 INFO [main] com.netscape.cms.tomcat.PKIListener.lifecycleEvent PKIListener: org.apache.catalina.core.StandardServer [configure_start]
09-Jan-2019 11:07:10.371 INFO [main] com.netscape.cms.tomcat.PKIListener.lifecycleEvent PKIListener: org.apache.catalina.core.StandardServer [start]
09-Jan-2019 11:07:10.381 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service [Catalina]
09-Jan-2019 11:07:10.386 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet Engine: Apache Tomcat/8.5.32
09-Jan-2019 11:07:10.441 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDescriptor Deploying configuration descriptor [/etc/pki/pki-tomcat/Catalina/localhost/pki.xml]
09-Jan-2019 11:07:18.433 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDescriptor Deployment of configuration descriptor [/etc/pki/pki-tomcat/Catalina/localhost/pki.xml] has finished in [7,992] ms
09-Jan-2019 11:07:18.436 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDescriptor Deploying configuration descriptor [/etc/pki/pki-tomcat/Catalina/localhost/ca.xml]
09-Jan-2019 11:07:18.471 INFO [localhost-startStop-1] com.netscape.cms.tomcat.AbstractPKIAuthenticator.<init> PKIAuthenticator: Creating SSLAuthenticatorWithFallback
09-Jan-2019 11:07:25.562 INFO [localhost-startStop-1] 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.
09-Jan-2019 11:07:25.810 SEVERE [localhost-startStop-1] 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:1132)
        at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1091)
        at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:983)
        at org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:4978)
        at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5290)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:754)
        at org.apache.catalina.core.ContainerBase.access$000(ContainerBase.java:129)
        at org.apache.catalina.core.ContainerBase$PrivilegedAddChild.run(ContainerBase.java:150)
        at org.apache.catalina.core.ContainerBase$PrivilegedAddChild.run(ContainerBase.java:140)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:728)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:734)
        at org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:629)
        at org.apache.catalina.startup.HostConfig$DeployDescriptor.run(HostConfig.java:1839)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
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)
        ... 33 more

09-Jan-2019 11:07:25.867 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDescriptor Deployment of configuration descriptor [/etc/pki/pki-tomcat/Catalina/localhost/ca.xml] has finished in [7,427] ms
09-Jan-2019 11:07:25.878 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDescriptor Deploying configuration descriptor [/etc/pki/pki-tomcat/Catalina/localhost/ROOT.xml]
09-Jan-2019 11:07:30.547 INFO [localhost-startStop-1] 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.
09-Jan-2019 11:07:30.566 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDescriptor Deployment of configuration descriptor [/etc/pki/pki-tomcat/Catalina/localhost/ROOT.xml] has finished in [4,688] ms
09-Jan-2019 11:07:30.578 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
09-Jan-2019 11:07:30.713 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["https-jsse-nio-8443"]
09-Jan-2019 11:07:30.836 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["ajp-nio-127.0.0.1-8009"]
09-Jan-2019 11:07:30.886 INFO [main] com.netscape.cms.tomcat.PKIListener.lifecycleEvent PKIListener: org.apache.catalina.core.StandardServer [after_start]
09-Jan-2019 11:07:30.899 INFO [main] com.netscape.cms.tomcat.PKIListener.verifySubsystems PKIListener: Subsystem CA is running.
09-Jan-2019 11:07:30.906 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 20661 ms
09-Jan-2019 11:07:40.591 WARNING [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.core.ContainerBase.backgroundProcess Exception processing realm [com.netscape.cms.tomcat.ProxyRealm@61344244] 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:1152)
        at org.apache.catalina.core.StandardContext.backgroundProcess(StandardContext.java:5648)
        at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1390)
        at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1394)
        at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1394)
        at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1362)
        at java.lang.Thread.run(Thread.java:748)



   The last section of the log starting at "09-Jan-2019 11:07:40.591" repeats every 10 seconds after that.

   At this point I tried issuing "ipa-server-upgrade" but of course that fails to contact the CA and the following url gives a "HTTP Status 500 – Internal Server Error":-

http://ipa.mydomain.org:8080/ca/admin/ca/getStatus

   Obviously, "ipa.mydomain.org is not the hostname for the server but used as an example...

   Sorry for the long post.

Jonny

mharmsen: is there any plan to fix this for future upgrades or are we just supposed to document this or what?

   Hi there, is there an update to this issue yet? I'm now using an unsupported version of fedora (27) and I am desperate to upgrade.

   Thanks in advance for your time...

Jonny

Jonny: sorry, I didn't notice your follow-up comment before. That looks like a different issue to this one, but I don't know how to fix it, sorry (I am no Java expert). Perhaps someone else on this bug could help you, or maybe ask in #freeipa on Freenode IRC?

Adam, I installed a new IPA server on F27 and it already has com.netscape.cms.tomcat.PKIListener. Did you upgrade your server from an older Fedora?

Jonny, the stack trace indicates a problem creating CMSEngine object. The constructor for this class indeed changed between PKI 10.5 and 10.6:
* https://github.com/dogtagpki/pki/blob/DOGTAG_10_5_BRANCH/base/server/cmscore/src/com/netscape/cmscore/apps/CMSEngine.java#L299
* https://github.com/dogtagpki/pki/blob/DOGTAG_10_6_BRANCH/base/server/cmscore/src/com/netscape/cmscore/apps/CMSEngine.java#L221

If the upgrade worked correctly you shouldn't see this problem. Could you check to make sure you don't have a mix of PKI 10.5 and 10.6 RPM packages? Regardless, I think this is a different issue. Feel free to open a separate ticket.

Endi: yes. It started out as approximately Fedora 19 or something. This is why I find a lot of bugs like this.

This is fixed in master (PKI 10.7):
https://github.com/dogtagpki/pki/commit/dd974891a22ecbbdffd91df9d75044e09e60ca71

It may need to be cherry-picked into PKI 10.6 branch and released into Fedora 28+.

   Hi Endi, after the dnf system-upgrade, I checked the versions of pki and there was only the new 10.6 rpms installed. How should I proceed at this point?

Jonny

Hi Jonny, the PKI 10.7 was released in F29 and F30:
* https://bodhi.fedoraproject.org/updates/FEDORA-2019-40e2ad6d2c
* https://bodhi.fedoraproject.org/updates/FEDORA-2019-1337735a42

As mentioned in comment #7, the CMSEngine issue seems to be an environment issue. Make sure all PKI packages installed are all in the same version.

   Thanks for the response Endi, I tried going from fc27 to 29 this time. PKI tomcat complains about a missing jar file:tomcat-pki-3.1-api.jar and fails. rpms installed for pki tomcat are all 10.7 this time.

   I guess I need to open a new ticket but need to ask for guidance on this issue as I have put quite a bit of time into this problem already. Can I even open a ticket for upgrade to fc28 now? Or would I need to try resolving through  upgrade from 27 to 29.

Jonny

   Sorry Endi, that jar filename was tomcat-servlet-3.1-api.jar

Jonny

Jonny, could you post the command that you executed and the actual error message?
Could you also show which pki/tomcat/jss/tomcatjss packages are installed?

I'm not sure you can open an F28 ticket, but for sure we can't release an official
F28 build anymore. I'd suggest you try upgrading directly to F29, and if it fails
with an error unrelated to the missing PKIListener please open a new ticket with
the above information included. 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.