Issue #4967: ipa-dnskeysync-replica unhandled exception - freeipa

freeipa

#4967 ipa-dnskeysync-replica unhandled exception

Closed: Invalid Opened Mar 29, 2015 by pdf.

I've just created a FreeIPA replica (on 4.1.3, as 4.1.4 was delayed landing in updates-testing) and ipa-dnskeysyncd will not start on the replica. It fails with the following stack trace:

ipa.ipapython.dnssec.keysyncer.KeySyncer: INFO     Initial LDAP dump is done, sychronizing with ODS and BIND
Traceback (most recent call last):
  File "/usr/libexec/ipa/ipa-dnskeysyncd", line 106, in <module>
    while ldap_connection.syncrepl_poll(all=1, msgid=ldap_search):
  File "/usr/lib64/python2.7/site-packages/ldap/syncrepl.py", line 409, in syncrepl_poll
    self.syncrepl_refreshdone()
  File "/usr/lib/python2.7/site-packages/ipapython/dnssec/keysyncer.py", line 114, in syncrepl_refreshdone
    self.hsm_replica_sync()
  File "/usr/lib/python2.7/site-packages/ipapython/dnssec/keysyncer.py", line 171, in hsm_replica_sync
    ipautil.run([paths.IPA_DNSKEYSYNCD_REPLICA])
  File "/usr/lib/python2.7/site-packages/ipapython/ipautil.py", line 356, in run
    raise CalledProcessError(p.returncode, arg_string, stdout)
subprocess.CalledProcessError: Command ''/usr/libexec/ipa/ipa-dnskeysync-replica'' returned non-zero exit status 1

Following the error down and executing ipa-dnskeysync-replica produces the following stack trace:

ipa         : DEBUG    Got TGT
ipa         : DEBUG    Connecting to LDAP
ipa.ipaserver.plugins.ldap2.ldap2: DEBUG    Created connection context.ldap2
ipa         : DEBUG    Connected
Traceback (most recent call last):
  File "/usr/libexec/ipa/ipa-dnskeysync-replica", line 160, in <module>
    open(paths.DNSSEC_SOFTHSM_PIN).read())
  File "/usr/lib/python2.7/site-packages/ipapython/dnssec/localhsm.py", line 97, in __init__
    self.p11 = _ipap11helper.P11_Helper(slot, pin, library)
_ipap11helper.Error: Error at open session: 0xe1
Exception AttributeError: "'LocalHSM' object has no attribute 'p11'" in <bound method LocalHSM.__del__ of <ipapython.dnssec.localhsm.LocalHSM object at 0x7f9e2c02f090>> ignored

I waited until 4.1.4 finally hit the repos before reporting, and can confirmed that this behavior is still present on 4.1.4, happy to perform any additional debugging to find the cause, and this is 100% reproducible on this host.

mbasti commented Mar 30, 2015

Hello,

error: CKR_TOKEN_NOT_RECOGNIZED

Can you check if /var/lib/ipa/dnssec/tokens contains any files/directories?

Does this file contain any value /var/lib/ipa/dnssec/softhsm_pin?

pdf commented Mar 30, 2015

Replying to [comment:1 mbasti]:

error: CKR_TOKEN_NOT_RECOGNIZED

That message doesn't appear in my logs anywhere.

Can you check if /var/lib/ipa/dnssec/tokens contains any files/directories?

It contains a UUID-named directory, which in turn contains a bunch of objects, locks and tokens.

Does this file contain any value /var/lib/ipa/dnssec/softhsm_pin?

It is populated.

pspacek commented Mar 31, 2015

Interesting. pdf, please run this command to see if it works:

python2 /usr/lib/python2.7/site-packages/ipapython/dnssec/localhsm.py

It should print a lot of text and no errors, please post the output here.

If it reports an error, please run following set of commands:

sudo -u ods -s /bin/bash
source /etc/sysconfig/ods
export SOFTHSM2_CONF
softhsm2-util --show-slots

Thank you!

pdf commented Mar 31, 2015

Output from localhsm.py:

