1984011 – DNSSEC related crashes in DNS managed by FreeIPA

RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.

Bug 1984011 - DNSSEC related crashes in DNS managed by FreeIPA

Summary: DNSSEC related crashes in DNS managed by FreeIPA

Keywords:
Status:	CLOSED WONTFIX
Alias:	None
Product:	Red Hat Enterprise Linux 9
Classification:	Red Hat
Component:	ipa
Sub Component:
Version:	unspecified
Hardware:	Unspecified
OS:	Unspecified
Priority:	unspecified
Severity:	unspecified
Target Milestone:	beta
Target Release:	---
Assignee:	Florence Blanc-Renaud
QA Contact:	ipa-qe
Docs Contact:
URL:
Whiteboard:
Depends On:	1978319
Blocks:
TreeView+	depends on / blocked

Reported:	2021-07-20 12:12 UTC by Petr Čech
Modified:	2023-01-20 07:27 UTC (History)
CC List:	16 users (show)
Fixed In Version:
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:	1978319
Environment:
Last Closed:	2023-01-20 07:27:41 UTC
Type:	Bug
Target Upstream Version:
Embargoed:
Dependent Products:

Attachments	(Terms of Use)

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Red Hat Issue Tracker	FREEIPA-9233	0	None	None	None	2022-12-21 07:34:12 UTC

Description Petr Čech 2021-07-20 12:12:22 UTC

+++ This bug was initially created as a clone of Bug #1978319 +++

I'm still working to produce an exact reproduction routine on this - however this is what I currently have:

Jun 30 02:21:15 ipa-dnskeysyncd[3047]: ipapython.ipautil: DEBUG    Starting external process
Jun 30 02:21:15 ipa-dnskeysyncd[3047]: ipapython.ipautil: DEBUG    args=['/usr/sbin/dnssec-keyfromlabel', '-K', '/var/named/dyndb-ldap/ipa/master/crc.id.au/tmplwvl5nae', '-a', b'RSASHA256', '-l', b'pkcs11:object=6a7e54fa1b34add8262a092919e6f0c7;pin-source=/var/lib/ipa/dnssec/softhsm_pin', '-P', b'20200516111958', '-A', 'none', '-I', 'none', '-D', 'none', '-E', 'pkcs11', 'crc.id.au.']
Jun 30 02:21:15 dnssec-keyfromlabel[3061]: Configuration.cpp(96): Missing log.level in configuration. Using default value: INFO
Jun 30 02:21:15 dnssec-keyfromlabel[3061]: Configuration.cpp(96): Missing slots.mechanisms in configuration. Using default value: ALL
Jun 30 02:21:15 dnssec-keyfromlabel[3061]: Configuration.cpp(124): Missing slots.removable in configuration. Using default value: false
Jun 30 02:21:15 kernel: dnssec-keyfroml[3061]: segfault at 18 ip 00007f6fa8574a84 sp 00007fffb47d9968 error 4 in libsofthsm2.so[7f6fa84de000+9a000]
Jun 30 02:21:15 kernel: Code: db 74 0a 48 89 5c 24 10 e9 65 fe ff ff 48 83 c4 28 5b 5d 41 5c 41 5d 41 5e 41 5f c3 66 2e 0f 1f 84 00 00 00 00 00 f3 0f 1e fa <48> 8b 47 18 48 85 c0 74 44 4c 8d 47 10 4c 89 c7 eb 12 66 2e 0f 1f
Jun 30 02:21:15 systemd[1]: Started Process Core Dump (PID 3062/UID 0).
Jun 30 02:21:15 systemd[1]: ipa-ods-exporter.service: Deactivated successfully.
Jun 30 02:21:15 systemd[1]: ipa-ods-exporter.service: Consumed 1.679s CPU time.
Jun 30 02:21:15 systemd-coredump[3063]: [🡕] Process 3061 (dnssec-keyfroml) of user 997 dumped core.
                                                      
                                                      Stack trace of thread 3061:
                                                      #0  0x00007f6fa8574a84 _ZN11SlotManager7getSlotEm (libsofthsm2.so + 0xaba84)
                                                      #1  0x00007f6fa850c0ed _ZN7SoftHSM18C_CloseAllSessionsEm (libsofthsm2.so + 0x430ed)
                                                      #2  0x00007f6fa84eba08 C_CloseAllSessions (libsofthsm2.so + 0x22a08)
                                                      #3  0x00007f6fa85f8aa9 pkcs11_release_slot (pkcs11.so + 0xaaa9)
                                                      #4  0x00007f6fa85f8bff engine_finish (pkcs11.so + 0xabff)
                                                      #5  0x00007f6fa8d23c32 engine_unlocked_finish (libcrypto.so.1.1 + 0x111c32)
                                                      #6  0x00007f6fa8d23d66 int_cleanup_cb_doall (libcrypto.so.1.1 + 0x111d66)
                                                      #7  0x00007f6fa8d55d5c OPENSSL_LH_doall (libcrypto.so.1.1 + 0x143d5c)
                                                      #8  0x00007f6fa8d2284c engine_unregister_all_RSA (libcrypto.so.1.1 + 0x11084c)
                                                      #9  0x00007f6fa8d1faca engine_cleanup_cb_free.lto_priv.0 (libcrypto.so.1.1 + 0x10daca)
                                                      #10 0x00007f6fa8d93180 OPENSSL_sk_pop_free (libcrypto.so.1.1 + 0x181180)
                                                      #11 0x00007f6fa8d50f64 OPENSSL_cleanup (libcrypto.so.1.1 + 0x13ef64)
                                                      #12 0x00007f6fa8fdc0de n/a (libc.so.6 + 0x400de)
                                                      #13 0x00007f6fa8c8e1d7 __do_global_dtors_aux (libcrypto.so.1.1 + 0x7c1d7)
                                                      #14 0x00007f6fa94489bc _dl_fini (ld-linux-x86-64.so.2 + 0x109bc)
                                                      #15 0x00007f6fa8fdbaf7 n/a (libc.so.6 + 0x3faf7)
                                                      #16 0x00007f6fa8fdbca0 n/a (libc.so.6 + 0x3fca0)
                                                      #17 0x0000557c08a7486a fatal (dnssec-keyfromlabel + 0x586a)
                                                      #18 0x0000557c08a74156 main (dnssec-keyfromlabel + 0x5156)
                                                      #19 0x00007f6fa8fc3b75 n/a (libc.so.6 + 0x27b75)
                                                      #20 0x0000557c08a7419e _start (dnssec-keyfromlabel + 0x519e)
