SunOS ldapslave01.unix 5.10 Generic_141445-09 i86pc i386 i86pc db-4.8.30.NC.tar.gz openldap-2.4.23.tgz
Hello list,
We have had a rare bug hit us now and then, that appears to be quite persistent. I know it isn't fun to read through someone else's setup and troubles, but I am hoping to at least get some hints at what to look at next.
Let us imagine our setup as:
uid=user1,o=a.gmail.com,ou=mail,dc=company,dc=com uid=user2,o=a.gmail.com,ou=mail,dc=company,dc=com uid=user1,o=b.gmail.com,ou=mail,dc=company,dc=com uid=user1,o=c.gmail.com,ou=mail,dc=company,dc=com
(Not literally gmail.com, replacing customer domains manually, but same "style" of service).
ldapmaster -> slave1 -> localhost slapd (pop/imap) -> slave2 -> localhost slapd (postfix) -> slave3 -> localhost slapd (ftp) -> slave4 -> localhost slapd (smtp/forward)
All using syncrepl. One master, only ever updated by the provisioning engine. 4 immediate slaves (full ldap tree), then about 150 work servers, running localhost slapd with only applicable tree. Ie, only "ou=mail" for the mail-related servers.
What happens now and then, is that:
o=b.gmail.com,ou=mail,dc=company,dc=com
gets deleted. Gone.
But you can access record "uid=user1,o=b.gmail.com,ou=mail,dc=company,dc=com" just fine. But not "o=b.gmail.com,ou=mail,dc=company,dc=com". How is that possible? Mismatching indexes?
Amusingly, POP and IMAP work fine since they authenticate against the final user record "uid=user1,o=b.gmail.com,ou=mail,dc=company,dc=com". but Postfix will fail, as it verifies that the domain exists "o=b.gmail.com,ou=mail,dc=company,dc=com". syncrepl for accounts under tree "o=b.gmail.com,ou=mail,dc=company,dc=com" appear to stop until the record is fixed.
There is an easy fix, if we modify the record "o=b.gmail.com,ou=mail,dc=company,dc=com" on the master, it gets pushed out.
It is not always the same record, but it does seem to be a class of certain records. And the missing records seem to happen most on certain servers. 80% of the time, on the vmx servers. It far worse when they disappear on the slaves, since many localhost slapds will then not get synced.
Now, this happens more frequently when we do deletions. Usually around the first of the month, since that is when we delete customers who left. Alas, we moved the entire LDAP DNS tree to its own LDAP master, so have been deleting this tree for 20 days, and will keep deleting for 12 more days. So, at the moment, we have this error once, or twice, a day.
At the moment, I do not really know what goes wrong. I am hoping that perhaps I can get some good ideas on where to look, and what to look for.
This morning, we lost "i.gmail.com" on vmx02. If I grep for it in the logs, we only find:
Apr 27 09:17:51 vmx02.unix slapd[13990]: [ID 338579 local4.debug] nonpresent_cal lback: rid=275 nonpresent UUID 82d9570a-cdd6-102f-9364-65cc77dfbe36, dn o=i.gmail.com,ou=mail,dc=company,dc=com
Apr 27 09:18:11 vmx02.unix slapd[13990]: [ID 905397 local4.debug] syncrepl_del_nonpresent: rid=275 be_delete o=i.gmail.com,ou=mail,dc=company,dc=com (66)
# grep nonpresent_callback /var/log/slaplog| wc -l 517707
# grep syncrepl_del_nonpresent /var/log/slaplog|wc -l 9
What is also curious, is the UUID, for example:
slaplog.20110424.gz:Apr 24 15:31:26 vmx02.unix slapd[13990]: [ID 338579 local4.debug] nonpresent_callback: rid=275 nonpresent UUID 82d9570a-cdd6-102f-9364-65cc77dfbe36, dn o=i.gmail.com,ou=mail,dc=company,dc=com
slaplog.20110424.gz:Apr 24 23:41:00 vmx02.unix slapd[13990]: [ID 338579 local4.debug] nonpresent_callback: rid=275 nonpresent UUID 82d9570a-cdd6-102f-9364-65cc77dfbe36, dn o=i.gmail.com,ou=mail,dc=company,dc=com
Persistent uuid? Is it ok that UUID is repeated? Are unique over time, or sometimes recycled?
If I move from vmx02, to its LDAP provider, in this case, ldapslave03 (rid = 329)
Apr 27 09:12:27 ldapslave03.unix slapd[20759]: [ID 338579 local4.debug] nonprese nt_callback: rid=329 present UUID d6215e0e-1c55-102f-8da7-0b6e3175d2bb, dn o=i.gmail.com,ou=mail,dc=company,dc=com
/export/backup/ldapslave03.unix# gzgrep d6215e0e-1c55-102f-8da7-0b6e35d2bb slaplog.20110* Jan 6 07:15:39 Feb 8 18:47:48 Apr 24 15:22:21 Apr 24 23:36:22
Is it worth pursuing the repeated UUID? Is that some stuck record that keeps retrying over and over? Is it that is constantly trying to delete these records, and correctly failing, except now and then, it succeeds like that of vmx02 this morning?
Then there is the slightly different message, with error "66".
Apr 27 09:20:06 ldapslave03.unix slapd[20759]: [ID 976560 local4.debug] syncprov_sendresp: cookie=
Apr 27 09:20:06 ldapslave03.unix last message repeated 1 time
Apr 27 09:20:06 ldapslave03.unix slapd[20759]: [ID 905397 local4.debug] syncrepl _del_nonpresent: rid=329 be_delete o=i.gmail.com,ou=ftp,dc=company,dc=com (66)
Apr 27 09:20:06 ldapslave03.unix slapd[20759]: [ID 976560 local4.debug] syncprov_sendresp: cookie=
Apr 27 09:20:06 ldapslave03.unix last message repeated 4 times
I believe 66 is LDAP_NOT_ALLOWED_ON_NONLEAF, which is correct. It has thousands of accounts in there, so it definitely should not delete it. But why does it try to delete it in the first place? It is not us trying to delete half the tree (well, you know, pretty sure...ish.. it isn't us) so where is it coming from?
Or should I look at that empty "cookie="? Why that empty, it starts back at:
Apr 27 09:17:29 ldapslave03.unix slapd[20759]: [ID 859137 local4.debug] slap_queue_csn: queing 21798d80 20110427000316.304365Z#000000#000#000000
Apr 27 09:17:29 ldapslave03.unix slapd[20759]: [ID 976560 local4.debug] syncprov_sendresp: cookie=rid=268,csn=20110427000316.304365Z#000000#000#000000
Apr 27 09:17:29 ldapslave03.unix slapd[20759]: [ID 976560 local4.debug] syncprov_sendresp: cookie=rid=278,csn=20110427000316.304365Z#000000#000#000000
Apr 27 09:17:29 ldapslave03.unix slapd[20759]: [ID 775493 local4.debug] slap_graduate_commit_csn: removing a2bee60 0110427000316.304365Z#000000#000#000000
Apr 27 09:17:29 ldapslave03.unix slapd[20759]: [ID 905397 local4.debug] syncrepl_del_nonpresent: rid=329 be_delete uid=$account,ou=users,ou=radius,dc=company,dc=com (0)
Apr 27 09:17:29 ldapslave03.unix slapd[20759]: [ID 502419 local4.debug] Entry uid=userX,o=$customerdomain.com,ou=mail,dc=company,dc=com CSN 20110426223343.974235Z#000000#000#000000 older or equal to ctx 20110426223343.974235Z#000000 #000#000000
Apr 27 09:17:29 ldapslave03.unix last message repeated 1 time
Apr 27 09:17:29 ldapslave03.unix slapd[20759]: [ID 976560 local4.debug] syncprov_sendresp: cookie=
Apr 27 09:17:29 ldapslave03.unix last message repeated 1 time
then a few hundred lines of empty "cookie=" lines.
It is also worth to note that very close to the time that it lost the record today, we have:
Apr 27 09:11:25 vmx02.unix slapd[13990]: [ID 763815 local4.debug] connection_input: conn=6946 deferring operation: too many executing
and it is almost as if, it kills the replication connection randomly when it gets busy. Whatever record it was working on at the time is half processed?
Alas, there are no entries at all for any of these on the master. Possibly because master's loglevel is "sync", which don't seem to do much when it is the provider. Recommended log level would be?
Now, there is version openldap-2.4.24 out, with a very large list of fixes, but I did not see anything immediately obvious. If there is a fix that "looks good" to fix this, I can go through the upgrade. But it is a 3 week process to make it happen on all servers.
Worse is, I have tried to replicate the trouble in a test network, running the exact same data, and binaries, with a master, slave and localhost slapd all on one machine. But I can not make the trouble happen in a simulated environment. Possibly as I am not generating the same load. Quite annoying.
slapd.conf is pushed out with git, and is the same everywhere, except that slaves have the syncrepl section, with separate rids, and memory cache size are set differently.
include /usr/local/etc/openldap/schema/core.schema include /usr/local/etc/openldap/schema/cosine.schema include /usr/local/etc/openldap/schema/nis.schema include /usr/local/etc/openldap/schema/qmail.schema include /usr/local/etc/openldap/schema/local.schema include /usr/local/etc/openldap/schema/RADIUS-LDAPv3.schema include /usr/local/etc/openldap/schema/AmavisdLDAP.schema include /usr/local/etc/openldap/schema/analyse.schema include /usr/local/etc/openldap/schema/formail.schema include /usr/local/etc/openldap/schema/dlz.schema include /usr/local/etc/openldap/schema/filter.schema pidfile /usr/local/var/run/slapd.pid argsfile /usr/local/var/run/slapd.args loglevel sync
database monitor access to dn.subtree="cn=Monitor" by dn="cn=admin,dc=company,dc=com" read by * none
access to attrs=userPassword by self write by anonymous auth by * none
access to * by self write by dn="cn=admin,dc=company,dc=com" write by * read
password-hash {CRYPT}
database hdb suffix "dc=company,dc=com" rootdn "cn=admin,dc=company,dc=com" directory /usr/local/var/openldap-data rootpw $secret
index objectClass eq index uid eq index uidNumber eq index mail eq index mailAlternateAddress pres,eq index deliveryMode eq index accountStatus eq index gecos eq index radiusGroupName eq index o pres,eq index entryCSN,entryUUID eq index gidNumber eq index DNSType eq index DNSIPAddr eq index DNSData eq index DNSHostName eq
checkpoint 128 15 cachesize 6000 idlcachesize 18000
overlay syncprov syncprov-checkpoint 100 10 syncprov-sessionlog 1000
dbconfig set_lk_detect DB_LOCK_DEFAULT dbconfig set_lg_max 52428800 dbconfig set_cachesize 4 0 1 dbconfig set_flags db_log_autoremove dbconfig set_lk_max_objects 1500 dbconfig set_lk_max_locks 1500 dbconfig set_lk_max_lockers 1500
syncrepl rid=( $IP-4TH-OCTET + 256 ) provider=ldap://172.20.12.163 type=refreshAndPersist interval=00:00:00:30 searchbase="dc=company,dc=com" filter="(objectClass=*)" attrs="*,+" scope=sub schemachecking=off bindmethod=simple binddn="cn=admin,dc=company,dc=com" credentials="$secret" retry="60 10 300 +"
updateref ldap://172.20.12.113
(Actually, 172.20.12.163 and 172.20.12.113 are the same server, just aliases on same nic. But updateref is never actually used, we only one writer that talks directly to master).