debugging syncrepl issue

[Guillaume Rousse <Guillaume.Rousse@inria.fr>]

Hello list.

I'm facing a syncrepl issue really strange. Sofar, everytime I had sync 
issue, I just had to stop the consumer, delete its database, and restart 
it again to make it work. However, this time it seems unsufficient, and 
synchronisation hangs on some entries.

In the consumer logs, with loglevel set to sync, starting with an empty 
base, I get lots of successfully synced entries:
Oct  7 17:55:25 nation slapd[30453]: syncrepl_entry: rid=123 be_search (0)
Oct  7 17:55:25 nation slapd[30453]: syncrepl_entry: rid=123 
uid=test,ou=users,dc=msr-inria,dc=inria,dc=fr
Oct  7 17:55:25 nation slapd[30453]: syncrepl_entry: rid=123 be_add (0)
Oct  7 17:55:25 nation slapd[30453]: syncrepl_entry: rid=123 
LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_ADD)
Oct  7 17:55:25 nation slapd[30453]: syncrepl_entry: rid=123 inserted 
UUID 86a10a62-ddf2-102c-9dfe-558a8530d5ee

Then I get a warning for some strange entry:
Oct  7 17:55:25 nation slapd[30453]: syncrepl_entry: rid=123 be_search (0)
Oct  7 17:55:25 nation slapd[30453]: syncrepl_entry: rid=123 
ou=kerberos,dc=msr-inria,dc=inria,dc=fr
Oct  7 17:55:25 nation slapd[30453]: syncrepl_entry: rid=123 be_add (68)
Oct  7 17:55:25 nation slapd[30453]: dn_callback : new entry is older 
than ours ou=kerberos,dc=msr-inria,dc=inria,dc=fr ours 
20080704085717.749336Z#000000#000#000000, new 
20080704085416.079377Z#000000#000#000000
Oct  7 17:55:25 nation slapd[30453]: syncrepl_entry: rid=123 entry 
unchanged, ignored (ou=kerberos,dc=msr-inria,dc=inria,dc=fr)
Oct  7 17:55:25 nation slapd[30453]: syncrepl_entry: rid=123 
LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_ADD)
Oct  7 17:55:25 nation slapd[30453]: syncrepl_entry: rid=123 inserted 
UUID 504ed75a-e374-102c-8faa-7b1baeea81b3

then additional successfully synced entries:
Oct  7 17:55:25 nation slapd[30453]: syncrepl_entry: rid=123 be_search (0)
Oct  7 17:55:25 nation slapd[30453]: syncrepl_entry: rid=123 
uid=jabbour,ou=users,dc=msr-inria,dc=inria,dc=fr
Oct  7 17:55:26 nation slapd[30453]: syncrepl_entry: rid=123 be_add (0)
Oct  7 17:55:26 nation slapd[30453]: syncrepl_entry: rid=123 
LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_ADD)
Oct  7 17:55:26 nation slapd[30453]: syncrepl_entry: rid=123 inserted 
UUID f516b45c-e38c-102c-8953-f71742eb083b

And then something fails:
Oct  7 17:55:26 nation slapd[30453]: do_syncrep2: rid=123 
LDAP_RES_SEARCH_RESULT
Oct  7 17:55:26 nation slapd[30453]: do_syncrep2: 
cookie=rid=123,csn=20081003163733.899132Z#000000#000#000000
Oct  7 17:55:26 nation slapd[30453]: slap_queue_csn: queing 0x846f858 
20081003163733.899132Z#000000#000#000000
Oct  7 17:55:26 nation slapd[30453]: slap_graduate_commit_csn: removing 
0x8471120 20081003163733.899132Z#000000#000#000000
Oct  7 17:55:26 nation slapd[30453]: do_syncrep2: 
cookie=rid=123,csn=20081006083018.748988Z#000000#000#000000
Oct  7 17:55:26 nation slapd[30453]: slap_queue_csn: queing 0x8386340 
20081006083018.748988Z#000000#000#000000
Oct  7 17:55:26 nation slapd[30453]: slap_graduate_commit_csn: removing 
0x841ad98 20081006083018.748988Z#000000#000#000000
Oct  7 17:55:26 nation slapd[30453]: syncrepl_message_to_op: rid=123 
be_modify uid=rousse,ou=users,dc=msr-inria,dc=inria,dc=fr (0)

I'm unable to understand what's going wrong there.

On provider's side, all I have is the warning for the entry with an 
apparent wrong timestamp:
Oct  7 17:55:22 etoile slapd[32640]: syncprov_search_response: 
cookie=rid=123,csn=20081003163733.899132Z#000000#000#000000
Oct  7 17:55:26 etoile slapd[32640]: Entry 
reqStart=20081003163733.000015Z,cn=log CSN 
20081003163733.899132Z#000000#000#000000 older or equal to ctx 
20081003163733.899132Z#000000#000#000000
Oct  7 17:55:26 etoile slapd[32640]: syncprov_search_response: 
cookie=rid=123,csn=20081007080656.987198Z#000000#000#000000

I checked access permissions and limits for syncrepl user on provider 
side, everything is OK. I'm using OpenLDAP 2.4.11 on both sides. And 
here is my syncrepl configuration:
syncrepl rid=123
    provider=ldaps://ldap1.msr-inria.inria.fr
    type=refreshAndPersist
    retry="60 +"
    logbase="cn=log"
    logfilter="(&(objectClass=auditWriteObject)(reqResult=0))"
    syncdata=accesslog
    searchbase="dc=msr-inria,dc=inria,dc=fr"
    scope=sub
    schemachecking=off
    bindmethod=simple
    binddn="cn=syncrepl,ou=roles,dc=msr-inria,dc=inria,dc=fr"
    credentials=XXXXX

Any hint welcome.
--
Guillaume Rousse
Moyens Informatiques - INRIA Futurs
Tel: 01 69 35 69 62