Bug 819063

Summary: sssd fails to provide partial data till paged search returns "Size Limit Exceeded"
Product: Red Hat Enterprise Linux 6 Reporter: Kaushik Banerjee <kbanerje>
Component: sssdAssignee: Stephen Gallagher <sgallagh>
Status: CLOSED ERRATA QA Contact: IDM QE LIST <seceng-idm-qe-list>
Severity: unspecified Docs Contact:
Priority: high    
Version: 6.3CC: grajaiya, jgalipea, jhrozek, prc
Target Milestone: rcKeywords: Regression
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: sssd-1.8.0-26.el6 Doc Type: Bug Fix
Doc Text:
No documentation required
Story Points: ---
Clone Of: Environment:
Last Closed: 2012-06-20 11:56:55 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:

Description Kaushik Banerjee 2012-05-04 17:43:50 UTC
Description of problem:
sssd fails to provide partial data till paged search returns "Size Limit Exceeded"

Version-Release number of selected component (if applicable):
1.8.0-25

How reproducible:
Always

Steps to Reproduce:
1. On openldap server, set maxpagesize=10,totalpageentries=5 as:
 
olcLimits: * size.pr=10 size.prtotal=5

2. Add a user puser21, belonging to 20 groups

3. Use ldapsearch to verify if 5 paged entries are returned:
# ldapsearch -xv -h openldap.example.com -E pr=05 -b "ou=Pagingtest,dc=example,dc=com" "(memberuid=puser21)"
ldap_initialize( ldap://openldap.example.com )
filter: (memberuid=puser21)
requesting: All userApplication attributes
# extended LDIF
#
# LDAPv3
# base <ou=Pagingtest,dc=example,dc=com> with scope subtree
# filter: (memberuid=puser21)
# requesting: ALL
# with pagedResults control: size=5
#
 
# puser21_grp1, Pagingtest, example.com
dn: cn=puser21_grp1,ou=Pagingtest,dc=example,dc=com
gidNumber: 1321
objectClass: posixGroup
memberUid: puser21
cn: puser21_grp1
 
# puser21_grp2, Pagingtest, example.com
dn: cn=puser21_grp2,ou=Pagingtest,dc=example,dc=com
gidNumber: 1322
objectClass: posixGroup
memberUid: puser21
cn: puser21_grp2
 
# puser21_grp3, Pagingtest, example.com
dn: cn=puser21_grp3,ou=Pagingtest,dc=example,dc=com
gidNumber: 1323
objectClass: posixGroup
memberUid: puser21
cn: puser21_grp3
 
# puser21_grp4, Pagingtest, example.com
dn: cn=puser21_grp4,ou=Pagingtest,dc=example,dc=com
gidNumber: 1324
objectClass: posixGroup
memberUid: puser21
cn: puser21_grp4
 
# puser21_grp5, Pagingtest, example.com
dn: cn=puser21_grp5,ou=Pagingtest,dc=example,dc=com
gidNumber: 1325
objectClass: posixGroup
memberUid: puser21
cn: puser21_grp5
 
# search result
search: 2
result: 0 Success
control: 1.2.840.113556.1.4.319 false MA0CAQAECNoLAAAAAAAA
pagedresults: cookie=2gsAAAAAAAA=
Press [size] Enter for the next {5|size} entries.
 
filter: (memberuid=puser21)
requesting: All userApplication attributes
# extended LDIF
#
# LDAPv3
# base <ou=Pagingtest,dc=example,dc=com> with scope subtree
# filter: (memberuid=puser21)
# requesting: ALL
# with pagedResults control: size=5
#
 
# search result
search: 3
result: 4 Size limit exceeded
 
# numResponses: 7
# numEntries: 5

4. Setup sssd with domain section as:
[domain/LDAP]
ldap_page_size = 5
id_provider = ldap
ldap_uri = ldap://openldap.example.com
ldap_search_base = ou=Pagingtest,dc=example,dc=com
debug_level = 0xFFF0
ldap_tls_cacert = /etc/openldap/certs/server.pem  


5. Verify using sssd if 5 objects are returned:
 
# id puser21
uid=1321(puser21) gid=1321(puser21_grp1) groups=1321(puser21_grp1)  <== Should have also returned puser1_[grp2,grp3,grp4,grp5]


Actual results:
initgroup doesn't return the data related to the first page. i.e. the first 5 groups.

Expected results:
sssd should return data for the pages that have been searched.

Additional info:
Log shows:
 
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_get_initgr_user] (0x4000): Process user's groups
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_initgr_rfc2307_next_base] (0x0400): Searching for groups with base [ou=Pagingtest,dc=example,dc=com]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(memberuid=puser21)(objectclass=posixGroup)(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][ou=Pagingtest,dc=example,dc=com].
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberuid]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 4
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_process_result] (0x2000): Trace: sh[0x18736e0], connected[1], ops[0x18759d0], ldap[0x186a170]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_process_result] (0x2000): Trace: sh[0x18736e0], connected[1], ops[0x18759d0], ldap[0x186a170]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_parse_entry] (0x4000): OriginalDN: [cn=puser21_grp1,ou=Pagingtest,dc=example,dc=com].
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_process_result] (0x2000): Trace: sh[0x18736e0], connected[1], ops[0x18759d0], ldap[0x186a170]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_parse_entry] (0x4000): OriginalDN: [cn=puser21_grp2,ou=Pagingtest,dc=example,dc=com].
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_process_result] (0x2000): Trace: sh[0x18736e0], connected[1], ops[0x18759d0], ldap[0x186a170]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_parse_entry] (0x4000): OriginalDN: [cn=puser21_grp3,ou=Pagingtest,dc=example,dc=com].
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_process_result] (0x2000): Trace: sh[0x18736e0], connected[1], ops[0x18759d0], ldap[0x186a170]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_parse_entry] (0x4000): OriginalDN: [cn=puser21_grp4,ou=Pagingtest,dc=example,dc=com].
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_process_result] (0x2000): Trace: sh[0x18736e0], connected[1], ops[0x18759d0], ldap[0x186a170]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_ENTRY]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_parse_entry] (0x4000): OriginalDN: [cn=puser21_grp5,ou=Pagingtest,dc=example,dc=com].
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_process_result] (0x2000): Trace: sh[0x18736e0], connected[1], ops[0x18759d0], ldap[0x186a170]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_get_generic_ext_done] (0x1000): Total count [0]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x0400): calling ldap_search_ext with [(&(memberuid=puser21)(objectclass=posixGroup)(cn=*)(&(gidNumber=*)(!(gidNumber=0))))][ou=Pagingtest,dc=example,dc=com].
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [objectClass]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [cn]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [userPassword]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [gidNumber]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [memberuid]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x1000): Requesting attrs: [modifyTimestamp]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_get_generic_ext_step] (0x2000): ldap_search_ext called, msgid = 5
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_process_result] (0x2000): Trace: sh[0x18736e0], connected[1], ops[0x1875c00], ldap[0x186a170]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_process_result] (0x2000): Trace: ldap_result found nothing!
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_process_result] (0x2000): Trace: sh[0x18736e0], connected[1], ops[0x1875c00], ldap[0x186a170]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_process_message] (0x4000): Message type: [LDAP_RES_SEARCH_RESULT]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_get_generic_ext_done] (0x0400): Search result: Size limit exceeded(4), no errmsg set
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_get_generic_ext_done] (0x0040): Unexpected result from ldap: Size limit exceeded(4), no errmsg set
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_get_generic_done] (0x0100): sdap_get_generic_ext_recv failed [5]: Input/output error
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_get_initgr_done] (0x4000): Initgroups done
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_get_initgr_done] (0x4000): Error in initgroups: [5][Input/output error]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_id_op_done] (0x0200): communication error on cached connection, moving to next server
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_id_op_done] (0x4000): too many communication failures, giving up...
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_id_op_done] (0x4000): releasing operation connection
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_id_release_conn_data] (0x4000): releasing unused connection
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [sdap_handle_release] (0x2000): Trace: sh[0x18736e0], connected[1], ops[(nil)], ldap[0x186a170], destructor_lock[0], release_memory[0]
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [remove_connection_callback] (0x4000): Successfully removed connection callback.
(Fri May  4 12:54:52 2012) [sssd[be[LDAP]]] [acctinfo_callback] (0x0100): Request processed. Returned 3,5,Init Groups Failed
(Fri May  4 12:54:54 2012) [sssd[be[LDAP]]] [sbus_dispatch] (0x4000): dbus conn: 1857730