replica public keys: CKA_WRAP = TRUE
====================================
1caa0a5e2d8923bfc2ea45cf0a165529
{'ipk11encrypt': False, 'ipk11trusted': False, 'ipk11label': u'dnssec-replica:replicahost.example.com.', 'ipk11modifiable': True, 'ipk11local': True, 'ipk11id': '\x1c\xaa\n^-\x89#\xbf\xc2\xeaE\xcf\n\x16U)', 'ipk11keytype': 'rsa', 'ipk11wrap': True, 'ipk11verify': False, 'ipk11private': True, 'ipk11derive': False, 'ipk11verifyrecover': False}
replica public keys: all
========================
1caa0a5e2d8923bfc2ea45cf0a165529
{'ipk11encrypt': False, 'ipk11trusted': False, 'ipk11label': u'dnssec-replica:replicahost.example.com.', 'ipk11modifiable': True, 'ipk11local': True, 'ipk11id': '\x1c\xaa\n^-\x89#\xbf\xc2\xeaE\xcf\n\x16U)', 'ipk11keytype': 'rsa', 'ipk11wrap': True, 'ipk11verify': False, 'ipk11private': True, 'ipk11derive': False, 'ipk11verifyrecover': False}
335f439249652d59f4c71fa3c82cca4b
{'ipk11encrypt': False, 'ipk11trusted': False, 'ipk11label': u'dnssec-replica:replicahost.example.com.', 'ipk11modifiable': True, 'ipk11local': True, 'ipk11id': '3_C\x92Ie-Y\xf4\xc7\x1f\xa3\xc8,\xcaK', 'ipk11keytype': 'rsa', 'ipk11wrap': False, 'ipk11verify': False, 'ipk11private': True, 'ipk11derive': False, 'ipk11verifyrecover': False}
master keys
===========
zone public keys
================
zone private keys
=================

For completeness, the output from the second command (I replaced /etc/sysconfig/ods with /etc/sysconfig/ipa-dnskeysyncd, that appears to be the right path on 4.1.4-1.fc21.x86_64):

Available slots:
Slot 0
    Slot info:
        Description:      SoftHSM slot 0
        Manufacturer ID:  SoftHSM project
        Hardware version: 2.0
        Firmware version: 2.0
        Token present:    yes
    Token info:
        Manufacturer ID:  SoftHSM project
        Model:            SoftHSM v2
        Hardware version: 2.0
        Firmware version: 2.0
        Serial number:    68786076f725f784
        Initialized:      yes
        User PIN init.:   yes
        Label:            ipaDNSSEC
Slot 1
    Slot info:
        Description:      SoftHSM slot 1
        Manufacturer ID:  SoftHSM project
        Hardware version: 2.0
        Firmware version: 2.0
        Token present:    yes
    Token info:
        Manufacturer ID:  SoftHSM project
        Model:            SoftHSM v2
        Hardware version: 2.0
        Firmware version: 2.0
        Serial number:
        Initialized:      no
        User PIN init.:   no
        Label:

pspacek commented Apr 1, 2015

Hmm, it seems that local data are okay. pdf, how did you execute ipa-dnskeysync-replica (to get the error message shown in ticket description)? It is not meant for manual execution so it will not work if you do not set environment properly as shown in comment #4.

Please re-run it in this way:

sudo -u ods -s /bin/bash
source /etc/sysconfig/ods
export SOFTHSM2_CONF
/usr/libexec/ipa/ipa-dnskeysync-replica

and post results here. Thank you!

pdf commented Apr 1, 2015

I first noticed it in the logs because the systemd unit was failing, then attempted to execute it manually as root/admin. Here's the output from running it as specified above (again, with the replacement of /etc/sysconfig/ods for /etc/sysconfig/ipa-dnskeysyncd):

ipa         : DEBUG    Kerberos principal: ipa-dnskeysyncd/replicahost.example.com
Traceback (most recent call last):
  File "/usr/libexec/ipa/ipa-dnskeysync-replica", line 142, in <module>
    ipautil.kinit_hostprincipal(paths.IPA_DNSKEYSYNCD_KEYTAB, WORKDIR, PRINCIPAL)
  File "/usr/lib/python2.7/site-packages/ipapython/ipautil.py", line 1208, in kinit_hostprincipal
    raise StandardError('Error initializing principal %s in %s: %s' % (principal, keytab, str(e)))
