Catastrophic failure

[Marin BERNARD]

Hi,

My NPO uses FreeIPA internally on a couple of Oracle Linux 8 instances. I know this is a Fedora ML, but since OL8 is derivated from EL8 (as CentOS is), I think it may not make any difference anyway.

The FreeIPA instance 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.

It worked flawlessly until the latest batch of updates which upgraded both systems to OL 8.5 + FreeIPA 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 in different ways on both systems, leaving them in unusable states. Of course, no backup to restore.

**Node #02** (ros-ass-ipa-02) upgraded first. The failure happened at IPA CA DNS update, because the named-pkcs11 service could not be restarted. Here are the last lines from the log:

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

**Node #01** (ros-ass-ipa-01) upgraded an hour after, and failed at step 5/9 when the directory server could not be restarted after disabling Schema compat. Here are the last log entries:

2021-11-17T06:45:38Z DEBUG stderr=
2021-11-17T06:45:38Z DEBUG Starting external process
2021-11-17T06:45:38Z DEBUG args=['/bin/systemctl', 'start', '[e-mail]']
2021-11-17T06:45:38Z DEBUG step duration: dirsrv __enable_ds_global_write_lock 0.09 sec
2021-11-17T06:45:38Z DEBUG   [4/9]: disabling Schema Compat
2021-11-17T06:45:38Z DEBUG step duration: dirsrv __disable_schema_compat 0.14 sec
2021-11-17T06:45:38Z DEBUG   [5/9]: starting directory server
2021-11-17T06:45:38Z DEBUG Starting external process
2021-11-17T06:45:38Z DEBUG args=['/bin/systemctl', 'start', '[e-mail]']
2021-11-17T06:45:38Z DEBUG Process finished, return code=1
2021-11-17T06:45:38Z DEBUG stdout=
2021-11-17T06:45:38Z DEBUG stderr=Job for [e-mail] failed because the control process exited with error code.
See "systemctl status [e-mail]" and "journalctl -xe" for details.

2021-11-17T06:45:38Z ERROR IPA server upgrade failed: Inspect /var/log/ipaupgrade.log and run command ipa-server-upgrade manually.
2021-11-17T06:45:38Z DEBUG Process finished, return code=1
2021-11-17T06:45:38Z DEBUG stdout=
2021-11-17T06:45:38Z DEBUG stderr=Job for [e-mail] failed because the control process exited with error code.
See "systemctl status [e-mail]" and "journalctl -xe" for details.

2021-11-17T06:45:38Z 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 1584, in upgrade_configuration
    ds.start(ds.serverid)
  File "/usr/lib/python3.6/site-packages/ipaserver/install/dsinstance.py", line 652, in start
    instance_name, capture_output=capture_output, wait=wait
  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/redhat/services.py", line 138, in 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-17T06:45:38Z DEBUG The ipa-server-upgrade command failed, exception: CalledProcessError: CalledProcessError(Command ['/bin/systemctl', 'start', '[e-mail]'] returned non-zero exit status 1: 'Job for [e-mail] failed because the control process exited with error code.\nSee "systemctl status [e-mail]" and "journalctl -xe" for details.\n')
2021-11-17T06:45:38Z ERROR Unexpected error - see /var/log/ipaupgrade.log for details:
CalledProcessError: CalledProcessError(Command ['/bin/systemctl', 'start', '[e-mail]'] returned non-zero exit status 1: 'Job for [e-mail] failed because the control process exited with error code.\nSee "systemctl status [e-mail]" and "journalctl -xe" for details.\n')
2021-11-17T06:45:38Z ERROR The ipa-server-upgrade command failed. See /var/log/ipaupgrade.log for more information
2021-11-17T06:45:38Z DEBUG Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/ipaserver/install/service.py", line 635, in start_creation
    run_step(full_msg, method)
  File "/usr/lib/python3.6/site-packages/ipaserver/install/service.py", line 621, in run_step
    method()
  File "/usr/lib/python3.6/site-packages/ipaserver/install/upgradeinstance.py", line 104, in __start
    srv.start(self.serverid, ldapi=True)
  File "/usr/lib/python3.6/site-packages/ipaplatform/redhat/services.py", line 138, in 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
ipapython.ipautil.CalledProcessError: CalledProcessError(Command ['/bin/systemctl', 'start', '[e-mail]'] returned non-zero exit status 1: 'Job for [e-mail] failed because the control process exited with error code.\nSee "systemctl status [e-mail]" and "journalctl -xe" for details.\n')