Comment 2 Stephen Gallagher 2012-05-04 17:55:45 UTC
Upstream ticket:
https://fedorahosted.org/sssd/ticket/1322

Comment 3 RHEL Program Management 2012-05-08 04:03:54 UTC
Since RHEL 6.3 External Beta has begun, and this bug remains
unresolved, it has been rejected as it is not proposed as
exception or blocker.

Red Hat invites you to ask your support representative to
propose this request, if appropriate and relevant, in the
next release of Red Hat Enterprise Linux.

Comment 6 Stephen Gallagher 2012-05-10 18:12:42 UTC
Patch is available upstream

Comment 10 Kaushik Banerjee 2012-05-16 10:42:15 UTC
Verified in version sssd-1.8.0-27


Output of automation run:
::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::
:: [   LOG    ] :: paging_control_007: maxpagesize=10,totalpageentries=5 on ldapserver & enumerate=false,ldap_page_size=5 in sssd. enumerate a user in 20 groups
::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

:: [   PASS   ] :: Running '> /var/log/sssd/sssd_LDAP.log'
Stopping sssd: [  OK  ]
:: [   PASS   ] :: Running 'service sssd stop'
:: [   PASS   ] :: Running 'rm -fr /var/lib/sss/db/*.ldb'
Starting sssd: [  OK  ]
[  OK  ]
:: [   PASS   ] :: Running 'service sssd start'
:: [   PASS   ] :: napping for 5 secs...
:: [   PASS   ] :: Running 'restart_clearing_cache'
uid=1321(puser21) gid=1321(puser21_grp1) groups=1321(puser21_grp1),1324(puser21_grp4),1325(puser21_grp5),1322(puser21_grp2),1323(puser21_grp3)
:: [   PASS   ] :: Running 'id puser21 | tee /tmp/output21'
:: [   PASS   ] :: File '/tmp/output21' should contain 'puser21_grp1'
:: [   PASS   ] :: File '/tmp/output21' should contain 'puser21_grp5'
:: [   PASS   ] :: File '/tmp/output21' should not contain 'puser21_grp10'
puser21_grp1
:: [   PASS   ] :: Running 'id -gn puser21 | tee /tmp/output21_primarygroup'
:: [   PASS   ] :: File '/tmp/output21_primarygroup' should contain 'puser21_grp1'
(Tue May 15 15:18:52 2012) [sssd[be[LDAP]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
(Tue May 15 15:18:52 2012) [sssd[be[LDAP]]] [sdap_get_generic_ext_done] (0x0400): Search result: Success(0), no errmsg set
:: [   PASS   ] :: Running 'cat /var/log/sssd/sssd_LDAP.log | grep -A 3 puser21_grp5 | grep "Search result: Success"'
spawn ssh -q -l puser21 localhost echo 'login successful'
puser21@localhost's password: 
Could not chdir to home directory /home/puser21: No such file or directory
login successful
:: [   PASS   ] :: Authentication successful, as expected
:: [   PASS   ] :: Running 'auth_success puser21 Secret123'
'02bd5bde-ffec-4b51-8d39-2529884042e4'
paging-control-007 result: PASS

Comment 11 Stephen Gallagher 2012-06-12 12:54:33 UTC
    Technical note added. If any revisions are required, please edit the "Technical Notes" field
    accordingly. All revisions will be proofread by the Engineering Content Services team.
    
    New Contents:
No documentation required

Comment 13 errata-xmlrpc 2012-06-20 11:56:55 UTC
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.

http://rhn.redhat.com/errata/RHBA-2012-0747.html