StandardError: Error initializing principal ipa-dnskeysyncd/replicahost.example.com in /etc/ipa/dnssec/ipa-dnskeysyncd.keytab: (-1765328188, 'Internal credentials cache
error')

Of note may be that the principal ipa-dnskeysyncd/replicahost.example.com doesn't appear to exist on the master, however I tried adding it and updating /etc/ipa/dnssec/ipa-dnskeysyncd.keytab via ipa-getkeytab, but that produced another error:

ipa         : DEBUG    Kerberos principal: ipa-dnskeysyncd/replicahost.example.com
Traceback (most recent call last):
  File "/usr/libexec/ipa/ipa-dnskeysync-replica", line 142, in <module>
    ipautil.kinit_hostprincipal(paths.IPA_DNSKEYSYNCD_KEYTAB, WORKDIR, PRINCIPAL)
  File "/usr/lib/python2.7/site-packages/ipapython/ipautil.py", line 1208, in kinit_hostprincipal
    raise StandardError('Error initializing principal %s in %s: %s' % (principal, keytab, str(e)))
StandardError: Error initializing principal ipa-dnskeysyncd/replicahost.example.com in /etc/ipa/dnssec/ipa-dnskeysyncd.keytab: (-1765328353, 'Decrypt integrity check failed')

My guess is that either ipa-replica-prepare or ipa-replica-install is where the initial breakage occurred.

pspacek commented Apr 2, 2015

Interesting. Please run following commands and let us know the results:

ls -l /etc/ipa/dnssec/ipa-dnskeysyncd.keytab
klist -kt /etc/ipa/dnssec/ipa-dnskeysyncd.keytab
kvno ipa-dnskeysyncd/replicahost.example.com

Thanks!

pdf commented Apr 2, 2015

Okay, having screwed up the diagnostics a bit by manually adding the service principal and updating the keytab, I uninstalled ipa-server on the replica, and deleted the replica on the master, confirmed that all relevant records had been removed from the master, then re-created the replica on the master, and re-installed the replica.

My previous replica install was performed using 4.1.3. Having repeated the process using 4.1.4, it appears that the ipa-dnskeysyncd service principal is created for the replica correctly, however I get a new problem with ipa-dnskeysync-replica:

ipa         : DEBUG    Kerberos principal: ipa-dnskeysyncd/vicechancellor.0xc0dedbad.com
ipa         : DEBUG    Got TGT
ipa         : DEBUG    Connecting to LDAP
ipa.ipaserver.plugins.ldap2.ldap2: DEBUG    Created connection context.ldap2
ipa         : DEBUG    Connected
ipa.ipapython.ipaldap.SchemaCache: DEBUG    retrieving schema for SchemaCache url=ldapi://%2fvar%2frun%2fslapd-0XC0DEDBAD-COM.socket conn=<ldap.ldapobject.SimpleLDAPObject instance at 0x7f29231b7488>
ipa         : DEBUG    master keys in local HSM: set(['0xcc6091c0516e31237d63e7417e7a060e'])
ipa         : DEBUG    master keys in LDAP HSM: set(['0xcc6091c0516e31237d63e7417e7a060e'])
ipa         : DEBUG    new master keys in LDAP HSM: set([])
ipa.sync_metadata: INFO     keys in local HSM & LDAP: set(['0xcc6091c0516e31237d63e7417e7a060e'])
ipa         : DEBUG    zone keys in local HSM: set(['0xcc6091c0516e31237d63e7417e7a060e'])
ipa         : DEBUG    zone keys in LDAP HSM: set(['0xcc6091c0516e31237d63e7417e7a060e'])
ipa         : DEBUG    new zone keys in LDAP HSM: set(['0x019682873b382f5a674b85e80e2d679d', '0x3dfbde2c9fec754e48ffea116f4d0cda', '0x3cf3af7c6fb48a51e4320ba88ed96b79', '0xf8c01ce099492abb7772e76d876bf9a1', '0x79b7174abc52e8dd3caaf75937f07329', '0x336c42105bd9856fc0fcaa1834a2a8c1', '0x108f0615c426bd683f5dc4215cdd5c66', '0x7858974fc89a8864e1751d670be5bd77', '0x5d238e7db26e6e11300adc337cc2e7cc', '0x7c58d7e1bf74ba2971f19eed5c69f464'])
ipa         : DEBUG    Looking for unwrapping key "pkcs11:id=%cc%60%91%c0%51%6e%31%23%7d%63%e7%41%7e%7a%06%0e;type=secret-key" for zone key 0xf8c01ce099492abb7772e76d876bf9a1
ipa         : DEBUG    Importing zone key pair 0xf8c01ce099492abb7772e76d876bf9a1
Traceback (most recent call last):
  File "/usr/libexec/ipa/ipa-dnskeysync-replica", line 163, in <module>
    ldap2replica_zone_keys_sync(log, ldapkeydb, localhsm)
  File "/usr/libexec/ipa/ipa-dnskeysync-replica", line 117, in ldap2replica_zone_keys_sync
    unwrapping_key)
  File "/usr/lib/python2.7/site-packages/ipapython/dnssec/localhsm.py", line 186, in import_private_key
    h = self.p11.import_wrapped_private_key(**params)
