search

abbra / freeipa

Mirror of FreeIPA, an integrated security information management solution
http://www.freeipa.org
GNU General Public License v3.0
2 stars 1 forks source link

gc-wip: Sync daemon fails to start after creating/deleting particular users #60

Open wladich opened 3 years ago

wladich commented 3 years ago

After a test session I can not start sync daemon anymore. I am not sure which action triggered the error so I am attaching output of ldapsearch for main and GC instances

Another issue I see is that the traceback is written only to journal but not to globalcatalog.log.

Oct 26 19:20:47 master1.testrelm.test systemd[1]: Started IPA Global Catalog Sync daemon.
Oct 26 19:20:47 master1.testrelm.test ipa-gcsyncd[49294]: ipa: DEBUG: importing all plugin modules in ipaserver.plugins...
...
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]: ipa: DEBUG: importing plugin module ipaserver.plugins.whoami
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]: ipa: DEBUG: importing plugin module ipaserver.plugins.xmlserver
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]: ipa: DEBUG: LDAP URL: ldapi://%2Frun%2Fslapd-TESTRELM-TEST.socket/cn%3Daccounts%2Cdc%3Dtestrelm%2Cdc%3Dtest?objectclass,cn,displayname,gidnumber,givenname,homedirectory,ipaextern>
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]: ipa: DEBUG: retrieving schema for SchemaCache url=ldapi://%2fvar%2frun%2fslapd-GLOBAL-CATALOG.socket conn=<ldap.ldapobject.ReconnectLDAPObject object at 0x7f5721f73d60>
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]: ipa: DEBUG: get_saved_cookie
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]: ipa: DEBUG: Read cookie master1.testrelm.test:389#cn=Directory Manager:cn=accounts,dc=testrelm,dc=test:(|(objectClass=groupofnames)(objectClass=person))#643
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]: ipa: DEBUG: New cookie is: master1.testrelm.test:389#cn=Directory Manager:cn=accounts,dc=testrelm,dc=test:(|(objectClass=groupofnames)(objectClass=person))#643
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]: ipa: INFO: LDAP bind...
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]: ipa: INFO: Commencing sync process
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]: ipa: DEBUG: Current cookie is: master1.testrelm.test:389#cn=Directory Manager:cn=accounts,dc=testrelm,dc=test:(|(objectClass=groupofnames)(objectClass=person))#643
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]: Traceback (most recent call last):
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:   File "/usr/lib/python3.8/site-packages/pyasn1/type/constraint.py", line 32, in __call__
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:     self._testValue(value, idx)
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:   File "/usr/lib/python3.8/site-packages/pyasn1/type/constraint.py", line 320, in _testValue
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:     raise error.ValueConstraintError(value)
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]: pyasn1.type.error.ValueConstraintError: b'\x1f\x86'
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]: During handling of the above exception, another exception occurred:
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]: Traceback (most recent call last):
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:   File "/usr/lib/python3.8/site-packages/pyasn1/type/base.py", line 269, in __init__
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:     self.subtypeSpec(value)
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:   File "/usr/lib/python3.8/site-packages/pyasn1/type/constraint.py", line 35, in __call__
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:     raise error.ValueConstraintError(
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]: pyasn1.type.error.ValueConstraintError: <ValueSizeConstraint object, consts 16, 16> failed at: ValueConstraintError(b'\x1f\x86')
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]: During handling of the above exception, another exception occurred:
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]: Traceback (most recent call last):
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:   File "/usr/libexec/ipa/gc/ipa-gcsyncd", line 111, in <module>
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:     while sync_conn.syncrepl_poll(all=1, msgid=ldap_search):
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:   File "/usr/lib64/python3.8/site-packages/ldap/syncrepl.py", line 449, in syncrepl_poll
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:     sim = SyncInfoMessage(resp)
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:   File "/usr/lib64/python3.8/site-packages/ldap/syncrepl.py", line 311, in __init__
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:     d = decoder.decode(encodedMessage, asn1Spec=SyncInfoValue())
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:   File "/usr/lib/python3.8/site-packages/pyasn1/codec/ber/decoder.py", line 1581, in __call__
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:     value, substrate = concreteDecoder.valueDecoder(
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:   File "/usr/lib/python3.8/site-packages/pyasn1/codec/ber/decoder.py", line 1006, in valueDecoder
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:     component, head = decodeFun(
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:   File "/usr/lib/python3.8/site-packages/pyasn1/codec/ber/decoder.py", line 1581, in __call__
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:     value, substrate = concreteDecoder.valueDecoder(
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:   File "/usr/lib/python3.8/site-packages/pyasn1/codec/ber/decoder.py", line 609, in valueDecoder
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:     component, head = decodeFun(head, componentType, **options)
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:   File "/usr/lib/python3.8/site-packages/pyasn1/codec/ber/decoder.py", line 1581, in __call__
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:     value, substrate = concreteDecoder.valueDecoder(
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:   File "/usr/lib/python3.8/site-packages/pyasn1/codec/ber/decoder.py", line 728, in valueDecoder
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:     component, head = decodeFun(head, componentType, **options)
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:   File "/usr/lib/python3.8/site-packages/pyasn1/codec/ber/decoder.py", line 1581, in __call__
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:     value, substrate = concreteDecoder.valueDecoder(
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:   File "/usr/lib/python3.8/site-packages/pyasn1/codec/ber/decoder.py", line 244, in valueDecoder
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:     return self._createComponent(asn1Spec, tagSet, head, **options), tail
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:   File "/usr/lib/python3.8/site-packages/pyasn1/codec/ber/decoder.py", line 55, in _createComponent
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:     return asn1Spec.clone(value)
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:   File "/usr/lib/python3.8/site-packages/pyasn1/type/base.py", line 376, in clone
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:     return self.__class__(value, **initializers)
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:   File "/usr/lib/python3.8/site-packages/pyasn1/type/univ.py", line 837, in __init__
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:     base.SimpleAsn1Type.__init__(self, value, **kwargs)
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:   File "/usr/lib/python3.8/site-packages/pyasn1/type/base.py", line 273, in __init__
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]:     raise exType('%s at %s' % (exValue, self.__class__.__name__))
Oct 26 19:20:48 master1.testrelm.test ipa-gcsyncd[49294]: pyasn1.type.error.ValueConstraintError: <ValueSizeConstraint object, consts 16, 16> failed at: ValueConstraintError(b'\x1f\x86') at SyncUUID
Oct 26 19:20:48 master1.testrelm.test systemd[1]: ipa-gcsyncd.service: Main process exited, code=exited, status=1/FAILURE
Oct 26 19:20:48 master1.testrelm.test systemd[1]: ipa-gcsyncd.service: Failed with result 'exit-code'.
Oct 26 19:20:48 master1.testrelm.test systemd[1]: ipa-gcsyncd.service: Consumed 1.657s CPU time.
wladich commented 3 years ago

gc_dump.txt main_dump.txt

wladich commented 3 years ago

@tbordaz Could you please look at the backtrace? Do you need any additional data to investigate the issue? I can reproduce the issue by running the test on local vagrant environment, but it PR-CI the it is passing succesfuly.

The test which triggers the issue: https://github.com/wladich/freeipa/blob/d3e6734c3f731df53764a14c3dee009fb23478f1/ipatests/test_integration/test_global_catalog.py#L565 http://freeipa-org-pr-ci.s3-website.eu-central-1.amazonaws.com/jobs/dbd7866a-17cf-11eb-be89-fa163e4ad552/report.html

wladich commented 3 years ago

Just hit the issue again, here is what the test is doing:

systemctl stop ipa-gcsyncd.service
ipa user-add StartupsyncComplex1 --first Startupsync --last Complex1
ipa user-add StartupsyncComplex2 --first Startupsync --last Complex2
ipa user-del StartupsyncComplex1
ipa group-add startupsynccomplex
ipa group-add-member startupsynccomplex --users StartupsyncComplex2
systemctl start ipa-gcsyncd.service

And ipa-gcsyncd fails to start, the traceback can be seen in the first comment