Bug 1593807

Summary: Fine grained password policy can impact search performance
Product: Red Hat Enterprise Linux 7 Reporter: German Parente <gparente>
Component: 389-ds-baseAssignee: thierry bordaz <tbordaz>
Status: CLOSED ERRATA QA Contact: RHDS QE <ds-qe-bugs>
Severity: high Docs Contact: Marc Muehlfeld <mmuehlfe>
Priority: high    
Version: 7.7-AltCC: mreynolds, msauton, nkinder, pasik, rmeggins, tbordaz, tmihinto
Target Milestone: rcKeywords: ZStream
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: 389-ds-base-1.3.8.4-1.el7 Doc Type: Bug Fix
Doc Text:
Improved performance when the fine-grained password policy is enabled in Directory Server When a search evaluates the "shadowAccount" entry, Directory Server adds the shadow attributes to the entry. If the fine-grained password policy is enabled, the "shadowAccount" entry can contain its own "pwdpolicysubentry" policy attribute. Previously, to retrieve this attribute, the server started an internal search for each "shadowAccount" entry, which was unnecessary because the entry was already known to the server. With this update, Directory Server only starts internal searches if if the entry is not known. As a result, the performance of searches, such as response time and throughput, is improved.
 Story Points: ---
Clone Of:
: 1615924 (view as bug list) Environment:
Last Closed: 2018-10-30 10:14:34 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: 1615924    

Description German Parente 2018-06-21 15:37:52 UTC 
Description of problem:

this is a request to backport 
https://pagure.io/389-ds-base/issue/49742

to RHEL7.


When a search evaluates an shadowAccount entry (to return it or not), it adds the shadow attributes (shadowMax, shadowMin....) to the entry.
With fine grained password policy (nsslapd-pwpolicy-local: on), it tries to retrieve the shadow attribute from a pwdpolicysubentry.

The problem is that it retrieves pwdpolicysubentry attribute value using an internal base search of the evaluated entry. It is useless as in such case we already have the entry.

a stack could look like this

#6  0x00007f2ce7aedc27 in ldbm_back_search () at /usr/lib64/dirsrv/plugins/libback-ldbm.so
#7  0x00007f2cf3fe59c2 in op_shared_search () at /usr/lib64/dirsrv/libslapd.so.0
#8  0x00007f2cf3ff7527 in search_internal_callback_pb () at /usr/lib64/dirsrv/libslapd.so.0
#9  0x00007f2cf3ff7778 in search_internal_pb () at /usr/lib64/dirsrv/libslapd.so.0
#10 0x00007f2cf3ff7b25 in slapi_search_internal_get_entry () at /usr/lib64/dirsrv/libslapd.so.0
#11 0x00007f2cf40017ff in get_entry () at /usr/lib64/dirsrv/libslapd.so.0
#12 0x00007f2cf3ffd1d6 in new_passwdPolicy () at /usr/lib64/dirsrv/libslapd.so.0
#13 0x00007f2cf40012bd in add_shadow_ext_password_attrs () at /usr/lib64/dirsrv/libslapd.so.0
#14 0x00007f2cf3fe413e in send_results_ext.constprop.4 () at /usr/lib64/dirsrv/libslapd.so.0
#15 0x00007f2cf3fe60f1 in op_shared_search () at /usr/lib64/dirsrv/libslapd.so.0
#16 0x0000564ae8ec844e in do_search ()
#17 0x0000564ae8eb6535 in connection_threadmain ()
#18 0x00007f2cf1db0bab in _pt_root () at /lib64/libnspr4.so
#19 0x00007f2cf1750dd5 in start_thread () at /lib64/libpthread.so.0
#20 0x00007f2cf0dfdb3d in clone () at /lib64/libc.so.6





Version-Release number of selected component (if applicable): 389-ds-base-1.3.6.1-28.el7_4x86_64.rpm

Steps to reproduce

1.Create an instance
2.Create a shadowAccount entry
3.Enable internal search logging (nsslapd-accesslog-leve: 260)
4. Enable nsslapd-pwpolicy-local: 1
5. Do a base search on the entry and check that it exists an additional internal search on the entry
Actual results

In some rsearch rate it can increase throughput by 3 times
Comment 8 Viktor Ashirov 2018-08-30 16:25:40 UTC 
Build tested: 389-ds-base-1.3.8.4-12.el7.x86_64

Before the fix (build 389-ds-base-1.3.7.5-25.el7_5.x86_64):
# ldapsearch -xLLL -b dc=example,dc=com '(uid=09999)'
dn: uid=09999,ou=People,dc=example,dc=com
uid: 09999
uid: testnew09999
objectClass: top
objectClass: person
objectClass: organizationalPerson
objectClass: inetorgperson
objectClass: posixAccount
objectClass: shadowAccount
sn: testnew09999
cn: testnew09999
givenName: testnew09999
description: description09999
mail: testnew09999
uidNumber: 309999
gidNumber: 409999
shadowMin: 0
shadowMax: 99999
shadowInactive: 30
shadowWarning: 7
homeDirectory: /home/uid09999
shadowLastChange: 17773