Jun 30 02:21:15 ipa-dnskeysyncd[3047]: ipapython.ipautil: DEBUG    Process finished, return code=-11
Jun 30 02:21:15 ipa-dnskeysyncd[3047]: ipapython.ipautil: DEBUG    stdout=
Jun 30 02:21:15 ipa-dnskeysyncd[3047]: ipapython.ipautil: DEBUG    stderr=Found uninitialized token
Jun 30 02:21:15 ipa-dnskeysyncd[3047]: Found uninitialized token
Jun 30 02:21:15 ipa-dnskeysyncd[3047]: Key not found.
Jun 30 02:21:15 ipa-dnskeysyncd[3047]: PKCS11_load_public_key returned NULL
Jun 30 02:21:15 ipa-dnskeysyncd[3047]: Found uninitialized token
Jun 30 02:21:15 ipa-dnskeysyncd[3047]: Key not found.
Jun 30 02:21:15 ipa-dnskeysyncd[3047]: PKCS11_get_private_key returned NULL
Jun 30 02:21:15 ipa-dnskeysyncd[3047]: dnssec-keyfromlabel: warning: ENGINE_load_private_key failed (not found)
Jun 30 02:21:15 ipa-dnskeysyncd[3047]: dnssec-keyfromlabel: fatal: failed to get key crc.id.au/RSASHA256: not found
Jun 30 02:21:15 systemd[1]: systemd-coredump: Deactivated successfully.
Jun 30 02:21:15 ipa-dnskeysyncd[3047]: Traceback (most recent call last):
Jun 30 02:21:15 ipa-dnskeysyncd[3047]:   File "/usr/libexec/ipa/ipa-dnskeysyncd", line 113, in <module>
Jun 30 02:21:15 ipa-dnskeysyncd[3047]:     while ldap_connection.syncrepl_poll(all=1, msgid=ldap_search):
Jun 30 02:21:15 ipa-dnskeysyncd[3047]:   File "/usr/lib64/python3.9/site-packages/ldap/syncrepl.py", line 465, in syncrepl_poll
Jun 30 02:21:15 ipa-dnskeysyncd[3047]:     self.syncrepl_refreshdone()
Jun 30 02:21:15 ipa-dnskeysyncd[3047]:   File "/usr/lib/python3.9/site-packages/ipaserver/dnssec/keysyncer.py", line 128, in syncrepl_refreshdone
Jun 30 02:21:15 ipa-dnskeysyncd[3047]:     self.bindmgr.sync(self.dnssec_zones)
Jun 30 02:21:15 ipa-dnskeysyncd[3047]:   File "/usr/lib/python3.9/site-packages/ipaserver/dnssec/bindmgr.py", line 231, in sync
Jun 30 02:21:15 ipa-dnskeysyncd[3047]:     self.sync_zone(zone)
Jun 30 02:21:15 ipa-dnskeysyncd[3047]:   File "/usr/lib/python3.9/site-packages/ipaserver/dnssec/bindmgr.py", line 204, in sync_zone
Jun 30 02:21:15 ipa-dnskeysyncd[3047]:     self.install_key(zone, uuid, attrs, tempdir)
Jun 30 02:21:15 ipa-dnskeysyncd[3047]:   File "/usr/lib/python3.9/site-packages/ipaserver/dnssec/bindmgr.py", line 145, in install_key
Jun 30 02:21:15 ipa-dnskeysyncd[3047]:     result = ipautil.run(cmd, capture_output=True)
Jun 30 02:21:15 ipa-dnskeysyncd[3047]:   File "/usr/lib/python3.9/site-packages/ipapython/ipautil.py", line 598, in run
Jun 30 02:21:15 ipa-dnskeysyncd[3047]:     raise CalledProcessError(
Jun 30 02:21:15 ipa-dnskeysyncd[3047]: ipapython.ipautil.CalledProcessError: CalledProcessError(Command ['/usr/sbin/dnssec-keyfromlabel', '-K', '/var/named/dyndb-ldap/ipa/master/crc.id.au/tmplwvl5nae', '-a', b'RSASHA256', '-l', b'pkcs11:object=6a7e54fa1b34add8262a092919e6f0c7;pin-source=/var/lib/ipa/dnssec/softhsm_pin', '-P', b'20200516111958', '-A', 'none', '-I', 'none', '-D', 'none', '-E', 'pkcs11', 'crc.id.au.'] returned non-zero exit status -11: 'Found uninitialized token\nFound uninitialized token\nKey not found.\nPKCS11_load_public_key returned NULL\nFound uninitialized token\nKey not found.\nPKCS11_get_private_key returned NULL\ndnssec-keyfromlabel: warning: ENGINE_load_private_key failed (not found)\ndnssec-keyfromlabel: fatal: failed to get key crc.id.au/RSASHA256: not found\n')

Bind is still actually running - and I can see successful transfers to the publicly accessible slaves...

named does seem to throw a similar error though:
Jun 25 14:20:11 named[830]: error:80067065:pkcs11 engine:ctx_load_privkey:object not found:eng_back.c:974:
Jun 25 14:20:11 named[830]: error:26096080:engine routines:ENGINE_load_private_key:failed loading private key:crypto/engine/eng_pkey.c:77:
Jun 25 14:20:11 named[830]: dns_dnssec_findmatchingkeys: error reading key file Kcrc.id.au.+008+35215.private: not found
Jun 25 14:20:11 named[830]: ENGINE_load_private_key failed (not found)

I don't see these files in /var/named/dyndb-ldap/ipa/master/crc.id.au/keys/

It doesn't look like any file in that directory has changed since May 26th.

I can't really see anything obvious to know what direction to go with this.

It may seem like the following is a minimal reproduction:
# ipa dnszone-mod --dnssec=false example.zone.
# ipa dnszone-mod --dnssec=true example.zone.

At this point, I see crashes like the above. To resolve this, I do:
# ipactl restart

At this point, the same process runs again, crashes once, then seems to function as intended. Further restarts of freeipa using 'ipactl restart' do not produce further crashes.

Versions:
# rpm -qa | grep ipa | sort
freeipa-client-4.9.4-1.fc34.x86_64
freeipa-client-common-4.9.4-1.fc34.noarch
freeipa-common-4.9.4-1.fc34.noarch
freeipa-healthcheck-core-0.9-2.fc34.noarch
freeipa-selinux-4.9.4-1.fc34.noarch
freeipa-server-4.9.4-1.fc34.x86_64
freeipa-server-common-4.9.4-1.fc34.noarch
freeipa-server-dns-4.9.4-1.fc34.noarch
freeipa-server-trust-ad-4.9.4-1.fc34.x86_64
libipa_hbac-2.5.1-2.fc34.x86_64
python3-ipaclient-4.9.4-1.fc34.noarch
python3-ipalib-4.9.4-1.fc34.noarch
python3-ipaserver-4.9.4-1.fc34.noarch
python3-libipa_hbac-2.5.1-2.fc34.x86_64
sssd-ipa-2.5.1-2.fc34.x86_64

# rpm -qa | grep bind | sort
bind-9.16.18-1.fc34.x86_64
bind-dnssec-doc-9.16.18-1.fc34.noarch
bind-dnssec-utils-9.16.18-1.fc34.x86_64
bind-dyndb-ldap-11.9-2.fc34.x86_64
bind-export-libs-9.11.10-1.fc30.x86_64
bind-libs-9.16.18-1.fc34.x86_64
bind-license-9.16.18-1.fc34.noarch
bind-pkcs11-9.16.18-1.fc34.x86_64
bind-pkcs11-libs-9.16.18-1.fc34.x86_64
bind-pkcs11-utils-9.16.18-1.fc34.x86_64
bind-utils-9.16.18-1.fc34.x86_64
jackson-databind-2.11.4-2.fc34.noarch
python3-bind-9.16.18-1.fc34.noarch
rpcbind-1.2.6-0.fc34.x86_64
samba-winbind-4.14.5-0.fc34.x86_64
samba-winbind-modules-4.14.5-0.fc34.x86_64

--- Additional comment from Steven Haigh on 2021-07-01 14:28:32 UTC ---

I do note that the keys in /var/named/dyndb-ldap/ipa/master/crc.id.au/keys/ have been rewritten around the time of the restart of FreeIPA.

I'm not 100% sure where to go with this report - or how to troubleshoot further at this stage.

--- Additional comment from Florence Blanc-Renaud on 2021-07-06 14:37:19 UTC ---

2 issues have been recently identified against OpenSC/libp11 that may be related:
- https://github.com/OpenSC/libp11/issues/393 thread locking issue crashes bind9/named
  a fix is available upstream in libp11 master branch
- https://github.com/opendnssec/SoftHSMv2/issues/635 SIGSEGV: NSS + SoftHSMv2 == crash during atexit()
  no fix yet

The last upstream release of OpenDNSSec fixes another issue, and the fedora maintainer is planning to update fedora with the latest version.

We'll keep you posted when we have more information.

--- Additional comment from François Cami on 2021-07-06 15:01:17 UTC ---

OpenDNSSec 2.1.9 is building for rawhide: https://koji.fedoraproject.org/koji/taskinfo?taskID=71399188

--- Additional comment from François Cami on 2021-07-12 14:41:55 UTC ---

OpenDNSSec 2.1.9 is getting pushed to updates-testing: https://bodhi.fedoraproject.org/updates/FEDORA-2021-daba24d590

This build contains the fix for: OPENDNSSEC-955: Prevent concurrency between certain valid PKCS#11 HSM operations to avoid some keys to be (transiently) unavailable.

Comment 2 RHEL Program Management 2023-01-20 07:27:41 UTC

After evaluating this issue, there are no plans to address it further or fix it in an upcoming release.  Therefore, it is being closed.  If plans change such that this issue will be fixed in an upcoming release, then the bug can be reopened.

Note You need to log in before you can comment on or make changes to this bug.