2021-11-17T06:45:38Z DEBUG   [error] CalledProcessError: CalledProcessError(Command ['/bin/systemctl', 'start', '[e-mail]'] returned non-zero exit status 1: 'Job for [e-mail] failed because the control process exited with error code.\nSee "systemctl status [e-mail]" and "journalctl -xe" for details.\n')
2021-11-17T06:45:38Z DEBUG   [cleanup]: stopping directory server
2021-11-17T06:45:38Z DEBUG Starting external process
2021-11-17T06:45:38Z DEBUG args=['/bin/systemctl', 'stop', '[e-mail]']
2021-11-17T06:45:38Z DEBUG Process finished, return code=0
2021-11-17T06:45:38Z DEBUG stdout=
2021-11-17T06:45:38Z DEBUG stderr=
2021-11-17T06:45:38Z DEBUG Stop of [e-mail] complete
2021-11-17T06:45:38Z DEBUG step duration: dirsrv __stop_instance 0.02 sec
2021-11-17T06:45:38Z DEBUG   [cleanup]: restoring configuration
2021-11-17T06:45:38Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
2021-11-17T06:45:38Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
2021-11-17T06:45:38Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
2021-11-17T06:45:38Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
2021-11-17T06:45:38Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
2021-11-17T06:45:38Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
2021-11-17T06:45:38Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
2021-11-17T06:45:38Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
2021-11-17T06:45:38Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
2021-11-17T06:45:38Z DEBUG step duration: dirsrv __restore_config 0.09 sec
2021-11-17T06:45:38Z ERROR IPA server upgrade failed: Inspect /var/log/ipaupgrade.log and run command ipa-server-upgrade manually.
2021-11-17T06:45:38Z 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 1946, in upgrade
    data_upgrade.create_instance()
  File "/usr/lib/python3.6/site-packages/ipaserver/install/upgradeinstance.py", line 134, in create_instance
    runtime=90)
  File "/usr/lib/python3.6/site-packages/ipaserver/install/service.py", line 635, in start_creation
    run_step(full_msg, method)
  File "/usr/lib/python3.6/site-packages/ipaserver/install/service.py", line 621, in run_step
    method()
  File "/usr/lib/python3.6/site-packages/ipaserver/install/upgradeinstance.py", line 104, in __start
    srv.start(self.serverid, ldapi=True)
  File "/usr/lib/python3.6/site-packages/ipaplatform/redhat/services.py", line 138, in 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-17T06:45:38Z DEBUG The ipa-server-upgrade command failed, exception: CalledProcessError: CalledProcessError(Command ['/bin/systemctl', 'start', '[e-mail]'] returned non-zero exit status 1: 'Job for [e-mail] failed because the control process exited with error code.\nSee "systemctl status [e-mail]" and "journalctl -xe" for details.\n')
2021-11-17T06:45:38Z ERROR Unexpected error - see /var/log/ipaupgrade.log for details:
CalledProcessError: CalledProcessError(Command ['/bin/systemctl', 'start', '[e-mail]'] returned non-zero exit status 1: 'Job for [e-mail] failed because the control process exited with error code.\nSee "systemctl status [e-mail]" and "journalctl -xe" for details.\n')
2021-11-17T06:45:38Z ERROR The ipa-server-upgrade command failed. See /var/log/ipaupgrade.log for more information

On both nodes, several IPA services such as named-pkcs11, ipa-custodia, krb5kdc and kdamin are now disabled in systemd. Of course, they were enabled before the update, since both nodes were serving DNS and kerberos requests. I can re-enable and start most of those services without an error except:

- dirsv@PEP06-IPA-FR, which seems OK on node #02 (ros-ass-ipa-02), but refuses to start on node #01 (ros-ass-ipa-01):

