#2363 Login failure on dereference operation error
Closed: Duplicate None Opened 9 years ago by simo.

I've got a setup that for some reason is failing to provide expected responses via the dereference control (the server is IPA master with 389ds 1.3.3.a2 built from git in Februari).

While trying to login with admin the HBAC code (I think) tried to find the Hosts and a dereference control returned unexpected results, the user login then failed with a System error:

This is the log I could get before fixing the problem (by removing the test group which was not part of any HBAC rule).

(Tue Jun 17 22:32:29 2014) [sssd[be[ipa.dev.lan]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(objectClass=ipaHost)(fqdn=idp.ipa.dev.lan))][cn=accounts,dc=ipa,dc=dev,dc=lan].
(Tue Jun 17 22:32:29 2014) [sssd[be[ipa.dev.lan]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
(Tue Jun 17 22:32:29 2014) [sssd[be[ipa.dev.lan]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(Tue Jun 17 22:32:29 2014) [sssd[be[ipa.dev.lan]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [fqdn]
(Tue Jun 17 22:32:29 2014) [sssd[be[ipa.dev.lan]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [serverHostname]
(Tue Jun 17 22:32:29 2014) [sssd[be[ipa.dev.lan]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf]
(Tue Jun 17 22:32:29 2014) [sssd[be[ipa.dev.lan]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaSshPubKey]
(Tue Jun 17 22:32:29 2014) [sssd[be[ipa.dev.lan]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaUniqueID]
(Tue Jun 17 22:32:29 2014) [sssd[be[ipa.dev.lan]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 21
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_process_result] (0x2000): Trace: sh[0x7f0991ad2240], connected[1], ops[0x7f0991a99e00], ldap[0x7f0991ad2570]
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_parse_entry] (0x4000): OriginalDN: [fqdn=idp.ipa.dev.lan,cn=computers,cn=accounts,dc=ipa,dc=dev,dc=lan].
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_parse_range] (0x2000): No sub-attributes for [objectClass]
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_parse_range] (0x2000): No sub-attributes for [cn]
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_parse_range] (0x2000): No sub-attributes for [fqdn]
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_parse_range] (0x2000): No sub-attributes for [serverHostname]
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_parse_range] (0x2000): No sub-attributes for [memberOf]
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_parse_range] (0x2000): No sub-attributes for [ipaSshPubKey]
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_parse_range] (0x2000): No sub-attributes for [ipaUniqueID]
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_process_result] (0x2000): Trace: sh[0x7f0991ad2240], connected[1], ops[0x7f0991a99e00], ldap[0x7f0991ad2570]
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_get_generic_ext_done] (0x2000): Total count [0]
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_has_deref_support] (0x0400): The server supports deref method OpenLDAP
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_deref_search_send] (0x2000): Server supports OpenLDAP deref
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_x_deref_search_send] (0x0400): Dereferencing entry [fqdn=idp.ipa.dev.lan,cn=computers,cn=accounts,dc=ipa,dc=dev,dc=lan] using OpenLDAP deref
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [no filter][fqdn=idp.ipa.dev.lan,cn=computers,cn=accounts,dc=ipa,dc=dev,dc=lan].
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberOf]
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [ipaUniqueID]
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 22
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_process_result] (0x2000): Trace: sh[0x7f0991ad2240], connected[1], ops[0x7f0991a99e00], ldap[0x7f0991ad2570]
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_process_result] (0x2000): Trace: sh[0x7f0991ad2240], connected[1], ops[0x7f0991a99e00], ldap[0x7f0991ad2570]
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_x_deref_parse_entry] (0x0400): Got deref control
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_parse_deref] (0x1000): Dereferenced DN: cn=test,cn=hostgroups,cn=accounts,dc=ipa,dc=dev,dc=lan
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_parse_deref] (0x0080): Dereferenced entry [cn=test,cn=hostgroups,cn=accounts,dc=ipa,dc=dev,dc=lan] has no attributes
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_x_deref_parse_entry] (0x0040): sdap_parse_deref failed [22]: Invalid argument
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_get_generic_ext_done] (0x0020): reply parsing callback failed.
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_x_deref_search_done] (0x0100): sdap_get_generic_ext_recv failed [22]: Invalid argument
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_deref_search_done] (0x0040): dereference processing failed [22]: Invalid argument
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [ipa_hostgroup_info_done] (0x0040): Error [22][Invalid argument]
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [sdap_id_op_done] (0x4000): releasing operation connection
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [be_pam_handler_callback] (0x0100): Backend returned: (3, 4, <NULL>) [Internal Error (System error)]
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [be_pam_handler_callback] (0x0100): Sending result [4][ipa.dev.lan]
(Tue Jun 17 22:32:30 2014) [sssd[be[ipa.dev.lan]]] [be_pam_handler_callback] (0x0100): Sent result [4][ipa.dev.lan]

It is interesting to note that the admins group later also shows the same behaviour during an initgroups but this didn't trigger a login failure.


I agree this failure should not be fatal. I thought we made dereference failures non-fatal already but maybe I'm confusing that with the identity lookup code.

We should also inspect other parts of sssd where dereference is used to make sure we can fall back to individual lookups.

I think we should lower the priority of this bug. Given that this happens in IPA code only where we know 389DS is on the server side and the failure Simo was seeing was caused by https://fedorahosted.org/freeipa/ticket/4389 I don't think we need to rush with the fix.

Fields changed

priority: major => minor

Given that the error was on the server side, moving to 1.14. We should be more defensive and retry no-dereference lookups, but in the normal case where the DS is not broken, the dereference should be available.

milestone: NEEDS_TRIAGE => SSSD 1.14 beta

Fields changed

rhbz: => todo

This is a duplicate of #2605 (which has much nicer description, so I'm closing this one..)

mark: => 0
resolution: => duplicate
sensitive: => 0
status: new => closed

Fields changed

rhbz: todo => 0

Metadata Update from @simo:
- Issue set to the milestone: SSSD 1.14 beta

7 years ago

SSSD is moving from Pagure to Github. This means that new issues and pull requests
will be accepted only in SSSD's github repository.

This issue has been cloned to Github and is available here:
- https://github.com/SSSD/sssd/issues/3405

If you want to receive further updates on the issue, please navigate to the github issue
and click on subscribe button.

Thank you for understanding. We apologize for all inconvenience.

Login to comment on this ticket.

Metadata