freeipa

#8757 freeipa pull 3063 breaks named/dnssec ( DNSKEY queries fail )

Opened Mar 15, 2021 by hcoin. Modified Apr 6, 2024

A recent freeipa patch meant to avoid dealing with nss related p11/pkcs11 complexity issues breaks freeipa-server-dns's DNSSEC capability.

https://github.com/freeipa/freeipa/pull/3063, which blocks p11-kit-proxy globally in freeipa-server-4.9.2-4.fc33 server setups, prevents freeipa-server-dns's named's ability to import DS keys from opendnssec, causing 'dig domain.com DNSKEY' requests to fail, in turn rendering dnssec-dsfromkey incapable of producing DS records (which records are required by domain registrars and without which dnssec is broken).

Fresh installs based on fc33 workstation give a normal seeming freeipa UI experience, including checking the inline dnssec box for zone signing. However, dig DNSKEY does not produce any records. Following along giving the 'check out' related commands in 'troubleshooters' such as https://www.freeipa.org/page/Troubleshooting/DNS and https://www.freeipa.org/page/Howto/DNSSEC#Confirm_DS_record_upload reveals proper operation within freeipa code, and opendnssec related key display commands, but no DNSKEY related output from 'dig' from named.

Logs have clues of more or less three bugs, each obscuring the one that appears before it, the last of which is generated by the above pull request blocking p11-kit-proxy.

It's possible existing users will not feel the effects of this until keys expire leading to mysterious broken trust chain complaints. However, new installs will not be able to get DNSKEY records from named (though they exist in opendnssec).

What with p11, openssl , named, opendnssec, pkcs11, etc.. there are so many 'libraries, modules, engines and daemons from different sources calling one another' it's not obvious which explanation pathway is best, so I just picked this one. Buckle up.

ipa-ods-exporter forms zone and other key-id uris with:

uri = "pkcs11:object=%s" % sql_keyid

isc's bind9/named as configured by freeipa fails when attempting to parse such keys, as shown by logs with 'no engine' errors. Step one to correct the error is to include '-E pkcs11' in the bind command line. (see eng_front.c eng_back.c eng_parse.c) I suggest /etc/sysconfig/named's OPTIONS line as the place to do that.

With "-E pkcs11" in the bind9 command line, a failure one before the final one occurs: (without regard to this blockage of the p11-proxy). Named's calls wind down the various layers only to fail trying to read .object files unless umask changes, default acls or freeipa's 'permission fix' routines enable access by named to ods user written files. Those files when created are secured initially with no group or other access. I added UMask=2 overrides to ods related daemons, and added setfacl commands with defaults and masks allowing named access. Once access to the files is provided, the final blocking error, created by the pull request above, prevents named's ability to access DNS keys, as follows:

With p11-proxy disabled, named's initialization of the pkcs11 engine results in the call to read K key files to report it can't find the key. However owing the the foregoing fixes named could read the file, but the p11 routines should have, but did not report the actual cause: 'no slots', and so no key is validated and reported.

As far as I can tell, without '-E pkcs11' on the named command line, named refuses to parse ods created URI's leading with 'pkcs11:...'. With '-E pkcs11' on the command line, and with the above freeipa pull request, there are no 'slots' available in the p11/pkcs11 parlance capable of reading the now available key file data.

Reverting this change ( commenting out the 'disable-in' ) DNSKEY records to report properly reported in response to dig DNSKEY commands.

I have to wonder whether the automated test procedures affirm freeipa-server-dns setup's ability to see proper DNSKEY output from named.

In response to the issues that generated the patch leading to breaking DNSSEC, I have a couple ideas for 'all y'all' (that's US 'southern accent') to consider.