nov. 17 09:17:17 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr systemd[1]: Starting 389 Directory Server IPA-PEP06-FR....
nov. 17 09:17:17 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr ns-slapd[5880]: [17/Nov/2021:09:17:17.220419556 +0100] - WARN - str2entry_dupcheckEntry (%s), ignoring invalid line "%s"...
nov. 17 09:17:17 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr ns-slapd[5880]:  - [17/Nov/2021:09:17:17.572658255 +0100] - NOTICE - config_set_port - Non-Secure Port Disabled
nov. 17 09:17:17 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr ns-slapd[5880]: [17/Nov/2021:09:17:17.637702405 +0100] - WARN - str2entry_dupcheckEntry (%s), ignoring invalid line "%s"...
nov. 17 09:17:17 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr ns-slapd[5880]:  - [17/Nov/2021:09:17:17.641830897 +0100] - ERR - slapi_entry_schema_check_ext - Entry "cn=SHA,cn=Password Storage Schemes,cn=plugins,cn=config" required attribute "objectclass" missing
nov. 17 09:17:17 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr ns-slapd[5880]: [17/Nov/2021:09:17:17.644760642 +0100] - ERR - init_dse_file - Could not load config file [dse.ldif]
nov. 17 09:17:17 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr ns-slapd[5880]: [17/Nov/2021:09:17:17.647669444 +0100] - ERR - setup_internal_backends - Please edit the file to correct the reported problems and then restart the server.
nov. 17 09:17:17 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr systemd[1]: [e-mail]: Main process exited, code=exited, status=1/FAILURE
nov. 17 09:17:17 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr systemd[1]: [e-mail]: Failed with result 'exit-code'.
nov. 17 09:17:17 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr systemd[1]: Failed to start 389 Directory Server IPA-PEP06-FR..

- named-pkcs11, which throws an "initializing DST: PKCS#11 initialization failed" error, on both nodes:

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.

I could not find much info about the BIND error. It is usually related to HSM configuration errors, but I couldn't find what's wrong:

[root@ros-ass-ipa-01 ~]# grep SOFTHSM2_CONF /etc/sysconfig/named
SOFTHSM2_CONF=/etc/ipa/dnssec/softhsm2.conf

[root@ros-ass-ipa-01 ~]# SOFTHSM2_CONF=/etc/ipa/dnssec/softhsm2.conf softhsm2-util --show-slots
Available slots:
Slot 1594851657
    Slot info:
        Description:      SoftHSM slot ID 0x5f0f8149
        Manufacturer ID:  SoftHSM project
        Hardware version: 2.6
        Firmware version: 2.6
        Token present:    yes
    Token info:
        Manufacturer ID:  SoftHSM project
        Model:            SoftHSM v2
        Hardware version: 2.6
        Firmware version: 2.6
        Serial number:    4a9fc4075f0f8149
        Initialized:      yes
        User PIN init.:   yes
        Label:            ipaDNSSEC
Slot 1
    Slot info:
        Description:      SoftHSM slot ID 0x1
        Manufacturer ID:  SoftHSM project
        Hardware version: 2.6
        Firmware version: 2.6
        Token present:    yes
    Token info:
        Manufacturer ID:  SoftHSM project
        Model:            SoftHSM v2
        Hardware version: 2.6
        Firmware version: 2.6
        Serial number:
        Initialized:      no
        User PIN init.:   no
        Label:

I tried re-running the IPA upgrade manually, and it failed on both nodes at the exact same step as during the automatic upgrade. While node #02 seems mostly OK (dirsrv and KDC are running, kinit does work; only named-pkcs11 is down), node #01 was more damaged as the directory server does not even start anymore.

Full upgrade logs:
- Node #01 (ros-ass-ipa-01):  https://gist.github.com/marinbernard-pep06/548c4aea3006e18b5f86cda6f935f2c5
- Node #02 (ros-ass-ipa-02): https://gist.github.com/marinbernard-pep06/7e5a76712cc4b23101f1fab39315f870

I would be **very** grateful to anyone sharing insight about this situation.

Thank you!

[François Cami]

Hi,

Try downgrading Java to the last known good version that worked for
your and report please.

Regards,
François

On Wed, Nov 17, 2021 at 10:17 AM Marin BERNARD via FreeIPA-users
 wrote:
