[Date Prev][Date Next] [Chronological] [Thread] [Top]
Re: ITS #4365 revisited

To: openldap-devel@OpenLDAP.org, Howard Chu <hyc@symas.com>
Subject: Re: ITS #4365 revisited
From: Aaron Richton <richton@nbcs.rutgers.edu>
Date: Wed, 15 Feb 2006 10:52:07 -0500 (EST)
In-reply-to: <43EA4D3B.2020209@symas.com>
References: <Pine.SOL.4.58.0602081304340.956@toolbox.rutgers.edu> <43EA4D3B.2020209@symas.com>
On suggestion from Howard, I've added Debug() from HEAD into 2.3.19.

The new syncrepl_del_nonpresent are tripping. With the DNs of possible
victims clearly being printed in the logs, it's becoming easier to
spot/correlate these users. In the first event, there were MODs to AAA and
BBB. BBB got deleted; AAA be_modify() correctly.

I found it curious that the second op (BBB) was deleted while AAA was
unchanged, so I modified (in one op) XXX and YYY in that order. (Somebody
else added ZZZ, and that also made it into that sync.) XXX modified
correctly, ZZZ added correctly, YYY got deleted.

To make sure that the first case works properly, I modified QQQ alone and
waited for sync. QQQ got modified as I would expect.

The last thing I tried was to modify III and JJJ in two different
connections. They both made it into the same sync set, one of them tripped
the new Debug(), but apparently everything worked properly.

So I'm seeing this new syncrepl_del_nonpresent trip on various
modifications, and I'm seeing trouble on modifications that aren't the
first one in a given connection. What next?





These logs all represent cases where entries got deleted from the slaves.

Feb 15 00:18:06 master.rutgers.edu slapd[7611]: [ID 249368 local4.debug]
conn=26201 op=2 MOD dn="uid=AAA,ou=People,dc=rci,dc=rutgers,dc=edu"
Feb 15 00:18:07 master.rutgers.edu slapd[7611]: [ID 588225 local4.debug]
conn=26201 op=2 RESULT tag=103 err=0 text=
Feb 15 00:18:07 master.rutgers.edu slapd[7611]: [ID 249368 local4.debug]
conn=26201 op=3 MOD dn="uid=BBB,ou=People,dc=rci,dc=rutgers,dc=edu"
Feb 15 00:18:07 master.rutgers.edu slapd[7611]: [ID 588225 local4.debug]
conn=26201 op=3 RESULT tag=103 err=0 text=
Feb 15 00:18:07 master.rutgers.edu slapd[7611]: [ID 218904 local4.debug]
conn=26201 op=4 UNBIND

Feb 15 00:19:12 slave2.rutgers.edu slapd[7662]: [ID 151447 local4.debug]
syncrepl_del_nonpresent: be_delete
uid=BBB,ou=People,dc=rci,dc=rutgers,dc=edu (0)
Feb 15 00:19:12 slave2.rutgers.edu slapd[7662]: [ID 801593 local4.debug]
syncrepl_entry: LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_ADD)
Feb 15 00:19:12 slave2.rutgers.edu slapd[7662]: [ID 181434 local4.debug]
syncrepl_entry: be_search (0)
Feb 15 00:19:12 slave2.rutgers.edu slapd[7662]: [ID 260518 local4.debug]
syncrepl_entry: uid=AAA,ou=People,dc=rci,dc=rutgers,dc=edu
Feb 15 00:19:12 slave2.rutgers.edu slapd[7662]: [ID 181434 local4.debug]
syncrepl_entry: be_modify (0)
Feb 15 00:19:12 slave2.rutgers.edu slapd[7662]: [ID 801593 local4.debug]
syncrepl_entry: LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_ADD)
Feb 15 00:19:12 slave2.rutgers.edu slapd[7662]: [ID 181434 local4.debug]
syncrepl_entry: be_search (0)
Feb 15 00:19:12 slave2.rutgers.edu slapd[7662]: [ID 260518 local4.debug]
syncrepl_entry: uid=BBB,ou=People,dc=rci,dc=rutgers,dc=edu