In the access logs:
[30/Aug/2018:14:36:03.572822516 +0000] conn=17 fd=64 slot=64 connection from ::1 to ::1
[30/Aug/2018:14:36:03.573064348 +0000] conn=17 op=0 BIND dn="" method=128 version=3
[30/Aug/2018:14:36:03.573203171 +0000] conn=17 op=0 RESULT err=0 tag=97 nentries=0 etime=0.0000309934 dn=""
[30/Aug/2018:14:36:03.573543220 +0000] conn=17 op=1 SRCH base="dc=example,dc=com" scope=2 filter="(uid=09999)" attrs=ALL
[30/Aug/2018:14:36:03.573858437 +0000] conn=Internal op=-1 SRCH base="uid=09999,ou=people,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[30/Aug/2018:14:36:03.573989379 +0000] conn=Internal op=-1 RESULT err=0 tag=48 nentries=1 etime=0.0000158917
[30/Aug/2018:14:36:03.574201475 +0000] conn=17 op=1 RESULT err=0 tag=101 nentries=1 etime=0.0000839187
[30/Aug/2018:14:36:03.574717051 +0000] conn=17 op=2 UNBIND
[30/Aug/2018:14:36:03.574743698 +0000] conn=17 op=2 fd=64 closed - U1


# ldclt -b "ou=people,dc=example,dc=com" -f uid=09999 -e esearch -I 32 -N 10
ldclt version 4.23
ldclt[1220]: Starting at Thu Aug 30 14:42:02 2018

ldclt[1220]: Average rate: 20849.60/thr  (20849.60/sec), total: 208496
ldclt[1220]: Average rate: 19070.30/thr  (19070.30/sec), total: 190703
ldclt[1220]: Average rate: 20754.90/thr  (20754.90/sec), total: 207549
ldclt[1220]: Average rate: 20763.00/thr  (20763.00/sec), total: 207630
ldclt[1220]: Average rate: 18704.90/thr  (18704.90/sec), total: 187049
ldclt[1220]: Average rate: 20681.30/thr  (20681.30/sec), total: 206813
ldclt[1220]: Average rate: 20674.30/thr  (20674.30/sec), total: 206743
ldclt[1220]: Average rate: 20155.40/thr  (20155.40/sec), total: 201554
ldclt[1220]: Average rate: 20670.30/thr  (20670.30/sec), total: 206703
ldclt[1220]: Average rate: 20770.40/thr  (20770.40/sec), total: 207704
ldclt[1220]: Number of samples achieved. Bye-bye...
ldclt[1220]: All threads are dead - exit.
ldclt[1220]: T002: thread is dead.
ldclt[1220]: Global average rate: 203094.41/thr  (20309.44/sec), total: 2030944
ldclt[1220]: Global number times "no activity" reports: never
ldclt[1220]: Global number of dead threads: 1
ldclt[1220]: Global no error occurs during this session.
ldclt[1220]: Ending at Thu Aug 30 14:43:42 2018
ldclt[1220]: Exit status 0 - No problem during execution.
ldclt[1220]: T003: thread is dead.
ldclt[1220]: T007: thread is dead.
ldclt[1220]: T007: thread is dead.


With the fix:

[30/Aug/2018:16:20:35.858739252 +0000] conn=2 fd=64 slot=64 connection from ::1 to ::1
[30/Aug/2018:16:20:35.858812922 +0000] conn=2 op=0 BIND dn="" method=128 version=3
[30/Aug/2018:16:20:35.858851101 +0000] conn=2 op=0 RESULT err=0 tag=97 nentries=0 etime=0.0000087840 dn=""
[30/Aug/2018:16:20:35.859145550 +0000] conn=2 op=1 SRCH base="dc=example,dc=com" scope=2 filter="(uid=09999)" attrs=ALL
[30/Aug/2018:16:20:35.859354708 +0000] conn=2 op=1 RESULT err=0 tag=101 nentries=1 etime=0.0000357791
[30/Aug/2018:16:20:35.859562726 +0000] conn=2 op=2 UNBIND
[30/Aug/2018:16:20:35.859576506 +0000] conn=2 op=2 fd=64 closed - U1


# ldclt -b "ou=people,dc=example,dc=com" -f uid=09999 -e esearch -I 32 -N 10
ldclt version 4.23
ldclt[732]: Starting at Thu Aug 30 16:21:50 2018

ldclt[732]: Average rate: 33711.70/thr  (33711.70/sec), total: 337117
ldclt[732]: Average rate: 35243.50/thr  (35243.50/sec), total: 352435
ldclt[732]: Average rate: 34308.20/thr  (34308.20/sec), total: 343082
ldclt[732]: Average rate: 35295.90/thr  (35295.90/sec), total: 352959
ldclt[732]: Average rate: 34962.70/thr  (34962.70/sec), total: 349627
ldclt[732]: Average rate: 33312.80/thr  (33312.80/sec), total: 333128
ldclt[732]: Average rate: 35389.00/thr  (35389.00/sec), total: 353890
ldclt[732]: Average rate: 34213.30/thr  (34213.30/sec), total: 342133
ldclt[732]: Average rate: 33938.10/thr  (33938.10/sec), total: 339381
ldclt[732]: Average rate: 35465.00/thr  (35465.00/sec), total: 354650
ldclt[732]: Number of samples achieved. Bye-bye...
ldclt[732]: All threads are dead - exit.
ldclt[732]: Global average rate: 345840.19/thr  (34584.02/sec), total: 3458402
ldclt[732]: Global number times "no activity" reports: never
ldclt[732]: Global no error occurs during this session.
ldclt[732]: T003: thread is dead.
ldclt[732]: Ending at Thu Aug 30 16:23:30 2018
ldclt[732]: Exit status 0 - No problem during execution.
ldclt[732]: T009: thread is dead.
ldclt[732]: T002: thread is dead.

Internal search is no longer present in the access logs and average search rate increased by ~60% (both tests were with nunc-stans on).

Marking as VERIFIED.
Comment 10 errata-xmlrpc 2018-10-30 10:14:34 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.

https://access.redhat.com/errata/RHSA-2018:3127