> Hi,
>
> My NPO uses FreeIPA internally on a couple of Oracle Linux 8 instances. I know this is a Fedora ML, but since OL8 is derivated from EL8 (as CentOS is), I think it may not make any difference anyway.
>
> The FreeIPA instance 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.
>
> It worked flawlessly until the latest batch of updates which upgraded both systems to OL 8.5 + FreeIPA 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 in different ways on both systems, leaving them in unusable states. Of course, no backup to restore.
>
> **Node #02** (ros-ass-ipa-02) upgraded first. The failure happened at IPA CA DNS update, because the named-pkcs11 service could not be restarted. Here are the last lines from the log:
>
> 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
>
> **Node #01** (ros-ass-ipa-01) upgraded an hour after, and failed at step 5/9 when the directory server could not be restarted after disabling Schema compat. Here are the last log entries:
>
> 2021-11-17T06:45:38Z DEBUG stderr=
> 2021-11-17T06:45:38Z DEBUG Starting external process
> 2021-11-17T06:45:38Z DEBUG args=['/bin/systemctl', 'start', '[e-mail]']
> 2021-11-17T06:45:38Z DEBUG step duration: dirsrv __enable_ds_global_write_lock 0.09 sec
> 2021-11-17T06:45:38Z DEBUG   [4/9]: disabling Schema Compat
> 2021-11-17T06:45:38Z DEBUG step duration: dirsrv __disable_schema_compat 0.14 sec
> 2021-11-17T06:45:38Z DEBUG   [5/9]: starting directory server
> 2021-11-17T06:45:38Z DEBUG Starting external process
> 2021-11-17T06:45:38Z DEBUG args=['/bin/systemctl', 'start', '[e-mail]']
> 2021-11-17T06:45:38Z DEBUG Process finished, return code=1
> 2021-11-17T06:45:38Z DEBUG stdout=
> 2021-11-17T06:45:38Z DEBUG stderr=Job for [e-mail] failed because the control process exited with error code.
> See "systemctl status [e-mail]" and "journalctl -xe" for details.
>
> 2021-11-17T06:45:38Z ERROR IPA server upgrade failed: Inspect /var/log/ipaupgrade.log and run command ipa-server-upgrade manually.
> 2021-11-17T06:45:38Z DEBUG Process finished, return code=1
> 2021-11-17T06:45:38Z DEBUG stdout=
> 2021-11-17T06:45:38Z DEBUG stderr=Job for [e-mail] failed because the control process exited with error code.
> See "systemctl status [e-mail]" and "journalctl -xe" for details.
>
> 2021-11-17T06:45:38Z 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 1584, in upgrade_configuration
>     ds.start(ds.serverid)
>   File "/usr/lib/python3.6/site-packages/ipaserver/install/dsinstance.py", line 652, in start
>     instance_name, capture_output=capture_output, wait=wait
>   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/redhat/services.py", line 138, in 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-17T06:45:38Z DEBUG The ipa-server-upgrade command failed, exception: CalledProcessError: CalledProcessError(Command ['/bin/systemctl', 'start', '[e-mail]'] returned non-zero exit status 1: 'Job for [e-mail] failed because the control process exited with error code.\nSee "systemctl status [e-mail]" and "journalctl -xe" for details.\n')
> 2021-11-17T06:45:38Z ERROR Unexpected error - see /var/log/ipaupgrade.log for details:
> CalledProcessError: CalledProcessError(Command ['/bin/systemctl', 'start', '[e-mail]'] returned non-zero exit status 1: 'Job for [e-mail] failed because the control process exited with error code.\nSee "systemctl status [e-mail]" and "journalctl -xe" for details.\n')
> 2021-11-17T06:45:38Z ERROR The ipa-server-upgrade command failed. See /var/log/ipaupgrade.log for more information
> 2021-11-17T06:45:38Z DEBUG Traceback (most recent call last):
>   File "/usr/lib/python3.6/site-packages/ipaserver/install/service.py", line 635, in start_creation
>     run_step(full_msg, method)
>   File "/usr/lib/python3.6/site-packages/ipaserver/install/service.py", line 621, in run_step
>     method()
>   File "/usr/lib/python3.6/site-packages/ipaserver/install/upgradeinstance.py", line 104, in __start
>     srv.start(self.serverid, ldapi=True)
>   File "/usr/lib/python3.6/site-packages/ipaplatform/redhat/services.py", line 138, in 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
> ipapython.ipautil.CalledProcessError: CalledProcessError(Command ['/bin/systemctl', 'start', '[e-mail]'] returned non-zero exit status 1: 'Job for [e-mail] failed because the control process exited with error code.\nSee "systemctl status [e-mail]" and "journalctl -xe" for details.\n')
>
> 2021-11-17T06:45:38Z DEBUG   [error] CalledProcessError: CalledProcessError(Command ['/bin/systemctl', 'start', '[e-mail]'] returned non-zero exit status 1: 'Job for [e-mail] failed because the control process exited with error code.\nSee "systemctl status [e-mail]" and "journalctl -xe" for details.\n')
> 2021-11-17T06:45:38Z DEBUG   [cleanup]: stopping directory server
> 2021-11-17T06:45:38Z DEBUG Starting external process
> 2021-11-17T06:45:38Z DEBUG args=['/bin/systemctl', 'stop', '[e-mail]']
> 2021-11-17T06:45:38Z DEBUG Process finished, return code=0
> 2021-11-17T06:45:38Z DEBUG stdout=
> 2021-11-17T06:45:38Z DEBUG stderr=
> 2021-11-17T06:45:38Z DEBUG Stop of [e-mail] complete
> 2021-11-17T06:45:38Z DEBUG step duration: dirsrv __stop_instance 0.02 sec
> 2021-11-17T06:45:38Z DEBUG   [cleanup]: restoring configuration
> 2021-11-17T06:45:38Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
> 2021-11-17T06:45:38Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
> 2021-11-17T06:45:38Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
> 2021-11-17T06:45:38Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
> 2021-11-17T06:45:38Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
> 2021-11-17T06:45:38Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
> 2021-11-17T06:45:38Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
> 2021-11-17T06:45:38Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
> 2021-11-17T06:45:38Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
> 2021-11-17T06:45:38Z DEBUG step duration: dirsrv __restore_config 0.09 sec
> 2021-11-17T06:45:38Z ERROR IPA server upgrade failed: Inspect /var/log/ipaupgrade.log and run command ipa-server-upgrade manually.
> 2021-11-17T06:45:38Z 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 1946, in upgrade
>     data_upgrade.create_instance()
>   File "/usr/lib/python3.6/site-packages/ipaserver/install/upgradeinstance.py", line 134, in create_instance
>     runtime=90)
>   File "/usr/lib/python3.6/site-packages/ipaserver/install/service.py", line 635, in start_creation
>     run_step(full_msg, method)
>   File "/usr/lib/python3.6/site-packages/ipaserver/install/service.py", line 621, in run_step
>     method()
>   File "/usr/lib/python3.6/site-packages/ipaserver/install/upgradeinstance.py", line 104, in __start
>     srv.start(self.serverid, ldapi=True)
>   File "/usr/lib/python3.6/site-packages/ipaplatform/redhat/services.py", line 138, in 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-17T06:45:38Z DEBUG The ipa-server-upgrade command failed, exception: CalledProcessError: CalledProcessError(Command ['/bin/systemctl', 'start', '[e-mail]'] returned non-zero exit status 1: 'Job for [e-mail] failed because the control process exited with error code.\nSee "systemctl status [e-mail]" and "journalctl -xe" for details.\n')
> 2021-11-17T06:45:38Z ERROR Unexpected error - see /var/log/ipaupgrade.log for details:
> CalledProcessError: CalledProcessError(Command ['/bin/systemctl', 'start', '[e-mail]'] returned non-zero exit status 1: 'Job for [e-mail] failed because the control process exited with error code.\nSee "systemctl status [e-mail]" and "journalctl -xe" for details.\n')
> 2021-11-17T06:45:38Z ERROR The ipa-server-upgrade command failed. See /var/log/ipaupgrade.log for more information
>
> On both nodes, several IPA services such as named-pkcs11, ipa-custodia, krb5kdc and kdamin are now disabled in systemd. Of course, they were enabled before the update, since both nodes were serving DNS and kerberos requests. I can re-enable and start most of those services without an error except:
> dirsv@PEP06-IPA-FR, which seems OK on node #02 (ros-ass-ipa-02), but refuses to start on node #01 (ros-ass-ipa-01):
>
> nov. 17 09:17:17 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr systemd[1]: Starting 389 Directory Server IPA-PEP06-FR....
> nov. 17 09:17:17 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr ns-slapd[5880]: [17/Nov/2021:09:17:17.220419556 +0100] - WARN - str2entry_dupcheckEntry (%s), ignoring invalid line "%s"...
> nov. 17 09:17:17 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr ns-slapd[5880]:  - [17/Nov/2021:09:17:17.572658255 +0100] - NOTICE - config_set_port - Non-Secure Port Disabled
> nov. 17 09:17:17 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr ns-slapd[5880]: [17/Nov/2021:09:17:17.637702405 +0100] - WARN - str2entry_dupcheckEntry (%s), ignoring invalid line "%s"...
> nov. 17 09:17:17 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr ns-slapd[5880]:  - [17/Nov/2021:09:17:17.641830897 +0100] - ERR - slapi_entry_schema_check_ext - Entry "cn=SHA,cn=Password Storage Schemes,cn=plugins,cn=config" required attribute "objectclass" missing
> nov. 17 09:17:17 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr ns-slapd[5880]: [17/Nov/2021:09:17:17.644760642 +0100] - ERR - init_dse_file - Could not load config file [dse.ldif]
> nov. 17 09:17:17 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr ns-slapd[5880]: [17/Nov/2021:09:17:17.647669444 +0100] - ERR - setup_internal_backends - Please edit the file to correct the reported problems and then restart the server.
> nov. 17 09:17:17 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr systemd[1]: [e-mail]: Main process exited, code=exited, status=1/FAILURE
> nov. 17 09:17:17 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr systemd[1]: [e-mail]: Failed with result 'exit-code'.
> nov. 17 09:17:17 ros-ass-ipa-01.core.ass.ros.ipa.pep06.fr systemd[1]: Failed to start 389 Directory Server IPA-PEP06-FR..
> named-pkcs11, which throws an "initializing DST: PKCS#11 initialization failed" error, on both nodes:
>
> 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.
>
> I could not find much info about the BIND error. It is usually related to HSM configuration errors, but I couldn't find what's wrong:
>
> [root@ros-ass-ipa-01 ~]# grep SOFTHSM2_CONF /etc/sysconfig/named
> SOFTHSM2_CONF=/etc/ipa/dnssec/softhsm2.conf
>
> [root@ros-ass-ipa-01 ~]# SOFTHSM2_CONF=/etc/ipa/dnssec/softhsm2.conf softhsm2-util --show-slots
> Available slots:
> Slot 1594851657
>     Slot info:
>         Description:      SoftHSM slot ID 0x5f0f8149
>         Manufacturer ID:  SoftHSM project
>         Hardware version: 2.6
>         Firmware version: 2.6
>         Token present:    yes
>     Token info:
>         Manufacturer ID:  SoftHSM project
>         Model:            SoftHSM v2
>         Hardware version: 2.6
>         Firmware version: 2.6
>         Serial number:    4a9fc4075f0f8149
>         Initialized:      yes
>         User PIN init.:   yes
>         Label:            ipaDNSSEC
> Slot 1
>     Slot info:
>         Description:      SoftHSM slot ID 0x1
>         Manufacturer ID:  SoftHSM project
>         Hardware version: 2.6
>         Firmware version: 2.6
>         Token present:    yes
>     Token info:
>         Manufacturer ID:  SoftHSM project
>         Model:            SoftHSM v2
>         Hardware version: 2.6
>         Firmware version: 2.6
>         Serial number:
>         Initialized:      no
>         User PIN init.:   no
>         Label:
>
> I tried re-running the IPA upgrade manually, and it failed on both nodes at the exact same step as during the automatic upgrade. While node #02 seems mostly OK (dirsrv and KDC are running, kinit does work; only named-pkcs11 is down), node #01 was more damaged as the directory server does not even start anymore.
>
> Full upgrade logs:
> Node #01 (ros-ass-ipa-01):  https://gist.github.com/marinbernard-pep06/548c4aea3006e18b5f86cda6f935f2c5
> Node #02 (ros-ass-ipa-02): https://gist.github.com/marinbernard-pep06/7e5a76712cc4b23101f1fab39315f870
>
> I would be **very** grateful to anyone sharing insight about this situation.
>
> Thank you!
> _______________________________________________
> FreeIPA-users mailing list -- [e-mail]
> To unsubscribe send an email to [e-mail]
> Fedora Code of Conduct: https://docs.fedoraproject.org/en-US/project/code-of-conduct/
> List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
> List Archives: https://lists.fedorahosted.org/archives/list/[e-mail]...
> Do not reply to spam on the list, report it: https://pagure.io/fedora-infrastructure