Feb 15 08:34:18 slave2.rutgers.edu slapd[7662]: [ID 496601 local4.debug]
do_syncrep2: LDAP_RES_SEARCH_RESULT
Feb 15 08:34:18 slave2.rutgers.edu slapd[7662]: [ID 968320 local4.debug]
do_syncrep2: LDAP_RES_INTERMEDIATE - SYNC_ID_SET
Feb 15 08:34:18 slave2.rutgers.edu slapd[7662]: [ID 496601 local4.debug]
do_syncrep2: LDAP_RES_SEARCH_RESULT
Feb 15 08:34:18 slave2.rutgers.edu slapd[7662]: [ID 151447 local4.debug]
syncrepl_del_nonpresent: be_delete
uid=BBB,ou=People,dc=rci,dc=rutgers,dc=edu (0)
Feb 15 08:34:18 slave2.rutgers.edu slapd[7662]: [ID 801593 local4.debug]
syncrepl_entry: LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_ADD)
Feb 15 08:34:18 slave2.rutgers.edu slapd[7662]: [ID 181434 local4.debug]
syncrepl_entry: be_search (0)
Feb 15 08:34:18 slave2.rutgers.edu slapd[7662]: [ID 260518 local4.debug]
syncrepl_entry: uid=sabolcsi,ou=People,dc=rci,dc=rutgers,dc=edu
Feb 15 08:34:18 slave2.rutgers.edu slapd[7662]: [ID 181434 local4.debug]
syncrepl_entry: be_add (0)
Feb 15 08:34:18 slave2.rutgers.edu slapd[7662]: [ID 496601 local4.debug]
do_syncrep2: LDAP_RES_SEARCH_RESULT

Feb 15 09:48:08 master.rutgers.edu slapd[7611]: [ID 249368 local4.debug]
conn=45508 op=2 MOD dn="uid=XXX,ou=People,dc=rci,dc=rutgers,dc=edu"
Feb 15 09:48:08 master.rutgers.edu slapd[7611]: [ID 588225 local4.debug]
conn=45508 op=2 RESULT tag=103 err=0 text=
Feb 15 09:48:08 master.rutgers.edu slapd[7611]: [ID 249368 local4.debug]
conn=45508 op=3 MOD dn="uid=YYY,ou=People,dc=rci,dc=rutgers,dc=edu"
Feb 15 09:48:08 master.rutgers.edu slapd[7611]: [ID 588225 local4.debug]
conn=45508 op=3 RESULT tag=103 err=0 text=
Feb 15 09:48:08 master.rutgers.edu slapd[7611]: [ID 585459 local4.debug]
conn=45511 op=2 ADD dn="uid=ZZZ,ou=People,dc=rci,dc=rutgers,dc=edu"
Feb 15 09:48:08 master.rutgers.edu slapd[7611]: [ID 588225 local4.debug]
conn=45511 op=2 RESULT tag=105 err=0 text=

