Bug 1994739

Summary:	FreeIPA deployment in Rawhide fails due to pki-tomcatd@pki-tomcat.service failure
Product:	[Fedora] Fedora	Reporter:	Adam Williamson <awilliam>
Component:	dogtag-pki	Assignee:	Matthew Harmsen <mharmsen>
Status:	CLOSED ERRATA	QA Contact:	Fedora Extras Quality Assurance <extras-qa>
Severity:	high	Docs Contact:
Priority:	unspecified
Version:	rawhide	CC:	abokovoy, alee, alexander.m.scheel, cdorney, cfu, ckelley, edewata, fcami, jmagne, jpazdziora, kwright, mharmsen, mkdineshprasanth, rcritten, robatino
Target Milestone:	---
Target Release:	---
Hardware:	All
OS:	Linux
Whiteboard:	openqa
Fixed In Version:		Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2021-08-20 12:15:58 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 Depends On:
Bug Blocks:	1891953

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.