[Marin BERNARD]

Hi François,

Both systems are using Java 1.8.0.312.b07, installed on 2021-10-21:

[root@ros-ass-ipa-02 ~]# dnf list installed java-*
Paquets installés
java-1.8.0-openjdk.x86_64                         1:1.8.0.312.b07-1.el8_4                 @ol8_appstream
java-1.8.0-openjdk-devel.x86_64                   1:1.8.0.312.b07-1.el8_4                 @ol8_appstream
java-1.8.0-openjdk-headless.x86_64                1:1.8.0.312.b07-1.el8_4                 @ol8_appstream

[root@ros-ass-ipa-02 ~]# rpm -qa --last | grep java-1.8.0-openjdk-
java-1.8.0-openjdk-devel-1.8.0.312.b07-1.el8_4.x86_64 jeu. 21 oct. 2021 06:15:20 CEST
java-1.8.0-openjdk-1.8.0.312.b07-1.el8_4.x86_64 jeu. 21 oct. 2021 06:15:17 CEST
java-1.8.0-openjdk-headless-1.8.0.312.b07-1.el8_4.x86_64 jeu. 21 oct. 2021 06:15:16 CEST

At least one IPA upgrade completed successfully on both nodes with the current Java version (I have logs for a successful upgrade on 2021-11-12), so the current Java version seems OK.

