Bug 1489184

Summary: ipa-dnskeysyncd fails in a loop in Fedora 27 ("pyasn1.error.PyAsn1Error: Uninitialized ASN.1 value ("__str__" attribute looked up)")
Product: [Fedora] Fedora Reporter: Adam Williamson <awilliam>
Component: python-ldapAssignee: John (J5) Palmieri <john.j5live>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: high Docs Contact:
Priority: unspecified    
Version: 27CC: abokovoy, alexl, amessina, caillon+fedoraproject, cheimes, cstratak, ietingof, ipa-maint, jcholast, jhrozek, john.j5live, kparal, mhroncok, mkosek, pviktori, pvoborni, python-sig, rcritten, rhughes, rkuska, rstrode, sandmann, sgallagh, slaznick, ssorce, tkrizek, vanmeeuwen+fedora
Target Milestone: ---   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard: AcceptedFreezeException
Fixed In Version: python-ldap-2.4.25-8.fc27 python-ldap-2.4.25-9.fc27 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-11-14 00:55:43 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1492243, 1502882    
Attachments:
Description Flags
Port of Ilya's pyldap patch for python-ldap
none
Port of Ilya's pyldap patch for python-ldap none

Description Adam Williamson 2017-09-06 22:15:43 UTC
With the latest update:

https://bodhi.fedoraproject.org/updates/FEDORA-2017-a79e85e4d3

All openQA FreeIPA tests pass (yay). However, in the server logs, I do see that the service ipa-dnskeysyncd just fails constantly, in a loop (fails, restarts, fails again) throughout the test:

Sep 06 13:49:43 ipa001.domain.local audit[1]: SERVICE_START 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=success'
Sep 06 13:49:43 ipa001.domain.local 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=success'
Sep 06 13:49:43 ipa001.domain.local audit[1]: SERVICE_START 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=success'
Sep 06 13:49:46 ipa001.domain.local ipa-dnskeysyncd[8004]: ipa-dnskeysyncd: INFO     LDAP bind...
Sep 06 13:49:46 ipa001.domain.local ipa-dnskeysyncd[8004]: ipa-dnskeysyncd: INFO     Commencing sync process
Sep 06 13:49:46 ipa001.domain.local ipa-dnskeysyncd[8004]: Traceback (most recent call last):
Sep 06 13:49:46 ipa001.domain.local ipa-dnskeysyncd[8004]:   File "/usr/libexec/ipa/ipa-dnskeysyncd", line 116, in <module>
Sep 06 13:49:46 ipa001.domain.local ipa-dnskeysyncd[8004]:     while ldap_connection.syncrepl_poll(all=1, msgid=ldap_search):
Sep 06 13:49:46 ipa001.domain.local ipa-dnskeysyncd[8004]:   File "/usr/lib64/python2.7/site-packages/ldap/syncrepl.py", line 393, in syncrepl_poll
Sep 06 13:49:46 ipa001.domain.local ipa-dnskeysyncd[8004]:     sim = SyncInfoMessage(resp)
Sep 06 13:49:46 ipa001.domain.local ipa-dnskeysyncd[8004]:   File "/usr/lib64/python2.7/site-packages/ldap/syncrepl.py", line 271, in __init__
Sep 06 13:49:46 ipa001.domain.local ipa-dnskeysyncd[8004]:     self.newcookie = str(comp)
Sep 06 13:49:46 ipa001.domain.local ipa-dnskeysyncd[8004]:   File "/usr/lib/python2.7/site-packages/pyasn1/type/univ.py", line 939, in __str__
Sep 06 13:49:46 ipa001.domain.local ipa-dnskeysyncd[8004]:     return str(self._value)
Sep 06 13:49:46 ipa001.domain.local ipa-dnskeysyncd[8004]:   File "/usr/lib/python2.7/site-packages/pyasn1/type/base.py", line 186, in plug
Sep 06 13:49:46 ipa001.domain.local ipa-dnskeysyncd[8004]:     raise error.PyAsn1Error('Uninitialized ASN.1 value ("%s" attribute looked up)' % name)
Sep 06 13:49:46 ipa001.domain.local ipa-dnskeysyncd[8004]: pyasn1.error.PyAsn1Error: Uninitialized ASN.1 value ("__str__" attribute looked up)
Sep 06 13:49:46 ipa001.domain.local systemd[1]: ipa-dnskeysyncd.service: Main process exited, code=exited, status=1/FAILURE
Sep 06 13:49:46 ipa001.domain.local 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'
Sep 06 13:49:46 ipa001.domain.local systemd[1]: ipa-dnskeysyncd.service: Unit entered failed state.
Sep 06 13:49:46 ipa001.domain.local systemd[1]: ipa-dnskeysyncd.service: Failed with result 'exit-code'.

