8:40 a.m.
Hi,
I've got a two-node MMR setup using syncrepl running 2.4.36 with back-bdb.
Last night, between 1/3 and 1/2 of the entries in our directory disappeared. Fortunately
I have olcLogLeve=sync set, so I think I have a line on what happened...
I see this at 4AM long of the morning before the fun started:
Jul 7 04:19:30 zoot slapd[15011]: bdb(dc=clarku,dc=edu): Lock table is out of available
lock entries
Jul 7 04:19:30 zoot slapd[15011]: => bdb_idl_insert_key: c_get failed: Cannot allocate
memory (12)
Then many hours later:
Jul 7 15:04:30 zoot slapd[15011]: bdb(dc=clarku,dc=edu): Lock table is out of available
lock entries
Jul 7 15:04:30 zoot slapd[15011]: => bdb_idl_delete_key: c_get failed: Cannot allocate
memory (12)
Jul 7 15:04:30 zoot slapd[15011]: null_callback : error code 0x50
Jul 7 15:04:30 zoot slapd[15011]: slap_graduate_commit_csn: removing 0x7fa33c248a80
20140707190424.188580Z#000000#001#000000
Jul 7 15:04:30 zoot slapd[15011]: syncrepl_del_nonpresent: rid=001 be_delete
cn=parents_ug_students,ou=Other,ou=Groups,dc=clarku,dc=edu (80)
This repeats itself several times:
Jul 7 16:41:09 zoot slapd[15011]: syncprov_matchops: skipping original sid 001
Jul 7 16:41:09 zoot slapd[15011]: bdb(dc=clarku,dc=edu): Lock table is out of available
lock entries
Jul 7 16:41:09 zoot slapd[15011]: => bdb_idl_delete_key: c_get failed: Cannot allocate
memory (12)
Jul 7 16:41:09 zoot slapd[15011]: null_callback : error code 0x50
Jul 7 16:41:09 zoot slapd[15011]: slap_graduate_commit_csn: removing 0x7fa37e4b4260
20140707204059.442906Z#000000#001#000000
Jul 7 16:41:09 zoot slapd[15011]: syncrepl_del_nonpresent: rid=001 be_delete
cn=parents_ug_students,ou=Other,ou=Groups,dc=clarku,dc=edu (80)
Jul 7 16:52:44 zoot slapd[2179]: bdb(dc=clarku,dc=edu): Lock table is out of available
lock entries
Jul 7 16:52:44 zoot slapd[2179]: => bdb_idl_delete_key: c_get failed: Cannot allocate
memory (12)
Jul 7 16:52:44 zoot slapd[2179]: null_callback : error code 0x50
Jul 7 16:52:44 zoot slapd[2179]: slap_graduate_commit_csn: removing 0x7f74581dae70
20140707205225.029175Z#000000#001#000000
Jul 7 16:52:44 zoot slapd[2179]: syncrepl_del_nonpresent: rid=001 be_delete
cn=parents_ug_students,ou=Other,ou=Groups,dc=clarku,dc=edu (80)
Jul 7 16:52:44 zoot slapd[2179]: slap_queue_csn: queing 0x7f7458be8470
20140707205225.029175Z#000000#001#000000
Jul 7 16:52:44 zoot slapd[2179]: slap_graduate_commit_csn: removing 0x7f74581ad2e0
20140707205225.029175Z#000000#001#000000
Then we get (possibly unrelated) a lengthy list of nonpresent_callbacks (tons more then I
list here):
Jul 7 17:06:24 zoot slapd[2179]: nonpresent_callback: rid=001 present UUID
5111f346-871c-1033-8d4b-f5dbd10b8ca0, dn uid=rvenkatachalam,ou=Users,dc=clarku,dc=edu
Jul 7 17:06:24 zoot slapd[2179]: nonpresent_callback: rid=001 present UUID
1e3d94e4-8ce8-1033-8d6a-f5dbd10b8ca0, dn
cn=BIOL399-09-SU14,ou=Courses,ou=Groups,dc=clarku,dc=edu
Jul 7 17:06:24 zoot slapd[2179]: nonpresent_callback: rid=001 present UUID
45843aa6-91b8-1033-81a9-ff6ec337b146, dn
cn=MSPC3090-01-F14,ou=Courses,ou=Groups,dc=clarku,dc=edu
Jul 7 17:06:24 zoot slapd[2179]: nonpresent_callback: rid=001 present UUID
4dd09f16-921b-1033-8d8e-f5dbd10b8ca0, dn
cn=msit3710-01-f14,ou=DL,ou=Groups,dc=clarku,dc=edu
Jul 7 17:06:24 zoot slapd[2179]: nonpresent_callback: rid=001 present UUID
0b3e8d76-9607-1033-81cf-ff6ec337b146, dn
cn=acct5411-01-f14,ou=DL,ou=Groups,dc=clarku,dc=edu
Jul 7 17:06:24 zoot slapd[2179]: nonpresent_callback: rid=001 present UUID
a698a278-9677-1033-81ee-ff6ec337b146, dn
cn=ESL0051-E1-F14,ou=Courses,ou=Groups,dc=clarku,dc=edu
Jul 7 17:06:24 zoot slapd[2179]: nonpresent_callback: rid=001 present UUID
ccf94c1c-979c-1033-8dc9-f5dbd10b8ca0, dn uid=dgunarajasingam,ou=Users,dc=clarku,dc=edu
Followed by another lock table / del_nonpresent:
Jul 7 17:06:24 zoot slapd[2179]: bdb(dc=clarku,dc=edu): Lock table is out of available
lock entries
Jul 7 17:06:24 zoot slapd[2179]: => bdb_idl_delete_key: c_del id failed: Cannot
allocate memory (12)
Jul 7 17:06:24 zoot slapd[2179]: null_callback : error code 0x50
Jul 7 17:06:24 zoot slapd[2179]: slap_graduate_commit_csn: removing 0x7f73e016cb40
20140707210614.062782Z#000000#001#000000
Jul 7 17:06:24 zoot slapd[2179]: syncrepl_del_nonpresent: rid=001 be_delete
cn=parents_ug_students,ou=Other,ou=Groups,dc=clarku,dc=edu (80)
Jul 7 17:06:24 zoot slapd[2179]: slap_queue_csn: queing 0x7f73e0f0eaa0
20140707210614.062782Z#000000#001#000000
Jul 7 17:06:24 zoot slapd[2179]: slap_graduate_commit_csn: removing 0x7f73e0f180c0
20140707210614.062782Z#000000#001#000000
That repeats itself @ 18:07, 18:47, 18:55. Then the train departs for crazy town...
notice this is the other node:
ul 7 18:55:59 animal slapd[10389]: nonpresent_callback: rid=002 nonpresent UUID
0e6fea9e-9279-1033-8d97-f5dbd10b8ca0, dn
cn=MSPC3070-01-F14,ou=Courses,ou=Groups,dc=clarku,dc=edu
Jul 7 18:55:59 animal slapd[10389]: nonpresent_callback: rid=002 nonpresent UUID
f710e364-958c-1033-8da2-f5dbd10b8ca0, dn
cn=MKT5900-01-F14,ou=Courses,ou=Groups,dc=clarku,dc=edu
Jul 7 18:55:59 animal slapd[10389]: nonpresent_callback: rid=002 nonpresent UUID
815ece60-965e-1033-8dab-f5dbd10b8ca0, dn
cn=ESL0067-M1-F14,ou=Courses,ou=Groups,dc=clarku,dc=edu
Jul 7 18:55:59 animal slapd[10389]: nonpresent_callback: rid=002 nonpresent UUID
f9d8a408-96cf-1033-8db0-f5dbd10b8ca0, dn
cn=eng2950-01-su14,ou=DL,ou=Groups,dc=clarku,dc=edu
Jul 7 18:55:59 animal slapd[10389]: nonpresent_callback: rid=002 nonpresent UUID
480d8cbc-96d3-1033-8dbf-f5dbd10b8ca0, dn
cn=esl0011-e1-f14,ou=DL,ou=Groups,dc=clarku,dc=edu
Jul 7 18:55:59 animal slapd[10389]: nonpresent_callback: rid=002 nonpresent UUID
ccf94c1c-979c-1033-8dc9-f5dbd10b8ca0, dn uid=dgunarajasingam,ou=Users,dc=clarku,dc=edu
Jul 7 18:55:59 animal slapd[10389]: slap_graduate_commit_csn: removing 0x7f59c8eddc00
20140707225554.051198Z#000000#002#000000
Jul 7 18:55:59 animal slapd[10389]: syncrepl_del_nonpresent: rid=002 be_delete
cn=MPA3950-03-SU14,ou=Courses,ou=Groups,dc=clarku,dc=edu (0)
Jul 7 18:55:59 animal slapd[10389]: syncprov_matchops: skipping original sid 002
Jul 7 18:55:59 animal slapd[10389]: syncrepl_del_nonpresent: rid=002 be_delete
cn=MSIT3950-0R-SU14,ou=Courses,ou=Groups,dc=clarku,dc=edu (0)
Jul 7 18:55:59 animal slapd[10389]: syncprov_matchops: skipping original sid 002
Jul 7 18:55:59 animal slapd[10389]: syncrepl_del_nonpresent: rid=002 be_delete
uid=zbamberger,ou=Users,dc=clarku,dc=edu (0)
Jul 7 18:55:59 animal slapd[10389]: syncprov_matchops: skipping original sid 002
Jul 7 18:55:59 animal slapd[10389]: syncrepl_del_nonpresent: rid=002 be_delete
uid=dgunarajasingam,ou=Users,dc=clarku,dc=edu (0)
Jul 7 18:55:59 animal slapd[10389]: syncprov_matchops: skipping original sid 002
Jul 7 18:55:59 animal slapd[10389]: syncrepl_del_nonpresent: rid=002 be_delete
uid=hmunawar,ou=Users,dc=clarku,dc=edu (0)
Jul 7 18:55:59 animal slapd[10389]: syncprov_matchops: skipping original sid 002
Jul 7 18:55:59 animal slapd[10389]: syncrepl_del_nonpresent: rid=002 be_delete
cn=scrn2940-01-su14,ou=DL,ou=Groups,dc=clarku,dc=edu (0)
Jul 7 18:55:59 animal slapd[10389]: syncprov_matchops: skipping original sid 002
Jul 7 18:55:59 animal slapd[10389]: syncrepl_del_nonpresent: rid=002 be_delete
cn=eng2940-02-su14,ou=DL,ou=Groups,dc=clarku,dc=edu (0)
Jul 7 18:55:59 animal slapd[10389]: syncprov_matchops: skipping original sid 002
Jul 7 18:55:59 animal slapd[10389]: syncrepl_del_nonpresent: rid=002 be_delete
cn=id2940-02-su14,ou=DL,ou=Groups,dc=clarku,dc=edu (0)
Jul 7 18:55:59 animal slapd[10389]: syncprov_matchops: skipping original sid 002
Jul 7 18:55:59 animal slapd[10389]: syncrepl_del_nonpresent: rid=002 be_delete
cn=msit3950-0p-su14,ou=DL,ou=Groups,dc=clarku,dc=edu (0)
Jul 7 18:55:59 animal slapd[10389]: syncprov_matchops: skipping original sid 002
Jul 7 18:55:59 animal slapd[10389]: syncrepl_del_nonpresent: rid=002 be_delete
cn=mspc3060-0p-su14,ou=DL,ou=Groups,dc=clarku,dc=edu (0)
That goes on, deleting things, until my pager exploded when some critical role accounts
got nuked and our radius servers died. I pulled an LDIF when I realized what was
happening and between 18:55 and 19:35, our LDIF went from 75MB to 45MB - so about 30MB of
stuff disappeared.
What happened? Did I get hit by an oddball BDB/Syncrepl behavior? Do I have a bad
misconfiguration in my replication setup?
Thanks for your time,
Aaron
----
Manager of Systems Administration
Clark University ITS
8:57 a.m.
On Tue, 8 Jul 2014, Aaron Bennett wrote:
Jul 7 04:19:30 zoot slapd[15011]: bdb(dc=clarku,dc=edu): Lock table
is out of available lock entries
Jul 7 04:19:30 zoot slapd[15011]: => bdb_idl_insert_key: c_get failed: Cannot
allocate memory (12)
[...]
That goes on, deleting things, until my pager exploded when some
critical role accounts got nuked and our radius servers died. I pulled
an LDIF when I realized what was happening and between 18:55 and 19:35,
our LDIF went from 75MB to 45MB ? so about 30MB of stuff disappeared.
What happened? Did I get hit by an oddball BDB/Syncrepl behavior? Do I
have a bad misconfiguration in my replication setup?
Usually what the syslogs say is right ... underconfigured re: number of
locks. Check your DB_CONFIG, per
http://www.openldap.org/faq/data/cache/893.html and the associated links.
I suppose there's a potential argument to be made for "I wish it died fast
instead of continued into a weird syncrepl state."
Other possibilities include a BDB bug, or perhaps you really were out of
memory (but I'd also expect core portions of slapd and possibly other
processes to be complaining in an OOM situation, which you didn't indicate
in your report).
#include obligatory lmdb plug here (no need to play around with this
stuff). This may help you justify the transition to management, if needed!
9:07 a.m.
Aaron Bennett wrote:
Hi,
I’ve got a two-node MMR setup using syncrepl running 2.4.36 with back-bdb.
Last night, between 1/3 and 1/2 of the entries in our directory disappeared.
Fortunately I have olcLogLeve=sync set, so I think I have a line on what happened…
I see this at 4AM long of the morning before the fun started:
Jul 7 04:19:30 zoot slapd[15011]: bdb(dc=clarku,dc=edu): Lock table is out of
available lock entries
Jul 7 04:19:30 zoot slapd[15011]: => bdb_idl_insert_key: c_get failed: Cannot
allocate memory (12)
What happened? Did I get hit by an oddball BDB/Syncrepl behavior?
Do I have
a bad misconfiguration in my replication setup?
You have a bad misconfig in your BDB, you need to configure a larger lock table.
and the syncrepl code probably needs to be fixed to quit if the backend
returns an LDAP_OTHER error code like this. Please submit an ITS for this.
Thanks for your time,
Aaron
----
Manager of Systems Administration
Clark University ITS
--
-- Howard Chu
CTO, Symas Corp. http://www.symas.com
Director, Highland Sun http://highlandsun.com/hyc/
Chief Architect, OpenLDAP http://www.openldap.org/project/
6:16 a.m.
-----Original Message-----
From: Howard Chu [mailto:hyc@symas.com]
Sent: Tuesday, July 8, 2014 12:08 PM
To: Aaron Bennett; openldap-technical(a)openldap.org
Subject: Re: syncrepl_del_nonpresent leading to directory implosion
You have a bad misconfig in your BDB, you need to configure a larger
lock table.
and the syncrepl code probably needs to be fixed to quit if the
backend returns an LDAP_OTHER error code like this. Please submit an ITS for this.
Thank you -- I will submit an ITS once the dust has cleared.
I adjusted our lock table significantly upwards. However, since then, I'm seeing
extreme replication delays in just one direction. I'm not sure if there's an
issue with BDB or if I did something else wrong. Here's the chain of events:
Two boxes are called animal and zoot.
1. DB_CONFIG looks like this on both boxes:
set_cachesize 0 524288000 1
set_lg_regionmax 262144
set_lg_bsize 2097152
set_flags DB_LOG_AUTOREMOVE
set_lk_max_lockers 9000
set_lk_max_locks 9000
set_lk_max_objects 9000
set_lk_partitions 900
2. To make sure I got a clean database, during a maintenance window I stopped slapd on
both machines, deleted /var/lib/ldap/* , and reloaded an ldif on animal with this command:
sudo -u ldap /usr/local/sbin/slapadd -S 1 -w -l /tmp/animal-now.ldif
3. Then I started slapd and watched zoot had pulled the replica over. Everything seemed
kosher -- replication from animal -> zoot is nearly instant as expected, but zoot ->
animal is very slow -- like, 15-30 second and often longer then 60, for one very trivial
change.
Any ideas what's wrong? If you'd like I can send syncrepl logs or db_stat output.
Thanks for your time,
Aaron Bennett
----
Manager of Systems Administration
Clark University ITS
3181
days inactive
3183
days old
openldap-technical@openldap.org
3 comments
3 participants
participants (3)
-
Aaron Bennett -
Aaron Richton -
Howard Chu