Bug 1300348

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

Description of problem:
During automated execution of ipa-backup/restore feature, following two crashes seen.

backtrace:
:ipautil.py:373:run:CalledProcessError: Command ''/usr/libexec/ipa/ipa-dnskeysync-replica'' returned non-zero exit status 1
:
:Traceback (most recent call last):
:  File "/usr/libexec/ipa/ipa-dnskeysyncd", line 112, in <module>
:    while ldap_connection.syncrepl_poll(all=1, msgid=ldap_search):
:  File "/usr/lib64/python2.7/site-packages/ldap/syncrepl.py", line 405, in syncrepl_poll
:    self.syncrepl_refreshdone()
:  File "/usr/lib/python2.7/site-packages/ipapython/dnssec/keysyncer.py", line 113, in syncrepl_refreshdone
:    self.hsm_replica_sync()
:  File "/usr/lib/python2.7/site-packages/ipapython/dnssec/keysyncer.py", line 170, in hsm_replica_sync
:    ipautil.run([paths.IPA_DNSKEYSYNCD_REPLICA])
:  File "/usr/lib/python2.7/site-packages/ipapython/ipautil.py", line 373, in run
:    raise CalledProcessError(p.returncode, arg_string, stdout)
:CalledProcessError: Command ''/usr/libexec/ipa/ipa-dnskeysync-replica'' returned non-zero exit status 1
:
:Local variables in innermost frame:
:p_in: None
:nolog: ()
:suplementary_groups: []
:preexec_fn: None
:arg_string: "'/usr/libexec/ipa/ipa-dnskeysync-replica'"
:stdout: ''
:p_out: -1
:p_err: -1
:runas: None
:stdin: None
:skip_output: False
:timeout: None
:capture_output: True
:p: <subprocess.Popen object at 0x6107f10>
:stderr: 'ipa: WARNING: session memcached servers not running\nipa         : DEBUG    Kerberos principal: ipa-dnskeysyncd/cloud-qe-3.testrelm.test\nipa         : DEBUG    Initializing principal ipa-dnskeysyncd/cloud-qe-3.testrelm.test using keytab /etc/ipa/dnssec/ipa-dnskeysyncd.keytab\nipa         : DEBUG    using ccache /tmp/ipa-dnskeysync-replica.ccache\nipa         : DEBUG    Attempt 1/5: success\nipa         : DEBUG    Got TGT\nipa         : DEBUG    Connecting to LDAP\nipa.ipaserver.plugins.ldap2.ldap2: DEBUG    Created connection context.ldap2_46913424\nipa         : DEBUG    Connected\nTraceback (most recent call last):\n  File "/usr/libexec/ipa/ipa-dnskeysync-replica", line 171, in <module>\n    open(paths.DNSSEC_SOFTHSM_PIN).read())\n  File "/usr/lib/python2.7/site-packages/ipapython/dnssec/localhsm.py", line 97, in __init__\n    self.p11 = _ipap11helper.P11_Helper(slot, pin, library)\n_ipap11helper.Error: Error at log in: 0xa0\n\nException AttributeError: "\'LocalHSM\' object has no attribute \'p11\'" in <bound method LocalHSM.__del__ of <ipapython.dnssec.localhsm.LocalHSM object at 0x47f1090>> ignored\n'
:raiseonerr: True
:env: {'LANG': 'en_US.UTF-8', 'SHELL': '/sbin/nologin', 'KRB5CCNAME': '/tmp/ipa-dnskeysyncd.ccache', 'LOGNAME': 'ods', 'USER': 'ods', 'SOFTHSM2_CONF': '/etc/ipa/dnssec/softhsm2.conf', 'PATH': '/bin:/sbin:/usr/kerberos/bin:/usr/kerberos/sbin:/usr/bin:/usr/sbin', 'HOME': '//var/lib/softhsm'}
:cwd: None
:args: ['/usr/libexec/ipa/ipa-dnskeysync-replica']

And
backtrace:
:localhsm.py:97:__init__:Error: Error at log in: 0xa0
:
:
:Traceback (most recent call last):
:  File "/usr/libexec/ipa/ipa-dnskeysync-replica", line 171, 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)
:Error: Error at log in: 0xa0
:
:
:Local variables in innermost frame:
:slot: 0
:self: <ipapython.dnssec.localhsm.LocalHSM object at 0x47f1090>
:library: '/usr/lib64/pkcs11/libsofthsm2.so'
:pin: 'OGIfVEsRqtgbB6vQuWMzjcCcDedA1K'