As mentioned the tests still pass, so this doesn't immediately appear to violate the release criteria, but I suspect it's still a problem (perhaps for replicated servers, which we don't currently test). I'll propose this as a Beta freeze exception for now, it smells like the kind of thing we'd like to fix if possible.

Comment 1 Standa Laznicka 2017-09-11 14:42:16 UTC
This is actually an issue with python-ldap. I just opened the same BZ with them about an hour ago not noticing this one.
Changing components.

Comment 2 Standa Laznicka 2017-09-11 14:43:44 UTC
*** Bug 1490381 has been marked as a duplicate of this bug. ***

Comment 3 Kamil Páral 2017-09-11 18:14:46 UTC
Discussed during blocker review [1]:

AcceptedFreezeException - this is a significant bug in a component shipped on the server DVD; it doesn't violate release criteria but it'd be good to have it fixed

[1] https://meetbot-raw.fedoraproject.org/fedora-blocker-review/2017-09-11/

Comment 4 Ilya Etingof 2017-10-11 19:13:55 UTC
Patch against pyldap: ttps://github.com/pyldap/pyldap/pull/126

Trying to figure out how to backport it to python-ldap as well.

Comment 5 Adam Williamson 2017-10-17 00:10:42 UTC
Moving to the Server-specific Beta FE tracker.

Comment 6 Anthony Messina 2017-10-27 22:14:38 UTC
Would it be worth is to upgrade to https://pypi.python.org/pypi/python-ldap/2.4.45 and include the other fixes that have been made upstream?

I'm looking to re-enable DNSSEC in my F27 FreeIPA instances.

Comment 7 Adam Williamson 2017-10-27 23:41:59 UTC
AIUI we actually use python-pyldap in Fedora, not python-ldap.

Comment 8 Anthony Messina 2017-10-27 23:58:23 UTC
(In reply to Adam Williamson from comment #7)
> AIUI we actually use python-pyldap in Fedora, not python-ldap.

Thanks Adam. It seems that F27 FreeIPA still requires python-ldap:

~]# rpm -q --requires freeipa-server-4.6.1-3.fc27.x86_64
...
python-ldap >= 2.4.15
...


~]# rpm -qi python2-ldap
Name        : python2-ldap
Epoch       : 0
Version     : 2.4.25
Release     : 7.fc27
Architecture: x86_64
Install Date: Wed Oct 25 20:24:16 2017
Group       : System Environment/Libraries
Size        : 731858
License     : Python
Signature   : RSA/SHA1, Wed Oct 25 09:43:49 2017, Key ID b6f26b8167c84842
Source RPM  : python-ldap-2.4.25-7.fc27.src.rpm
Build Date  : Wed Oct 25 09:43:46 2017
Build Host  : copr-builder-64578154.novalocal
Relocations : (not relocatable)
URL         : http://python-ldap.sourceforge.net/
Summary     : An object-oriented API to access LDAP directory servers

Comment 9 Adam Williamson 2017-10-28 00:02:17 UTC
huh, you're right, my bad. Can't remember what it is that uses pyldap, then...