Thank you,
--
Marin

[Marin BERNARD]

Hi again,

It seems named-pkcs11 fails to start because it cannot read PKCS11 objects from the HSM.

Yet, user 'named' is able to access the HSM, at least interactively:

[root@ros-ass-ipa-02 ~]# sudo -u named bash
bash-4.4$ cd
bash-4.4$ export SOFTHSM2_CONF=/etc/ipa/dnssec/softhsm2.conf
bash-4.4$ export SOFTHSM2_PIN="$(cat /var/lib/ipa/dnssec/softhsm_pin)"
bash-4.4$ softhsm2-util --show-slots
Available slots:
Slot 1007503753
    Slot info:
        Description:      SoftHSM slot ID 0x3c0d4989
        Manufacturer ID:  SoftHSM project
        Hardware version: 2.4
        Firmware version: 2.4
        Token present:    yes
    Token info:
        Manufacturer ID:  SoftHSM project
        Model:            SoftHSM v2
        Hardware version: 2.4
        Firmware version: 2.4
        Serial number:    226b9cd63c0d4989
        Initialized:      yes
        User PIN init.:   yes
        Label:            ipaDNSSEC
Slot 1
    Slot info:
        Description:      SoftHSM slot ID 0x1
        Manufacturer ID:  SoftHSM project
        Hardware version: 2.4
        Firmware version: 2.4
        Token present:    yes
    Token info:
        Manufacturer ID:  SoftHSM project
        Model:            SoftHSM v2
        Hardware version: 2.4
        Firmware version: 2.4
        Serial number:
        Initialized:      no
        User PIN init.:   no
        Label:
bash-4.4$ pkcs11-list -p "${SOFTHSM2_PIN}" -s 1007503753
slot 1007503753
object[0]: handle 2 class 3 label[56] 'dnssec-replica:ros-ass-ipa-02.core.ass.ros.ipa.pep06.fr.' id[16] 0xb1fab57b623bf846... E:never
object[1]: handle 3 class 2 label[56] 'dnssec-replica:ros-ass-ipa-02.core.ass.ros.ipa.pep06.fr.' id[16] 0xb1fab57b623bf846...

Of course, specifying a non-existent slot ID returns a terminating error:

bash-4.4$ pkcs11-list -p "${SOFTHSM2_PIN}" -s 0
Unrecoverable error initializing PKCS#11: not found
Unrecoverable error initializing PKCS#11: not found

We can also list PKCS11 tokens:

bash-4.4$ pkcs11-tokens
DEFAULTS
        rand_token=0x55ae13fa0180
        best_rsa_token=0x55ae13fa0180
        best_dsa_token=0x55ae13fa0180
        best_dh_token=0x55ae13fa0180
        digest_token=0x55ae13fa0180
        best_ec_token=0x55ae13fa0180
        best_gost_token=(nil)
        aes_token=0x55ae13fa0180

TOKEN
        address=0x55ae13fa0180
        slotID=1007503753
        label=ipaDNSSEC
        manufacturerID=SoftHSM project
        model=SoftHSM v2
        serialNumber=226b9cd63c0d4989
        supported operations=0x17e (RANDRSA,DSA,DH,DIGEST,EC,AES)

TOKEN
        address=0x55ae13fa0320
        slotID=1
        label=
        manufacturerID=SoftHSM project
        model=SoftHSM v2
        serialNumber=
        supported operations=0x17e (RANDRSA,DSA,DH,DIGEST,EC,AES)

File permissions seem OK. Putting SELinux in permissive mode did not help.
What else could prevent BIND from accessing the HSM ?