An advertised, but unimplemented, bind9/named default causes bind/named to not report DS keys, breaking DNSSEC in freeipa. Adding OPTIONS="-E pkcs11" to /etc/sysconfig/named prevents such as Mar 08 20:26:07 registry1.1.quietfountain.com named[1388]: dns_dnssec_findmatchingkeys: error reading key file K11.quietfountain.com.+008+37760.private: no engine If you run gdb against named without it, you'll see the 'engine' variable is null. With it pkcs11 is loaded. I hope freeipa writes /etc/sysconfig/named , but if it isn't default writes named.ipa But, even with the fix, DS records still aren't getting back to named because, later on, the key file exists and in a properly named file, and both named and the ods users can access it, but when read we have many examples that follow. After the examples is some gdb supporting detail. Also an issue do do with ods being listed as the owner of a file beneath a directory ods can't traverse without being in the named group. I sure would like some guidance about why it can't find those keys. DNSSEC cant report ds records until then. freeipa-4.9.2-4.fc33 Mar 10 00:53:28 registry1.1.quietfountain.com ipa-dnskeysyncd[9215]: ipaserver.dnssec.bindmgr: DEBUG Fixing file permissions: /var/lib/ipa/dnssec/tokens/c755c3e2-5207-f870-bcc7-7bccf97c4076/de899b92-1f0e-9d02-227e-5e386921438d.object Mar 10 00:53:28 registry1.1.quietfountain.com ipa-dnskeysyncd[9215]: ipaserver.dnssec.bindmgr: DEBUG Fixing file permissions: /var/lib/ipa/dnssec/tokens/c755c3e2-5207-f870-bcc7-7bccf97c4076/de899b92-1f0e-9d02-227e-5e386921438d.lock Mar 10 00:53:28 registry1.1.quietfountain.com ipa-dnskeysyncd[9215]: ipaserver.dnssec.bindmgr: INFO attrs: <ldap.cidict.cidict object at 0x7f3c81be75b0> Mar 10 00:53:28 registry1.1.quietfountain.com ipa-dnskeysyncd[9215]: ipapython.ipautil: DEBUG Starting external process Mar 10 00:53:28 registry1.1.quietfountain.com ipa-dnskeysyncd[9215]: ipapython.ipautil: DEBUG args=['/usr/sbin/dnssec-keyfromlabel', '-K', '/var/named/dyndb-ldap/ipa/master/quietfountain.com/tmpbbsuull5', '-a', b'RSASHA256', '-l', b'pkcs11:object=372912f762bd7b5f5a97092da4b9f7a6;pin-source=/var/lib/ipa/dnssec/softhsm_pin', '-P', b'20210309003029', '-A', b'20210309003029', '-I', 'none', '-D', 'none', '-f', 'KSK', '-E', 'pkcs11', 'quietfountain.com.'] Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: error:26096080:engine routines:ENGINE_load_private_key:failed loading private key:crypto/engine/eng_pkey.c:77: Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: dns_dnssec_findmatchingkeys: error reading key file Kquietfountain.com.+008+41325.private: not found Mar 10 00:53:28 registry1.1.quietfountain.com audit[441]: AVC avc: denied { getattr } for pid=441 comm="systemd-journal" path="/var/log/journal/659f950795794c76814a499623c1ddf1/system.journal" dev="virtiofs" ino=385819 scontext=system_u:system_r:syslogd_t:s0 tcontext=system_u:object_r:unlabeled_t:s0 tclass=file permissive=1 Mar 10 00:53:28 registry1.1.quietfountain.com audit[441]: SYSCALL arch=c000003e syscall=5 success=yes exit=0 a0=39 a1=557d96b696f8 a2=557d96b696f8 a3=7fff0b5a6080 items=0 ppid=1 pid=441 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="systemd-journal" exe="/usr/lib/systemd/systemd-journald" subj=system_u:system_r:syslogd_t:s0 key=(null) Mar 10 00:53:28 registry1.1.quietfountain.com audit: CWD cwd="/" Mar 10 00:53:28 registry1.1.quietfountain.com audit: PROCTITLE proctitle="/usr/lib/systemd/systemd-journald" Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: ENGINE_load_private_key failed (not found) Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: error:80067065:pkcs11 engine:ctx_load_privkey:object not found:eng_back.c:975: Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: error:26096080:engine routines:ENGINE_load_private_key:failed loading private key:crypto/engine/eng_pkey.c:77: Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: dns_dnssec_findmatchingkeys: error reading key file Kquietfountain.com.+008+54600.private: not found Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: ENGINE_load_private_key failed (not found) Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: error:80067065:pkcs11 engine:ctx_load_privkey:object not found:eng_back.c:975: Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: error:26096080:engine routines:ENGINE_load_private_key:failed loading private key:crypto/engine/eng_pkey.c:77: Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: dns_dnssec_findmatchingkeys: error reading key file Kquietfountain.com.+008+61837.private: not found Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: ENGINE_load_private_key failed (not found) Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: error:80067065:pkcs11 engine:ctx_load_privkey:object not found:eng_back.c:975: Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: error:26096080:engine routines:ENGINE_load_private_key:failed loading private key:crypto/engine/eng_pkey.c:77: Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: dns_dnssec_findmatchingkeys: error reading key file Kquietfountain.com.+008+42124.private: not found Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: ENGINE_load_private_key failed (not found) Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: error:80067065:pkcs11 engine:ctx_load_privkey:object not found:eng_back.c:975: Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: error:26096080:engine routines:ENGINE_load_private_key:failed loading private key:crypto/engine/eng_pkey.c:77: Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: dns_dnssec_findmatchingkeys: error reading key file Kquietfountain.com.+008+17815.private: not found Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: ENGINE_load_private_key failed (not found) Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: error:80067065:pkcs11 engine:ctx_load_privkey:object not found:eng_back.c:975: Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: error:26096080:engine routines:ENGINE_load_private_key:failed loading private key:crypto/engine/eng_pkey.c:77: Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: dns_dnssec_findmatchingkeys: error reading key file Kquietfountain.com.+008+22209.private: not found Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: ENGINE_load_private_key failed (not found) Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: error:80067065:pkcs11 engine:ctx_load_privkey:object not found:eng_back.c:975: Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: error:26096080:engine routines:ENGINE_load_private_key:failed loading private key:crypto/engine/eng_pkey.c:77: Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: dns_dnssec_findmatchingkeys: error reading key file Kquietfountain.com.+008+37145.private: not found Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: ENGINE_load_private_key failed (not found) Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: error:80067065:pkcs11 engine:ctx_load_privkey:object not found:eng_back.c:975: Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: error:26096080:engine routines:ENGINE_load_private_key:failed loading private key:crypto/engine/eng_pkey.c:77: Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: dns_dnssec_findmatchingkeys: error reading key file Kquietfountain.com.+008+50985.private: not found Mar 10 00:53:27 registry1.1.quietfountain.com named[44640]: zone quietfountain.com/IN (signed): next key event: 10-Mar-2021 01:53:26.966 Mar 10 00:53:28 registry1.1.quietfountain.com dnssec-keyfromlabel[47710]: Configuration.cpp(96): Missing slots.mechanisms in configuration. Using default value: ALL Mar 10 00:53:28 registry1.1.quietfountain.com dnssec-keyfromlabel[47710]: Configuration.cpp(124): Missing slots.removable in configuration. Using default value: false I added verbose=31 to openssl.conf to get the detail. it's necessary to add ods to the named group, otherwise: [root@registry1 ~]# su -s /bin/bash ods bash-5.0$ ls -l /var/named/dyndb-ldap/ipa/master/rocksteady.systems/keys/Ksomedn.com.+008+49744.private ls: cannot access '/var/named/dyndb-ldap/ipa/master/rocksteady.systems/keys/Ksomedn.com.+008+49744.private': Permission denied since [root@registry1 ~]# ls -ld /var/named/dyndb-ldap/ipa/master/rocksteady.systems/keys drwxrwx---. 1 ods named 1120 Mar 9 13:45 /var/named/dyndb-ldap/ipa/master/rocksteady.systems/keys [root@registry1 ~]# ls -ld /var/named/dyndb-ldap/ipa/master/rocksteady.systems drwxrwx---. 1 named named 34 Mar 9 14:29 /var/named/dyndb-ldap/ipa/master/rocksteady.systems [root@registry1 ~]# ls -ld /var/named/dyndb-ldap/ipa/master drwxrwx---. 1 named named 7932 Mar 9 10:42 /var/named/dyndb-ldap/ipa/master [root@registry1 ~]# ls -ld /var/named/dyndb-ldap/ipa drwxrwx---. 1 named named 12 Mar 8 17:44 /var/named/dyndb-ldap/ipa [root@registry1 ~]# ls -ld /var/named/dyndb-ldap drwxrwx---. 1 root named 6 Mar 8 17:44 /var/named/dyndb-ldap # usermod -a -G named ods # systemctl restart named Starting program: /usr/sbin/named -u named -c /etc/rssmonitor_named.conf -f displays Mar 09 10:56:32 registry1.1.quietfountain.com named[59594]: starting BIND 9.11.28-RedHat-9.11.28-1.fc33 (Extended Support Version) <id:60f9417> Mar 09 10:56:32 registry1.1.quietfountain.com named[59594]: running on Linux x86_64 5.10.19-200.fc33.x86_64 #1 SMP Fri Feb 26 16:21:30 UTC 2021 Mar 09 10:56:32 registry1.1.quietfountain.com named[59594]: built with '--build=x86_64-redhat-linux-gnu' '--host=x86_64-redhat-linux-gnu' '--program-prefix=' '--disable-dependency-tracking' '--prefix=/usr' '--exec-prefix=/usr' '--bindir=/usr/bin' '--sbindir=/usr/sbin' '--sysconfdir=/etc' '--datadir=/usr/share' '--includedir=/usr/include' '--libdir=/usr/lib64' '--libexecdir=/usr/libexec' '--sharedstatedir=/var/lib' '--mandir=/usr/share/man' '--infodir=/usr/share/info' '--with-python=/usr/bin/python3' '--with-libtool' '--localstatedir=/var' '--enable-threads' '--enable-ipv6' '--enable-filter-aaaa' '--with-pic' '--disable-static' '--includedir=/usr/include/bind9' '--with-tuning=large' '--with-libidn2' '--enable-openssl-hash' '--with-geoip2' '--enable-native-pkcs11' '--with-pkcs11=/usr/lib64/pkcs11/libsofthsm2.so' '--with-dlopen=yes' '--with-dlz-ldap=yes' '--with-dlz-postgres=yes' '--with-dlz-mysql=yes' '--with-dlz-filesystem=yes' '--with-gssapi=yes' '--disable-isc-spnego' '--with-lmdb=yes' '--with-libjson' '--enable-dnstap' '--with-cmocka' '--enable-fixed-rrset' '--with-docbook-xsl=/usr/share/sgml/docbook/xsl-ns-stylesheets' '--enable-full-report' 'build_alias=x86_64-redhat-linux-gnu' 'host_alias=x86_64-redhat-linux-gnu' 'CC=gcc' 'CFLAGS= -O2 -flto=auto -ffat-lto-objects -fexceptions -g -grecord-gcc-switches -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -Wp,-D_GLIBCXX_ASSERTIONS -specs=/usr/lib/rpm/redhat/redhat-hardened-cc1 -fstack-protector-strong -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 -m64 -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection' 'LDFLAGS=-Wl,-z,relro -Wl,--as-needed -Wl,-z,now -specs=/usr/lib/rpm/redhat/redhat-hardened-ld ' 'CPPFLAGS= -DDIG_SIGCHASE' 'LT_SYS_LIBRARY_PATH=/usr/lib64:' 'PKG_CONFIG_PATH=:/usr/lib64/pkgconfig:/usr/share/pkgconfig' then in gdb we have: [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib64/libthread_db.so.1". [New Thread 0x7ffff5d48640 (LWP 59595)] [New Thread 0x7ffff5547640 (LWP 59596)] [New Thread 0x7ffff4d46640 (LWP 59597)] [New Thread 0x7ffff4545640 (LWP 59598)] [New Thread 0x7ffff3d44640 (LWP 59599)] [New Thread 0x7ffff3519640 (LWP 59600)] Thread 1 "named" hit Breakpoint 4, dst_lib_init2 (mctx=0x55555562e730, ectx=0x7ffff5d52010, engine=0x0, eflags=eflags@entry=1) at ../../../lib/dns/dst_api.c:155 155 const char *engine, unsigned int eflags) { (gdb) c Continuing. Thread 1 "named" hit Breakpoint 5, dst__openssl_init (engine=0x0) at ../../../lib/dns/openssl_link.c:196 196 dst__openssl_init(const char *engine) { (gdb) bt #0 dst__openssl_init (engine=0x0) at ../../../lib/dns/openssl_link.c:196 #1 0x00007ffff7f00de7 in dst_lib_init2 (mctx=<optimized out>, ectx=0x7ffff5d52010, engine=0x0, eflags=eflags@entry=1) at ../../../lib/dns/dst_api.c:198 #2 0x00005555555c1c56 in ns_server_create (mctx=0x55555562e730, serverp=0x555555627e60 <ns_g_server>) at ../../../bin/named/server.c:9157 #3 0x0000555555579332 in setup () at ../../../bin/named/main.c:1337 #4 main (argc=<optimized out>, argv=0x7fffffffe2c8) at ../../../bin/named/main.c:1556 (gdb) n 209 CRYPTO_set_mem_functions(mem_alloc, mem_realloc, mem_free); (gdb) n 250 OPENSSL_load_builtin_modules(); (gdb) n 251 ENGINE_load_builtin_engines(); (gdb) n 252 ERR_clear_error(); (gdb) n 253 CONF_modules_load_file(NULL, NULL, (gdb) n 258 if (engine != NULL && *engine == '\0') (gdb) p engine $32 = 0x0 (gdb) info args engine = 0x0 (gdb) show args But: Argument list to give program being debugged when it is started is "-u named -c /etc/rssmonitor_named.conf -f". (gdb) set args -u named -c /etc/rssmonitor_named.conf -f -E pkcs11 (gdb) run The program being debugged has been started already. Start it from the beginning? (y or n) y Starting program: /usr/sbin/named -u named -c /etc/rssmonitor_named.conf -f -E pkcs11 [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib64/libthread_db.so.1". [New Thread 0x7ffff5d48640 (LWP 59634)] [New Thread 0x7ffff5547640 (LWP 59635)] [New Thread 0x7ffff4d46640 (LWP 59636)] [New Thread 0x7ffff4545640 (LWP 59637)] [New Thread 0x7ffff3d44640 (LWP 59638)] [New Thread 0x7ffff3519640 (LWP 59639)] Thread 1 "named" hit Breakpoint 4, dst_lib_init2 (mctx=0x55555562e730, ectx=0x7ffff5d52010, engine=0x7fffffffe5ce "pkcs11", eflags=eflags@entry=1) at ../../../lib/dns/dst_api.c:155 155 const char *engine, unsigned int eflags) { (gdb) n 158 REQUIRE(mctx != NULL); (gdb) n 159 REQUIRE(dst_initialized == false); (gdb) n 165 dst__memory_pool = NULL; (gdb) n 177 result = isc_mem_createx2(0, 0, default_memalloc, default_memfree, (gdb) n 179 if (result != ISC_R_SUCCESS) (gdb) n 181 isc_mem_setname(dst__memory_pool, "dst", NULL); (gdb) n 183 isc_mem_setdestroycheck(dst__memory_pool, false); (gdb) n 188 if (ectx != NULL) { (gdb) n 189 isc_entropy_attach(ectx, &dst_entropy_pool); (gdb) n 190 dst_entropy_flags = eflags; (gdb) n 193 dst_result_register(); (gdb) n 195 memset(dst_t_func, 0, sizeof(dst_t_func)); (gdb) n 198 RETERR(dst__openssl_init(engine)); (gdb) n Thread 1 "named" hit Breakpoint 5, dst__openssl_init (engine=0x7fffffffe5ce "pkcs11") at ../../../lib/dns/openssl_link.c:196 196 dst__openssl_init(const char *engine) { (gdb) n 209 CRYPTO_set_mem_functions(mem_alloc, mem_realloc, mem_free); (gdb) n 250 OPENSSL_load_builtin_modules(); (gdb) n 251 ENGINE_load_builtin_engines(); (gdb) n 252 ERR_clear_error(); (gdb) n 253 CONF_modules_load_file(NULL, NULL, (gdb) n 258 if (engine != NULL && *engine == '\0') (gdb) p engine $33 = 0x7fffffffe5ce "pkcs11" (gdb) n 262 e = ENGINE_by_id(engine); (gdb) (gdb) s dst__openssl_getengine (engine=0x7fab75c325d0 "pkcs11") at ../../../lib/dns/openssl_link.c:475 475 dst__openssl_getengine(const char *engine) { (gdb) n 477 if (engine == NULL) (gdb) n 479 if (e == NULL) (gdb) p engine $29 = 0x7fab75c325d0 "pkcs11"
The 'partial fix' of -E pkcs11 in the bind command line appears to generate a fight with with freeipa's disablement of p11-kit-proxy https://github.com/freeipa/freeipa/pull/3063 Back to the drawing board.
This appears related to a freeipa pull request, the details are here: https://pagure.io/freeipa/issue/8757