Version-Release number of selected component (if applicable):
[root@dhcp207-229 ~]# rpm -q ipa-server
ipa-server-4.2.0-8.el7.x86_64
[root@dhcp207-229 ~]# 

How reproducible:
Always

Steps to Reproduce:
1. Do ipa backup
2. ipa restore (full) from backup taken in step(1)

Actual results:
Crashes of ipa-dnskeysync-replica observed

Expected results:
No crash during ipa-restore process.

Additional info:

--- Additional comment from RHEL Product and Program Management on 2015-09-07 08:35:24 EDT ---

Since this bug report was entered in bugzilla, the release flag has been
set to ? to ensure that it is properly evaluated for this release.

--- Additional comment from Martin Bašti on 2015-09-09 11:20:44 EDT ---

Steps to reproduce:
1. server install
2. backup
3. server uninstall
4. server install
5. restore


Because server is installed, directory /var/lib/ipa/dnssec/tokens/ contains current tokens.

Restore adds there new tokens, but unfortunately old tokens are not removed, new tokens are just added into directory, and this cause issues with login.

--- Additional comment from Martin Bašti on 2015-09-10 07:40:02 EDT ---

Upstream ticket:
https://fedorahosted.org/freeipa/ticket/5293

--- Additional comment from Martin Bašti on 2015-09-11 09:00:58 EDT ---

Fixed upstream
master:
https://fedorahosted.org/freeipa/changeset/f8f5bd644aee5c54acc857061868e659ae449e48
ipa-4-2:
https://fedorahosted.org/freeipa/changeset/21f2a3d1731a43551cc130356329bcadba7ffdfe

--- Additional comment from Petr Vobornik on 2015-09-11 09:21:48 EDT ---

Exception justification: needed for DNSSEC to work after restoration from a backup.

--- Additional comment from errata-xmlrpc on 2015-09-16 08:44:53 EDT ---

Bug report changed to ON_QA status by Errata System.
A QE request has been submitted for advisory RHBA-2015:20912-01
https://errata.devel.redhat.com/advisory/20912

--- Additional comment from Kaleem on 2015-10-01 10:08:53 EDT ---

Still observing the crash with ipa-4.2.0-12.el7

Please find the attached file with crash info.

--- Additional comment from Kaleem on 2015-10-01 10:09 EDT ---



--- Additional comment from Kaleem on 2015-10-16 02:40:10 EDT ---

Crash not seen with latest beaker runs of b&r feature, so turning it to verified state.

snip from beaker log:
=====================

 +-----------------------------[RPMs & OS: [RedHat - x86_64]-----------------------------+
|       ipa-admintools-4.2.0-15.el7.x86_64
|       ipa-client-4.2.0-15.el7.x86_64
|       ipa-server-4.2.0-15.el7.x86_64
|       ipa-server-dns-4.2.0-15.el7.x86_64
|       ipa-tests-ipa-server-rhel72-ipa-backup-restore-ksiddiqu-20150828120910-0.noarch
|       ipa-tests-ipa-server-rhel72-shared-20150930150523-0.noarch
|       sssd-ipa-1.13.0-40.el7.x86_64
------------------------------------------------------------------------------------------

 +-----------------------------------------------------------------------------------------+
     Test:[/ipa-server/rhel72/ipa-backup-restore/root]: [ Pass(8/8): 100% ] 
 +-----------------------------------------------------------------------------------------+
:: [   PASS   ]   ipa-backup_restore startup: Initial setup
:: [   PASS   ]   TC_001 :: IPA backup restore full
:: [   PASS   ]   TC_002 :: IPA backup restore full with gpg encryption/decryption related test cases
:: [   PASS   ]   TC_003 :: Data backup/restore related test cases
:: [   PASS   ]   TC_004 :: Data backup/restore backend/instance related test cases 
:: [   PASS   ]   TC_005 :: Additional test cases
:: [   PASS   ]   TC_006 :: Data restore from full backup related test cases
:: [   PASS   ]   /ipa-server/rhel72/ipa-backup-restore/root

 +----------------------------------------------------------------------+

--- Additional comment from errata-xmlrpc on 2015-11-19 07:06:19 EST ---

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHBA-2015-2362.html