Bug 1994739 - FreeIPA deployment in Rawhide fails due to pki-tomcatd failure
Summary: FreeIPA deployment in Rawhide fails due to pki-tomcatd@pki-tomcat.service fai...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: dogtag-pki
Version: rawhide
Hardware: All
OS: Linux
unspecified
high
Target Milestone: ---
Assignee: Matthew Harmsen
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard: openqa
Depends On:
Blocks: F35BetaBlocker
TreeView+ depends on / blocked
 
Reported: 2021-08-17 19:35 UTC by Adam Williamson
Modified: 2021-08-20 12:27 UTC (History)
15 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2021-08-20 12:15:58 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description Adam Williamson 2021-08-17 19:35:56 UTC
In current Fedora Rawhide, FreeIPA server deployment (and FreeIPA start after upgrade from a stable release) fails. It fails because pki-tomcatd does not start successfully. These are the errors from the system log:

Aug 16 16:56:54 ipa001.test.openqa.fedoraproject.org ipa-pki-wait-running[31439]: ipa-pki-wait-running: Connection failed: HTTPConnectionPool(host='ipa001.test.openqa.fedoraproject.org', port=8080): Read timed out. (read timeout=1.0)
Aug 16 16:56:56 ipa001.test.openqa.fedoraproject.org ipa-pki-wait-running[31439]: ipa-pki-wait-running: Connection failed: HTTPConnectionPool(host='ipa001.test.openqa.fedoraproject.org', port=8080): Read timed out. (read timeout=1.0)
Aug 16 16:56:58 ipa001.test.openqa.fedoraproject.org ipa-pki-wait-running[31439]: ipa-pki-wait-running: Connection failed: HTTPConnectionPool(host='ipa001.test.openqa.fedoraproject.org', port=8080): Read timed out. (read timeout=1.0)
Aug 16 16:57:00 ipa001.test.openqa.fedoraproject.org ipa-pki-wait-running[31439]: ipa-pki-wait-running: Connection failed: HTTPConnectionPool(host='ipa001.test.openqa.fedoraproject.org', port=8080): Read timed out. (read timeout=1.0)
Aug 16 16:57:02 ipa001.test.openqa.fedoraproject.org ipa-pki-wait-running[31439]: ipa-pki-wait-running: Connection failed: HTTPConnectionPool(host='ipa001.test.openqa.fedoraproject.org', port=8080): Read timed out. (read timeout=1.0)
Aug 16 16:57:04 ipa001.test.openqa.fedoraproject.org python3[31439]: detected unhandled Python exception in '/usr/libexec/ipa/ipa-pki-wait-running'
Aug 16 16:57:04 ipa001.test.openqa.fedoraproject.org ipa-pki-wait-running[31439]: Traceback (most recent call last):
Aug 16 16:57:04 ipa001.test.openqa.fedoraproject.org ipa-pki-wait-running[31439]:   File "/usr/libexec/ipa/ipa-pki-wait-running", line 132, in <module>
Aug 16 16:57:04 ipa001.test.openqa.fedoraproject.org ipa-pki-wait-running[31439]:     main()
Aug 16 16:57:04 ipa001.test.openqa.fedoraproject.org ipa-pki-wait-running[31439]:   File "/usr/libexec/ipa/ipa-pki-wait-running", line 99, in main
Aug 16 16:57:04 ipa001.test.openqa.fedoraproject.org ipa-pki-wait-running[31439]:     status, error = get_status(conn, CONNECTION_TIMEOUT)
Aug 16 16:57:04 ipa001.test.openqa.fedoraproject.org ipa-pki-wait-running[31439]:   File "/usr/libexec/ipa/ipa-pki-wait-running", line 77, in get_status
Aug 16 16:57:04 ipa001.test.openqa.fedoraproject.org ipa-pki-wait-running[31439]:     root = ElementTree.fromstring(response)
Aug 16 16:57:04 ipa001.test.openqa.fedoraproject.org ipa-pki-wait-running[31439]:   File "/usr/lib64/python3.10/xml/etree/ElementTree.py", line 1347, in XML
Aug 16 16:57:04 ipa001.test.openqa.fedoraproject.org ipa-pki-wait-running[31439]:     parser.feed(text)
Aug 16 16:57:04 ipa001.test.openqa.fedoraproject.org ipa-pki-wait-running[31439]: xml.etree.ElementTree.ParseError: not well-formed (invalid token): line 1, column 0
Aug 16 16:57:04 ipa001.test.openqa.fedoraproject.org systemd[1]: pki-tomcatd: Control process exited, code=exited, status=1/FAILURE
Aug 16 16:57:04 ipa001.test.openqa.fedoraproject.org server[31438]: WARNING: An illegal reflective access operation has occurred
Aug 16 16:57:04 ipa001.test.openqa.fedoraproject.org server[31438]: WARNING: Illegal reflective access by org.apache.catalina.loader.WebappClassLoaderBase (file:/usr/share/java/tomcat/catalina.jar) to field java.io.ObjectStreamClass$Caches.localDescs
Aug 16 16:57:04 ipa001.test.openqa.fedoraproject.org server[31438]: WARNING: Please consider reporting this to the maintainers of org.apache.catalina.loader.WebappClassLoaderBase
Aug 16 16:57:04 ipa001.test.openqa.fedoraproject.org server[31438]: WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
Aug 16 16:57:04 ipa001.test.openqa.fedoraproject.org server[31438]: WARNING: All illegal access operations will be denied in a future release
Aug 16 16:57:06 ipa001.test.openqa.fedoraproject.org server[31438]: WARNING: The web application [ca] appears to have started a thread named [AsyncLoader watchdog] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
Aug 16 16:57:06 ipa001.test.openqa.fedoraproject.org server[31438]:  java.base.12/java.lang.Object.wait(Native Method)
Aug 16 16:57:06 ipa001.test.openqa.fedoraproject.org server[31438]:  java.base.12/java.util.TimerThread.mainLoop(Timer.java:553)
Aug 16 16:57:06 ipa001.test.openqa.fedoraproject.org server[31438]:  java.base.12/java.util.TimerThread.run(Timer.java:506)
Aug 16 16:57:06 ipa001.test.openqa.fedoraproject.org server[31438]: WARNING: The web application [ca] appears to have started a thread named [LDAPConnThread-11 ldaps://ipa001.test.openqa.fedoraproject.org:389] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
Aug 16 16:57:06 ipa001.test.openqa.fedoraproject.org server[31438]:  java.base.12/java.net.SocketInputStream.socketRead0(Native Method)
Aug 16 16:57:06 ipa001.test.openqa.fedoraproject.org server[31438]:  java.base.12/java.net.SocketInputStream.socketRead(SocketInputStream.java:115)
Aug 16 16:57:06 ipa001.test.openqa.fedoraproject.org server[31438]:  java.base.12/java.net.SocketInputStream.read(SocketInputStream.java:168)
Aug 16 16:57:06 ipa001.test.openqa.fedoraproject.org server[31438]:  java.base.12/java.net.SocketInputStream.read(SocketInputStream.java:140)
Aug 16 16:57:06 ipa001.test.openqa.fedoraproject.org server[31438]:  java.base.12/java.io.BufferedInputStream.fill(BufferedInputStream.java:252)
Aug 16 16:57:06 ipa001.test.openqa.fedoraproject.org server[31438]:  java.base.12/java.io.BufferedInputStream.read(BufferedInputStream.java:271)
Aug 16 16:57:06 ipa001.test.openqa.fedoraproject.org server[31438]:  netscape.ldap.ber.stream.BERElement.getElement(Unknown Source)
Aug 16 16:57:06 ipa001.test.openqa.fedoraproject.org server[31438]:  netscape.ldap.LDAPConnThread.run(Unknown Source)
Aug 16 16:57:06 ipa001.test.openqa.fedoraproject.org server[31438]:  java.base.12/java.lang.Thread.run(Thread.java:829)
Aug 16 16:57:06 ipa001.test.openqa.fedoraproject.org server[31438]: WARNING: The web application [ca] appears to have started a thread named [profileChangeMonitor] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
Aug 16 16:57:06 ipa001.test.openqa.fedoraproject.org server[31438]:  java.base.12/java.lang.Object.wait(Native Method)
Aug 16 16:57:06 ipa001.test.openqa.fedoraproject.org server[31438]:  java.base.12/java.lang.Object.wait(Object.java:328)
Aug 16 16:57:06 ipa001.test.openqa.fedoraproject.org server[31438]:  netscape.ldap.LDAPMessageQueue.waitForMessage(Unknown Source)
Aug 16 16:57:06 ipa001.test.openqa.fedoraproject.org server[31438]:  netscape.ldap.LDAPMessageQueue.nextMessage(Unknown Source)
Aug 16 16:57:06 ipa001.test.openqa.fedoraproject.org server[31438]:  netscape.ldap.LDAPSearchListener.nextMessage(Unknown Source)
Aug 16 16:57:06 ipa001.test.openqa.fedoraproject.org server[31438]:  netscape.ldap.LDAPSearchResults.fetchResult(Unknown Source)
Aug 16 16:57:06 ipa001.test.openqa.fedoraproject.org server[31438]:  netscape.ldap.LDAPSearchResults.hasMoreElements(Unknown Source)
Aug 16 16:57:06 ipa001.test.openqa.fedoraproject.org server[31438]:  com.netscape.cmscore.profile.LDAPProfileSubsystem.run(LDAPProfileSubsystem.java:472)
Aug 16 16:57:06 ipa001.test.openqa.fedoraproject.org server[31438]:  java.base.12/java.lang.Thread.run(Thread.java:829)
Aug 16 16:57:06 ipa001.test.openqa.fedoraproject.org systemd[1]: pki-tomcatd: Failed with result 'exit-code'.
Aug 16 16:57:06 ipa001.test.openqa.fedoraproject.org systemd[1]: Failed to start PKI Tomcat Server pki-tomcat.
Aug 16 16:57:06 ipa001.test.openqa.fedoraproject.org systemd[1]: pki-tomcatd: Consumed 22.057s CPU time.

The test last passed in Fedora-Rawhide-20210808.n.0. In Fedora-Rawhide-20210813.n.0 (the next successful compose) the test failed due to an error in the samba spec file, so I can't tell if that compose had this bug or not. This specific failure first showed up in the next compose, Fedora-Rawhide-20210814.n.0 .

It doesn't look like freeipa or pki-core were changed across the relevant time frame. However, there were version bumps for jss, tomcatjss, ldapjdk and dogtag-pki; dogtag-pki seems like the most likely suspect, so I'm filing against that for now.

Proposing as a Beta blocker as a violation of Basic criterion "It must be possible to configure a Fedora Server system installed according to the above criteria as a FreeIPA domain controller, using the official deployment tools provided in the distribution FreeIPA packages." - https://fedoraproject.org/wiki/Basic_Release_Criteria#FreeIPA_server_requirements

Comment 1 Rob Crittenden 2021-08-17 20:55:58 UTC
I suspect this is related to the RPC switch from XML to JSON which is not yet in a freeipa release, only merged upstream.

Comment 2 Fedora Update System 2021-08-20 12:14:38 UTC
FEDORA-2021-169ba63cbe has been submitted as an update to Fedora 36. https://bodhi.fedoraproject.org/updates/FEDORA-2021-169ba63cbe

Comment 3 Fedora Update System 2021-08-20 12:15:58 UTC
FEDORA-2021-169ba63cbe has been pushed to the Fedora 36 stable repository.
If problem still persists, please make note of it in this bug report.

Comment 4 Fedora Update System 2021-08-20 12:24:33 UTC
FEDORA-2021-0192369fd9 has been submitted as an update to Fedora 35. https://bodhi.fedoraproject.org/updates/FEDORA-2021-0192369fd9

Comment 5 Fedora Update System 2021-08-20 12:27:59 UTC
FEDORA-2021-0192369fd9 has been pushed to the Fedora 35 stable repository.
If problem still persists, please make note of it in this bug report.


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