One: Is it possible to use a combination of 'enable-in' and 'disable-in' ( https://p11-glue.github.io/p11-glue/p11-kit/manual/pkcs11-conf.html ) to either more specifically disable the modules giving the other parts of freeipa problems and leave named able to load the proxy.. or .. enable named to load the proxy but by default nothing else?

Two: Might this or similar polkit rule change avoid the need for the patch in first place:

[root@registry1 etc]# cat /etc/polkit-1/rules.d/00-rss_allowpkiuser.rules

polkit.addRule(function(action, subject) {
if (action.id == "org.debian.pcsc-lite.access_pcsc" ||
action.id == "org.debian.pcsc-lite.access_card") {
if ((subject.user == "pkiuser") || (subject.user == "dirsrv") || (subject.user == "named")) {
return polkit.Result.YES;
}
polkit.log("action=" + action);
polkit.log("subject=" + subject);
}
});

Three: The logs get cluttered with softhsm2 complaining of using its defaults. To /etc/ipa/dnssec/softhsm2.conf can we add the defaults it presumes in the log messages:

log.level = INFO
slots.mechanisms = ALL
slots.removable = false

Four:

Change /etc/sysconfig/named OPTIONS line:

BIND named process options

~~~~~~~~~~~~~~~~~~~~~~~~~~

+OPTIONS="-E pkcs11"

Five:

Add overrides or change the .service files of ipa-dns and ipa-ods and ods* to include
UMask = 0002

Six:

setfacl -R -m d:m::rwX /var/lib/ipa/dnssec/tokens
setfacl -R -m m::rwX /var/lib/ipa/dnssec/tokens
setfacl -R -m d:g:named:rwX /var/lib/ipa/dnssec/tokens
setfacl -R -m g:named:rwX /var/lib/ipa/dnssec/tokens

might avoid the need for the 'fix-permissions' ipa daemon activity. Also in the alternative maybe something like "usermod -a -G named ods"

There are a few related bug reports I participated in that were subsets of this or arose during the investigation leading to this, this supercedes all of those. Thanks to the many of you who have given tips and hints leading to the system finally able to produce DNSKEY records from named. There are likely other issues fixing these will reveal, but it seemed to me there's enough here to have other people get along with for a start.

abbra commented Mar 15, 2021

@hcoin we already have support for setting up /etc/sysconfig/named with -E pkcs11 and set required parameters for named to access DNSSEC tokens. This is done in ipaserver/install/dnskeysyncinstance.py when we set up SoftHSM configuration during named setup.

I wonder if you have enabled DNSSEC first? The following works for me:

Install IPA

[root@master ~]# ipa-server-install -U --auto-forwarders --no-dnssec-validation --allow-zone-overlap -p Secret123 -a Secret123 -n ipa.test -r IPA.TEST --setup-dns --mkhomedir -N
...
Setup complete
Next steps:
    1. You must make sure these network ports are open:
        TCP Ports:
          * 80, 443: HTTP/HTTPS
          * 389, 636: LDAP/LDAPS
          * 88, 464: kerberos
          * 53: bind
        UDP Ports:
          * 88, 464: kerberos
          * 53: bind
    2. You can now obtain a kerberos ticket using the command: 'kinit admin'
       This ticket will allow you to use the IPA tools (e.g., ipa user-add)
       and the web user interface.
Be sure to back up the CA certificates stored in /root/cacert.p12
These files are required to create replicas. The password for these
files is the Directory Manager password
The ipa-server-install command was successful

Add DNSSEC master

[root@master ~]# ipa-dns-install --dnssec-master
The log file for this installation can be found in /var/log/ipaserver-dns-install.log
==============================================================================
This program will setup DNS for the IPA Server.
This includes:
  * Configure DNS (bind)
  * Configure SoftHSM (required by DNSSEC)
  * Configure ipa-dnskeysyncd (required by DNSSEC)
  * Configure ipa-ods-exporter (required by DNSSEC key master)
  * Configure OpenDNSSEC (required by DNSSEC key master)
  * Generate DNSSEC master key (required by DNSSEC key master)
NOTE: DNSSEC zone signing is not enabled by default
Plan carefully, replacing DNSSEC key master is not recommended
To accept the default shown in brackets, press the Enter key.
Do you want to setup this IPA server as DNSSEC key master? [no]: yes
...
==============================================================================
Setup complete
Global DNS configuration in LDAP server is empty
You can use 'dnsconfig-mod' command to set global DNS options that
would override settings in local named.conf files
    You must make sure these network ports are open:
        TCP Ports:
          * 53: bind
        UDP Ports:
          * 53: bind

Enable DNSSEC for the specific zone:

[root@master ~]# ipa dnszone-mod ipa.test. --dnssec=true
  Zone name: ipa.test.
  Active zone: TRUE
  Authoritative nameserver: master.ipa.test.
  Administrator e-mail address: hostmaster.ipa.test.
  SOA serial: 1615836685
  SOA refresh: 3600
  SOA retry: 900
  SOA expire: 1209600
  SOA minimum: 3600
  BIND update policy: grant IPA.TEST krb5-self * A; grant IPA.TEST krb5-self * AAAA; grant IPA.TEST krb5-self * SSHFP;
  Dynamic update: TRUE
  Allow query: any;
  Allow transfer: none;
  Allow in-line DNSSEC signing: TRUE

Verify that DNSSEC works:

[root@master ~]# dig @master.ipa.test. +dnssec ipa.test. SOA
; <<>> DiG 9.11.28-RedHat-9.11.28-1.fc33 <<>> @master.ipa.test. +dnssec ipa.test. SOA
; (2 servers found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 44176
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 2, AUTHORITY: 2, ADDITIONAL: 3
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 1232
; COOKIE: 7e75c59980accbafeb29f52d604fb69e8b7492c8801c3c74 (good)
;; QUESTION SECTION:
;ipa.test.          IN  SOA
;; ANSWER SECTION:
ipa.test.       86400   IN  SOA master.ipa.test. hostmaster.ipa.test. 1615836814 3600 900 1209600 3600
ipa.test.       86400   IN  RRSIG   SOA 8 2 86400 20210414193332 20210315183332 16159 ipa.test. HSX30wBtstnfftkDgLNnUHp2ViCaTkWZvZ8tReR7vTmKSpWeE4cyR/g0 9y8ShpyfCBINDXwbflh+xycnS2/EXZttpUuKv00JcliEuXeyPXfZ34/V 9CJQtFAWHASdDqu4v9y1NYjrgerbxyGQP6t5fL+iMBu8sFqPOm4SdBEo 6hCaPclC5qaT1YJ02+8LoXrMplDnGng+B/PvNIiCVdG4CygjQdRuIiB6 oaarCCUFnAyu+xRHQu6aJAHeKPemZR0WUDfabLhDXEChPQa6Nl7vlrWH ZH2Qt/2veYSv67vX7pTh/P6yLgaZbZarp4w1tM8POEWBiJ94GEllB7Dr nT0eaUK6QUruvej0rgA1NwAQwmlIoDqH2vEEmlyzXI60Ti2MlI4Q1Qf0 kiqjtKPzqq/niJqW4HJxTk3DuOyq140PxiFzf9K/1Akq0Eh9UPGHhlUk 1brmEH5f87urALuxfXiK/oB9ZJFF/hSzL0grAWa9f2xYOqCg8KrJIBx3 V4x/EduR
;; AUTHORITY SECTION:
ipa.test.       86400   IN  NS  master.ipa.test.
ipa.test.       86400   IN  RRSIG   NS 8 2 86400 20210328094953 20210315183332 16159 ipa.test. dzEd0o5I+vQnRDxOvk9zJ4VWUdCfMrQtoXbuW5oXNBFyb27P++bj9yDt GOkdRLc6B/jNheN/QGG7GhCau2GuEzYhEhJ8u468CbAd2rCsMF2WT4AH 9iniPS70PVYaF5C+jIsj55GbnwE+OEdX8sbigW0iCzleAxTYWxfmfLOE CX1aZRWZDXTbiTzcu6+Gw5UWRKHLdyVl3XLK3PUkUvSyeJtclgDntxQ0 P8zJXmtpmVAMTkC+wt7Xev/lHIW4nkOZe9fOwtgdp20jDuccoqNZ8g+7 gyvNO+lJoEzixC4p9Q7feUVboEWvRc5dDdpO0ntVFM0402Ynr4Gk1bjY DRcgVDKeSunHeLrc7xc1cvFZW2F5VjknNh/MIuaOpB75bIuo6rYVo5jT /JbJcIF5fHMMAN4Am9vfvNJSap0CS/lvFdBa0o40jGseWPyIbZPhykM/ 7EoyQM+pXNcudTAFCyUO1xEKuAt79QsShBup7oK1avXEeqmiJjjsKsUJ Ep6eIA0X
;; ADDITIONAL SECTION:
master.ipa.test.    1200    IN  AAAA    2620:52:0:88:f816:3eff:fe7e:4ec9
master.ipa.test.    1200    IN  A   10.0.138.108
;; Query time: 0 msec
;; SERVER: 2620:52:0:88:f816:3eff:fe7e:4ec9#53(2620:52:0:88:f816:3eff:fe7e:4ec9)
;; WHEN: ma maalis 15 15:33:50 EDT 2021
;; MSG SIZE  rcvd: 1025
[root@master ~]# dig @master.ipa.test. +dnssec ipa.test. DNSKEY
; <<>> DiG 9.11.28-RedHat-9.11.28-1.fc33 <<>> @master.ipa.test. +dnssec ipa.test. DNSKEY
; (2 servers found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 8785
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 3, AUTHORITY: 0, ADDITIONAL: 1
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 1232
; COOKIE: 71ab077b5c79a3a5a52b9aba604fb7506b135ca49be7f0e3 (good)
;; QUESTION SECTION:
;ipa.test.          IN  DNSKEY
;; ANSWER SECTION:
ipa.test.       86400   IN  DNSKEY  256 3 8 AwEAAeCUQV57kufXf5rdqrcug/KLYnKHKW4gv1+J6EXiw4fFo8evA4hJ qth7rInkWEmruiwIUBXC38Z/EFSaaBpxjs4/HQMFltAVos+FfExxMFU8 71g92grkMIGwCENrT8ApX4blGRn/Ejy9yQREzusitSnu99gtW3cUbh0i cSazfVI5+IOz/F8UaBEEsKHsxhhaQdLpz2VEN5hjoQ2Noy6dR5pRODiA 4chWZ2yLpRTGlCs1sTAv5P59hHohgpnSjYeMxaTZv9dJcEj0CDro4PDQ mD9bwX36yGeLKoHZJMKU6TiQarczxljA57OcUcir2V2dtJXMF/E5y8L1 +11wD7dqh08=
ipa.test.       86400   IN  DNSKEY  257 3 8 AwEAAayawZ4EGYpxoXZOIt5a/+AHxUlzMMWvUZ35+RIC8i4YnXXT8tdw Am+zZ4/FvbOtJVXNhgAR4JlJYEp7RY0ndW+CYNK4kQdnxw3A2a2+zSZl vlbfbQPc3E2A1NfeC9k/9VDy8n2h8LZIGHc+UIcvbbvLitZbaGHTGr8Y om8+LG8sXXTA2ismgQh1wqfWkiIn47NTcjDbXsW+fQjb2LO3kt4u8ZFC 7hAPQ5sftbI3nxk1bbTeej+s+wQx0HP6GDXNTNVLvXfq+zhjn8gHoJAW H6NhwooDK2AgekLmSEDDVbbkQhv2pikGmLxPYfu0PlG5oMdSgNduMP6p jTuDq+jBCPUolntXsP9J+2L3v5ww1GGFjaXbQkGHqklxCiLwo1AthGzT Vor/g+k7ps08vF4aKEx6wNI6GVvGZZ66WlqlMRysv6VYTloezeU2v2My IWl296xjhb8Nk7rFoBFppkcRdG36FKDOdsFSA6N7QpxYLukoVFz82ABP e12BP1UGsmEuTQ==
ipa.test.       86400   IN  RRSIG   DNSKEY 8 2 86400 20210414193332 20210315183332 16159 ipa.test. W/hpjWpBbiZNV9R0v6DBBwXcdze39aDOHupm0tb1J5Y2+LcjhF+chLmP CT5xQvCtzaViIisnUxOm06hmX0C3WrlGz1dZP0ApB9MSmOJ246Tbv8sC Z++Ey3JrsYBcWOxz+Nq2OR4jg+5iLVouYn7nOlm4jJuq0YxWA/GxmQ75 tHIQis7Wacj9f1I0ID63f3cnutVpJNyJqWLwuxlH9gv3KAz5WRWJkXc8 oeauktMbT/BpwVdJEM+A1RF7PcKjbtIZ6gOq4Phd5o9dZj4y8y7vt+TF xVw6NDoMopMnmu3ggvLJY5pzUxZU3R8ddKlVa7n3aCsR62i8xxZfwqcF fMpIwzPVsGFGxUO0S1Kxq2t6oWGgBY1lIkZu9OMxTAwtsym+6xrG1uhS e6T75HXVxvEUpX57kpbmz+PIdQWcDDCu7DUSO/YAR3WSsCeL964sdOy1 UETZl5GhcK89Ou5fOuBj8kKml5/Xb3Dg2nul08z4TDz0eZtqlZ2ftW1S TkmtmO8x
;; Query time: 0 msec
;; SERVER: 2620:52:0:88:f816:3eff:fe7e:4ec9#53(2620:52:0:88:f816:3eff:fe7e:4ec9)
;; WHEN: ma maalis 15 15:36:48 EDT 2021
;; MSG SIZE  rcvd: 1169

abbra commented Mar 15, 2021

Permissions are also correct:

[root@master ~]# ls -la /var/named/dyndb-ldap/ipa/master/ipa.test/
total 44
drwxrwx---. 3 named named  4096 15. 3. 15:33 .
drwxrwx---. 3 named named  4096 15. 3. 15:25 ..
drwxrwx---. 2 ods   named  4096 15. 3. 15:33 keys
-rw-r--r--. 1 named named   512 15. 3. 15:33 raw.jbk
-rw-r--r--. 1 named named  1294 15. 3. 15:33 signed
-rw-r--r--. 1 named named 22638 15. 3. 15:33 signed.jnl
[root@master ~]# ls -la /var/named/dyndb-ldap/ipa/master/ipa.test/keys/
total 40
drwxrwx---. 2 ods   named 4096 15. 3. 15:33 .
drwxrwx---. 3 named named 4096 15. 3. 15:33 ..
-rw-rw----. 1 ods   named  104 15. 3. 15:33 Kipa.test.+008+16159.dn
-rw-rw----. 1 ods   named  774 15. 3. 15:33 Kipa.test.+008+16159.key
-rw-rw----. 1 ods   named  815 15. 3. 15:33 Kipa.test.+008+16159.private
-rw-rw----. 1 ods   named   36 15. 3. 15:33 Kipa.test.+008+16159.uuid
-rw-rw----. 1 ods   named  104 15. 3. 15:33 Kipa.test.+008+45810.dn
-rw-rw----. 1 ods   named  546 15. 3. 15:33 Kipa.test.+008+45810.key
-rw-rw----. 1 ods   named  622 15. 3. 15:33 Kipa.test.+008+45810.private
-rw-rw----. 1 ods   named   36 15. 3. 15:33 Kipa.test.+008+45810.uuid
[root@master ~]# ls -la /var/lib/ipa/dnssec/tokens/
total 12
drwxrws---. 3 ods named 4096 15. 3. 15:25 .
drwxrwx---. 3 ods named 4096 15. 3. 15:25 ..
drwxrws---. 2 ods named 4096 15. 3. 15:33 40a954e5-e7cc-5df4-acf7-47d001e270cf
[root@master ~]# ls -la /var/lib/ipa/dnssec/tokens/40a954e5-e7cc-5df4-acf7-47d001e270cf/
total 100
drwxrws---. 2 ods named 4096 15. 3. 15:33 .
drwxrws---. 3 ods named 4096 15. 3. 15:25 ..
-rw-rw----. 1 ods named    0 15. 3. 15:33 09889d6f-c634-130b-60a9-2b010e32c877.lock
-rw-rw----. 1 ods named 2273 15. 3. 15:33 09889d6f-c634-130b-60a9-2b010e32c877.object
-rw-rw----. 1 ods named    0 15. 3. 15:31 0e8988ae-2a47-dbbf-2e13-07d6783bb37b.lock
-rw-rw----. 1 ods named  964 15. 3. 15:31 0e8988ae-2a47-dbbf-2e13-07d6783bb37b.object
-rw-rw----. 1 ods named    0 15. 3. 15:33 16c1459d-a3c5-8738-f829-dede3ec8dbae.lock
-rw-rw----. 1 ods named  855 15. 3. 15:33 16c1459d-a3c5-8738-f829-dede3ec8dbae.object
-rw-rw----. 1 ods named    0 15. 3. 15:33 17c0dca9-dd32-31de-8ffe-f791b554327a.lock
-rw-rw----. 1 ods named  855 15. 3. 15:33 17c0dca9-dd32-31de-8ffe-f791b554327a.object
-rw-rw----. 1 ods named    0 15. 3. 15:33 225cf5a7-04ae-578b-0536-06ad856995ea.lock
-rw-rw----. 1 ods named 2849 15. 3. 15:33 225cf5a7-04ae-578b-0536-06ad856995ea.object
-rw-rw----. 1 ods named    0 15. 3. 15:31 24ad535a-61ea-85f4-91e7-16fbf1bba526.lock
-rw-rw----. 1 ods named 2257 15. 3. 15:31 24ad535a-61ea-85f4-91e7-16fbf1bba526.object
-rw-rw----. 1 ods named    0 15. 3. 15:33 294cce9d-8ae5-a9fc-bf7c-3d6cf75f4948.lock
-rw-rw----. 1 ods named 2273 15. 3. 15:33 294cce9d-8ae5-a9fc-bf7c-3d6cf75f4948.object
-rw-rw----. 1 ods named    0 15. 3. 15:33 2a06d560-7a39-62e7-6771-d361db673c49.lock
-rw-rw----. 1 ods named 2273 15. 3. 15:33 2a06d560-7a39-62e7-6771-d361db673c49.object
-rw-rw----. 1 ods named    0 15. 3. 15:25 5393eb65-f026-25e7-e87d-a09880faf2d5.lock
-rw-rw----. 1 ods named 2257 15. 3. 15:25 5393eb65-f026-25e7-e87d-a09880faf2d5.object
-rw-rw----. 1 ods named    0 15. 3. 15:31 5dbf1405-9a71-f3c4-30c8-2cdddbf1d5f5.lock
-rw-rw----. 1 ods named  964 15. 3. 15:31 5dbf1405-9a71-f3c4-30c8-2cdddbf1d5f5.object
-rw-------. 1 ods named    0 15. 3. 15:33 7abbdb88-b0b3-cac7-f570-102811f0c1a0.lock
-rw-------. 1 ods named 2273 15. 3. 15:33 7abbdb88-b0b3-cac7-f570-102811f0c1a0.object
-rw-rw----. 1 ods named    0 15. 3. 15:31 7d811f29-89d8-4866-84da-d6cec283c803.lock
-rw-rw----. 1 ods named  803 15. 3. 15:31 7d811f29-89d8-4866-84da-d6cec283c803.object
-rw-rw----. 1 ods named    0 15. 3. 15:33 7efb84b3-a985-9cc9-05ca-3e5367350d32.lock
-rw-rw----. 1 ods named 2273 15. 3. 15:33 7efb84b3-a985-9cc9-05ca-3e5367350d32.object
-rw-rw----. 1 ods named    0 15. 3. 15:33 96cea6e1-6e38-6ff7-7ec2-109dc7fe4132.lock
-rw-rw----. 1 ods named 2257 15. 3. 15:33 96cea6e1-6e38-6ff7-7ec2-109dc7fe4132.object
-rw-rw----. 1 ods named    0 15. 3. 15:33 b126566f-d755-0609-2774-43c75292f100.lock
-rw-rw----. 1 ods named  855 15. 3. 15:33 b126566f-d755-0609-2774-43c75292f100.object
-rw-rw----. 1 ods named    0 15. 3. 15:33 b43351cb-f42e-ffb6-5ad1-77c01a54c785.lock
-rw-rw----. 1 ods named  855 15. 3. 15:33 b43351cb-f42e-ffb6-5ad1-77c01a54c785.object
-rw-------. 1 ods named    0 15. 3. 15:33 be944cfe-aeb1-65ec-f6d5-b70280a8eb6f.lock
-rw-------. 1 ods named  855 15. 3. 15:33 be944cfe-aeb1-65ec-f6d5-b70280a8eb6f.object
-rw-rw----. 1 ods named    0 15. 3. 15:33 c3c2350e-03ee-acae-6827-dbd1179e60a1.lock
-rw-rw----. 1 ods named  855 15. 3. 15:33 c3c2350e-03ee-acae-6827-dbd1179e60a1.object
-rw-------. 1 ods named    0 15. 3. 15:33 d7480195-36b3-b400-3902-a3d003020ab1.lock
-rw-------. 1 ods named 2849 15. 3. 15:33 d7480195-36b3-b400-3902-a3d003020ab1.object
-rw-------. 1 ods named    0 15. 3. 15:33 ed74c9a3-be44-86fb-a8a4-23aaee786266.lock
-rw-------. 1 ods named  983 15. 3. 15:33 ed74c9a3-be44-86fb-a8a4-23aaee786266.object
-rw-rw----. 1 ods named    0 15. 3. 15:33 f12c3d8a-18c2-4b71-b5cc-4cfcefb02217.lock
-rw-rw----. 1 ods named  983 15. 3. 15:33 f12c3d8a-18c2-4b71-b5cc-4cfcefb02217.object
-rw-rw----. 1 ods named    8 15. 3. 15:33 generation
-rw-rw----. 1 ods named    0 15. 3. 15:33 token.lock
-rw-rw----. 1 ods named  320 15. 3. 15:33 token.object

abbra commented Mar 15, 2021

All this is on F33:

[root@master ~]# rpm -q freeipa-server bind softhsm
freeipa-server-4.9.2-4.fc33.x86_64
bind-9.11.28-1.fc33.x86_64
softhsm-2.6.1-3.fc33.4.x86_64

hcoin commented Mar 15, 2021

All is well for me up to the step "Verify that DNSSEC works". There are no rrsigs, no dnskeys. After reverting the patch, restarting named, and waiting, there are.

You also mention 'permissions are correct' -- but only if you don't notice the race between the 'permission fixer' daemon and the code that needs access to the files. Better to create the files with the correct permissions and access than to see if the consumer needs it before the fixer gets to it.

abbra commented Mar 15, 2021

I used a throw-away VM with F33, this is not something I specifically modified to make it working. So I cannot reproduce your issue.

We have DNSSEC tests running in nightly FreeIPA upstream tests on F33. While test_dnssec did overall fail last night, it is due to systemd-resolved integration in our test runners (known issue) and not due to DNSSEC configuration. You can see results in http://freeipa-org-pr-ci.s3-website.eu-central-1.amazonaws.com/jobs/f711a062-8478-11eb-bce3-fa163e0320b2/report.html (and logs accessible if you'd remove report.html from the URL).

hcoin commented Mar 15, 2021

[root@registry1 system]# rpm -q freeipa-server bind softhsm
freeipa-server-4.9.2-4.fc33.x86_64
bind-9.11.28-1.fc33.x86_64
softhsm-2.6.1-3.fc33.4.x86_64

And notice, fc33 workstation. Without the polkit fix your logs had to be filled with pcscd and related errors.
See:
https://pagure.io/freeipa/issue/8701
https://bugzilla.redhat.com/show_bug.cgi?id=1937207
https://bugzilla.redhat.com/show_bug.cgi?id=1933443

hcoin commented Mar 15, 2021

Seems the 'permission fixer' unfixed my acl fix:
Mar 15 15:17:00 registry1.1.quietfountain.com named[1467]: File.cpp(94): Could not open the file (Permission denied): /var/lib/ipa/dnssec/tokens/9eb656cf-79e1-2ea1-708b-a1ae8194ed38/b5547f05-8600-1cc6-8f86-59efe4729390.object
Mar 15 15:17:00 registry1.1.quietfountain.com named[1467]: File.cpp(94): Could not open the file (Permission denied): /var/lib/ipa/dnssec/tokens/9eb656cf-79e1-2ea1-708b-a1ae8194ed38/c73b63be-4925-d5a8-9fdf-98a0a4678329.object
Mar 15 15:17:00 registry1.1.quietfountain.com named[1467]: File.cpp(94): Could not open the file (Permission denied): /var/lib/ipa/dnssec/tokens/9eb656cf-79e1-2ea1-708b-a1ae8194ed38/c73b63be-4925-d5a8-9fdf-98a0a4678329.object

But a little later:
ls -l /var/lib/ipa/dnssec/tokens/9eb656cf-79e1-2ea1-708b-a1ae8194ed38/
total 504
-rw-rw----+ 1 ods named 0 Mar 14 23:15 02e7a3cd-3adb-772d-5bd0-0386b539caa3.lock
-rw-rw----+ 1 ods named 2833 Mar 14 23:15 02e7a3cd-3adb-772d-5bd0-0386b539caa3.object
-rw-rw----+ 1 ods named 0 Mar 15 02:06 03a6c2e1-9e15-68fa-106e-a1b2970c4ab9.lock
-rw-rw----+ 1 ods named 2273 Mar 15 02:06 03a6c2e1-9e15-68fa-106e-a1b2970c4ab9.object

hcoin commented Mar 15, 2021

This one seems related, pulled from the logs after reverting the patch and rebooting (but with the polkit fix)

Mar 15 15:26:59 registry1.1.quietfountain.com ipa-dnskeysyncd[3164]: ipapython.ipautil: DEBUG Starting external process
Mar 15 15:26:59 registry1.1.quietfountain.com ipa-dnskeysyncd[3164]: ipapython.ipautil: DEBUG args=['/usr/sbin/dnssec-keyfromlabel', '-K', '/var/named/dyndb-ldap/ipa/master/somedomain.com/tmp_b305dun', '-a', b'RSASHA256', '-l', b'pkcs11:object=7c7344f8b53c49e7c3aa506aa28cef96;pin-source=/var/lib/ipa/dnssec/softhsm_pin', '-P', b'20210315072656', '-A', b'20210315072656', '-I', 'none', '-D', 'none', '-f', 'KSK', '-E', 'pkcs11', 'somedomain.com.']
Mar 15 15:27:05 registry1.1.quietfountain.com named[1467]: zone 3.quietfountain.com/IN (signed): sending notifies (serial 2021031453)
Mar 15 15:27:05 registry1.1.quietfountain.com ipa-dnskeysyncd[3164]: ipapython.ipautil: DEBUG Process finished, return code=1
Mar 15 15:27:05 registry1.1.quietfountain.com ipa-dnskeysyncd[3164]: ipapython.ipautil: DEBUG stdout=
Mar 15 15:27:05 registry1.1.quietfountain.com ipa-dnskeysyncd[3164]: ipapython.ipautil: DEBUG stderr=Found uninitialized token
Mar 15 15:27:05 registry1.1.quietfountain.com ipa-dnskeysyncd[3164]: Found uninitialized token
Mar 15 15:27:05 registry1.1.quietfountain.com ipa-dnskeysyncd[3164]: Found uninitialized token
Mar 15 15:27:05 registry1.1.quietfountain.com ipa-dnskeysyncd[3164]: dnssec-keyfromlabel: fatal: dnssec-keyfromlabel: /var/named/dyndb-ldap/ipa/master/somedomain.com/tmp_b305dun/Ksomedomain.com.+008+39871 already exists
Mar 15 15:27:05 registry1.1.quietfountain.com python3[3164]: detected unhandled Python exception in '/usr/libexec/ipa/ipa-dnskeysyncd'
Mar 15 15:27:06 registry1.1.quietfountain.com ipa-dnskeysyncd[3164]: Traceback (most recent call last):
Mar 15 15:27:06 registry1.1.quietfountain.com ipa-dnskeysyncd[3164]: File "/usr/libexec/ipa/ipa-dnskeysyncd", line 113, in
Mar 15 15:27:06 registry1.1.quietfountain.com ipa-dnskeysyncd[3164]: while ldap_connection.syncrepl_poll(all=1, msgid=ldap_search):
Mar 15 15:27:06 registry1.1.quietfountain.com ipa-dnskeysyncd[3164]: File "/usr/lib64/python3.9/site-packages/ldap/syncrepl.py", line 465, in syncrepl_poll
Mar 15 15:27:06 registry1.1.quietfountain.com ipa-dnskeysyncd[3164]: self.syncrepl_refreshdone()
Mar 15 15:27:06 registry1.1.quietfountain.com ipa-dnskeysyncd[3164]: File "/usr/lib/python3.9/site-packages/ipaserver/dnssec/keysyncer.py", line 128, in syncrepl_refreshdone
Mar 15 15:27:06 registry1.1.quietfountain.com ipa-dnskeysyncd[3164]: self.bindmgr.sync(self.dnssec_zones)
Mar 15 15:27:06 registry1.1.quietfountain.com ipa-dnskeysyncd[3164]: File "/usr/lib/python3.9/site-packages/ipaserver/dnssec/bindmgr.py", line 231, in sync
Mar 15 15:27:06 registry1.1.quietfountain.com ipa-dnskeysyncd[3164]: self.sync_zone(zone)
Mar 15 15:27:06 registry1.1.quietfountain.com ipa-dnskeysyncd[3164]: File "/usr/lib/python3.9/site-packages/ipaserver/dnssec/bindmgr.py", line 204, in sync_zone
Mar 15 15:27:06 registry1.1.quietfountain.com ipa-dnskeysyncd[3164]: self.install_key(zone, uuid, attrs, tempdir)
Mar 15 15:27:06 registry1.1.quietfountain.com ipa-dnskeysyncd[3164]: File "/usr/lib/python3.9/site-packages/ipaserver/dnssec/bindmgr.py", line 145, in install_key
Mar 15 15:27:06 registry1.1.quietfountain.com ipa-dnskeysyncd[3164]: result = ipautil.run(cmd, capture_output=True)
Mar 15 15:27:06 registry1.1.quietfountain.com ipa-dnskeysyncd[3164]: File "/usr/lib/python3.9/site-packages/ipapython/ipautil.py", line 598, in run
Mar 15 15:27:06 registry1.1.quietfountain.com ipa-dnskeysyncd[3164]: raise CalledProcessError(
Mar 15 15:27:06 registry1.1.quietfountain.com ipa-dnskeysyncd[3164]: ipapython.ipautil.CalledProcessError: CalledProcessError(Command ['/usr/sbin/dnssec-keyfromlabel', '-K', '/var/named/dyndb-ldap/ipa/master/somedomain.com/tmp_b305dun', '-a', b'RSASHA256', '-l', b'pkcs11:object=7c7344f8b53c49e7c3aa506aa28cef96;pin-source=/var/lib/ipa/dnssec/softhsm_pin', '-P', b'20210315072656', '-A', b'20210315072656', '-I', 'none', '-D', 'none', '-f', 'KSK', '-E', 'pkcs11', 'somedomain.com.'] returned non-zero exit status 1: 'Found uninitialized token\nFound uninitialized token\nFound uninitialized token\ndnssec-keyfromlabel: fatal: dnssec-keyfromlabel: /var/named/dyndb-ldap/ipa/master/somedomain.com/tmp_b305dun/Ksomedomain.com.+008+39871 already exists\n\n')

hcoin commented Mar 15, 2021

Mar 15 15:50:18 registry1.1.quietfountain.com systemd[1]: ipa-dnskeysyncd.service: Scheduled restart job, restart counter is at 8.

...
Mar 15 15:53:26 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: ipaserver.dnssec.bindmgr: DEBUG Fixing file permissions: /var/lib/ipa/dnssec/tokens/9eb656cf-79e1-2ea1-708b-a1ae8194ed38/b5547f05-8600-1cc6-8f86-59efe4729390.object
Mar 15 15:53:26 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: ipaserver.dnssec.bindmgr: DEBUG Fixing file permissions: /var/lib/ipa/dnssec/tokens/9eb656cf-79e1-2ea1-708b-a1ae8194ed38/b5547f05-8600-1cc6-8f86-59efe4729390.lock
Mar 15 15:53:26 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: ipaserver.dnssec.bindmgr: INFO attrs:
Mar 15 15:53:26 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: ipapython.ipautil: DEBUG Starting external process
Mar 15 15:53:26 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: ipapython.ipautil: DEBUG args=['/usr/sbin/dnssec-keyfromlabel', '-K', '/var/named/dyndb-ldap/ipa/master/rocksteady.systems/tmpk3l7vzjz', '-a', b'RSASHA256', '-l', b'pkcs11:object=3a4e3c5ac639dc5b5d2ee6d4e51253c8;pin-source=/var/lib/ipa/dnssec/softhsm_pin', '-P', b'20210315070224', '-A', 'none', '-I', 'none', '-D', 'none', '-E', 'pkcs11', 'rocksteady.systems.']
Mar 15 15:53:26 registry1.1.quietfountain.com named[4007]: zone 9.quietfountain.com/IN (signed): next key event: 15-Mar-2021 16:53:18.797
Mar 15 15:53:28 registry1.1.quietfountain.com named[4007]: zone 9.quietfountain.com/IN (signed): sending notifies (serial 2021031428)
Mar 15 15:53:29 registry1.1.quietfountain.com named[4007]: zone 1.quietfountain.com/IN (signed): sending notifies (serial 1615840952)
Mar 15 15:53:30 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: ipapython.ipautil: DEBUG Process finished, return code=0
Mar 15 15:53:30 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: ipapython.ipautil: DEBUG stdout=Krocksteady.systems.+008+39871
Mar 15 15:53:30 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: ipapython.ipautil: DEBUG stderr=Found uninitialized token
Mar 15 15:53:30 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: Found uninitialized token
Mar 15 15:53:30 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: ipaserver.dnssec.bindmgr: INFO attrs:
Mar 15 15:53:30 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: ipapython.ipautil: DEBUG Starting external process
Mar 15 15:53:30 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: ipapython.ipautil: DEBUG args=['/usr/sbin/dnssec-keyfromlabel', '-K', '/var/named/dyndb-ldap/ipa/master/rocksteady.systems/tmpk3l7vzjz', '-a', b'RSASHA256', '-l', b'pkcs11:object=7c7344f8b53c49e7c3aa506aa28cef96;pin-source=/var/lib/ipa/dnssec/softhsm_pin', '-P', b'20210315072656', '-A', b'20210315072656', '-I', 'none', '-D', 'none', '-f', 'KSK', '-E', 'pkcs11', 'rocksteady.systems.']
Mar 15 15:53:34 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: ipapython.ipautil: DEBUG Process finished, return code=1
Mar 15 15:53:34 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: ipapython.ipautil: DEBUG stdout=
Mar 15 15:53:34 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: ipapython.ipautil: DEBUG stderr=Found uninitialized token
Mar 15 15:53:34 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: Found uninitialized token
Mar 15 15:53:34 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: Found uninitialized token
Mar 15 15:53:34 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: dnssec-keyfromlabel: fatal: dnssec-keyfromlabel: /var/named/dyndb-ldap/ipa/master/rocksteady.systems/tmpk3l7vzjz/Krocksteady.systems.+008+39871 already exists
Mar 15 15:53:34 registry1.1.quietfountain.com python3[4360]: detected unhandled Python exception in '/usr/libexec/ipa/ipa-dnskeysyncd'
Mar 15 15:53:35 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: Traceback (most recent call last):
Mar 15 15:53:35 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: File "/usr/libexec/ipa/ipa-dnskeysyncd", line 113, in
Mar 15 15:53:36 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: while ldap_connection.syncrepl_poll(all=1, msgid=ldap_search):
Mar 15 15:53:36 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: File "/usr/lib64/python3.9/site-packages/ldap/syncrepl.py", line 465, in syncrepl_poll
Mar 15 15:53:36 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: self.syncrepl_refreshdone()
Mar 15 15:53:36 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: File "/usr/lib/python3.9/site-packages/ipaserver/dnssec/keysyncer.py", line 128, in syncrepl_refreshdone
Mar 15 15:53:36 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: self.bindmgr.sync(self.dnssec_zones)
Mar 15 15:53:36 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: File "/usr/lib/python3.9/site-packages/ipaserver/dnssec/bindmgr.py", line 231, in sync
Mar 15 15:53:36 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: self.sync_zone(zone)
Mar 15 15:53:36 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: File "/usr/lib/python3.9/site-packages/ipaserver/dnssec/bindmgr.py", line 204, in sync_zone
Mar 15 15:53:36 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: self.install_key(zone, uuid, attrs, tempdir)
Mar 15 15:53:36 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: File "/usr/lib/python3.9/site-packages/ipaserver/dnssec/bindmgr.py", line 145, in install_key
Mar 15 15:53:36 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: result = ipautil.run(cmd, capture_output=True)
Mar 15 15:53:36 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: File "/usr/lib/python3.9/site-packages/ipapython/ipautil.py", line 598, in run
Mar 15 15:53:36 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: raise CalledProcessError(
Mar 15 15:53:36 registry1.1.quietfountain.com ipa-dnskeysyncd[4360]: ipapython.ipautil.CalledProcessError: CalledProcessError(Command ['/usr/sbin/dnssec-keyfromlabel', '-K', '/var/named/dyndb-ldap/ipa/master/rocksteady.systems/tmpk3l7vzjz', '-a', b'RSASHA256', '-l', b'pkcs11:object=7c7344f8b53c49e7c3aa506aa28cef96;pin-source=/var/lib/ipa/dnssec/softhsm_pin', '-P', b'20210315072656', '-A', b'20210315072656', '-I', 'none', '-D', 'none', '-f', 'KSK', '-E', 'pkcs11', 'rocksteady.systems.'] returned non-zero exit status 1: 'Found uninitialized token\nFound uninitialized token\nFound uninitialized token\ndnssec-keyfromlabel: fatal: dnssec-keyfromlabel: /var/named/dyndb-ldap/ipa/master/rocksteady.systems/tmpk3l7vzjz/Krocksteady.systems.+008+39871 already exists\n\n')
Mar 15 15:53:37 registry1.1.quietfountain.com named[4007]: zone 2.quietfountain.com/IN (signed): sending notifies (serial 2021032469)
Mar 15 15:53:37 registry1.1.quietfountain.com named[4007]: zone rockstablesystems.com/IN (signed): next key event: 15-Mar-2021 16:53:26.106
Mar 15 15:53:37 registry1.1.quietfountain.com named[4007]: zone rockstablesystems.com/IN (signed): sending notifies (serial 2021031524)
Mar 15 15:53:38 registry1.1.quietfountain.com systemd[1]: ipa-dnskeysyncd.service: Main process exited, code=exited, status=1/FAILURE
Mar 15 15:53:38 registry1.1.quietfountain.com audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=ipa-dnskeysyncd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
Mar 15 15:53:38 registry1.1.quietfountain.com systemd[1]: ipa-dnskeysyncd.service: Failed with result 'exit-code'.
Mar 15 15:53:38 registry1.1.quietfountain.com systemd[1]: ipa-dnskeysyncd.service: Consumed 46.078s CPU time.
Mar 15 15:53:39 registry1.1.quietfountain.com abrt-server[4534]: Deleting problem directory Python3-2021-03-15-15:53:35-4360 (dup of Python3-2021-03-14-23:22:54-10327)

hcoin commented Mar 15, 2021

Your tip about the server install ipaserver/install/dnskeysyncinstance.py helped. Perhaps you'd consider adding to /etc/sysconfig/named the message that freeipa 'owns' that file, or depends on having modified it, in the same fashion freeipa does in named.conf, and related /etc/named/ipa-options*. That would have made a nice difference.

I suspect I'm not alone in missing the commit of 7 months ago

https://pagure.io/freeipa/c/5c907e34ae4496482151cd9c8271d9931ac4056d?branch=master

which, by other freeipa named.conf config standards 'silently' added the -E and OPENSSL_CONF to /etc/sysconfig/named

(Previous versions of named required acls to be defined before use in global options, and freeipa didn't allow that in named.conf, so my NAMEDCONF defined the acl then called freeipa's /etc/named.conf --- which meant freeipa's takeover of /etc/sysconfig/named went un-noticed )

Related, I have to add a longer timeout 25 to dyndb "ipa" to prevent failure when under load in named.conf.

I'm running our test suite now that includes an automated install of freeipa as a component. I hope to report good news tomorrow.

hcoin commented Mar 16, 2021

Interim report. Took out all local customization. 1 domain has a DNSKEY, the first added. None of the others do though dnssec was enabled on them. Logs filled with 'permission denied' and crash ods exporter reports. One DNSKEY on one domain, is one more than I had this morning, so progress of a sort. Relevant log entries and config details follow.

Thousands of lines like:
Mar 15 19:41:53 registry1.1.quietfountain.com named[13504]: File.cpp(94): Could not open the file (Permission denied): /var/lib/ipa/dnssec/tokens/9eb656cf-79e1-2ea1-708b-a1ae8194ed38/ee163ba5-8948-b8f1-eaee-7b37a309293b.object
Mar 15 19:41:53 registry1.1.quietfountain.com named[13504]: File.cpp(94): Could not open the file (Permission denied): /var/lib/ipa/dnssec/tokens/9eb656cf-79e1-2ea1-708b-a1ae8194ed38/ee163ba5-8948-b8f1-eaee-7b37a309293b.object
Mar 15 19:41:53 registry1.1.quietfountain.com named[13504]: File.cpp(94): Could not open the file (Permission denied): /var/lib/ipa/dnssec/tokens/9eb656cf-79e1-2ea1-708b-a1ae8194ed38/2415bc30-95b4-9fc8-6bb0-1d6a951a05a9.object
Mar 15 19:41:53 registry1.1.quietfountain.com named[13504]: File.cpp(94): Could not open the file (Permission denied): /var/lib/ipa/dnssec/tokens/9eb656cf-79e1-2ea1-708b-a1ae8194ed38/2415bc30-95b4-9fc8-6bb0-1d6a951a05a9.object
Mar 15 19:41:53 registry1.1.quietfountain.com named[13504]: File.cpp(94): Could not open the file (Permission denied): /var/lib/ipa/dnssec/tokens/9eb656cf-79e1-2ea1-708b-a1ae8194ed38/2bb55f68-61ae-9b25-a9fe-daf13aaa6a82.object
Mar 15 19:41:53 registry1.1.quietfountain.com named[13504]: File.cpp(94): Could not open the file (Permission denied): /var/lib/ipa/dnssec/tokens/9eb656cf-79e1-2ea1-708b-a1ae8194ed38/2bb55f68-61ae-9b25-a9fe-daf13aaa6a82.object
Mar 15 19:41:53 registry1.1.quietfountain.com named[13504]: File.cpp(94): Could not open the file (Permission denied): /var/lib/ipa/dnssec/tokens/9eb656cf-79e1-2ea1-708b-a1ae8194ed38/3e38f3e5-cf2f-e8ae-31cd-d890bf1bcc82.object
Mar 15 19:41:53 registry1.1.quietfountain.com named[13504]: File.cpp(94): Could not open the file (Permission denied): /var/lib/ipa/dnssec/tokens/9eb656cf-79e1-2ea1-708b-a1ae8194ed38/3e38f3e5-cf2f-e8ae-31cd-d890bf1bcc82.object
Mar 15 19:41:53 registry1.1.quietfountain.com [13583]: GSSAPI client step 1

Several instance of blocks like these ( ipa-ods-exporter.service: Scheduled restart job, restart counter is at 27.)
Mar 15 20:21:42 registry1.1.quietfountain.com named[13504]: resolver priming query complete
...
Mar 15 20:35:58 registry1.1.quietfountain.com ipa-ods-exporter[16221]: Traceback (most recent call last):
Mar 15 20:35:59 registry1.1.quietfountain.com ipa-ods-exporter[16221]: File "/usr/libexec/ipa/ipa-ods-exporter", line 689, in
Mar 15 20:35:59 registry1.1.quietfountain.com ipa-ods-exporter[16221]: ldap2master_replica_keys_sync(ldapkeydb, localhsm)
Mar 15 20:35:59 registry1.1.quietfountain.com ipa-ods-exporter[16221]: File "/usr/libexec/ipa/ipa-ods-exporter", line 293, in ldap2master_replica_keys_sync
Mar 15 20:35:59 registry1.1.quietfountain.com ipa-ods-exporter[16221]: hex_set(localhsm.replica_pubkeys_wrap))
Mar 15 20:35:59 registry1.1.quietfountain.com ipa-ods-exporter[16221]: File "/usr/lib/python3.9/site-packages/ipaserver/dnssec/localhsm.py", line 138, in replica_pubkeys_wrap
Mar 15 20:35:59 registry1.1.quietfountain.com ipa-ods-exporter[16221]: self.find_keys(objclass=_ipap11helper.KEY_CLASS_PUBLIC_KEY,
Mar 15 20:35:59 registry1.1.quietfountain.com ipa-ods-exporter[16221]: File "/usr/lib/python3.9/site-packages/ipaserver/dnssec/localhsm.py", line 122, in find_keys
Mar 15 20:35:59 registry1.1.quietfountain.com ipa-ods-exporter[16221]: key = Key(self.p11, h)
Mar 15 20:35:59 registry1.1.quietfountain.com ipa-ods-exporter[16221]: File "/usr/lib/python3.9/site-packages/ipaserver/dnssec/localhsm.py", line 46, in init
Mar 15 20:35:59 registry1.1.quietfountain.com ipa-ods-exporter[16221]: assert len(cka_id) != 0, 'ipk11id length should not be 0'
Mar 15 20:35:59 registry1.1.quietfountain.com ipa-ods-exporter[16221]: AssertionError: ipk11id length should not be 0
Mar 15 20:36:00 registry1.1.quietfountain.com named[13504]: client @0x7f691418f650 51.38.107.74#51126 (www.rockstablesystems.com): query (cache) 'www.rockstablesystems.com/A/IN' denied
Mar 15 20:36:00 registry1.1.quietfountain.com named[13504]: client @0x7f6914171eb0 51.38.107.66#37470 (rockstablesystems.com): query (cache) 'rockstablesystems.com/DNSKEY/IN' denied
Mar 15 20:36:00 registry1.1.quietfountain.com named[13504]: limit REFUSED error responses to 51.38.107.0/24
Mar 15 20:36:01 registry1.1.quietfountain.com systemd[1]: ipa-ods-exporter.service: Main process exited, code=exited, status=1/FAILURE
Mar 15 20:36:01 registry1.1.quietfountain.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'
Mar 15 20:36:01 registry1.1.quietfountain.com systemd[1]: ipa-ods-exporter.service: Failed with result 'exit-code'.
Mar 15 20:36:01 registry1.1.quietfountain.com systemd[1]: ipa-ods-exporter.service: Consumed 12.161s CPU time.

Install details:

[root@registry1 ~]# cat /etc/sysconfig/named

BIND named process options

~~~~~~~~~~~~~~~~~~~~~~~~~~

OPTIONS="whatever" -- These additional options will be passed to named

OPTIONS=" -E pkcs11"

at startup. Don't add -t here, enable proper

-chroot.service unit file.

NAMEDCONF=/etc/named/alternate.conf

-- Don't use -c to change configuration file.

Extend systemd named.service instead or use this

variable.

DISABLE_ZONE_CHECKING -- By default, service file calls named-checkzone

utility for every zone to ensure all zones are

valid before named starts. If you set this option

to 'yes' then service file doesn't perform those

checks.

SOFTHSM2_CONF=/etc/ipa/dnssec/softhsm2.conf
OPENSSL_CONF=/etc/ipa/dnssec/openssl.cnf
[root@registry1 ~]# cat /etc/named/ipa-options-ext.conf

allow-query { any; };
allow-recursion { trusted; };
allow-query-cache { trusted; };     
// notify explicit; 
// also-notify { 10.12.112.3; };
rate-limit {
    exempt-clients { trusted; };
    responses-per-second 5;
    nodata-per-second 2;
    errors-per-second 1;
    qps-scale 200;
    window 1800;
};

[root@registry1 ~]# head /etc/named/ipa-ext.conf

// This file will NOT be overridden during ipa updates!
acl "trusted" {
localnets;
localhost;
...
};

[root@registry1 ~]# systemctl is-system-running
running
[root@registry1 ~]# head /var/log/ipaserver-dns-install.log
2021-03-15T02:19:46Z DEBUG /usr/sbin/ipa-dns-install was invoked with options: {'debug': False, 'ip_addresses': [], 'forwarders': None, 'no_forwarders': True, 'auto_forwarders': False, 'forward_policy': None, 'reverse_zones': [], 'no_reverse': False, 'auto_reverse': True, 'allow_zone_overlap': True, 'no_dnssec_validation': False, 'dnssec_master': True, 'zonemgr': 'administrator@quietfountain.com', 'unattended': True, 'disable_dnssec_master': False, 'kasp_db_file': None, 'force': None}
2021-03-15T02:19:46Z DEBUG missing options might be asked for interactively later

2021-03-15T02:19:46Z DEBUG IPA version 4.9.2-4.fc33
2021-03-15T02:19:46Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
2021-03-15T02:19:46Z DEBUG Loading StateFile from '/var/lib/ipa/sysrestore/sysrestore.state'
2021-03-15T02:19:47Z DEBUG importing all plugin modules in ipaserver.plugins...
2021-03-15T02:19:47Z DEBUG importing plugin module ipaserver.plugins.aci
2021-03-15T02:19:47Z DEBUG importing plugin module ipaserver.plugins.automember
2021-03-15T02:19:47Z DEBUG importing plugin module ipaserver.plugins.automount
[root@registry1 ~]# tail /var/log/ipaserver-dns-install.log
Starting ipa-ods-exporter Service
Starting ods-enforcerd Service
Starting ipa-dnskeysyncd Service

2021-03-16T00:19:16Z DEBUG stderr=Existing service file detected!
Assuming stale, cleaning and proceeding
ipa: INFO: The ipactl command was successful

2021-03-16T00:19:16Z DEBUG Destroyed connection context.ldap2_140548350387968
2021-03-16T00:19:16Z INFO The ipa-dns-install command was successful
[root@registry1 ~]#
I did not include the polkit fix. The domain installed at freeipa server dns install time has a DNSKEY and dnssec-ds-from-key produces a valid DS record -- great improvement from before. However, all the domains for which dnssec inline was enabled later do not produce dnskey output.

So, well, half a car anyhow! The system is still loading domains, it will probably finish in the middle of the night and I'll have more tomorrow.

hcoin commented Mar 16, 2021

p.s. The reason permission is denied is:
[root@registry1 ~]# ls -l /var/lib/ipa/dnssec/tokens/9eb656cf-79e1-2ea1-708b-a1ae8194ed38/2415bc30-95b4-9fc8-6bb0-1d6a951a05a9.object
-rw-------+ 1 ods named 2849 Mar 15 19:35 /var/lib/ipa/dnssec/tokens/9eb656cf-79e1-2ea1-708b-a1ae8194ed38/2415bc30-95b4-9fc8-6bb0-1d6a951a05a9.object

hcoin commented Mar 16, 2021

Alexander, are there other testing venues than AWS? Maybe just a VM on older simple 'baremetal' box running fedora workstation 33, or something with markedly different processing power, cpu count, memory, lesser cpu features? There are so many 'timeout tests' in freeipa instead specifics, generally along module or subsystem boundaries.

Also, consider instead of retroactive permission munging maybe

setfacl -R -m u:named:rwX /var/lib/ipa/dnssec/tokens
setfacl -R -m d:u:named:rwX /var/lib/ipa/dnssec/tokens
??
ls -l /var/lib/ipa/dnssec/tokens/
total 0
drwxrws---+ 1 ods named 5776 Mar 15 19:35 9eb656cf-79e1-2ea1-708b-a1ae8194ed38
getfacl /var/lib/ipa/dnssec/tokens
getfacl: Removing leading '/' from absolute path names

file: var/lib/ipa/dnssec/tokens

owner: ods

group: named

flags: -s-

user::rwx
user:named:rwx
group::rwx
group:named:rwx
mask::rwx
other::---
default:user::rwx
default:user:named:rwx
default:group::rwx
default:group:named:rwx
default:mask::rwx
default:other::---

abbra commented Mar 16, 2021

We do not test in AWS. Most of the test environments are either OpenStack-based or VMs in libvirt/kvm.

I am not sure why you are trying to use Fedora Workstation as a starting image, though.

slev commented Mar 16, 2021

The aforementioned patch for p11-kit-proxy has been merged into master before the switching to openssl-pkcs11. To get things work with the disabled p11-kit-proxy the custom OPENSSL_CONF was added(located on /etc/ipa/dnssec/openssl.cnf) and referenced from all the related services via env variable.

The race you told exists, this is because softhsm(actually manages its storage) has no option to change the owner:group(only the mode IIRC), but it may be treated as warnings.

cheimes commented Mar 16, 2021

We have had other reports that the PC/SC daemon is causing problems with SoftHSM2 and DNSSEC. The easiest solution would be to define a package conflict with pcsc-lite in freeipa-server package. This would prevent installation of pcscd on an IPA server. It's not the most elegant solution, though.

In the past FreeIPA's client test suite was failing or very slow on my laptop. It turned out to be related to PKCS#11. Certain operations were slow or failed when I either had my CyberJACK SC reader for German passport plugged in or my YubiKey was in OpenPGP applet mode.

hcoin commented Mar 16, 2021

I have what I hope is some good new information. It's my hunch the install process we have that uses freeipa as a component exposes a race condition. Our routine maintains a roster of domains, some world visible, some internal, all of which use dnssec. Upon a fresh install of freeipa server, once freeipa dns has been reported as installed (which is itself automated), the code in an automated way enables inline dnssec on dozens of domains as quickly as the process allows. What I'm seeing is the first domain gets dnskey's, and none of the rest do. Here's a patch I suggest that exposes the problem and avoids crashes in ipa-ods-exporter. After the patch is a log of the run. What happens is one of two DNSKEYS shows up in some of the domains, and later crashes to do with duplicates occur. A pretty strong sign of errors in locking / lock checking.

[root@registry1 ~]# diff -u localhsm_upstream.py /usr/lib/python3.9/site-packages/ipaserver/dnssec/localhsm.py  
--- localhsm_upstream.py        2021-03-16 11:49:42.876558282 -0500
+++ /usr/lib/python3.9/site-packages/ipaserver/dnssec/localhsm.py       2021-03-16 13:04:14.194058656 -0500
@@ -8,6 +8,7 @@
 from pprint import pprint
 import six
+import logging
 from ipalib.constants import SOFTHSM_DNSSEC_TOKEN_LABEL
 from ipaplatform.paths import paths
@@ -24,6 +25,7 @@
     from collections import MutableMapping
 # pylint: enable=no-name-in-module, import-error
+logger = logging.getLogger(os.path.basename(__file__))
 private_key_api_params = set(["label", "id", "data", "unwrapping_key",
     "wrapping_mech", "key_type", "cka_always_authenticate", "cka_copyable",
@@ -43,17 +45,17 @@
         # sanity check CKA_ID and CKA_LABEL
         try:
             cka_id = self.p11.get_attribute(handle, _ipap11helper.CKA_ID)
-            assert len(cka_id) != 0, 'ipk11id length should not be 0'
         except _ipap11helper.NotFound:
             raise _ipap11helper.NotFound('key without ipk11id: handle %s' % handle)
+        if len(cka_id) == 0: raise _ipap11helper.NotFound('ipk11id length should not be 0 in CKA_ID '+str(_ipap11helper.CKA_ID))
         try:
             cka_label = self.p11.get_attribute(handle, _ipap11helper.CKA_LABEL)
-            assert len(cka_label) != 0, 'ipk11label length should not be 0'
         except _ipap11helper.NotFound:
             raise _ipap11helper.NotFound(
                 'key without ipk11label: id 0x%s' % str_hexlify(cka_id))
+        if len(cka_label) == 0: raise _ipap11helper.NotFound('ipk11label length should not be 0 in  CKA_ID '+str(_ipap11helper.CKA_ID))
     def __getitem__(self, key):
         key = key.lower()
@@ -104,7 +106,9 @@
         self.p11 = _ipap11helper.P11_Helper(label, pin, library)
     def __del__(self):
-        self.p11.finalize()
+        if not (self.p11 is None): 
+            self.p11.finalize()
+            self.p11=None
     def find_keys(self, **kwargs):
         """Return dict with Key objects matching given criteria.
@@ -119,12 +123,15 @@
         handles = self.p11.find_keys(**kwargs)
         keys = {}
         for h in handles:
-            key = Key(self.p11, h)
-            o_id = key['ipk11id']
-            assert o_id not in keys, 'duplicate ipk11Id = 0x%s; keys = %s' % (
-                    str_hexlify(o_id), keys)
-            keys[o_id] = key
-
+            try:
+                key = Key(self.p11, h)
+                o_id = key['ipk11id']
+                assert o_id not in keys, 'duplicate ipk11Id = 0x%s; keys = %s' % (
+                        str_hexlify(o_id), keys)
+                keys[o_id] = key
+            except Exception as e:
+                logger.error("Ignoring invalid key handle "+str(h)+".  Reason: "+str(e))
+        assert len(keys)>0, "No valid keys found."
         return keys
     @property

The above code generates this in the logs:

Mar 16 13:09:31 registry1.1.quietfountain.com ipa-ods-exporter[31477]: ipa-ods-exporter: DEBUG    Kerberos principal: ipa-ods-exporter/registry1.1.quietfountain.com
Mar 16 13:09:31 registry1.1.quietfountain.com ipa-ods-exporter[31477]: ipalib.install.kinit: DEBUG    Initializing principal ipa-ods-exporter/registry1.1.quietfountain.com using keytab /etc/ipa/dnssec/ipa-ods-exporter.keytab
Mar 16 13:09:31 registry1.1.quietfountain.com ipa-ods-exporter[31477]: ipalib.install.kinit: DEBUG    using ccache /var/opendnssec/tmp/ipa-ods-exporter.ccache
Mar 16 13:09:31 registry1.1.quietfountain.com ipa-ods-exporter[31477]: ipalib.install.kinit: DEBUG    Attempt 1/5: success
Mar 16 13:09:31 registry1.1.quietfountain.com ipa-ods-exporter[31477]: ipa-ods-exporter: DEBUG    Got TGT
Mar 16 13:09:31 registry1.1.quietfountain.com ipa-ods-exporter[31477]: ipa-ods-exporter: DEBUG    Connecting to LDAP
Mar 16 13:09:31 registry1.1.quietfountain.com python3[31477]: GSSAPI client step 1
Mar 16 13:09:31 registry1.1.quietfountain.com python3[31477]: GSSAPI client step 1
Mar 16 13:09:31 registry1.1.quietfountain.com python3[31477]: GSSAPI client step 1
Mar 16 13:09:31 registry1.1.quietfountain.com ipa-ods-exporter[31477]: ipa-ods-exporter: DEBUG    Connected
Mar 16 13:09:32 registry1.1.quietfountain.com ipa-ods-exporter[31477]: ipapython.ipaldap: DEBUG    retrieving schema for SchemaCache url=ldapi://%2Frun%2Fslapd-1-QUIETFOUNTAIN-COM.socket conn=<ldap.ldapobject.SimpleLDAPObject object at 0x7f9224a4e040>
Mar 16 13:09:32 registry1.1.quietfountain.com ipa-ods-exporter[31477]: ipa-ods-exporter: DEBUG    replica pub keys in LDAP: {'0x3074928be04991daf5d49008b4333a5a'}
Mar 16 13:09:33 registry1.1.quietfountain.com ipa-ods-exporter[31477]: localhsm.py : ERROR    Ignoring invalid key handle 2.  Reason: ipk11id length should not be 0 in CKA_ID 258
Mar 16 13:09:33 registry1.1.quietfountain.com ipa-ods-exporter[31477]: ipa-ods-exporter: DEBUG    replica pub keys in SoftHSM: {'0x3074928be04991daf5d49008b4333a5a'}
Mar 16 13:09:33 registry1.1.quietfountain.com ipa-ods-exporter[31477]: localhsm.py : ERROR    Ignoring invalid key handle 2.  Reason: ipk11id length should not be 0 in CKA_ID 258
Mar 16 13:09:33 registry1.1.quietfountain.com ipa-ods-exporter[31477]: ipa-ods-exporter: INFO     new replica keys in LDAP: set()
Mar 16 13:09:34 registry1.1.quietfountain.com ipa-ods-exporter[31477]: localhsm.py : ERROR    Ignoring invalid key handle 2.  Reason: ipk11id length should not be 0 in CKA_ID 258
Mar 16 13:09:34 registry1.1.quietfountain.com ipa-ods-exporter[31477]: ipa-ods-exporter: INFO     obsolete replica keys in local HSM: set()
Mar 16 13:09:34 registry1.1.quietfountain.com ipa-ods-exporter[31477]: localhsm.py : ERROR    Ignoring invalid key handle 2.  Reason: ipk11id length should not be 0 in CKA_ID 258
Mar 16 13:09:34 registry1.1.quietfountain.com ipa-ods-exporter[31477]: ipa-ods-exporter: INFO     ldap2master_replica: keys in local HSM & LDAP: {'0x3074928be04991daf5d49008b4333a5a'}
Mar 16 13:09:35 registry1.1.quietfountain.com ipa-ods-exporter[31477]: ipa-ods-exporter: DEBUG    master keys in local HSM: {'0x35e912cdc427f8dd73140216ceabf86d', '0x5c948271b79d1854f41b6dc3e6c4834e'}
Mar 16 13:09:35 registry1.1.quietfountain.com ipa-ods-exporter[31477]: ipa-ods-exporter: DEBUG    master keys in LDAP HSM: {'0x5c948271b79d1854f41b6dc3e6c4834e', '0x35e912cdc427f8dd73140216ceabf86d'}
Mar 16 13:09:35 registry1.1.quietfountain.com ipa-ods-exporter[31477]: ipa-ods-exporter: DEBUG    new master keys in local HSM: set()
Mar 16 13:09:35 registry1.1.quietfountain.com ipa-ods-exporter[31477]: ipa-ods-exporter: DEBUG    master keys in LDAP after flush: {'0x5c948271b79d1854f41b6dc3e6c4834e', '0x35e912cdc427f8dd73140216ceabf86d'}
Mar 16 13:09:36 registry1.1.quietfountain.com ipa-ods-exporter[31477]: ipa-ods-exporter: DEBUG    synchronizing master key metadata: 0x5c948271b79d1854f41b6dc3e6c4834e
Mar 16 13:09:36 registry1.1.quietfountain.com ipa-ods-exporter[31477]: ipa-ods-exporter: DEBUG    synchronizing master key metadata: 0x35e912cdc427f8dd73140216ceabf86d
Mar 16 13:09:36 registry1.1.quietfountain.com ipa-ods-exporter[31477]: localhsm.py : ERROR    Ignoring invalid key handle 2.  Reason: ipk11id length should not be 0 in CKA_ID 258
Mar 16 13:09:36 registry1.1.quietfountain.com ipa-ods-exporter[31477]: ipa-ods-exporter: DEBUG    enabled replica key ids: {'0x3074928be04991daf5d49008b4333a5a'}
Mar 16 13:09:36 registry1.1.quietfountain.com ipa-ods-exporter[31477]: ipa-ods-exporter: DEBUG    processing master key data: 0x35e912cdc427f8dd73140216ceabf86d
Mar 16 13:09:37 registry1.1.quietfountain.com ipa-ods-exporter[31477]: ipa-ods-exporter: DEBUG    master key 0x35e912cdc427f8dd73140216ceabf86d is not wrapped with replica keys set()
Mar 16 13:09:38 registry1.1.quietfountain.com ipa-ods-exporter[31477]: ipa-ods-exporter: DEBUG    processing master key data: 0x5c948271b79d1854f41b6dc3e6c4834e
Mar 16 13:09:38 registry1.1.quietfountain.com ipa-ods-exporter[31477]: ipa-ods-exporter: DEBUG    master key 0x5c948271b79d1854f41b6dc3e6c4834e is not wrapped with replica keys set()
Mar 16 13:09:39 registry1.1.quietfountain.com python3[31477]: detected unhandled Python exception in '/usr/libexec/ipa/ipa-ods-exporter'
Mar 16 13:09:39 registry1.1.quietfountain.com named[1391]: limit responses to 74.63.26.0/24 for quietfountain.com IN DNSKEY  (3df7ca42)
Mar 16 13:09:39 registry1.1.quietfountain.com named[1391]: client @0x7f06981367b0 74.63.26.247#24226 (quietfountain.com): rate limit slip response to 74.63.26.0/24 for quietfountain.com IN DNSKEY  (3df7ca42)
Mar 16 13:09:40 registry1.1.quietfountain.com ipa-ods-exporter[31477]: Traceback (most recent call last):
Mar 16 13:09:40 registry1.1.quietfountain.com ipa-ods-exporter[31477]:   File "/usr/libexec/ipa/ipa-ods-exporter", line 691, in <module>
Mar 16 13:09:40 registry1.1.quietfountain.com ipa-ods-exporter[31477]:     master2ldap_zone_keys_sync(ldapkeydb, localhsm)
Mar 16 13:09:40 registry1.1.quietfountain.com ipa-ods-exporter[31477]:   File "/usr/libexec/ipa/ipa-ods-exporter", line 396, in master2ldap_zone_keys_sync
Mar 16 13:09:40 registry1.1.quietfountain.com ipa-ods-exporter[31477]:     keypairs_ldap = ldapkeydb.zone_keypairs
Mar 16 13:09:40 registry1.1.quietfountain.com ipa-ods-exporter[31477]:   File "/usr/lib/python3.9/site-packages/ipaserver/dnssec/ldapkeydb.py", line 452, in zone_keypairs
Mar 16 13:09:40 registry1.1.quietfountain.com ipa-ods-exporter[31477]:     self._get_key_dict(Key,
Mar 16 13:09:40 registry1.1.quietfountain.com ipa-ods-exporter[31477]:   File "/usr/lib/python3.9/site-packages/ipaserver/dnssec/ldapkeydb.py", line 319, in _get_key_dict
Mar 16 13:09:40 registry1.1.quietfountain.com ipa-ods-exporter[31477]:     raise ValueError(
Mar 16 13:09:40 registry1.1.quietfountain.com ipa-ods-exporter[31477]: ValueError: duplicate ipk11Id=0x5ebe14a8c10f2ce2768ea9c46e6ac0a3 in 'ipk11UniqueID=55704d0a-867e-11eb-9dd6-52540057e6ad,cn=keys,cn=sec,cn=dns,dc=1,dc=quietfountain,dc=com' and 'ipk11UniqueID=54d1ee12-867e-11eb-ab25-52540057e6ad,cn=keys,cn=sec,cn=dns,dc=1,dc=quietfountain,dc=com'

hcoin commented Mar 16, 2021

I'll check on the effort involved to change our code. At the moment it just loops through all the zones and enables dnssec. Instead, I'll see what's involved to enable dnssec on one zone, wait until DNSKEY records show up in named, then go on to the next zone. If that works (which I suspect it might do) then we'll all know something useful.

hcoin commented Mar 16, 2021

@Christian, If it's possible and the resources are available it would be better to understand the nature of the p11 conflict and permit the further engines and tokens to co-exist. After all the whole point of the p11 suite is to manage and sequence traffic to the various possible slot providers and the possible tokens they might offer. In the case of freeipa-server, you could imagine requiring a key card for any operations, so that even an image of the system would not work unless it had the card.

hcoin commented Mar 17, 2021

I have evidence of a destructive race condition with dnssec inline signing. When a vm copy enables DNSSEC on several domains at once, at least several before the keys are created and exported for the first of them -- it fails as noted above. However, rolling back to the original vm and then enabling dnssec on a domain, waiting for the DNSKEY to appear in named before enabling dnssec on another domain -- the same vm produces dnskeys correctly.

The run hasn't completed yet, but named has produced 6 keys where before on the same host and same starting image all the bugs noted above happened. Certainly evidence of a race condition in the DNSSEC logic somewhere.

abbra commented Mar 17, 2021

@hcoin, we had recently fixed https://pagure.io/freeipa/issue/8654 which handles some of similar concurrency issues in the case old replica key being disabled. I am planning 4.9.3 update in next couple weeks that would bring it to F33 among other fixes but if you want to get it faster, patching the code with those two patches or using one of IPA nightly builds would help?

http://freeipa-org-pr-ci.s3-website.eu-central-1.amazonaws.com/jobs/ce5c3138-83d2-11eb-9816-fa163eca8e86/rpms/freeipa-prci.repo is one of the latest (two days ago) ipa-4-9 builds for F33.

hcoin commented Mar 17, 2021

Thanks for your focus on my struggle with this Alexander and team. Looking at the results of the run last night creating then populating the records on 25+ domains: evidence of the dnssec key production failure owing to a lock/race condition is affirmed, but a workaround exists. Some clues to help focus debugging follow.

When the domains are created with dnssec enabled as fast as the api allows one thread in one process to do so, then that same thread adding A / AAAA records as fast as the api allows: DNSKEY reports are empty for all but one zone for which one (KSK?) DNSKEY record appears, while the logs fill with the above noted ipa-ods-exporter crashes with asserts noting 0 length CKA_ID's. I suspect a test script that used the api to define 15+ domains with dnssec enabled then populated those domains with A/AAAA records while looking for DNSKEY entries would provoke the bug for you in a repeatable way.

Rolling back that vm to the point just before freeipa's dns installer then changing the logic to create the zones without dnssec, as fast as the api allows one thread to do so, then populating the zones one at a time with a few A/AAAA records, interspersed with calls to enable DNSsec on a zone, then wait before enabling dnssec on other zones until named reports a DNS KSK key capable of producing a valid DS key from dnssec-dsfromkey, correct operation results and for 25+ domains and counting so far. I hope those details help focus looking for where the race condition might exist.

It's great news for me, as I now have a way forward as correct DNSKEYS are produced by the new 'serial dnskey' logic, waiting for freeipa to orchestrate through all the 'permission denied' log entries and 'permission fixer' entries (maybe just setfacl -u ... with a defauit mask so named gets owner rights to the .object and .lock files)?

I kindly ask that freeipa formally adopt a policy to copy what you folks did for named.conf and other config files to apply across all freeipa modified configuration files: put some comments in the file to note freeipa's dependence upon and modification of those files? In particular /etc/sysconfig/named re a custom ssl/p11 config. One might imagine a 'health checker' looking for 'freeipa' in each config file freeipa depends upon and reporting misses, maybe log warnings on system startups? Given freeipa collects all the paths related constants in one spot it seems a 'doable' thing.

You might imagine I'm under considerable time pressure owing to the delays getting freeipa going, so much else has had to wait beyond due dates. Once I catch those up I'll upgrade freeipa to check out the ideas Alexander offered.

Hope this helps! Is there some conference or event generally attended by contributors here? I'd like to participate.

abbra commented Mar 17, 2021

Glad to hear you found a reliable way to get around the race.

We may plan to look into the race processing later this year. Please tell us when you are ready for additional investigations.

Regarding the comments in the configuration files, we certainly can improve on that. It would need a separate ticket and a review of existing configuration files (we do have some comments already in most of them).

As to conferences/events, we typically have majority of FreeIPA developers present at devconf.cz and sometimes at devconf.us. We also attend FOSDEM, SambaXP, and Fedora project events. With current state of events most of gatherings are happening online, though.

hcoin commented Mar 24, 2021

It turns out openssl-pkcs11 has a very-not-threadsafe eng_back.c module. I heavily re-wrote it, adding the missing and fixing a few bugs. Patches here. Named under heavy dnssec load no longer crashes.
https://bugzilla.redhat.com/show_bug.cgi?id=1940659

Metadata Update from @pcech:
- Issue set to the milestone: DNSSEC

Apr 1, 2021

hcoin commented Apr 6, 2024

Still exists latest April 2024. DNSSec appears to generate enough changes that race-condition related bugs eventually crop up and kill freeipa. Fixes to date have delayed when the problem emerges, but not fixed it. Freeipa Dnssec corruption remains a 'when', not 'if'.

5.14.0-362.24.2.el9_3.x86_64 #1 SMP PREEMPT_DYNAMIC Sat Mar 30 14:11:54 EDT 2024 x86_64 x86_64 x86_64 GNU/Linux
# dnf info ipa-server
Last metadata expiration check: 3:57:47 ago on Sat 06 Apr 2024 07:07:16 AM CDT.
Installed Packages
Name         : ipa-server
Version      : 4.10.2
Release      : 8.el9_3.alma.1
Architecture : x86_64
Size         : 1.1 M
Source       : ipa-4.10.2-8.el9_3.alma.1.src.rpm
Repository   : @System
From repo    : appstream
Summary      : The IPA authentication server
URL          : http://www.freeipa.org/
License      : GPL-3.0-or-later
Apr 06 11:02:43 registry1.1.quietfountain.com systemd[1]: ipa-ods-exporter.service: Scheduled restart job, restart counter is at 1017.
Apr 06 11:02:43 registry1.1.quietfountain.com systemd[1]: Stopped IPA OpenDNSSEC Signer replacement.
Apr 06 11:02:43 registry1.1.quietfountain.com systemd[1]: ipa-ods-exporter.service: Consumed 2.733s CPU time.
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.

Metadata

Assignee

None

Tags

None

Blocking

None

Depending on

None

Priority

None

rhbz

None

freeipa

#8757 freeipa pull 3063 breaks named/dnssec ( DNSKEY queries fail ) Opened Mar 15, 2021 by hcoin. Modified Apr 6, 2024

BIND named process options

~~~~~~~~~~~~~~~~~~~~~~~~~~

BIND named process options

~~~~~~~~~~~~~~~~~~~~~~~~~~

OPTIONS="whatever" -- These additional options will be passed to named

at startup. Don't add -t here, enable proper

-chroot.service unit file.

NAMEDCONF=/etc/named/alternate.conf

-- Don't use -c to change configuration file.

Extend systemd named.service instead or use this

variable.

DISABLE_ZONE_CHECKING -- By default, service file calls named-checkzone

utility for every zone to ensure all zones are

valid before named starts. If you set this option

to 'yes' then service file doesn't perform those

checks.

file: var/lib/ipa/dnssec/tokens

owner: ods

group: named

flags: -s-

Metadata

#8757 freeipa pull 3063 breaks named/dnssec ( DNSKEY queries fail )

Opened Mar 15, 2021 by hcoin. Modified Apr 6, 2024