#5104 F20-F21 update and crashing bind-pkcs11
Closed: Invalid Opened by alich.

I was doing the testing of upgrades, from Fedora 20 to Fedora 21. I was using "fedup" and everything went almost OK. Now I'm on the state where system seems to be updated but there is a problem with bind-pkcs11 package and that also means that freeipa-server cannot start (in my configuration). See my logs...

[root@vm-095 ~]# journalctl -xe
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit named-pkcs11.service has failed.
--
-- The result is failed.
Jul 07 18:30:19 vm-095.idm.lab.eng.brq.redhat.com systemd[1]: Unit named-pkcs11.service entered failed state.
Jul 07 18:30:19 vm-095.idm.lab.eng.brq.redhat.com systemd[1]: named-pkcs11.service failed.
Jul 07 18:39:30 vm-095.idm.lab.eng.brq.redhat.com named-checkconf[1820]: zone localhost.localdomain/IN: loaded serial 0
Jul 07 18:39:30 vm-095.idm.lab.eng.brq.redhat.com named-pkcs11[1826]: starting BIND 9.9.6-P1-RedHat-9.9.6-8.P1.fc21 -u named
Jul 07 18:39:30 vm-095.idm.lab.eng.brq.redhat.com named-pkcs11[1826]: built with '--build=x86_64-redhat-linux-gnu' '--host=x86_64-redhat-linux-gnu' '--program-prefix=' '--disab
Jul 07 18:39:30 vm-095.idm.lab.eng.brq.redhat.com named-pkcs11[1826]: ----------------------------------------------------
Jul 07 18:39:30 vm-095.idm.lab.eng.brq.redhat.com named-pkcs11[1826]: BIND 9 is maintained by Internet Systems Consortium,
Jul 07 18:39:30 vm-095.idm.lab.eng.brq.redhat.com named-pkcs11[1826]: Inc. (ISC), a non-profit 501(c)(3) public-benefit
Jul 07 18:39:30 vm-095.idm.lab.eng.brq.redhat.com named-pkcs11[1826]: corporation. Support and training for BIND 9 are
Jul 07 18:39:30 vm-095.idm.lab.eng.brq.redhat.com named-pkcs11[1826]: available at https://www.isc.org/support
Jul 07 18:39:30 vm-095.idm.lab.eng.brq.redhat.com named-pkcs11[1826]: ----------------------------------------------------
Jul 07 18:39:30 vm-095.idm.lab.eng.brq.redhat.com named-pkcs11[1826]: adjusted limit on open files from 4096 to 1048576
Jul 07 18:39:30 vm-095.idm.lab.eng.brq.redhat.com named-pkcs11[1826]: found 1 CPU, using 1 worker thread
Jul 07 18:39:30 vm-095.idm.lab.eng.brq.redhat.com named-pkcs11[1826]: using 1 UDP listener per interface
Jul 07 18:39:30 vm-095.idm.lab.eng.brq.redhat.com named-pkcs11[1826]: using up to 4096 sockets
Jul 07 18:39:30 vm-095.idm.lab.eng.brq.redhat.com named-pkcs11[1826]: ObjectStore.cpp(59): Failed to enumerate object store in /var/lib/softhsm/tokens/
Jul 07 18:39:30 vm-095.idm.lab.eng.brq.redhat.com named-pkcs11[1826]: SoftHSM.cpp(437): Could not load the object store
Jul 07 18:39:30 vm-095.idm.lab.eng.brq.redhat.com named-pkcs11[1826]: initializing DST: PKCS#11 initialization failed
Jul 07 18:39:30 vm-095.idm.lab.eng.brq.redhat.com named-pkcs11[1826]: exiting (due to fatal error)
Jul 07 18:39:30 vm-095.idm.lab.eng.brq.redhat.com systemd[1]: named-pkcs11.service: control process exited, code=exited status=1
Jul 07 18:39:30 vm-095.idm.lab.eng.brq.redhat.com systemd[1]: Failed to start Berkeley Internet Name Domain (DNS) with native PKCS#11.
-- Subject: Unit named-pkcs11.service has failed
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit named-pkcs11.service has failed.
--
-- The result is failed.
Jul 07 18:39:30 vm-095.idm.lab.eng.brq.redhat.com systemd[1]: Unit named-pkcs11.service entered failed state.
Jul 07 18:39:30 vm-095.idm.lab.eng.brq.redhat.com systemd[1]: named-pkcs11.service failed.
Jul 07 18:39:30 vm-095.idm.lab.eng.brq.redhat.com named-checkconf[1820]: zone localhost/IN: loaded serial 0
Jul 07 18:39:30 vm-095.idm.lab.eng.brq.redhat.com named-checkconf[1820]: zone 1.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.ip6.arpa/IN: loaded serial 0
Jul 07 18:39:30 vm-095.idm.lab.eng.brq.redhat.com named-checkconf[1820]: zone 1.0.0.127.in-addr.arpa/IN: loaded serial 0
Jul 07 18:39:30 vm-095.idm.lab.eng.brq.redhat.com named-checkconf[1820]: zone 0.in-addr.arpa/IN: loaded serial 0

[root@vm-095 ~]# ipa-dns-install

The log file for this installation can be found in /var/log/ipaserver-install.log

This program will setup DNS for the FreeIPA Server.

This includes:
- Configure DNS (bind)
- Configure SoftHSM (required by DNSSEC)
- Configure ipa-dnskeysyncd (required by DNSSEC)

