(ITS#5303) idlcache problem with new entries

[quanah@zimbra.com]

Full_Name: Quanah Gibson-Mount
Version: 2.3.39
OS: NA
URL: ftp://ftp.openldap.org/incoming/idlcache-bug.tar.gz
Submission from: (NULL) (76.21.80.71)


While testing heavy account provisioning using multiple threads to create
accounts in an OpenLDAP server, we discovered that the idl cache fails to
properly update, making searches for successfully added accounts fail to find
them.  Setting the idlcachesize to zero resolved the search problem, indicating
an issue inside the idl cache code.

Zimbra bug is here:

http://bugzilla.zimbra.com/show_bug.cgi?id=22933


Description:
============
    - OpenLDAP build: openldap-2.3.39
    - 20 concurrent threads are ADDing (distinct) entries in a loop under a
common base DN. 
    - It seems intermittently upon DB_LOCK_DEADLOCK errors, the integrity of
indexes are broken 
      for a period of time even after the ADD returns a good code(err=0). 
Search filtered on an indexed 
      attribute of the newly ADDed entry cannot be found.  If the same query is
done again later, it 
      did find the entry.
    - This seems to happen only after "many" DB_LOCK_DEADLOCK errors.  The
search failure usually happens 
      after 20 to 80 iterations into the loop, while the deadlock error would
start happening since earlier 
      iterations.

Notes on info in attached slapd.log:
====================================
1. The described test started on line 996.

2. Line 25510 shows the ADD
       Dec 20 14:45:51 phoebe slapd[209]: conn=2235 op=1 ADD
dn="uid=a-120-thread-3,ou=people,dc=test-accounts-20071220-143806,dc=ldaptest"

3. Line 25542 shows the ADD was successful
       Dec 20 14:45:52 phoebe slapd[209]: conn=2235 op=1 RESULT tag=105 err=0
text=
   
   This entry should contain (among other attributes):
       objectClass: zimbraAccount
       zimbraId: be0b628b-b8d1-4fce-99cd-7b7f6864149a
   
4. Line 25549 - 25550 shows the search on that zimbraId returned 0 entry:
       Dec 20 14:45:52 phoebe slapd[209]: conn=2235 op=2 SRCH base="" scope=2
deref=3 filter="(&(zimbraId=be0b628b-b8d1-4fce-99cd-7b7f6864149a)(objectClass=zimbraAccount))"
       Dec 20 14:45:52 phoebe slapd[209]: conn=2235 op=2 SEARCH RESULT tag=101
err=0 nentries=0 text=
       
5. Later, the same search(as in 3) was attempted.  Line 25756 - 25757 shows the
same query did find one entry this time:
       Dec 20 14:48:25 phoebe slapd[209]: conn=2250 op=1 SRCH base="" scope=2
deref=3 filter="(&(zimbraId=be0b628b-b8d1-4fce-99cd-7b7f6864149a)(objectClass=zimbraAccount))"
       Dec 20 14:48:25 phoebe slapd[209]: conn=2250 op=1 SEARCH RESULT tag=101
err=0 nentries=1 text=
       
6. As shown in the log, there was no MOD or anything on DN
dn="uid=a-120-thread-3,ou=people,dc=test-accounts-20071220-143806,dc=ldaptest"
between 3 and 4.

7. Other info:
   - zimbraId is an indexed attribute.  see slapd.conf.
   - Note, the test stops when it encounters the first failed search after a
successful create.



slapd.conf and slapd.log files are on the OpenLDAP ftp server as:
ftp://ftp.openldap.org/incoming/idlcache-bug.tar.gz