_ipap11helper.Error: Error at import_wrapped_key: key unwrapping: 0x5

/var/lib/ipa/dnssec/tokens has a new UUID.
/var/lib/ipa/dnssec/softhsm_pin is populated.
/usr/lib/python2.7/site-packages/ipapython/dnssec/localhsm.py interestingly now has master keys:

replica public keys: CKA_WRAP = TRUE

82ea79ab8591641ae2b57966b4926d42
{'ipk11encrypt': False, 'ipk11trusted': False, 'ipk11label': u'dnssec-replica:vicechancellor.0xc0dedbad.com.', 'ipk11modifiable': True, 'ipk11local': True, 'ipk11id': '\x82\xeay\xab\x85\x91d\x1a\xe2\xb5yf\xb4\x92mB', 'ipk11keytype': 'rsa', 'ipk11wrap': True, 'ipk11verify': False, 'ipk11private': True, 'ipk11derive': False, 'ipk11verifyrecover': False}

replica public keys: all

82ea79ab8591641ae2b57966b4926d42
{'ipk11encrypt': False, 'ipk11trusted': False, 'ipk11label': u'dnssec-replica:vicechancellor.0xc0dedbad.com.', 'ipk11modifiable': True, 'ipk11local': True, 'ipk11id': '\x82\xeay\xab\x85\x91d\x1a\xe2\xb5yf\xb4\x92mB', 'ipk11keytype': 'rsa', 'ipk11wrap': True, 'ipk11verify': False, 'ipk11private': True, 'ipk11derive': False, 'ipk11verifyrecover': False}

master keys

cc6091c0516e31237d63e7417e7a060e
{'ipk11encrypt': False, 'ipk11alwayssensitive': False, 'ipk11trusted': False, 'ipk11decrypt': False, 'ipk11label': u'dnssec-master', 'ipk11modifiable': True, 'ipk11unwrap': True, 'ipk11local': False, 'ipk11neverextractable': False, 'ipk11id': '\xcc`\x91\xc0Qn1#}c\xe7A~z\x06\x0e', 'ipk11keytype': 'aes', 'ipk11wrap': True, 'ipk11verify': False, 'ipk11private': True, 'ipk11derive': False, 'ipk11extractable': True, 'ipk11sensitive': True, 'ipk11sign': False, 'ipk11wrapwithtrusted': False}

zone public keys

zone private keys
softhsm2-util --show-slots:

