[Date Prev][Date Next] [Chronological] [Thread] [Top]
Re: syncrepl'd MOD deleted entry

To: Howard Chu <hyc@symas.com>
Subject: Re: syncrepl'd MOD deleted entry
From: Aaron Richton <richton@nbcs.rutgers.edu>
Date: Sun, 22 Jan 2006 16:57:44 -0500 (EST)
Cc: openldap-devel@OpenLDAP.org
In-reply-to: <43D3DCAE.8040806@symas.com>
References: <Pine.SOL.4.58.0601220915280.956@toolbox.rutgers.edu> <43D3DCAE.8040806@symas.com>
Hmm. Well, I triggered off another modification, which went through as
hdb_modify. Then I modified four DNs in one connection, which went
through as an add/delete. As of yet they haven't "disappeared" -- maybe
they will with time?

entryUUID on both the master and slave, both before and after, all appear
to be the same on a spot check of one DN.

On Sun, 22 Jan 2006, Howard Chu wrote:

> This may indicate some other problem in back-hdb.
>
> The log at 16:48:51 shows the mod turning into a be_add() which
> succeeds, returning 0. But if the entry was already present in the DB,
> that should have returned LDAP_ALREADY_EXISTS and subsequently been
> retried as a be_modify. A key factor here would be to display the
> entryUUID of the suspect entry at each point in time to see if it's
> always the same (it should be) and matches the entryUUID on the provider.
>
> Aaron Richton wrote:
> > Well, I can remove the "(?)" from the last time I posted this, because now
> > I've got a trace showing a couple hdb_delete.
> >
> > I'm still seeing the issue described in
> > http://www.openldap.org/lists/openldap-software/200512/msg00180.html in
> > 2.3.18. To try and get somewhere towards figuring out why this is
> > happening, I put up a slave but have disallowed all "public" clients. All
> > typo'd search operations are entirely my own.
> >
> > Consider the following syslogs, combined with some of the more interesting
> > trace logs. I'll give out the full trace log upon request (don't want to
> > spam everybody, because it's three days worth of trace). Unfortunately,
> > this did NOT happen immediately (note the time between nentries=1 and
> > nentires=0 search results); I'd given up on repro based on the 16:51:05
> > search result before I decided to try on a whim.
> >
> > I'm also not sure about the two different keys -- I thought MODs
> > actually were MODs nowadays in syncrepl? Yet every MOD in this environment
> > seems to go through a hdb_delete. Only this lucky entry hit it twice:
> > hdb_delete: deleted id=00003281 dn="cn=announce,ou=Group,dc=rci,dc=rutgers,dc=edu"
> > hdb_delete: deleted id=00003a74 dn="cn=announce,ou=Group,dc=rci,dc=rutgers,dc=edu"
> >
> > although that might be a herring, I just searched for one of the items
> > that got MOD's and then hdb_delete once (i.e. not twice) and it's not
> > there either.
> >
> >
> > /* prove it was there */
> > Jan 20 16:33:49 slave5.rutgers.edu slapd[16242]: [ID 469902 local4.debug]
> > conn=0 op=1 SRCH base="ou=Group,dc=rci,dc=rutgers,dc=edu"
> >  scope=2 deref=0 filter="(cn=announce)"
> > Jan 20 16:33:49 slave5.rutgers.edu slapd[16242]: [ID 167594 local4.debug]
> > conn=0 op=1 SEARCH RESULT tag=101 err=0 nentries=1 text=
> >
> > /* the mod arrives */
> > Jan 20 16:48:51 slave5.rutgers.edu slapd[16242]: [ID 260518 local4.debug]
> > syncrepl_entry: cn=announce,ou=Group,dc=rci,dc=rutgers,dc=edu
> > Jan 20 16:48:51 slave5.rutgers.edu slapd[16242]: [ID 181434 local4.debug]
> > syncrepl_entry: be_add (0)
> >
> > /* I search to see if it's gone -- it's there correctly! */
> > Jan 20 16:51:05 slave5.rutgers.edu slapd[16242]: [ID 469902 local4.debug]
> > conn=1 op=1 SRCH base="ou=Group,dc=rci,dc=rutgers,dc=edu"
> >  scope=2 deref=0 filter="(cn=announce)"
> > Jan 20 16:51:05 slave5.rutgers.edu slapd[16242]: [ID 167594 local4.debug]
> > conn=1 op=1 SEARCH RESULT tag=101 err=0 nentries=1 text=
> >
> > /* later, with no further syncrepl action on that entry, it's gone */
> > Jan 22 08:52:50 slave5.rutgers.edu slapd[16242]: [ID 469902 local4.debug]
> > conn=9 op=1 SRCH base="ou=Group,dc=rci,dc=rutgers,dc=edu"
> >  scope=2 deref=0 filter="(cn=announce)"
> > Jan 22 08:52:50 slave5.rutgers.edu slapd[16242]: [ID 167594 local4.debug]
> > conn=9 op=1 SEARCH RESULT tag=101 err=0 nentries=0 text=
> >
> >
> > => send_search_entry: conn 0 dn="cn=announce,ou=Group,dc=rci,dc=rutgers,dc=edu"
> > ber_flush: 279 bytes to sd 33
> > <= send_search_entry: conn 0 exit.
> > send_ldap_result: conn=0 op=1 p=3
> > send_ldap_result: conn=0 op=1 p=3
> > send_ldap_response: msgid=2 tag=101 err=0
> > [...]
> > bdb_dn2entry("cn=announce,ou=group,dc=rci,dc=rutgers,dc=edu")
> > => index_entry_del( 12929, "cn=announce,ou=Group,dc=rci,dc=rutgers,dc=edu" )
> > => key_change(DELETE,3281)
> > <= key_change 0
> > [...]
> > => key_change(DELETE,3281)
> > <= key_change 0
> > <= index_entry_del( 12929, "cn=announce,ou=Group,dc=rci,dc=rutgers,dc=edu" ) success
> > ====> bdb_cache_delete( 12929 )
> > [...]
> > hdb_delete: deleted id=00003281 dn="cn=announce,ou=Group,dc=rci,dc=rutgers,dc=edu"
> > [...]
> >
> >>>> dnPrettyNormal: <cn=announce,ou=Group,dc=rci,dc=rutgers,dc=edu>
> >>>>
> > <<< dnPrettyNormal: <cn=announce,ou=Group,dc=rci,dc=rutgers,dc=edu>,
> > <cn=announce,ou=group,dc=rci,dc=rutgers,dc=edu>
> > [...]
> > oc_check_required entry (cn=announce,ou=Group,dc=rci,dc=rutgers,dc=edu),
> > objectClass "posixGroup"
> > [...]
> > bdb_dn2entry("cn=announce,ou=group,dc=rci,dc=rutgers,dc=edu")
> > => index_entry_add( 14964, "cn=announce,ou=Group,dc=rci,dc=rutgers,dc=edu" )
> > => key_change(ADD,3a74)
> > <= key_change 0
> > => key_change(ADD,3a74)
> > <= key_change 0
> > [...]
> > <= index_entry_add( 14964, "cn=announce,ou=Group,dc=rci,dc=rutgers,dc=edu" ) success
> > => entry_encode(0x00003a74):
> > hdb_add: added id=00003a74
> > dn="cn=announce,ou=Group,dc=rci,dc=rutgers,dc=edu"
> > send_ldap_result: conn=-1 op=0 p=3
> > [...]
> > => send_search_entry: conn 1
> > dn="cn=announce,ou=Group,dc=rci,dc=rutgers,dc=edu"
> > [...]
> > <= bdb_index_read 1 candidates
> > <= bdb_equality_candidates: id=1, first=14964, last=14964
> > bdb_search_candidates: id=1 first=14964 last=14964
> > send_ldap_result: conn=-1 op=0 p=3
> > bdb_dn2entry("cn=announce,ou=group,dc=rci,dc=rutgers,dc=edu")
> > [...]
> > => index_entry_del( 14964, "cn=announce,ou=Group,dc=rci,dc=rutgers,dc=edu" )
> > => key_change(DELETE,3a74)
> > <= key_change 0
> > => key_change(DELETE,3a74)
> > <= key_change 0
> > [...]
> > <= index_entry_del( 14964, "cn=announce,ou=Group,dc=rci,dc=rutgers,dc=edu" ) success
> > ====> bdb_cache_delete( 14964 )
> > hdb_delete: deleted id=00003a74 dn="cn=announce,ou=Group,dc=rci,dc=rutgers,dc=edu"
> > [...]
> > => hdb_search
> > bdb_dn2entry("ou=group,dc=rci,dc=rutgers,dc=edu")
> > search_candidates: base="ou=group,dc=rci,dc=rutgers,dc=edu" (0x00000006)
> > scope=2
> > => hdb_dn2idl("ou=group,dc=rci,dc=rutgers,dc=edu")
> > => bdb_equality_candidates (objectClass)
> > => key_read
> > <= bdb_index_read: failed (-30990)
> > <= bdb_equality_candidates: id=0, first=0, last=0
> > => bdb_equality_candidates (cn)
> > => key_read
> > <= bdb_index_read 1 candidates
> > <= bdb_equality_candidates: id=1, first=570, last=570
> > bdb_search_candidates: id=1 first=570 last=570
> > hdb_search: 570 scope not okay
> >
> >
> >
> >
>
>
> --
>   -- Howard Chu
>   Chief Architect, Symas Corp.  http://www.symas.com
>   Director, Highland Sun        http://highlandsun.com/hyc
>   OpenLDAP Core Team            http://www.openldap.org/project/
>
>
References:
- syncrepl'd MOD deleted entry
  - From: Aaron Richton <richton@nbcs.rutgers.edu>
- Re: syncrepl'd MOD deleted entry
  - From: Howard Chu <hyc@symas.com>
Prev by Date: Re: syncrepl'd MOD deleted entry
Next by Date: Re: 2.3.18 not stable on Solaris
Index(es):
- Chronological
- Thread