Feb 15 09:49:20 slave2.rutgers.edu slapd[7662]: [ID 151447 local4.debug]
syncrepl_del_nonpresent: be_delete
uid=YYY,ou=People,dc=rci,dc=rutgers,dc=edu (0)
Feb 15 09:49:20 slave2.rutgers.edu slapd[7662]: [ID 801593 local4.debug]
syncrepl_entry: LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_ADD)
Feb 15 09:49:20 slave2.rutgers.edu slapd[7662]: [ID 181434 local4.debug]
syncrepl_entry: be_search (0)
Feb 15 09:49:20 slave2.rutgers.edu slapd[7662]: [ID 260518 local4.debug]
syncrepl_entry: uid=XXX,ou=People,dc=rci,dc=rutgers,dc=edu
Feb 15 09:49:20 slave2.rutgers.edu slapd[7662]: [ID 181434 local4.debug]
syncrepl_entry: be_modify (0)
Feb 15 09:49:20 slave2.rutgers.edu slapd[7662]: [ID 801593 local4.debug]
syncrepl_entry: LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_ADD)
Feb 15 09:49:20 slave2.rutgers.edu slapd[7662]: [ID 181434 local4.debug]
syncrepl_entry: be_search (0)
Feb 15 09:49:20 slave2.rutgers.edu slapd[7662]: [ID 260518 local4.debug]
syncrepl_entry: uid=YYY,ou=People,dc=rci,dc=rutgers,dc=edu
Feb 15 09:49:20 slave2.rutgers.edu slapd[7662]: [ID 181434 local4.debug]
syncrepl_entry: be_add (0)
Feb 15 09:49:20 slave2.rutgers.edu slapd[7662]: [ID 801593 local4.debug]
syncrepl_entry: LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_ADD)
Feb 15 09:49:20 slave2.rutgers.edu slapd[7662]: [ID 181434 local4.debug]
syncrepl_entry: be_search (0)
Feb 15 09:49:20 slave2.rutgers.edu slapd[7662]: [ID 260518 local4.debug]
syncrepl_entry: uid=ZZZ,ou=People,dc=rci,dc=rutgers,dc=edu
Feb 15 09:49:20 slave2.rutgers.edu slapd[7662]: [ID 181434 local4.debug]
syncrepl_entry: be_add (0)
Feb 15 09:49:20 slave2.rutgers.edu slapd[7662]: [ID 496601 local4.debug]
do_syncrep2: LDAP_RES_SEARCH_RESULT


Everything worked OK in this set.


Feb 15 10:10:01 master.rutgers.edu slapd[7611]: [ID 249368 local4.debug]
conn=46264 op=2 MOD dn="uid=QQQ,ou=People,dc=rci,dc=rutgers,dc=edu"
Feb 15 10:10:01 master.rutgers.edu slapd[7611]: [ID 588225 local4.debug]
conn=46264 op=2 RESULT tag=103 err=0 text=

Feb 15 10:10:31 master.rutgers.edu slapd[7611]: [ID 469902 local4.debug]
conn=46293 op=2 SRCH base="dc=rci,dc=rutgers,dc=edu" scope=2 deref=0
filter="(objectClass=*)"
Feb 15 10:10:31 master.rutgers.edu slapd[7611]: [ID 744844 local4.debug]
conn=46293 op=2 SRCH attr=* +
Feb 15 10:10:31 master.rutgers.edu slapd[7611]: [ID 167594 local4.debug]
conn=46293 op=2 SEARCH RESULT tag=101 err=0 nentries=1 text=
Feb 15 10:10:31 slave1.rutgers.edu slapd[19741]: [ID 496601 local4.debug]
do_syncrep2: LDAP_RES_SEARCH_RESULT
Feb 15 10:10:31 slave1.rutgers.edu last message repeated 1 time
Feb 15 10:10:31 slave1.rutgers.edu slapd[19741]: [ID 801593 local4.debug]
syncrepl_entry: LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_ADD)
Feb 15 10:10:31 slave1.rutgers.edu slapd[19741]: [ID 181434 local4.debug]
syncrepl_entry: be_search (0)
Feb 15 10:10:31 slave1.rutgers.edu slapd[19741]: [ID 260518 local4.debug]
syncrepl_entry: uid=QQQ,ou=People,dc=rci,dc=rutgers,dc=edu
Feb 15 10:10:31 slave1.rutgers.edu slapd[19741]: [ID 181434 local4.debug]
syncrepl_entry: be_modify (0)
Feb 15 10:10:31 slave1.rutgers.edu slapd[19741]: [ID 496601 local4.debug]
do_syncrep2: LDAP_RES_SEARCH_RESULT
Feb 15 10:10:31 master.rutgers.edu slapd[7611]: [ID 218904 local4.debug]
conn=46293 op=3 UNBIND
Feb 15 10:10:31 master.rutgers.edu slapd[7611]: [ID 952275 local4.debug]
conn=46293 fd=102 closed