NOTE: DNSSEC zone signing is not enabled by default

To accept the default shown in brackets, press the Enter key.

Existing BIND configuration detected, overwrite? [no]: yes
Directory Manager password:

Do you want to configure DNS forwarders? [yes]: yes
Enter the IP address of DNS forwarder to use, or press Enter to finish.
Enter IP address for a DNS forwarder: 10.34.47.2
DNS forwarder 10.34.47.2 added
Enter IP address for a DNS forwarder: 10.34.47.1
DNS forwarder 10.34.47.1 added
Enter IP address for a DNS forwarder:
Checking forwarders, please wait ...

The following operations may take some minutes to complete.
Please wait until the prompt is returned.

Configuring DNS (named)
[1/8]: generating rndc key file
[2/8]: setting up our own record
[3/8]: adding NS record to the zones
[4/8]: setting up CA record
[5/8]: setting up kerberos principal
[6/8]: setting up named.conf
[7/8]: configuring named to start on boot
[8/8]: changing resolv.conf to point to ourselves
Done configuring DNS (named).
Configuring DNS key synchronization service (ipa-dnskeysyncd)
[1/7]: checking status
[2/7]: setting up bind-dyndb-ldap working directory
[3/7]: setting up kerberos principal
[4/7]: setting up SoftHSM
[5/7]: adding DNSSEC containers
[6/7]: creating replica keys
[error] ObjectclassViolation: unknown object class "ipaPublicKeyObject"
Unexpected error - see /var/log/ipaserver-install.log for details:
ObjectclassViolation: unknown object class "ipaPublicKeyObject"
[root@vm-095 ~]#

[root@vm-095 ~]# rpm -q freeipa-server 389-ds-base bind-pkcs11 bind-dyndb-ldap
freeipa-server-4.1.4-1.fc21.x86_64
389-ds-base-1.3.3.8-1.fc21.x86_64
bind-pkcs11-9.9.6-8.P1.fc21.x86_64
bind-dyndb-ldap-6.1-1.fc21.x86_64

[root@vm-095 ~]# systemctl restart named-pkcs11.service
Job for named-pkcs11.service failed. See "systemctl status named-pkcs11.service" and "journalctl -xe" for details.
[root@vm-095 ~]# journalctl -xe
#5 0x00007f9ef55c9fe8 isc_sha1_init (libisc-pkcs11.so.95)
#6 0x00007f9ef55d8ba6 isc_entropy_getdata (libisc-pkcs11.so.95)
#7 0x00007f9ef55b2ea5 isc_hash_ctxinit (libisc-pkcs11.so.95)
#8 0x00007f9ef55b33bd isc_hash_calc (libisc-pkcs11.so.95)
#9 0x00007f9ef588eb8e dns_rbt_addnode (libdns-pkcs11.so.104)
#10 0x00007f9ef58a881d dns_rbtdb_create (libdns-pkcs11.so.104)
#11 0x00007f9ef584a372 dns_db_create (libdns-pkcs11.so.104)
#12 0x00007f9ef590ef40 dns_rootns_create (libdns-pkcs11.so.104)
#13 0x00007f9ef60668f2 ns_server_create (named-pkcs11)
#14 0x00007f9ef603e655 main (named-pkcs11)
#15 0x00007f9ef297ffe0 __libc_start_main (libc.so.6)
#16 0x00007f9ef603e922 _start (named-pkcs11)

                                                                      Stack trace of thread 2180:
                                                                      #0  0x00007f9ef37b2590 pthread_cond_wait@@GLIBC_2.3.2 (libpthread.so.0)
                                                                      #1  0x00007f9ef55cec0a run (libisc-pkcs11.so.95)
                                                                      #2  0x00007f9ef37ad52a start_thread (libpthread.so.0)
                                                                      #3  0x00007f9ef2a6022d __clone (libc.so.6)
                                                                      Stack trace of thread 2182:
                                                                      #0  0x00007f9ef2a60833 epoll_wait (libc.so.6)
                                                                      #1  0x00007f9ef55e14fe watcher (libisc-pkcs11.so.95)
                                                                      #2  0x00007f9ef37ad52a start_thread (libpthread.so.0)
                                                                      #3  0x00007f9ef2a6022d __clone (libc.so.6)
                                                                      Stack trace of thread 2181:
                                                                      #0  0x00007f9ef37b2590 pthread_cond_wait@@GLIBC_2.3.2 (libpthread.so.0)
                                                                      #1  0x00007f9ef55d3f2f run (libisc-pkcs11.so.95)
                                                                      #2  0x00007f9ef37ad52a start_thread (libpthread.so.0)
                                                                      #3  0x00007f9ef2a6022d __clone (libc.so.6)

-- Subject: Process 2179 (named-pkcs11) dumped core
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- Documentation: man:core(5)
--
-- Process 2179 (named-pkcs11) crashed and dumped core.
--
-- This usually indicates a programming error in the crashing program and
-- should be reported to its vendor as a bug.


Was the upgrade successfull?

Did you run ipa-ldap-updater --upgrade and ipa-upgradeconfig in proper order?

Can you isnpect /var/log/ipaupgrade.log for errors?

Well, after:
ipa-ldap-updater --upgrade
ipa-upgradeconfig
everything worked fine (thanks mbasti for help). Closing this ticket (and opening bug for bind package).

Metadata Update from @alich:
- Issue assigned to someone
- Issue set to the milestone: 0.0 NEEDS_TRIAGE

Metadata