Dec 09 08:50:07 registry1.fugazi.com python3[116629]: detected unhandled Python exception in '/usr/libexec/ipa/ipa-ods-exporter' Dec 09 08:50:07 registry1.fugazi.com ipa-ods-exporter[116629]: Traceback (most recent call last): Dec 09 08:50:07 registry1.fugazi.com ipa-ods-exporter[116629]: File "/usr/libexec/ipa/ipa-ods-exporter", line 715, in <module> Dec 09 08:50:07 registry1.fugazi.com ipa-ods-exporter[116629]: master2ldap_zone_keys_sync(ldapkeydb, localhsm) Dec 09 08:50:07 registry1.fugazi.com ipa-ods-exporter[116629]: File "/usr/libexec/ipa/ipa-ods-exporter", line 424, in master2ldap_zone_keys_sync Dec 09 08:50:07 registry1.fugazi.com ipa-ods-exporter[116629]: privkeys_local = localhsm.zone_privkeys Dec 09 08:50:07 registry1.fugazi.com ipa-ods-exporter[116629]: File "/usr/lib/python3.9/site-packages/ipaserver/dnssec/localhsm.py", line 173, in zone_privkeys Dec 09 08:50:07 registry1.fugazi.com ipa-ods-exporter[116629]: self.find_keys(objclass=_ipap11helper.KEY_CLASS_PRIVATE_KEY)) Dec 09 08:50:07 registry1.fugazi.com ipa-ods-exporter[116629]: File "/usr/lib/python3.9/site-packages/ipaserver/dnssec/localhsm.py", line 122, in find_keys Dec 09 08:50:07 registry1.fugazi.com ipa-ods-exporter[116629]: key = Key(self.p11, h) Dec 09 08:50:07 registry1.fugazi.com ipa-ods-exporter[116629]: File "/usr/lib/python3.9/site-packages/ipaserver/dnssec/localhsm.py", line 46, in init Dec 09 08:50:07 registry1.fugazi.com ipa-ods-exporter[116629]: assert len(cka_id) != 0, 'ipk11id length should not be 0' Dec 09 08:50:07 registry1.fugazi.com ipa-ods-exporter[116629]: AssertionError: ipk11id length should not be 0 Dec 09 08:50:08 registry1.fugazi.com abrt-server[116646]: Deleting problem directory Python3-2021-12-09-08:50:07-116629 (dup of Python3-2021-12-08-22:41:56-8656) Dec 09 08:50:08 registry1.fugazi.com systemd[1]: ipa-ods-exporter.service: Main process exited, code=exited, status=1/FAILURE Dec 09 08:50:08 registry1.fugazi.com systemd[1]: ipa-ods-exporter.service: Failed with result 'exit-code'. Dec 09 08:50:08 registry1.fugazi.com audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=ipa-ods-exporter comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed' Dec 09 08:50:08 registry1.fugazi.com systemd[1]: ipa-ods-exporter.service: Consumed 8.377s CPU time. Dec 09 08:50:08 registry1.fugazi.com abrt-notification[116658]: [🡕] Process 8656 (ipa-ods-exporter) of user 982 encountered an uncaught AssertionError exception
$ rpm -q freeipa-server freeipa-client ipa-server ipa-client 389-ds-base pki-ca krb5-server freeipa-server-4.9.6-4.fc34.x86_64 freeipa-client-4.9.6-4.fc34.x86_64 package ipa-server is not installed package ipa-client is not installed 389-ds-base-2.0.11-1.fc34.x86_64 pki-ca-10.10.6-1.fc34.noarch krb5-server-1.19.2-2.fc34.x86_64
This message:
Dec 09 08:50:08 registry1.fugazi.com abrt-server[116646]: Deleting problem directory Python3-2021-12-09-08:50:07-116629 (dup of Python3-2021-12-08-22:41:56-8656)
says that the problem was also encountered the day before. Was it with the previous version of any of these packages or also after the upgrade?
4.9.6-4 didn't change anything related to DNSSEC handling at all. In fact, all changes since -2.fc34 were related to KDC, not DNSSEC.
The crash repeats every run of the program. I just so happened to not catch the first instance of it yesterday after I ran dnf upgrade. The configuration is very basic, two vms running freeipa on fedora server, master <-> master.
Can you provide an output from running
# python /usr/lib/python3.9/site-packages/ipaserver/dnssec/localhsm.py
?
This will attempt to look into your SoftHSM token used by IPA and show replica and master keys, as well as zone keys and private keys. I don't need the keys themselves, you can cleanse the output for them, but the rest of the content and any possible exceptions would be great to see.
ipk11id must not be zero-sized because it is the ID to address a specific key and if its length is 0, we have nothing to address.
The replica completes normally. On the master: '''
... zone public keys ================ ... {'ipk11derive': False, 'ipk11encrypt': False, 'ipk11id': b'\x9cM]\xc5e\xff*\xd8\x1e\rt\xa9A\x16\xd5\xd2', 'ipk11keytype': 'rsa', 'ipk11label': '9c4d5dc565ff2ad81e0d74a94116d5d2', 'ipk11local': True, 'ipk11modifiable': True, 'ipk11private': False, 'ipk11trusted': False, 'ipk11verify': True, 'ipk11verifyrecover': True, 'ipk11wrap': False}
Traceback (most recent call last): File "/usr/lib/python3.9/site-packages/ipaserver/dnssec/localhsm.py", line 234, in <module> for key_id, zkey in localhsm.zone_privkeys.items(): File "/usr/lib/python3.9/site-packages/ipaserver/dnssec/localhsm.py", line 173, in zone_privkeys self.find_keys(objclass=_ipap11helper.KEY_CLASS_PRIVATE_KEY)) File "/usr/lib/python3.9/site-packages/ipaserver/dnssec/localhsm.py", line 122, in find_keys key = Key(self.p11, h) File "/usr/lib/python3.9/site-packages/ipaserver/dnssec/localhsm.py", line 46, in init assert len(cka_id) != 0, 'ipk11id length should not be 0' AssertionError: ipk11id length should not be 0 '''
@frenaud I think you saw somewhat similar when upgrading OpenDNSSEC from 1.4 to 2.x?
My hunch is the latest fc34 upgrade to freeipa release required something only in fc35. I'm upgrading to fc35, stay tuned...
No, it shouldn't have any additional requirements other than what is already in F34. The patches in -3..-4 builds only required Samba update that went into F34 at the same time. There is really nothing related to OpenDNSSEC at all in those changes.
Was this host installed while OpenDNSSEC was 1.4? E.g. Fedora 31 or around that?
I don't want to trust my guess about when it was installed, it's possible. Any file somewhere with a date on it that would decide it?
May be look at the timestamps of files in /var/lib/ipa/sysrestore. Some of them never change since original deployment.
/var/lib/ipa/sysrestore
Unrelated, watching the startup on fc35, certmonger should wait for kerberos, at present it complains there is no kdc and that's even before dirsrv.
Sysrestore files date from june 2, 2021 (...ssl.conf) through today.
total 320 -rw-r--r--. 1 root root 1174 Dec 9 12:29 sysrestore.state -rw-r--r--. 1 root root 1738 Aug 24 22:44 sysrestore.index -rw-r--r--. 1 root root 951 Aug 24 22:41 56958b6a6ae89c1d0a99ba7f315d14007897a0e9e4288c77c6a73b5d28e812ca-named -r--------. 1 root root 626 Aug 24 22:41 2ed204b414ea9ccea5da5aff886844866c07e9b5be3cf441af15c503b20aced8-named.keytab -rw-r--r--. 1 root root 20 Aug 24 22:22 ebc91262937820767ab78c818df66baf0141c43098553354919e7abc922e7d42-resolv.conf -rw-r--r--. 1 root root 177 Aug 24 22:21 009131c774e525a30478b96a5a2b3b52526a5b5a3433b6b7ff89dcc6a3867dea-chrony.conf -rw-r--r--. 1 root root 150335 Aug 24 22:06 61b9f393af5a09fd2977586d4c105172c6141cf95d8c93ea380d088a81bbfd2b-hosts -rw-r-----. 1 root root 1722 Aug 24 22:01 3d0f726b82c7121961de26e561fea3a23864178ed0008b0de375d64964eb23b5-named.conf -rw-rw----. 1 root root 102400 Aug 24 22:01 7e9656eb2460ef1cfe362d3935a3ff092c3acfc041c93619446fd420bbdc8bb0-kasp.db -rw-r--r--. 1 root root 845 Aug 19 12:43 8f8eff846667b7811358e289e9fe594de17d0e47f2b8cebf7840ad8db7f34816-named -rw-r--r--. 1 root root 880 Aug 19 11:35 87fa5619a6494774d5ea569df972a95691974cfed439f1e0f0e8dcb54cac5cb4-krb5.conf -rw-------. 1 root root 476 Aug 19 11:35 eaad41ccb5fe439c7bebd16746a86374cb86c5920e1915136e12755adb216e24-kdc.conf -rw-r--r--. 1 root root 14 Aug 19 11:35 edf95267244d57b6c953ea3ad197c12e2e342e237d2b31d2d75e5aeac3e06e03-krb5kdc -rw-r--r--. 1 root root 40 Jul 12 06:32 25adeae8fa3ee4c4d95ce737685dbc01e7e23060d8655f5d86bbdf1dd28c1119-ods -rw-rw----. 1 root root 2092 Jul 12 06:32 ff493cc1356b7a99d9b439a6f54d58d11ab8157ea33ae71c833399736a92783f-conf.xml -rw-rw----. 1 root root 1808 Jul 12 06:31 dbb4e496c2120e55950bc53be0f69e041543fc2fbe155d7076813270363f57bb-zonelist.xml -rw-rw----. 1 root root 3327 Jul 12 06:31 a40126c907b7f5bd1ae4869b1b62e94a416896401e9c85b3bf4fe2c5588a7fdf-kasp.xml -rw-r--r--. 1 root root 9556 Jun 2 2021 6690cb873d2312d0ecffcda3822562cd1b1b11ac44b1fcb7bd1b720a9e53c333-ssl.conf
fc35 didn't help...
Dec 09 13:17:45 registry1.fugazi.com ipa-ods-exporter[2827]: ipa-ods-exporter: DEBUG zone keys in LDAP: {...big list...} Dec 09 13:17:46 registry1.fugazi.com python3[2827]: detected unhandled Python exception in '/usr/libexec/ipa/ipa-ods-exporter' Dec 09 13:17:46 registry1.fugazi.com ipa-ods-exporter[2827]: Traceback (most recent call last): Dec 09 13:17:46 registry1.fugazi.com ipa-ods-exporter[2827]: File "/usr/libexec/ipa/ipa-ods-exporter", line 715, in <module> Dec 09 13:17:46 registry1.fugazi.com ipa-ods-exporter[2827]: master2ldap_zone_keys_sync(ldapkeydb, localhsm) Dec 09 13:17:46 registry1.fugazi.com ipa-ods-exporter[2827]: File "/usr/libexec/ipa/ipa-ods-exporter", line 424, in master2ldap_zone_keys_sync Dec 09 13:17:46 registry1.fugazi.com ipa-ods-exporter[2827]: privkeys_local = localhsm.zone_privkeys Dec 09 13:17:46 registry1.fugazi.com ipa-ods-exporter[2827]: File "/usr/lib/python3.10/site-packages/ipaserver/dnssec/localhsm.py", line 173, in zone_privkeys Dec 09 13:17:46 registry1.fugazi.com ipa-ods-exporter[2827]: self.find_keys(objclass=_ipap11helper.KEY_CLASS_PRIVATE_KEY)) Dec 09 13:17:46 registry1.fugazi.com ipa-ods-exporter[2827]: File "/usr/lib/python3.10/site-packages/ipaserver/dnssec/localhsm.py", line 122, in find_keys Dec 09 13:17:46 registry1.fugazi.com ipa-ods-exporter[2827]: key = Key(self.p11, h) Dec 09 13:17:46 registry1.fugazi.com ipa-ods-exporter[2827]: File "/usr/lib/python3.10/site-packages/ipaserver/dnssec/localhsm.py", line 46, in __init__ Dec 09 13:17:46 registry1.fugazi.com ipa-ods-exporter[2827]: assert len(cka_id) != 0, 'ipk11id length should not be 0' Dec 09 13:17:46 registry1.fugazi.com ipa-ods-exporter[2827]: AssertionError: ipk11id length should not be 0 Dec 09 13:17:46 registry1.fugazi.com ipa-ods-exporter[2827]: Exception ignored in: <function LocalHSM.__del__ at 0x7f2f678c76d0> Dec 09 13:17:46 registry1.fugazi.com ipa-ods-exporter[2827]: Traceback (most recent call last): Dec 09 13:17:46 registry1.fugazi.com ipa-ods-exporter[2827]: File "/usr/lib/python3.10/site-packages/ipaserver/dnssec/localhsm.py", line 107, in __del__ Dec 09 13:17:46 registry1.fugazi.com ipa-ods-exporter[2827]: File "/usr/lib/python3.10/site-packages/ipaserver/p11helper.py", line 939, in finalize Dec 09 13:17:46 registry1.fugazi.com ipa-ods-exporter[2827]: TypeError: 'NoneType' object is not callable Dec 09 13:17:47 registry1.fugazi.com systemd[1]: ipa-ods-exporter.service: Main process exited, code=exited, status=1/FAILURE
```
Added a couple of debug prints. Looks like some kind of secondary failure/race condition in del, brought about by a primary error of an unexpected 0 key length.
... Dec 09 15:38:47 registry1.fugazi.com ipa-ods-exporter[3345]: File "/usr/lib/python3.10/site-packages/ipaserver/dnssec/localhsm.py", line 46, in __init__ Dec 09 15:38:47 registry1.fugazi.com ipa-ods-exporter[3345]: assert len(cka_id) != 0, 'ipk11id length should not be 0' Dec 09 15:38:47 registry1.fugazi.com ipa-ods-exporter[3345]: AssertionError: ipk11id length should not be 0 Dec 09 15:38:47 registry1.fugazi.com ipa-ods-exporter[3345]: Exception ignored in: <function LocalHSM.__del__ at 0x7f9df04e56c0> Dec 09 15:38:47 registry1.fugazi.com ipa-ods-exporter[3345]: Traceback (most recent call last): Dec 09 15:38:47 registry1.fugazi.com ipa-ods-exporter[3345]: File "/usr/lib/python3.10/site-packages/ipaserver/dnssec/localhsm.py", line 107, in __del__ Dec 09 15:38:47 registry1.fugazi.com ipa-ods-exporter[3345]: File "/usr/lib/python3.10/site-packages/ipaserver/p11helper.py", line 942, in finalize Dec 09 15:38:47 registry1.fugazi.com ipa-ods-exporter[3345]: TypeError: 'NoneType' object is not callable Dec 09 15:38:47 registry1.fugazi.com ipa-ods-exporter[3345]: c logout is: <cdata 'unsigned long(*)(unsigned long)' 0x7f9dea9c5ca0> Dec 09 15:38:47 registry1.fugazi.com ipa-ods-exporter[3345]: self.session is 1 Dec 09 15:38:47 registry1.fugazi.com ipa-ods-exporter[3345]: rv is : 0
fc36 fails the same way, even with the 'thread safety' attempt/upgrade (not mine) in openssl-pkcs11.
I remember this issue: https://pagure.io/freeipa/issue/8654 but the error was different.
@hcoin the change of version between Fedora releases is not really going to help here. You have data that is somewhat incorrect and it needs to be fixed. I don't have time right now to look into these details, sadly.
One way going forward is to be able to reproduce your setup. Perhaps you can share your OpenDNSSEC database and IPA LDAP dump so that we can look at the content and see what's wrong? This can be done offline, may be next week or so.
I've added to the debug write to identify one 'handle' associated with a failure, all the others succeed. Any hint for how to identify which file is associated with a 'handle number' in p11/softhsm parlance?
Also, I really think the routine about enumerating the keys shouldn't crash the entire dnssec process over one bad file, that could be handled better.
Here's one perfectly formatted and entirely incorrect .object file. Any idea how it could have been created? There is only one file in the directory with 0 length CKA_ID.
Dump of object file "/var/lib/ipa/dnssec/tokens/35c0069a-5a74-df91-32c5-09191e997b3a/69813ca2-a7bd-f187-b0c5-540cae9d5ca5.object" 00 00 00 00 00 00 00 45 generation 69 00 00 00 00 00 00 00 00 CKA_CLASS 00 00 00 00 00 00 00 02 unsigned long attribute 00 00 00 00 00 00 00 03 CKO_PRIVATE_KEY 00 00 00 00 00 00 00 01 CKA_TOKEN 00 00 00 00 00 00 00 01 boolean attribute 00 FALSE 00 00 00 00 00 00 00 02 CKA_PRIVATE 00 00 00 00 00 00 00 01 boolean attribute ff TRUE 00 00 00 00 00 00 00 03 CKA_LABEL 00 00 00 00 00 00 00 03 byte string attribute 00 00 00 00 00 00 00 00 (length 0) 00 00 00 00 00 00 01 00 CKA_KEY_TYPE 00 00 00 00 00 00 00 02 unsigned long attribute 00 00 00 00 00 00 00 00 CKK_RSA 00 00 00 00 00 00 01 01 CKA_SUBJECT 00 00 00 00 00 00 00 03 byte string attribute 00 00 00 00 00 00 00 00 (length 0) 00 00 00 00 00 00 01 02 CKA_ID 00 00 00 00 00 00 00 03 byte string attribute 00 00 00 00 00 00 00 00 (length 0) 00 00 00 00 00 00 01 03 CKA_SENSITIVE 00 00 00 00 00 00 00 01 boolean attribute 00 FALSE 00 00 00 00 00 00 01 05 CKA_DECRYPT 00 00 00 00 00 00 00 01 boolean attribute ff TRUE 00 00 00 00 00 00 01 07 CKA_UNWRAP 00 00 00 00 00 00 00 01 boolean attribute ff TRUE 00 00 00 00 00 00 01 08 CKA_SIGN 00 00 00 00 00 00 00 01 boolean attribute ff TRUE 00 00 00 00 00 00 01 09 CKA_SIGN_RECOVER 00 00 00 00 00 00 00 01 boolean attribute ff TRUE 00 00 00 00 00 00 01 0c CKA_DERIVE 00 00 00 00 00 00 00 01 boolean attribute 00 FALSE 00 00 00 00 00 00 01 10 CKA_START_DATE 00 00 00 00 00 00 00 03 byte string attribute 00 00 00 00 00 00 00 00 (length 0) 00 00 00 00 00 00 01 11 CKA_END_DATE 00 00 00 00 00 00 00 03 byte string attribute 00 00 00 00 00 00 00 00 (length 0) 00 00 00 00 00 00 01 20 CKA_MODULUS 00 00 00 00 00 00 00 03 byte string attribute 00 00 00 00 00 00 00 00 (length 0) 00 00 00 00 00 00 01 22 CKA_PUBLIC_EXPONENT 00 00 00 00 00 00 00 03 byte string attribute 00 00 00 00 00 00 00 00 (length 0) 00 00 00 00 00 00 01 23 CKA_PRIVATE_EXPONENT 00 00 00 00 00 00 00 03 byte string attribute 00 00 00 00 00 00 00 00 (length 0) 00 00 00 00 00 00 01 24 CKA_PRIME_1 00 00 00 00 00 00 00 03 byte string attribute 00 00 00 00 00 00 00 00 (length 0) 00 00 00 00 00 00 01 25 CKA_PRIME_2 00 00 00 00 00 00 00 03 byte string attribute 00 00 00 00 00 00 00 00 (length 0) 00 00 00 00 00 00 01 26 CKA_EXPONENT_1 00 00 00 00 00 00 00 03 byte string attribute 00 00 00 00 00 00 00 00 (length 0) 00 00 00 00 00 00 01 27 CKA_EXPONENT_2 00 00 00 00 00 00 00 03 byte string attribute 00 00 00 00 00 00 00 00 (length 0) 00 00 00 00 00 00 01 28 CKA_COEFFICIENT 00 00 00 00 00 00 00 03 byte string attribute 00 00 00 00 00 00 00 00 (length 0) 00 00 00 00 00 00 01 29 CKA_PUBLIC_KEY_INFO 00 00 00 00 00 00 00 03 byte string attribute 00 00 00 00 00 00 00 00 (length 0) 00 00 00 00 00 00 01 62 CKA_EXTRACTABLE 00 00 00 00 00 00 00 01 boolean attribute 00 FALSE 00 00 00 00 00 00 01 63 CKA_LOCAL 00 00 00 00 00 00 00 01 boolean attribute 00 FALSE 00 00 00 00 00 00 01 64 CKA_NEVER_EXTRACTABLE 00 00 00 00 00 00 00 01 boolean attribute ff TRUE 00 00 00 00 00 00 01 65 CKA_ALWAYS_SENSITIVE 00 00 00 00 00 00 00 01 boolean attribute 00 FALSE 00 00 00 00 00 00 01 66 CKA_KEY_GEN_MECHANISM 00 00 00 00 00 00 00 02 unsigned long attribute ff ff ff ff ff ff ff ff CK_UNAVAILABLE_INFORMATION 00 00 00 00 00 00 01 70 CKA_MODIFIABLE 00 00 00 00 00 00 00 01 boolean attribute ff TRUE 00 00 00 00 00 00 01 71 CKA_COPYABLE 00 00 00 00 00 00 00 01 boolean attribute ff TRUE 00 00 00 00 00 00 01 72 CKA_DESTROYABLE 00 00 00 00 00 00 00 01 boolean attribute ff TRUE 00 00 00 00 00 00 02 02 CKA_ALWAYS_AUTHENTICATE 00 00 00 00 00 00 00 01 boolean attribute 00 FALSE 00 00 00 00 00 00 02 10 CKA_WRAP_WITH_TRUSTED 00 00 00 00 00 00 00 01 boolean attribute 00 FALSE 00 00 00 00 40 00 02 12 CKA_UNWRAP_TEMPLATE 00 00 00 00 00 00 00 04 attribute map attribute 00 00 00 00 00 00 00 00 (length 0) 00 00 00 00 40 00 06 00 CKA_ALLOWED_MECHANISMS 00 00 00 00 00 00 00 05 mechanism set attribute 00 00 00 00 00 00 00 00 (length 0)
Recently I got a similar issue during the IPA tests: test_integration/test_dnssec.py::TestInstallDNSSECLast::test_disable_reenable_signing_replica
test_integration/test_dnssec.py::TestInstallDNSSECLast::test_disable_reenable_signing_replica
https://github.com/stanislavlevin/freeipa/runs/4501933370?check_suite_focus=true
logs: https://github.com/stanislavlevin/freeipa/suites/4634403617/artifacts/125567557
I didn't check the reason, just saw the same traceback (so, it may be unrelated).
And, here's the likely culprit. segfault in dnssec-keyfroml
Dec 13 09:15:11 registry2.1.fugazi.com ipa-dnskeysyncd[2498]: ipaserver.dnssec.bindmgr: DEBUG Fixing file permissions: /var/lib/ipa/dnssec/tokens/f2378ee5-e58b-8f33-7a56-571ab1389cf3/45dcff25-e909-4b79-f44b-80c5a72c3f7c.object Dec 13 09:15:11 registry2.1.fugazi.com ipa-dnskeysyncd[2498]: ipaserver.dnssec.bindmgr: DEBUG Fixing file permissions: /var/lib/ipa/dnssec/tokens/f2378ee5-e58b-8f33-7a56-571ab1389cf3/45dcff25-e909-4b79-f44b-80c5a72c3f7c.lock Dec 13 09:15:11 registry2.1.fugazi.com ipa-dnskeysyncd[2498]: ipaserver.dnssec.bindmgr: INFO attrs: <ldap.cidict.cidict object at 0x7f6564f20eb0> Dec 13 09:15:11 registry2.1.fugazi.com ipa-dnskeysyncd[2498]: ipapython.ipautil: DEBUG Starting external process Dec 13 09:15:11 registry2.1.fugazi.com ipa-dnskeysyncd[2498]: ipapython.ipautil: DEBUG args=['/usr/sbin/dnssec-keyfromlabel', '-E', 'pkcs11', '-K', '/var/named/dyndb-ldap/ipa/master/fugazi.com/tmpxqg2akx4', '-a', b'RSASHA256', '-l', b'pkcs11:object=604ba54adca520df30e50bc459fe71ed;pin-source=/var/lib/ipa/dnssec/softhsm_pin', '-P', b'20210825150205', '-A', 'none', '-I', 'none', '-D', 'none', '-E', 'pkcs11', 'fugazi.com.'] Dec 13 09:15:11 registry2.1.fugazi.com dnssec-keyfromlabel[2582]: Configuration.cpp(96): Missing log.level in configuration. Using default value: INFO Dec 13 09:15:11 registry2.1.fugazi.com dnssec-keyfromlabel[2582]: Configuration.cpp(96): Missing slots.mechanisms in configuration. Using default value: ALL Dec 13 09:15:11 registry2.1.fugazi.com dnssec-keyfromlabel[2582]: Configuration.cpp(124): Missing slots.removable in configuration. Using default value: false Dec 13 09:15:12 registry2.1.fugazi.com named[1077]: zone _domainkey.fugazi2.com/IN (signed): sending notifies (serial 2021121531) Dec 13 09:15:12 registry2.1.fugazi.com named[1077]: client @0x7fd5c89f7d78 10.12.112.3#53874: received notify for zone '_domainkey.fugazi2.com' Dec 13 09:15:12 registry2.1.fugazi.com kernel: dnssec-keyfroml[2582]: segfault at 18 ip 00007fb393a9e464 sp 00007fff08e95618 error 4 in libsofthsm2.so[7fb393a07000+9b000] Dec 13 09:15:12 registry2.1.fugazi.com kernel: Code: 75 f4 48 8b 53 30 49 89 4c 24 20 49 89 44 24 10 49 89 54 24 28 48 83 c4 08 4c 89 e0 5b 41 5c c3 66 0f 1f 44 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 Dec 13 09:15:12 registry2.1.fugazi.com audit[2582]: ANOM_ABEND auid=4294967295 uid=982 gid=25 ses=4294967295 subj=system_u:system_r:ipa_dnskey_t:s0 pid=2582 comm="dnssec-keyfroml" exe="/usr/sbin/dnssec-keyfromlabel" sig=11 res=1 Dec 13 09:15:12 registry2.1.fugazi.com audit: BPF prog-id=67 op=LOAD Dec 13 09:15:12 registry2.1.fugazi.com audit: BPF prog-id=68 op=LOAD Dec 13 09:15:12 registry2.1.fugazi.com audit: BPF prog-id=69 op=LOAD Dec 13 09:15:12 registry2.1.fugazi.com systemd[1]: Started Process Core Dump (PID 2583/UID 0). Dec 13 09:15:12 registry2.1.fugazi.com audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-coredump@1-2583-0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Dec 13 09:15:12 registry2.1.fugazi.com named[1077]: client @0x7fd5cc2e0138 fc00:1002:c7::3#34626: received notify for zone '_domainkey.fugazi2.com' Dec 13 09:15:12 registry2.1.fugazi.com named[1077]: client @0x7fd5d04edf18 10.12.127.253#56978: received notify for zone '_domainkey.fugazi2.com' Dec 13 09:15:13 registry2.1.fugazi.com systemd-coredump[2584]: [🡕] Process 2582 (dnssec-keyfroml) of user 982 dumped core. Module linux-vdso.so.1 with build-id 95e8a8e63cdbe4bc004c6a2484f9e810a2c2a88c Module libgcc_s.so.1 with build-id 57f16b11e94df4d1ef6999e2356068d3a1a1711c Module libstdc++.so.6 with build-id 967e0a75c826edcb531f536ad5623f4c2f78f41a Module libsqlite3.so.0 with build-id 8ece8ec2c8a36d02b50c0713fd365d721e4fdb72 Module libsofthsm2.so with build-id 646af6ff5ef7daa87d763d6a616509b85ba7cf13 Module pkcs11.so with build-id 56591f517147f20bcbb3c2f60ff9b5b66e17c49f Module libpcre2-8.so.0 with build-id 55ab4840aedc13b763ba6cc43ab07d6481784eef Module libselinux.so.1 with build-id 2ae8a807e94e1ba36f05475ae393f58aa42fb583 Module libresolv.so.2 with build-id 559b53ed025f3575d86bcf3438917ded57df8a17 Module libkeyutils.so.1 with build-id 2560a16099ad1875f7ea2195ae25b97ea168a758 Module libkrb5support.so.0 with build-id 586b9de88a8400c9972935ad046e7621aaee010e Module libm.so.6 with build-id d0e38d8e86cd7683cbfe0d81d8f268a174472b6f Module liblzma.so.5 with build-id 7fec53ce7cba9489f130c99cfd3ace82e9dde0ee Module ld-linux-x86-64.so.2 with build-id c54ef399916379f8295b1b00cadb3048ceb89211 Module libprotobuf-c.so.1 with build-id 03e5ec06792b0a34c1c580897325b9588f20e046 Module liblmdb.so.0.0.0 with build-id 181e0de8868e445b0cb1158be1df3f18651f2342 Module libmaxminddb.so.0 with build-id 3f299153f94684fd09a91c314930b36aae4ed1cc Module libfstrm.so.0 with build-id 75b3d0647dba8b692467f23d7499339e11f04428 Module libcom_err.so.2 with build-id b20d36abf2fe7612cfb9e4672c79cc13cf38c24e Module libk5crypto.so.3 with build-id 6b8bce93506d3fc76113a64ca0fed387ae35da86 Module libkrb5.so.3 with build-id e4151623b02f86f0414d38be6a1c72694ab98a55 Module libgssapi_krb5.so.2 with build-id 37c2008c7d6460e30bac261fabce0ebd19e83e17 Module libz.so.1 with build-id 5903f5c355c264403e4e7cdc66779584425ca3b8 Module libxml2.so.2 with build-id 8f21e0bbe0106c5c5cd35859487dcc074b8f13bd Module libuv.so.1 with build-id ca47d3186d6e3ca485c7c51540c17a77f30c5157 Module libjson-c.so.5 with build-id 5ee4e811709779102a0862e28e7f3752c0fdc5d1 Module libcrypto.so.3 with build-id 33c9efd543b137a4afcd691c012752b1850136d7 Module libssl.so.3 with build-id ae5b7c5a3d62b433440ba9cf854314f1e948d506 Module libc.so.6 with build-id a94031fb833ad21713ebb33092fd8e751ed304e5 Module libisc-9.16.23-RH.so with build-id 06acbd8e917570f9226d5437c848fa729d511958 Module libdns-9.16.23-RH.so with build-id 3386e9749fa54a930756cadf3c99a1f5659ec0f9 Module dnssec-keyfromlabel with build-id 2c904b00063386ef974bee393063d7fe56d5fa41 Stack trace of thread 2582: #0 0x00007fb393a9e464 _ZN11SlotManager7getSlotEm (libsofthsm2.so + 0xac464) #1 0x00007fb393a352dd _ZN7SoftHSM18C_CloseAllSessionsEm (libsofthsm2.so + 0x432dd) #2 0x00007fb393a14b68 C_CloseAllSessions (libsofthsm2.so + 0x22b68) #3 0x00007fb393b24bdf pkcs11_release_slot (pkcs11.so + 0xcbdf) #4 0x00007fb393b24d47 engine_finish (pkcs11.so + 0xcd47) #5 0x00007fb394213f56 engine_unlocked_finish (libcrypto.so.3 + 0x168f56) #6 0x00007fb394214096 int_cleanup_cb_doall (libcrypto.so.3 + 0x169096) #7 0x00007fb3942515bc OPENSSL_LH_doall (libcrypto.so.3 + 0x1a65bc) #8 0x00007fb39420f318 engine_table_cleanup (libcrypto.so.3 + 0x164318) #9 0x00007fb39420d1fa engine_cleanup_cb_free.lto_priv.0 (libcrypto.so.3 + 0x1621fa) #10 0x00007fb3942a66f0 OPENSSL_sk_pop_free (libcrypto.so.3 + 0x1fb6f0) #11 0x00007fb39426322a OPENSSL_cleanup (libcrypto.so.3 + 0x1b822a) #12 0x00007fb3945be2c7 __cxa_finalize (libc.so.6 + 0x452c7) #13 0x00007fb39415a0f7 __do_global_dtors_aux (libcrypto.so.3 + 0xaf0f7) #14 0x00007fb394a63d8b _dl_fini (ld-linux-x86-64.so.2 + 0x10d8b) #15 0x00007fb3945bddd5 __run_exit_handlers (libc.so.6 + 0x44dd5) #16 0x00007fb3945bdf50 exit (libc.so.6 + 0x44f50) #17 0x000056037fbcf86a fatal (dnssec-keyfromlabel + 0x486a) #18 0x000056037fbcf156 main (dnssec-keyfromlabel + 0x4156) #19 0x00007fb3945a6590 __libc_start_call_main (libc.so.6 + 0x2d590) #20 0x00007fb3945a663c __libc_start_main@@GLIBC_2.34 (libc.so.6 + 0x2d63c) #21 0x000056037fbcf195 _start (dnssec-keyfromlabel + 0x4195) ELF object binary architecture: AMD x86-64 Dec 13 09:15:13 registry2.1.fugazi.com ipa-dnskeysyncd[2498]: ipapython.ipautil: DEBUG Process finished, return code=-11 Dec 13 09:15:13 registry2.1.fugazi.com ipa-dnskeysyncd[2498]: ipapython.ipautil: DEBUG stdout= Dec 13 09:15:13 registry2.1.fugazi.com ipa-dnskeysyncd[2498]: ipapython.ipautil: DEBUG stderr=Found uninitialized token Dec 13 09:15:13 registry2.1.fugazi.com ipa-dnskeysyncd[2498]: Found uninitialized token Dec 13 09:15:13 registry2.1.fugazi.com ipa-dnskeysyncd[2498]: Key not found. Dec 13 09:15:13 registry2.1.fugazi.com ipa-dnskeysyncd[2498]: PKCS11_load_public_key returned NULL Dec 13 09:15:13 registry2.1.fugazi.com ipa-dnskeysyncd[2498]: Found uninitialized token Dec 13 09:15:13 registry2.1.fugazi.com ipa-dnskeysyncd[2498]: Key not found. Dec 13 09:15:13 registry2.1.fugazi.com ipa-dnskeysyncd[2498]: PKCS11_get_private_key returned NULL Dec 13 09:15:13 registry2.1.fugazi.com ipa-dnskeysyncd[2498]: dnssec-keyfromlabel: warning: ENGINE_load_private_key failed (not found) Dec 13 09:15:13 registry2.1.fugazi.com ipa-dnskeysyncd[2498]: dnssec-keyfromlabel: fatal: failed to get key fugazi.com/RSASHA256: not found
https://pagure.io/freeipa/issue/9057
Issue also seen in nightly tests, in PR#1372, in test_backup_and_restore_TestBackupReinstallRestoreWithDNSSEC (Details). The journal shows:
test_backup_and_restore_TestBackupReinstallRestoreWithDNSSEC
Dec 14 00:17:06 master.ipa.test ipa-ods-exporter[24036]: Traceback (most recent call last): Dec 14 00:17:06 master.ipa.test ipa-ods-exporter[24036]: File "/usr/libexec/ipa/ipa-ods-exporter", line 715, in <module> Dec 14 00:17:06 master.ipa.test ipa-ods-exporter[24036]: master2ldap_zone_keys_sync(ldapkeydb, localhsm) Dec 14 00:17:06 master.ipa.test ipa-ods-exporter[24036]: File "/usr/libexec/ipa/ipa-ods-exporter", line 424, in master2ldap_zone_keys_sync Dec 14 00:17:06 master.ipa.test ipa-ods-exporter[24036]: privkeys_local = localhsm.zone_privkeys Dec 14 00:17:06 master.ipa.test ipa-ods-exporter[24036]: File "/usr/lib/python3.10/site-packages/ipaserver/dnssec/localhsm.py", line 173, in zone_privkeys Dec 14 00:17:06 master.ipa.test ipa-ods-exporter[24036]: self.find_keys(objclass=_ipap11helper.KEY_CLASS_PRIVATE_KEY)) Dec 14 00:17:06 master.ipa.test ipa-ods-exporter[24036]: File "/usr/lib/python3.10/site-packages/ipaserver/dnssec/localhsm.py", line 122, in find_keys Dec 14 00:17:06 master.ipa.test ipa-ods-exporter[24036]: key = Key(self.p11, h) Dec 14 00:17:06 master.ipa.test ipa-ods-exporter[24036]: File "/usr/lib/python3.10/site-packages/ipaserver/dnssec/localhsm.py", line 46, in __init__ Dec 14 00:17:06 master.ipa.test ipa-ods-exporter[24036]: assert len(cka_id) != 0, 'ipk11id length should not be 0' Dec 14 00:17:06 master.ipa.test ipa-ods-exporter[24036]: AssertionError: ipk11id length should not be 0 Dec 14 00:17:06 master.ipa.test ipa-ods-exporter[24036]: Exception ignored in: <function LocalHSM.__del__ at 0x7f0b434213f0> Dec 14 00:17:06 master.ipa.test ipa-ods-exporter[24036]: Traceback (most recent call last): Dec 14 00:17:06 master.ipa.test ipa-ods-exporter[24036]: File "/usr/lib/python3.10/site-packages/ipaserver/dnssec/localhsm.py", line 107, in __del__ Dec 14 00:17:06 master.ipa.test ipa-ods-exporter[24036]: File "/usr/lib/python3.10/site-packages/ipaserver/p11helper.py", line 939, in finalize Dec 14 00:17:06 master.ipa.test ipa-ods-exporter[24036]: TypeError: 'NoneType' object is not callable
Metadata Update from @frenaud: - Issue tagged with: test-failure
This smells like: https://bugzilla.redhat.com/show_bug.cgi?id=1978319
Which may, or may not be related to: https://issues.opendnssec.org/browse/OPENDNSSEC-955 " Prevent concurrency between certain valid PKCS#11 HSM operations to avoid some keys to be (transiently) unavailable." "Some HSMs may also report it multiple times. SoftHSMv2 in database backend mode for instance."
Unfortunately, I thought this was fixed in 2.1.10 from the release notes, but it is still marked as open in the upstream Jira instance. I've opened https://issues.opendnssec.org/browse/SUPPORT-267 for clarification.
Still exists in 4.10.2
Apr 06 11:02:43 registry1.1.quietfountain.com systemd[1]: Started IPA OpenDNSSEC Signer replacement. Apr 06 11:02:44 registry1.1.quietfountain.com ipa-ods-exporter[1174411]: ipa-ods-exporter: INFO To increase debugging set debug=True in dns.conf See default.conf(5) for details Apr 06 11:02:45 registry1.1.quietfountain.com python3[1174411]: GSSAPI client step 1 Apr 06 11:02:45 registry1.1.quietfountain.com python3[1174411]: GSSAPI client step 1 Apr 06 11:02:45 registry1.1.quietfountain.com python3[1174411]: GSSAPI client step 1 Apr 06 11:02:45 registry1.1.quietfountain.com python3[1174411]: Configuration.cpp(96): Missing log.level in configuration. Using default value: INFO Apr 06 11:02:45 registry1.1.quietfountain.com python3[1174411]: Configuration.cpp(96): Missing slots.mechanisms in configuration. Using default value: ALL Apr 06 11:02:45 registry1.1.quietfountain.com python3[1174411]: Configuration.cpp(124): Missing slots.removable in configuration. Using default value: false Apr 06 11:02:46 registry1.1.quietfountain.com ipa-ods-exporter[1174411]: Traceback (most recent call last): Apr 06 11:02:46 registry1.1.quietfountain.com ipa-ods-exporter[1174411]: File "/usr/libexec/ipa/ipa-ods-exporter", line 718, in <module> Apr 06 11:02:46 registry1.1.quietfountain.com ipa-ods-exporter[1174411]: ldap2master_replica_keys_sync(ldapkeydb, localhsm) Apr 06 11:02:46 registry1.1.quietfountain.com ipa-ods-exporter[1174411]: File "/usr/libexec/ipa/ipa-ods-exporter", line 295, in ldap2master_replica_keys_sync Apr 06 11:02:46 registry1.1.quietfountain.com ipa-ods-exporter[1174411]: hex_set(localhsm.replica_pubkeys_wrap)) Apr 06 11:02:46 registry1.1.quietfountain.com ipa-ods-exporter[1174411]: File "/usr/lib/python3.9/site-packages/ipaserver/dnssec/localhsm.py", line 130, in replica_pubkeys_wrap Apr 06 11:02:46 registry1.1.quietfountain.com ipa-ods-exporter[1174411]: self.find_keys(objclass=_ipap11helper.KEY_CLASS_PUBLIC_KEY, Apr 06 11:02:46 registry1.1.quietfountain.com ipa-ods-exporter[1174411]: File "/usr/lib/python3.9/site-packages/ipaserver/dnssec/localhsm.py", line 114, in find_keys Apr 06 11:02:46 registry1.1.quietfountain.com ipa-ods-exporter[1174411]: key = Key(self.p11, h) Apr 06 11:02:46 registry1.1.quietfountain.com ipa-ods-exporter[1174411]: File "/usr/lib/python3.9/site-packages/ipaserver/dnssec/localhsm.py", line 38, in __init__ Apr 06 11:02:46 registry1.1.quietfountain.com ipa-ods-exporter[1174411]: assert len(cka_id) != 0, 'ipk11id length should not be 0' Apr 06 11:02:46 registry1.1.quietfountain.com ipa-ods-exporter[1174411]: AssertionError: ipk11id length should not be 0 Apr 06 11:02:46 registry1.1.quietfountain.com systemd[1]: ipa-ods-exporter.service: Main process exited, code=exited, status=1/FAILURE Apr 06 11:02:46 registry1.1.quietfountain.com systemd[1]: ipa-ods-exporter.service: Failed with result 'exit-code'. Apr 06 11:02:46 registry1.1.quietfountain.com systemd[1]: ipa-ods-exporter.service: Consumed 2.674s CPU time.
Login to comment on this ticket.