And notice this one having two different CONNs on the master MODs.  Both
of these entries are still present in the slaves.

Feb 15 10:32:49 master.rutgers.edu slapd[7611]: [ID 249368 local4.debug]
conn=47064 op=2 MOD
dn="uid=JJJ,ou=People,dc=rci,dc=rutgers,dc=edu"
Feb 15 10:33:23 master.rutgers.edu slapd[7611]: [ID 249368 local4.debug]
conn=47097 op=2 MOD
dn="uid=III,ou=People,dc=rci,dc=rutgers,dc=edu"

Feb 15 10:34:20 slave2.rutgers.edu slapd[7662]: [ID 496601 local4.debug]
do_syncrep2: LDAP_RES_SEARCH_RESULT
Feb 15 10:34:20 slave2.rutgers.edu slapd[7662]: [ID 968320 local4.debug]
do_syncrep2: LDAP_RES_INTERMEDIATE - SYNC_ID_SET
Feb 15 10:34:20 slave2.rutgers.edu slapd[7662]: [ID 496601 local4.debug]
do_syncrep2: LDAP_RES_SEARCH_RESULT
Feb 15 10:34:20 slave2.rutgers.edu slapd[7662]: [ID 151447 local4.debug]
syncrepl_del_nonpresent: be_delete
uid=III,ou=People,dc=rci,dc=rutgers,dc=edu (0)
Feb 15 10:34:20 slave2.rutgers.edu slapd[7662]: [ID 801593 local4.debug]
syncrepl_entry:
LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_ADD)
Feb 15 10:34:20 slave2.rutgers.edu slapd[7662]: [ID 181434 local4.debug]
syncrepl_entry: be_search (0)
Feb 15 10:34:20 slave2.rutgers.edu slapd[7662]: [ID 260518 local4.debug]
syncrepl_entry:
uid=JJJ,ou=People,dc=rci,dc=rutgers,dc=edu
Feb 15 10:34:20 slave2.rutgers.edu slapd[7662]: [ID 181434 local4.debug]
syncrepl_entry: be_modify (0)
Feb 15 10:34:20 slave2.rutgers.edu slapd[7662]: [ID 801593 local4.debug]
syncrepl_entry:
LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_ADD)
Feb 15 10:34:20 slave2.rutgers.edu slapd[7662]: [ID 181434 local4.debug]
syncrepl_entry: be_search (0)
Feb 15 10:34:20 slave2.rutgers.edu slapd[7662]: [ID 260518 local4.debug]
syncrepl_entry:
uid=III,ou=People,dc=rci,dc=rutgers,dc=edu
Feb 15 10:34:20 slave2.rutgers.edu slapd[7662]: [ID 181434 local4.debug]
syncrepl_entry: be_add (0)
Feb 15 10:34:20 slave2.rutgers.edu slapd[7662]: [ID 496601 local4.debug]
do_syncrep2: LDAP_RES_SEARCH_RESULT



On Wed, 8 Feb 2006, Howard Chu wrote:

> Since we have no idea what's causing this behavior you're seeing,
> there's no way to state whether any recent changes have any bearing on
> it. But I'd say it's unlikely that any recent changes will have affected
> it at all.
Follow-Ups:
- Re: ITS #4365 revisited
  - From: Aaron Richton <richton@nbcs.rutgers.edu>
References:
- ITS #4365 revisited
  - From: Aaron Richton <richton@nbcs.rutgers.edu>
- Re: ITS #4365 revisited
  - From: Howard Chu <hyc@symas.com>
Prev by Date: Re: commit: ldap/clients/tools ldapexop.c
Next by Date: Advertising configcontext in Root-DSE
Index(es):
- Chronological
- Thread