Hi,
We use IPA on a couple of OL 8 instances for HA. IPA was deployed 6-8 months ago, with the LDAP, CA DNS roles enabled on both nodes. DNSSEC was never enabled. An AD trust was created with the AD domain.
The whole setup worked flawlessly until last night, when both systems upgraded to Oracle Linux 8.5 with IPA 4.9.6-6.0.1. An IPA upgrade was automatically started to migrate from version 4.9.2-4.0.2 to 4.9.6-6.0.1, but it failed on both systems, leaving them in unusable states. The failure happens on IPA CA DNS update, because BIND service cannot be started.
2021-11-17T05:59:11Z DEBUG stderr=
2021-11-17T05:59:11Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
2021-11-17T05:59:11Z INFO dnssec-validation yes
2021-11-17T05:59:11Z INFO [Add missing CA DNS records]
2021-11-17T05:59:11Z DEBUG Loading StateFile from '/var/lib/ipa/sysupgrade/sysupgrade.state'
2021-11-17T05:59:11Z INFO IPA CA DNS records already processed
2021-11-17T05:59:11Z DEBUG Loading StateFile from '/var/lib/ipa/sysupgrade/sysupgrade.state'
2021-11-17T05:59:11Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
2021-11-17T05:59:11Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
2021-11-17T05:59:11Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
2021-11-17T05:59:11Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
2021-11-17T05:59:11Z DEBUG Loading StateFile from '/var/lib/ipa/sysupgrade/sysupgrade.state'
2021-11-17T05:59:11Z DEBUG Loading StateFile from '/var/lib/ipa/sysupgrade/sysupgrade.state'
2021-11-17T05:59:11Z DEBUG Loading StateFile from '/var/lib/ipa/sysupgrade/sysupgrade.state'
2021-11-17T05:59:11Z DEBUG Loading StateFile from '/var/lib/ipa/sysupgrade/sysupgrade.state'
2021-11-17T05:59:11Z DEBUG Loading StateFile from '/var/lib/ipa/sysupgrade/sysupgrade.state'
2021-11-17T05:59:11Z DEBUG Loading StateFile from '/var/lib/ipa/sysupgrade/sysupgrade.state'
2021-11-17T05:59:11Z DEBUG Loading StateFile from '/var/lib/ipa/sysupgrade/sysupgrade.state'
2021-11-17T05:59:11Z DEBUG Loading StateFile from '/var/lib/ipa/sysupgrade/sysupgrade.state'
2021-11-17T05:59:11Z DEBUG Loading StateFile from '/var/lib/ipa/sysupgrade/sysupgrade.state'
2021-11-17T05:59:11Z DEBUG Loading StateFile from '/var/lib/ipa/sysupgrade/sysupgrade.state'
2021-11-17T05:59:11Z DEBUG Loading StateFile from '/var/lib/ipa/sysupgrade/sysupgrade.state'
2021-11-17T05:59:11Z DEBUG Starting external process
2021-11-17T05:59:11Z DEBUG args=['/bin/systemctl', 'is-active', 'named-pkcs11.service']
2021-11-17T05:59:11Z DEBUG Process finished, return code=3
2021-11-17T05:59:11Z DEBUG stdout=failed
2021-11-17T05:59:11Z DEBUG stderr=
2021-11-17T05:59:11Z DEBUG Starting external process
2021-11-17T05:59:11Z DEBUG args=['/bin/systemctl', 'start', 'named-pkcs11.service']
2021-11-17T05:59:12Z DEBUG Process finished, return code=1
2021-11-17T05:59:12Z DEBUG stdout=
2021-11-17T05:59:12Z DEBUG stderr=Job for named-pkcs11.service failed because the control process exited with error code.
See "systemctl status named-pkcs11.service" and "journalctl -xe" for details.
2021-11-17T05:59:12Z ERROR IPA server upgrade failed: Inspect /var/log/ipaupgrade.log and run command ipa-server-upgrade manually.
2021-11-17T05:59:12Z DEBUG File "/usr/lib/python3.6/site-packages/ipapython/admintool.py", line 180, in execute
return_value = self.run()
File "/usr/lib/python3.6/site-packages/ipaserver/install/ipa_server_upgrade.py", line 54, in run
server.upgrade()
File "/usr/lib/python3.6/site-packages/ipaserver/install/server/upgrade.py", line 1961, in upgrade
upgrade_configuration()
File "/usr/lib/python3.6/site-packages/ipaserver/install/server/upgrade.py", line 1791, in upgrade_configuration
upgrade_bind(fstore)
File "/usr/lib/python3.6/site-packages/ipaserver/install/server/upgrade.py", line 1453, in upgrade_bind
bind.start()
File "/usr/lib/python3.6/site-packages/ipaserver/install/service.py", line 524, in start
self.service.start(instance_name, capture_output=capture_output, wait=wait)
File "/usr/lib/python3.6/site-packages/ipaplatform/base/services.py", line 311, in start
skip_output=not capture_output)
File "/usr/lib/python3.6/site-packages/ipapython/ipautil.py", line 599, in run
p.returncode, arg_string, output_log, error_log
2021-11-17T05:59:12Z DEBUG The ipa-server-upgrade command failed, exception: CalledProcessError: CalledProcessError(Command ['/bin/systemctl', 'start', 'named-pkcs11.service'] returned non-zero exit status 1: 'Job for named-pkcs11.service failed because the control process exited with error code.\nSee "systemctl status named-pkcs11.service" and "journalctl -xe" for details.\n')
2021-11-17T05:59:12Z ERROR Unexpected error - see /var/log/ipaupgrade.log for details:
CalledProcessError: CalledProcessError(Command ['/bin/systemctl', 'start', 'named-pkcs11.service'] returned non-zero exit status 1: 'Job for named-pkcs11.service failed because the control process exited with error code.\nSee "systemctl status named-pkcs11.service" and "journalctl -xe" for details.\n')
2021-11-17T05:59:12Z ERROR The ipa-server-upgrade command failed. See /var/log/ipaupgrade.log for more information
On both systems, most IPA-related services (krb5kdc, kadmin, ipa-custodia...) were set to disabled in systemd. I was able to re-enable all of them except the named-pkcs11 service, which refuses to start with an initializing DST: PKCS#11 initialization failed error:
nov. 17 09:30:05 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr named-pkcs11[5910]: running as: named-pkcs11 -u named -c /etc/named.conf
nov. 17 09:30:05 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr named-pkcs11[5910]: compiled by GCC 8.5.0 20210514 (Red Hat 8.5.0-3.0.1)
nov. 17 09:30:05 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr named-pkcs11[5910]: compiled with libxml2 version: 2.9.7
nov. 17 09:30:05 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr named-pkcs11[5910]: linked to libxml2 version: 20907
nov. 17 09:30:05 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr named-pkcs11[5910]: compiled with libjson-c version: 0.13.1
nov. 17 09:30:05 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr named-pkcs11[5910]: linked to libjson-c version: 0.13.1
nov. 17 09:30:05 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr named-pkcs11[5910]: compiled with zlib version: 1.2.11
nov. 17 09:30:05 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr named-pkcs11[5910]: linked to zlib version: 1.2.11
nov. 17 09:30:05 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr named-pkcs11[5910]: threads support is enabled
nov. 17 09:30:05 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr named-pkcs11[5910]: ----------------------------------------------------
nov. 17 09:30:05 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr named-pkcs11[5910]: BIND 9 is maintained by Internet Systems Consortium,
nov. 17 09:30:05 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr named-pkcs11[5910]: Inc. (ISC), a non-profit 501(c)(3) public-benefit
nov. 17 09:30:05 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr named-pkcs11[5910]: corporation. Support and training for BIND 9 are
nov. 17 09:30:05 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr named-pkcs11[5910]: available at https://www.isc.org/support
nov. 17 09:30:05 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr named-pkcs11[5910]: ----------------------------------------------------
nov. 17 09:30:05 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr named-pkcs11[5910]: adjusted limit on open files from 262144 to 1048576
nov. 17 09:30:05 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr named-pkcs11[5910]: found 4 CPUs, using 4 worker threads
nov. 17 09:30:05 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr named-pkcs11[5910]: using 3 UDP listeners per interface
nov. 17 09:30:05 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr named-pkcs11[5910]: using up to 21000 sockets
nov. 17 09:30:05 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr named-pkcs11[5910]: initializing DST: PKCS#11 initialization failed
nov. 17 09:30:05 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr named-pkcs11[5910]: exiting (due to fatal error)
nov. 17 09:30:05 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr systemd[1]: named-pkcs11.service: Control process exited, code=exited status=1
nov. 17 09:30:05 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr systemd[1]: named-pkcs11.service: Failed with result 'exit-code'.
nov. 17 09:30:05 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr systemd[1]: Failed to start Berkeley Internet Name Domain (DNS) with native PKCS#11.
Does anyone have any idea about what's going on ?
Thanks!