Comment 10 Christian Heimes 2017-11-07 12:08:48 UTC
For the record, FreeIPA uses python-ldap (https://www.python-ldap.org/) upstream for Python 2. Since upstream does not support Python 3, FreeIPA depends on the fork python3-pyldap (https://github.com/pyldap/pyldap/). I'm a co-maintainer of pyldap.

Both python2-ldap and python3-pyldap have broken syncrepl and needs fixing. In general pyldap prefers to pull fixes from its origin python-ldap rather than fixing issues locally. I'll talk to Martin to get the fix into python-ldap.

Comment 11 Christian Heimes 2017-11-07 12:35:55 UTC
I have contacted Michael Ströter and submitted a patch for python-ldap on the python-ldap mailing list, https://mail.python.org/pipermail/python-ldap/2017q4/003976.html

Comment 12 Christian Heimes 2017-11-07 12:58:02 UTC
Created attachment 1348952 [details]
Port of Ilya's pyldap patch for python-ldap

https://github.com/pyldap/pyldap/pull/126

https://mail.python.org/pipermail/python-ldap/2017q4/003976.html

Comment 13 Christian Heimes 2017-11-07 13:17:29 UTC
Comment on attachment 1348952 [details]
Port of Ilya's pyldap patch for python-ldap

patch is buggy

Comment 14 Christian Heimes 2017-11-07 13:45:45 UTC
Created attachment 1348963 [details]
Port of Ilya's pyldap patch for python-ldap

Comment 15 Christian Heimes 2017-11-07 13:46:48 UTC
I created scratch builds of python-ldap-2.4.25-8.fc27 for testing, https://koji.fedoraproject.org/koji/taskinfo?taskID=22974113

Comment 16 Fedora Update System 2017-11-07 19:15:29 UTC
python-pyldap-2.4.37-3.fc27 has been pushed to the Fedora 27 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2017-8972a1f113

Comment 17 Fedora Update System 2017-11-07 19:15:38 UTC
python-ldap-2.4.25-8.fc27 has been pushed to the Fedora 27 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2017-3fd7329764

Comment 18 Adam Williamson 2017-11-07 20:15:11 UTC
So to be clear on this: do we need to push python-ldap, python-pyldap, or both stable in order to fix this in practical terms in Fedora 27?

Comment 19 Christian Heimes 2017-11-07 20:25:32 UTC
In practical terms, python-ldap is sufficient to fix ipa-dnskeysyncd and to unblock F27 server. python-pyldap can be updated through regular channels after the release.

Comment 20 Adam Williamson 2017-11-07 20:35:21 UTC
OK. For the record, I ran openQA tests on both updates. https://openqa.fedoraproject.org/tests/166954 is the FreeIPA server deployment test for the python-ldap update. The logs - https://openqa.fedoraproject.org/tests/166954/file/role_deploy_domain_controller_check-var_log.tar.gz - show that ipa-dnskeysyncd service tries to start four times total during the test; the first three it fails with a traceback ending in "AttributeError: SyncStateControl instance has no attribute 'cookie'", but the fourth time it succeeds.

Comment 21 Christian Heimes 2017-11-07 20:39:24 UTC
That should not have happened. Please post the traceback and I'll address the issue first thing tomorrow.

Comment 22 Adam Williamson 2017-11-07 21:55:18 UTC
You can find it in that tarball I linked - https://openqa.fedoraproject.org/tests/166954/file/role_deploy_domain_controller_check-var_log.tar.gz .

Nov 07 11:58:40 ipa001.domain.local ipa-dnskeysyncd[7503]: ipa-dnskeysyncd: INFO     LDAP bind...
Nov 07 11:58:40 ipa001.domain.local ipa-dnskeysyncd[7503]: ipa-dnskeysyncd: INFO     Commencing sync process
Nov 07 11:58:40 ipa001.domain.local ipa-dnskeysyncd[7503]: ipaserver.dnssec.keysyncer: INFO     Initial LDAP dump is done, sychronizing with ODS and BIND
Nov 07 11:58:44 ipa001.domain.local ipa-dnskeysyncd[7503]: Traceback (most recent call last):
Nov 07 11:58:44 ipa001.domain.local ipa-dnskeysyncd[7503]:   File "/usr/libexec/ipa/ipa-dnskeysyncd", line 116, in <module>
Nov 07 11:58:44 ipa001.domain.local ipa-dnskeysyncd[7503]:     while ldap_connection.syncrepl_poll(all=1, msgid=ldap_search):
Nov 07 11:58:44 ipa001.domain.local ipa-dnskeysyncd[7503]:   File "/usr/lib64/python2.7/site-packages/ldap/syncrepl.py", line 354, in syncrepl_poll
Nov 07 11:58:44 ipa001.domain.local ipa-dnskeysyncd[7503]:     add_intermediates=1, add_ctrls=1, all = 0
Nov 07 11:58:44 ipa001.domain.local ipa-dnskeysyncd[7503]:   File "/usr/lib64/python2.7/site-packages/ldap/ldapobject.py", line 531, in result4
Nov 07 11:58:44 ipa001.domain.local ipa-dnskeysyncd[7503]:     resp_data = [ (t,r,DecodeControlTuples(c,resp_ctrl_classes)) for t,r,c in resp_data ]
Nov 07 11:58:44 ipa001.domain.local ipa-dnskeysyncd[7503]:   File "/usr/lib64/python2.7/site-packages/ldap/controls/__init__.py", line 147, in DecodeControlTuples
Nov 07 11:58:44 ipa001.domain.local ipa-dnskeysyncd[7503]:     control.decodeControlValue(encodedControlValue)
Nov 07 11:58:44 ipa001.domain.local ipa-dnskeysyncd[7503]:   File "/usr/lib64/python2.7/site-packages/ldap/syncrepl.py", line 140, in decodeControlValue
Nov 07 11:58:44 ipa001.domain.local ipa-dnskeysyncd[7503]:     self.cookie = str(self.cookie)
Nov 07 11:58:44 ipa001.domain.local ipa-dnskeysyncd[7503]: AttributeError: SyncStateControl instance has no attribute 'cookie'
Nov 07 11:58:44 ipa001.domain.local 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'

It's not the only thing that does this, BTW. Quite a few bits of IPA seem to try and start up during the deployment process and fail, without it preventing the deployment from ultimately working.

Comment 23 Christian Heimes 2017-11-08 09:16:47 UTC
The problem is my fault. I made a typo when I ported the patch from pyldap to python-ldap. The typo did not show up in my tests because my test system never triggered the erroneous path.

Fix: https://src.fedoraproject.org/rpms/python-ldap/pull-request/2

Sorry :/

Comment 24 Charalampos Stratakis 2017-11-08 12:39:25 UTC
The reasoning behind making both updates pointing at the same bugzilla, is that pyldap is used for the python3 package of FreeIPA, which I am not sure if it would be included in the final compose, thus I included both the ldap fix and pyldap fix.

Comment 25 Adam Williamson 2017-11-08 20:16:49 UTC
cheimes: how bad is the problem? should we update the update to include the fix?

Comment 26 Fedora Update System 2017-11-08 20:31:49 UTC
python-ldap-2.4.25-9.fc27 has been pushed to the Fedora 27 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2017-56c25cb772

Comment 27 Christian Heimes 2017-11-09 13:37:41 UTC
The bug affects dnssec key distribution. Please get python-ldap-2.4.25-9.fc27 into the build.

Comment 28 Adam Williamson 2017-11-09 17:20:44 UTC
Roger. sgallagh, see above - if we do more Beta RCs, please pull in the updated-updated python-ldap.

Comment 29 Fedora Update System 2017-11-14 00:55:43 UTC
python-pyldap-2.4.37-3.fc27 has been pushed to the Fedora 27 stable repository. If problems still persist, please make note of it in this bug report.

Comment 30 Fedora Update System 2017-11-14 09:23:39 UTC
python-pyldap-2.4.37-3.fc27 has been pushed to the Fedora 27 stable repository. If problems still persist, please make note of it in this bug report.

Comment 31 Fedora Update System 2017-11-15 17:46:54 UTC
python-ldap-2.4.25-8.fc27 has been pushed to the Fedora 27 stable repository. If problems still persist, please make note of it in this bug report.

Comment 32 Fedora Update System 2017-11-15 17:47:41 UTC
python-ldap-2.4.25-9.fc27 has been pushed to the Fedora 27 stable repository. If problems still persist, please make note of it in this bug report.