Bug 772163

Summary: Iterator loop reuse cases a tight loop in the native IPA netgroups code
Product: Red Hat Enterprise Linux 6 Reporter: Jakub Hrozek <jhrozek>
Component: sssdAssignee: Stephen Gallagher <sgallagh>
Status: CLOSED ERRATA QA Contact: IDM QE LIST <seceng-idm-qe-list>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 6.3CC: dpal, grajaiya, jgalipea, prc, shaines, spoore
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: sssd-1.8.0-2.el6.beta2 Doc Type: Bug Fix
Doc Text:
No documentation needed.
 Story Points: ---
Clone Of: Environment:
Last Closed: 2012-06-20 11:51:15 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:

Description Jakub Hrozek 2012-01-06 08:51:40 UTC 
Description of problem:
When the same netgroup is requested twice, the getent request seemingly pauses and then only returns the data from cache.

This is caused by an iterator variable reused in inner loop in the code.

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

How reproducible:
always

Steps to Reproduce:
1. on an IPA server, add a netgroup. Mine looks like this:
$ ipa netgroup-show testngr
  Netgroup name: testngr
  Description: a test netgroup
  NIS domain name: idm.lab.bos.redhat.com
  Member User: foobar

2. on the client, set a low entry_cache_timeout to force requests to go to the server.
3. run getent netgr testngr. Results show up.
4. run it again, 
  
Actual results:
The second invocation will pause for a moment and then fall back to cached data (which can be verified by adding another member user on the server)

Expected results:
No pause and up to date data is returned