Available slots:
Slot 0
Slot info:
Description: SoftHSM slot 0
Manufacturer ID: SoftHSM project
Hardware version: 2.0
Firmware version: 2.0
Token present: yes
Token info:
Manufacturer ID: SoftHSM project
Model: SoftHSM v2
Hardware version: 2.0
Firmware version: 2.0
Serial number: 671d10abcc423204
Initialized: yes
User PIN init.: yes
Label: ipaDNSSEC
Slot 1
Slot info:
Description: SoftHSM slot 1
Manufacturer ID: SoftHSM project
Hardware version: 2.0
Firmware version: 2.0
Token present: yes
Token info:
Manufacturer ID: SoftHSM project
Model: SoftHSM v2
Hardware version: 2.0
Firmware version: 2.0
Serial number:
Initialized: no
User PIN init.: no
Label:
ls -l /etc/ipa/dnssec/ipa-dnskeysyncd.keytab:

-r--r-----. 1 root ods 422 Apr 3 10:09 /etc/ipa/dnssec/ipa-dnskeysyncd.keytab
klist -kt /etc/ipa/dnssec/ipa-dnskeysyncd.keytab:

Keytab name: FILE:/etc/ipa/dnssec/ipa-dnskeysyncd.keytab
KVNO Timestamp Principal

2 03/04/15 10:09:59 ipa-dnskeysyncd/replicahost.example.com@EXAMPLE.COM
2 03/04/15 10:09:59 ipa-dnskeysyncd/replicahost.example.com@EXAMPLE.COM
2 03/04/15 10:09:59 ipa-dnskeysyncd/replicahost.example.com@EXAMPLE.COM
2 03/04/15 10:09:59 ipa-dnskeysyncd/replicahost.example.com@EXAMPLE.COM
kvno ipa-dnskeysyncd/replicahost.example.com

ipa-dnskeysyncd/replicahost.example.com@EXAMPLE.COM: kvno = 2

pspacek commented Apr 3, 2015

pdf, I guess that you are hitting https://bugzilla.redhat.com/show_bug.cgi?id=1185878 on the DNSSEC key master. As a result, garbage is stored in LDAP instead of wrapped DNSSEC keys.

To remedy the problem, please:
0. make sure you have latest openssl* packages on all FreeIPA servers
1. shutdown ipa-dnskeysyncd service on all servers (you do not have to shutdown whole IPA)
2. kinit as FreeIPA admin
3. delete all key blobs from LDAP:

$ ldapdelete -r -Y GSSAPI 'cn=keys,cn=sec,cn=dns,dc=ipa,dc=example'

re-create keys container:

$ ldapadd -Y GSSAPI
dn: cn=keys,cn=sec,cn=dns,dc=ipa,dc=example
objectClass: top
objectClass: nsContainer
cn: keys
re-export all keys from DNSSEC key master server:

$ sudo -u ods ods-signer ipa-hsm-update
HSM synchronization finished, exiting.
start service ipa-dnskeysyncd on all servers

Please let me know if this works for you.

pdf commented Apr 3, 2015

Bingo, everything is syncing correctly now. Thanks very much for working through this with me. Apologies for not having already tried re-creating the replica on 4.1.4, the original error I got (having executed ipa-dnskeysync-replica incorrectly) led me to believe it the issue was unrelated to the version, because it persisted after the upgrade.

Please feel free to close this issue with your preferred status.

pspacek commented Apr 7, 2015

pdf, thank you for patience with us :-)

Closing as invalid because it was caused by OpenSSL bug, not a FreeIPA bug.

Metadata Update from @pdf:
- Issue assigned to someone
- Issue set to the milestone: FreeIPA 4.1.5

Feb 27, 2017

Metadata

Assignee

someone

Tags

None

Blocking

None

Depending on

None

Priority

Normal

type

defect

component

DNS

on_review

rhbz

reviewer

None

freeipa

#4967 ipa-dnskeysync-replica unhandled exception Closed: Invalid Opened Mar 29, 2015 by pdf.

replica public keys: CKA_WRAP = TRUE

replica public keys: all

master keys

zone public keys

zone private keys

Metadata

#4967 ipa-dnskeysync-replica unhandled exception

Closed: Invalid Opened Mar 29, 2015 by pdf.