[Date Prev][Date Next]
[Chronological]
[Thread]
[Top]
syncrepl'd MOD deleted entry
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