Additional info:
Comment 1 Jakub Hrozek 2012-01-06 08:57:08 UTC 
Upstream ticket:
https://fedorahosted.org/sssd/ticket/1134
Comment 3 Jenny Severance 2012-02-02 21:05:56 UTC 
Jakub can you please add the required steps to set a low entry_cache_timeout - thanks!
Comment 4 Jakub Hrozek 2012-02-02 22:16:57 UTC 
(In reply to comment #3)
> Jakub can you please add the required steps to set a low entry_cache_timeout -
> thanks!

Putting "entry_cache_timeout=1" into the [domain/$name] section and restarting the SSSD should force SSSD to refresh cache entries one seconds after they have been saved (which would probably translate to "always refresh").
Comment 7 Scott Poore 2012-02-15 01:18:17 UTC 
Are there log entries that we could look for to confirm behaviour?  

Couldn't you see the same thing if you lookup a netgroup before changing the entry_cache_timeout value?   

I haven't been able to consistently reproduce this yet except when I did a getent before so that it was cached before the timeout change.  

If I do a lookup BEFORE the timeout change, I do see it returned the previously cached entry.   If I add a netgroup AFTER the timeout change, I see it updated for each change.

Is this not expected?  

Versions I was testing against today:
sssd-1.8.0-3.el6.beta2.x86_64
and
sssd-1.5.17-0.20120103T0145z.20120103T0159z.el6.x86_64

################################################################
###  Example with entry cached BEFORE timeout change:
################################################################
# ipa netgroup-add mytestng1 --desc=mytestng1
--------------------------
Added netgroup "mytestng1"
--------------------------
  Netgroup name: mytestng1
  Description: mytestng1
  NIS domain name: testrelm.com
  IPA unique ID: 74aaf0f8-5771-11e1-a765-5254008e05e2

# getent netgroup mytestng1
mytestng1             (-, -, testrelm.com)

# ipa netgroup-add-member mytestng1 --users=user1
  Netgroup name: mytestng1
  Description: mytestng1
  NIS domain name: testrelm.com
  Member User: user1
-------------------------
Number of members added 1
-------------------------

# getent netgroup mytestng1
mytestng1             (-, -, testrelm.com)
[root@spoore-dvm3 acceptance]# getent netgroup mytestng1
mytestng1             (-, -, testrelm.com)
[root@spoore-dvm3 acceptance]# getent netgroup mytestng1
mytestng1             (-, -, testrelm.com)
[root@spoore-dvm3 acceptance]# getent netgroup mytestng1
mytestng1             (-, -, testrelm.com)

# sed -i 's/\(\[domain.*\]\)$/\1\nentry_cache_timeout = 1/' /etc/sssd/sssd.conf

# service sssd restart
Stopping sssd:                                             [  OK  ]
Starting sssd:                                             [  OK  ]
[root@spoore-dvm3 acceptance]# getent netgroup mytestng1
mytestng1             (-, -, testrelm.com)

# ipa netgroup-add-member mytestng1 --users=user2
  Netgroup name: mytestng1
  Description: mytestng1
  NIS domain name: testrelm.com
  Member User: user1, user2
-------------------------
Number of members added 1
-------------------------

# getent netgroup mytestng1
mytestng1             (-, -, testrelm.com)

################################################################
### Example with entry AFTER timeout change
################################################################
# ipa netgroup-add mytestng2 --desc=mytestng2
--------------------------
Added netgroup "mytestng2"
--------------------------
  Netgroup name: mytestng2
  Description: mytestng2
  NIS domain name: testrelm.com
  IPA unique ID: dec98620-5771-11e1-964e-5254008e05e2

# getent netgroup mytestng2
mytestng2             (-, -, testrelm.com)

# ipa netgroup-add-member mytestng2 --users=user2
  Netgroup name: mytestng2
  Description: mytestng2
  NIS domain name: testrelm.com
  Member User: user2
-------------------------
Number of members added 1
-------------------------

# getent netgroup mytestng2
mytestng2             (-, user2, testrelm.com)

# ipa netgroup-add-member mytestng2 --users=user3
  Netgroup name: mytestng2
  Description: mytestng2
  NIS domain name: testrelm.com
  Member User: user2, user3
-------------------------
Number of members added 1
-------------------------

# getent netgroup mytestng2
mytestng2             (-, user2, testrelm.com) (-, user3, testrelm.com)
Comment 8 Jakub Hrozek 2012-02-15 10:38:03 UTC 
(In reply to comment #7)
> Are there log entries that we could look for to confirm behaviour?  
> 
> Couldn't you see the same thing if you lookup a netgroup before changing the
> entry_cache_timeout value?   
> 
> I haven't been able to consistently reproduce this yet except when I did a
> getent before so that it was cached before the timeout change.  
> 
> If I do a lookup BEFORE the timeout change, I do see it returned the previously
> cached entry.   If I add a netgroup AFTER the timeout change, I see it updated
> for each change.
> 
> Is this not expected?  
> 
> Versions I was testing against today:
> sssd-1.8.0-3.el6.beta2.x86_64
> and
> sssd-1.5.17-0.20120103T0145z.20120103T0159z.el6.x86_64
> 

I'm sorry Scott, I realized that 1.5.x isn't affected. This bug affects the native IPA netgroups implementation only and that was a new feature of 1.7.x

I'm not sure if we did any RHEL builds of 1.7 that you can grab and test. To provide you with a buggy package I could either make a special build reverting the single change or rebuild the Fedora 1.7 package. Would that work for you?
Comment 10 Scott Poore 2012-02-15 13:42:48 UTC 
Jakub, No problem.   

Ah, 1.7.  Looks like I tested too high and too low.   I do believe I have a repo I can test 1.7.92.  I'll try that and ping you back if I have any further questions or need a special build to test.  

Thanks
Comment 11 Stephen Gallagher 2012-02-15 13:44:37 UTC 
Scott, 1.7.92 is the same as 1.8.0 beta 2 (the internal version number doesn't go to 1.8.0 until it's actually released).

So that's not going to help you :)
Comment 12 Jakub Hrozek 2012-02-15 13:47:14 UTC 
Sorry, the component change to 389-ds-base was accidental. I've re-requested
the flags again. I'm also resetting the state to MODIFIED, where it was before.
Comment 13 Stephen Gallagher 2012-02-15 13:56:24 UTC 
Sorry, ON_QA was correct. This is included in the errata filing.
Comment 14 Jakub Hrozek 2012-04-03 18:10:26 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 needed.
Comment 15 Scott Poore 2012-04-04 16:35:48 UTC 
Verified.

It does take some time for the first lookup but, subsequent ones do not.  Also, I have not seen what appears to be cached results returned on subsequent lookups.  

Version :: sssd-1.8.0-17.el6.x86_64

Automated Test Results :: 

This is a manual run of the automated test results.

# netgroup_bz_772163 

::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::
:: [   LOG    ] :: netgroup_bz_772163: Iterator loop reuse cases a tight loop in the native IPA netgroups code
::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

:: [12:08:49] ::  Adding necessary users and netgroup for test
--------------------------
Added user "testuser10000"
--------------------------
  User login: testuser10000
  First name: first
  Last name: last
  Full name: first last
  Display name: first last
  Initials: fl
  Home directory: /home/testuser10000
  GECOS field: first last
  Login shell: /bin/sh
  Kerberos principal: testuser10000
  UID: 1786400062
  GID: 1786400062
  Password: False
  Kerberos keys available: False
:: [   PASS   ] :: Running 'ipa user-add testuser10000 --first=first --last=last'
--------------------------
Added user "testuser10001"
--------------------------
  User login: testuser10001
  First name: first
  Last name: last
  Full name: first last
  Display name: first last
  Initials: fl
  Home directory: /home/testuser10001
  GECOS field: first last
  Login shell: /bin/sh
  Kerberos principal: testuser10001
  UID: 1786400063
  GID: 1786400063
  Password: False
  Kerberos keys available: False
:: [   PASS   ] :: Running 'ipa user-add testuser10001 --first=first --last=last'
--------------------------
Added user "testuser10002"
--------------------------
  User login: testuser10002
  First name: first
  Last name: last
  Full name: first last
  Display name: first last
  Initials: fl
  Home directory: /home/testuser10002
  GECOS field: first last
  Login shell: /bin/sh
  Kerberos principal: testuser10002
  UID: 1786400064
  GID: 1786400064
  Password: False
  Kerberos keys available: False
:: [   PASS   ] :: Running 'ipa user-add testuser10002 --first=first --last=last'
---------------------------------
Added netgroup "testnetgroup1000"
---------------------------------
  Netgroup name: testnetgroup1000
  Description: test
  NIS domain name: testrelm.com
  IPA unique ID: 7f79bb56-7e70-11e1-b5a1-00142272fa2d
:: [   PASS   ] :: Running 'ipa netgroup-add testnetgroup1000 --desc=test'
  Netgroup name: testnetgroup1000
  Description: test
  NIS domain name: testrelm.com
  Member User: testuser10000
-------------------------
Number of members added 1
-------------------------
:: [   PASS   ] :: Running 'ipa netgroup-add-member testnetgroup1000 --users=testuser10000'
:: [12:09:07] ::  Setting SSSD cache timeout low to test
:: [   PASS   ] :: Running 'sed -i 's/\(\[domain.*\]\)$/\1\nentry_cache_timeout = 1/' /etc/sssd/sssd.conf'
Stopping sssd: [  OK  ]
[  OK  ] sssd: [  OK  ]
:: [   PASS   ] :: Running 'service sssd restart'
:: [12:09:08] ::  Waiting for 5 seconds for SSSD to completely start up
:: [   PASS   ] :: Running 'sleep 5'
testnetgroup1000      (-, testuser10000, testrelm.com)

real	0m4.711s
user	0m0.000s
sys	0m0.005s
:: [   PASS   ] :: Running 'time getent netgroup testnetgroup1000'
:: [12:09:18] ::  Add another member to netgroup and check if it shows up from getent
Wed Apr  4 12:09:18 EDT 2012
:: [   PASS   ] :: Running 'date'
  Netgroup name: testnetgroup1000
  Description: test
  NIS domain name: testrelm.com
  Member User: testuser10000, testuser10001
-------------------------
Number of members added 1
-------------------------
:: [   PASS   ] :: Running 'ipa netgroup-add-member testnetgroup1000 --users=testuser10001'
Wed Apr  4 12:09:21 EDT 2012
:: [   PASS   ] :: Running 'date'

real	0m0.241s
user	0m0.001s
sys	0m0.003s
:: [   PASS   ] :: Running '(time getent netgroup testnetgroup1000 > /tmp/errormsg.out 2>&1) 2>&1 | tee /tmp/timer.netgroup_bz_772163'
testnetgroup1000      (-, testuser10000, testrelm.com) (-, testuser10001, testrelm.com)
:: [   PASS   ] :: Running 'cat /tmp/errormsg.out'
:: [   PASS   ] :: BZ 772163 not found...added user seen in netgroup
:: [12:09:22] ::  Add another member to netgroup and check if it shows up from getent
Wed Apr  4 12:09:22 EDT 2012
:: [   PASS   ] :: Running 'date'
  Netgroup name: testnetgroup1000
  Description: test
  NIS domain name: testrelm.com
  Member User: testuser10000, testuser10001, testuser10002
-------------------------
Number of members added 1
-------------------------
:: [   PASS   ] :: Running 'ipa netgroup-add-member testnetgroup1000 --users=testuser10002'
Wed Apr  4 12:09:26 EDT 2012
:: [   PASS   ] :: Running 'date'

real	0m0.309s
user	0m0.000s
sys	0m0.004s
:: [   PASS   ] :: Running '(time getent netgroup testnetgroup1000 > /tmp/errormsg.out 2>&1) 2>&1 | tee /tmp/timer.netgroup_bz_772163'
testnetgroup1000      (-, testuser10000, testrelm.com) (-, testuser10001, testrelm.com) (-, testuser10002, testrelm.com)
:: [   PASS   ] :: Running 'cat /tmp/errormsg.out'
:: [   PASS   ] :: BZ 772163 not found...added user seen in netgroup
:: [12:09:27] ::  Cleaning up after netgroup_bz_772163 test
-----------------------------------
Deleted netgroup "testnetgroup1000"
-----------------------------------
:: [   PASS   ] :: Running 'ipa netgroup-del testnetgroup1000'
:: [12:09:30] ::  Deleting user testuser10000
----------------------------
Deleted user "testuser10000"
----------------------------
:: [   PASS   ] :: Running 'ipa user-del testuser10000'
:: [12:09:33] ::  Deleting user testuser10001
----------------------------
Deleted user "testuser10001"
----------------------------
:: [   PASS   ] :: Running 'ipa user-del testuser10001'
:: [12:09:37] ::  Deleting user testuser10002
----------------------------
Deleted user "testuser10002"
----------------------------
:: [   PASS   ] :: Running 'ipa user-del testuser10002'
:: [12:09:40] ::  Resetting SSSD to default cache timeout
:: [   PASS   ] :: Running 'sed -i '/entry_cache_timeout = 1/d' /etc/sssd/sssd.conf'
Stopping sssd: [  OK  ]
[  OK  ] sssd: [  OK  ]
:: [   PASS   ] :: Running 'service sssd restart'
[root@storm ipa-netgroup-cli]# report=/tmp/rhts.report.1
[root@storm ipa-netgroup-cli]# makereport $report
report saved as: /tmp/rhts.report.1
================ final pass/fail report =================
   Test Date: Wed Apr  4 12:10:07 EDT 2012 
   Total : [1] 
   Passed: [1] 
   Failed: [0] 
   Abort : [0]
---------------------------------------------------------
   [   PASS   ]      netgroup_bz_772163  Iterator loop reuse cases a tight loop in the native IPA netgroups code


=========================================================


Manual Test Results :: 


# ipa user-add testu1 --first=f --last=l
-------------------
Added user "testu1"
-------------------
  User login: testu1
  First name: f
  Last name: l
  Full name: f l
  Display name: f l
  Initials: fl
  Home directory: /home/testu1
  GECOS field: f l
  Login shell: /bin/sh
  Kerberos principal: testu1
  UID: 1786400065
  GID: 1786400065
  Password: False
  Kerberos keys available: False

# ipa user-add testu2 --first=f --last=l
-------------------
Added user "testu2"
-------------------
  User login: testu2
  First name: f
  Last name: l
  Full name: f l
  Display name: f l
  Initials: fl
  Home directory: /home/testu2
  GECOS field: f l
  Login shell: /bin/sh
  Kerberos principal: testu2
  UID: 1786400066
  GID: 1786400066
  Password: False
  Kerberos keys available: False

# ipa netgroup-add testn1 --desc=desc
-----------------------
Added netgroup "testn1"
-----------------------
  Netgroup name: testn1
  Description: desc
  NIS domain name: testrelm.com
  IPA unique ID: 59fd2252-7e73-11e1-a06c-00142272fa2d

# ipa netgroup-add-member testn1 --users=testu1
  Netgroup name: testn1
  Description: desc
  NIS domain name: testrelm.com
  Member User: testu1
-------------------------
Number of members added 1
-------------------------

# sed -i 's/\(\[domain.*\]\)$/\1\nentry_cache_timeout = 1/' /etc/sssd/sssd.conf

# service sssd restart
Stopping sssd: [  OK  ]
[  OK  ] sssd: [  OK  ]

# sleep 5

# time getent netgroup testn1
testn1                (-, testu1, testrelm.com)

real	0m4.225s
user	0m0.000s
sys	0m0.009s

# date
Wed Apr  4 12:32:15 EDT 2012

# ipa netgroup-add-member testn1 --users=testu2
  Netgroup name: testn1
  Description: desc
  NIS domain name: testrelm.com
  Member User: testu1, testu2
-------------------------
Number of members added 1
-------------------------

# date
Wed Apr  4 12:32:18 EDT 2012

# time getent netgroup testn1
testn1                (-, testu1, testrelm.com) (-, testu2, testrelm.com)

real	0m0.277s
user	0m0.000s
sys	0m0.003s

# date
Wed Apr  4 12:32:18 EDT 2012

# ipa netgroup-add-member testn1 --users=admin
  Netgroup name: testn1
  Description: desc
  NIS domain name: testrelm.com
  Member User: testu1, testu2, admin
-------------------------
Number of members added 1
-------------------------

# date
Wed Apr  4 12:32:21 EDT 2012

# time getent netgroup testn1
testn1                (-, testu1, testrelm.com) (-, testu2, testrelm.com) (-, admin, testrelm.com)

real	0m0.257s
user	0m0.000s
sys	0m0.003s
Comment 17 errata-xmlrpc 2012-06-20 11:51:15 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