Forum Stats

  • 3,771,078 Users
  • 2,253,218 Discussions
  • 7,875,738 Comments

Discussions

IPA server crash after upgrade to OL8.5

User_1SDTX
User_1SDTX Member Posts: 3 Green Ribbon
edited Nov 17, 2021 2:14PM in Oracle Linux

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!

Tagged:

Comments

  • User_1SDTX
    User_1SDTX Member Posts: 3 Green Ribbon
    edited Nov 17, 2021 2:07PM

    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:

    [[email protected] ~]# 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 ?

  • User_1SDTX
    User_1SDTX Member Posts: 3 Green Ribbon

    Hi,

    I was able to fix BIND startup by downgrading the bind and bind-* packages from version 9.11.26-6 to 9.11.26-4. This is only a temporary fix, but it points towards a possible regression. The discussion continues on the FreeIPA bug tracker.