(ITS#6346) syncrepl problems with 2.4.19 - openldap-bugs

22 Oct 2009


      Full_Name: Christoph Herrmann
Version: 2.4.19
OS: SLES11
URL: ftp://ftp.openldap.org/incoming/
Submission from: (NULL) (193.17.244.2)
we did some stress tests to an openldap-2.4.19 test infrastructure.
we are running the tests in a single master environment with 5 slave servers,
all with openldap-2.4.19. All machines are running ntpd and are in sync:
ntpq -p:
server                            remote           refid      st t when poll
reach   delay   offset  jitter
===========================================================================================================
ldapma01                     *172.26.248.222  172.26.228.131   6 u    2   16 
377    0.291   -0.812   0.027
ldapsl01                     *172.26.248.222  172.26.228.131   6 u   10   64 
377    0.272   -4.486   0.024
ldapsl02                     *172.26.248.222  172.26.228.131   6 u    2   32 
377    0.244   -1.424   0.006
ldapsl03                     *172.26.248.222  172.26.228.131   6 u   15   32 
377    0.195   -3.411   0.056
ldapsl04                     *172.26.248.222  172.26.228.131   6 u    2   16 
377    0.258   -0.039   0.017
ldapsl05                     *172.26.248.222  172.26.228.131   6 u    4   32 
377    0.260   -0.040   0.027
this is our syncrepl config:
master/provider:
overlay syncprov
    syncprov-checkpoint 100 10
    syncprov-sessionlog 100
slave/consumer:
syncrepl rid=467
        provider=ldap://ldapma01:389
        type=refreshAndPersist
        retry=2,30,15,40,60,+
        searchbase="o=example,c=de"
        filter="(objectClass=*)"
        scope=sub
        schemachecking=on
        bindmethod=simple
        binddn="cn=replica,ou=replica,o=example,c=de"
        credentials="replica"
updateref ldap://ldapma01:389
During the tests we always run in to problems with syncrepl. We are doing tests
in the way:
bind; add|modify|delete; unbind; wait for n ms; bind .... (10 =< n =< 100)
depending on the time between the requests, about 1% of our write requests will
not be
synchronized to any off the slaves. It seems, that the master send the
syncreplrequests out of sync,
and all slaves reject syncing with the message: CSN too old, ignoring ...
attached you will find one add example and one delete example. (the logs on all
slaves are
identical)
ADD:
master.log:
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2121 fd=15 ACCEPT from
IP=172.26.248.57:50294 (IP=0.0.0.0:389)
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2121 op=0 BIND
dn="uid=ladmin,ou=verwaltung,o=example,c=de" method=128
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2121 op=0 BIND
dn="uid=ladmin,ou=Verwaltung,o=example,c=de" mech=SIMPLE ssf=0
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2121 op=0 RESULT tag=97 err=0 text=
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2121 op=1 ADD
dn="cn=15,ou=slamdtest,o=example,c=de"
Oct 20 09:47:18 ldapma01 slapd[8354]: slap_queue_csn: queing 0x9fdf298a
20091020074718.210361Z#000000#000#000000
Oct 20 09:47:18 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=332,csn=20091020074718.210361Z#000000#000#000000
Oct 20 09:47:18 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=330,csn=20091020074718.210361Z#000000#000#000000
Oct 20 09:47:18 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=467,csn=20091020074718.210361Z#000000#000#000000
Oct 20 09:47:18 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=442,csn=20091020074718.210361Z#000000#000#000000
Oct 20 09:47:18 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=466,csn=20091020074718.210361Z#000000#000#000000
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2121 op=1 RESULT tag=105 err=0 text=
Oct 20 09:47:18 ldapma01 slapd[8354]: slap_graduate_commit_csn: removing
0x1218ee70 20091020074718.210361Z#000000#000#000000
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2121 op=2 UNBIND
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2121 fd=15 closed
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2122 fd=15 ACCEPT from
IP=172.26.248.57:50295 (IP=0.0.0.0:389)
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2122 op=0 BIND
dn="uid=ladmin,ou=verwaltung,o=example,c=de" method=128
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2122 op=0 BIND
dn="uid=ladmin,ou=Verwaltung,o=example,c=de" mech=SIMPLE ssf=0
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2122 op=0 RESULT tag=97 err=0 text=
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2123 fd=19 ACCEPT from
IP=172.26.248.57:50296 (IP=0.0.0.0:389)
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2122 op=1 ADD
dn="cn=16,ou=slamdtest,o=example,c=de"
Oct 20 09:47:18 ldapma01 slapd[8354]: slap_queue_csn: queing 0xa450b98a
20091020074718.707969Z#000000#000#000000
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2123 op=0 BIND
dn="uid=ladmin,ou=verwaltung,o=example,c=de" method=128
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2123 op=0 BIND
dn="uid=ladmin,ou=Verwaltung,o=example,c=de" mech=SIMPLE ssf=0
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2123 op=0 RESULT tag=97 err=0 text=
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2123 op=1 ADD
dn="cn=17,ou=slamdtest,o=example,c=de"
Oct 20 09:47:18 ldapma01 slapd[8354]: slap_queue_csn: queing 0x983f698a
20091020074718.719682Z#000000#000#000000
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2124 fd=20 ACCEPT from
IP=172.26.248.57:50297 (IP=0.0.0.0:389)
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2124 op=0 BIND
dn="uid=ladmin,ou=verwaltung,o=example,c=de" method=128
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2124 op=0 BIND
dn="uid=ladmin,ou=Verwaltung,o=example,c=de" mech=SIMPLE ssf=0
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2124 op=0 RESULT tag=97 err=0 text=
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2124 op=1 ADD
dn="cn=18,ou=slamdtest,o=example,c=de"
Oct 20 09:47:18 ldapma01 slapd[8354]: slap_queue_csn: queing 0x9c6e798a
20091020074718.732501Z#000000#000#000000
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2123 op=1 RESULT tag=105 err=0 text=
Oct 20 09:47:18 ldapma01 slapd[8354]: slap_graduate_commit_csn: removing
0x120f5400 20091020074718.719682Z#000000#000#000000
Oct 20 09:47:18 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=332,csn=20091020074718.732501Z#000000#000#000000
Oct 20 09:47:18 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=330,csn=20091020074718.732501Z#000000#000#000000
Oct 20 09:47:18 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=467,csn=20091020074718.732501Z#000000#000#000000
Oct 20 09:47:18 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=467,csn=20091020074718.719682Z#000000#000#000000
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2124 op=1 RESULT tag=105 err=0 text=
Oct 20 09:47:18 ldapma01 slapd[8354]: slap_graduate_commit_csn: removing
0xa32039b8 20091020074718.732501Z#000000#000#000000
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2123 op=2 UNBIND
Oct 20 09:47:18 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=332,csn=20091020074718.719682Z#000000#000#000000
Oct 20 09:47:18 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=330,csn=20091020074718.719682Z#000000#000#000000
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2124 op=2 UNBIND
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2124 fd=20 closed
Oct 20 09:47:18 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=442,csn=20091020074718.732501Z#000000#000#000000
Oct 20 09:47:18 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=442,csn=20091020074718.719682Z#000000#000#000000
Oct 20 09:47:18 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=466,csn=20091020074718.732501Z#000000#000#000000
Oct 20 09:47:18 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=466,csn=20091020074718.719682Z#000000#000#000000
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2122 op=1 RESULT tag=105 err=0 text=
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2122 op=2 UNBIND
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2123 fd=19 closed
Oct 20 09:47:18 ldapma01 slapd[8354]: slap_graduate_commit_csn: removing
0x1218c070 20091020074718.707969Z#000000#000#000000
Oct 20 09:47:18 ldapma01 slapd[8354]: conn=2122 fd=15 closed
slave.log:
Oct 20 09:47:18 ldapsl01 slapd[11608]: syncrepl_entry: rid=467
LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_ADD)
Oct 20 09:47:18 ldapsl01 slapd[11608]: syncrepl_entry: rid=467 be_search (0)
Oct 20 09:47:18 ldapsl01 slapd[11608]: syncrepl_entry: rid=467
cn=15,ou=slamdtest,o=example,c=de
Oct 20 09:47:18 ldapsl01 slapd[11608]: slap_queue_csn: queing 0x12159830
20091020074718.210361Z#000000#000#000000
Oct 20 09:47:18 ldapsl01 slapd[11608]: slap_graduate_commit_csn: removing
0x120f6b20 20091020074718.210361Z#000000#000#000000
Oct 20 09:47:18 ldapsl01 slapd[11608]: syncrepl_entry: rid=467 be_add
cn=15,ou=slamdtest,o=example,c=de (0)
Oct 20 09:47:18 ldapsl01 slapd[11608]: slap_queue_csn: queing 0x12159830
20091020074718.210361Z#000000#000#000000
Oct 20 09:47:18 ldapsl01 slapd[11608]: slap_graduate_commit_csn: removing
0x120f6b20 20091020074718.210361Z#000000#000#000000
Oct 20 09:47:18 ldapsl01 slapd[11608]: do_syncrep2: cookie=
Oct 20 09:47:18 ldapsl01 slapd[11608]: syncrepl_entry: rid=467
LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_ADD)
Oct 20 09:47:18 ldapsl01 slapd[11608]: syncrepl_entry: rid=467 be_search (0)
Oct 20 09:47:18 ldapsl01 slapd[11608]: syncrepl_entry: rid=467
cn=17,ou=slamdtest,o=example,c=de
Oct 20 09:47:18 ldapsl01 slapd[11608]: syncrepl_entry: rid=467 be_add
cn=17,ou=slamdtest,o=example,c=de (0)
Oct 20 09:47:18 ldapsl01 slapd[11608]: do_syncrep2:
cookie=rid=467,csn=20091020074718.732501Z#000000#000#000000
Oct 20 09:47:18 ldapsl01 slapd[11608]: syncrepl_entry: rid=467
LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_ADD)
Oct 20 09:47:18 ldapsl01 slapd[11608]: syncrepl_entry: rid=467 be_search (0)
Oct 20 09:47:18 ldapsl01 slapd[11608]: syncrepl_entry: rid=467
cn=18,ou=slamdtest,o=example,c=de
Oct 20 09:47:18 ldapsl01 slapd[11608]: slap_queue_csn: queing 0x12159830
20091020074718.732501Z#000000#000#000000
Oct 20 09:47:18 ldapsl01 slapd[11608]: slap_graduate_commit_csn: removing
0x12142e30 20091020074718.732501Z#000000#000#000000
Oct 20 09:47:18 ldapsl01 slapd[11608]: syncrepl_entry: rid=467 be_add
cn=18,ou=slamdtest,o=example,c=de (0)
Oct 20 09:47:18 ldapsl01 slapd[11608]: slap_queue_csn: queing 0x12159830
20091020074718.732501Z#000000#000#000000
Oct 20 09:47:18 ldapsl01 slapd[11608]: slap_graduate_commit_csn: removing
0x12142e30 20091020074718.732501Z#000000#000#000000
Oct 20 09:47:18 ldapsl01 slapd[11608]: do_syncrep2:
cookie=rid=467,csn=20091020074718.719682Z#000000#000#000000
Oct 20 09:47:18 ldapsl01 slapd[11608]: do_syncrep2: rid=467 CSN too old,
ignoring 20091020074718.719682Z#000000#000#000000
Oct 20 09:47:19 ldapsl01 slapd[11608]: do_syncrep2:
cookie=rid=467,csn=20091020074719.251457Z#000000#000#000000
Oct 20 09:47:19 ldapsl01 slapd[11608]: syncrepl_entry: rid=467
LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_ADD)
Oct 20 09:47:19 ldapsl01 slapd[11608]: syncrepl_entry: rid=467 be_search (0)
Oct 20 09:47:19 ldapsl01 slapd[11608]: syncrepl_entry: rid=467
cn=19,ou=slamdtest,o=example,c=de
Oct 20 09:47:19 ldapsl01 slapd[11608]: slap_queue_csn: queing 0x121789b0
20091020074719.251457Z#000000#000#000000
Oct 20 09:47:19 ldapsl01 slapd[11608]: slap_graduate_commit_csn: removing
0x120f6b20 20091020074719.251457Z#000000#000#000000
Oct 20 09:47:19 ldapsl01 slapd[11608]: syncrepl_entry: rid=467 be_add
cn=19,ou=slamdtest,o=example,c=de (0)
Oct 20 09:47:19 ldapsl01 slapd[11608]: slap_queue_csn: queing 0x121789b0
20091020074719.251457Z#000000#000#000000
Oct 20 09:47:19 ldapsl01 slapd[11608]: slap_graduate_commit_csn: removing
0x120f6b20 20091020074719.251457Z#000000#000#000000
DELETE:
master.log:
Oct 20 09:53:25 ldapma01 slapd[8354]: conn=3574 fd=15 ACCEPT from
IP=172.26.248.57:55919 (IP=0.0.0.0:389)
Oct 20 09:53:25 ldapma01 slapd[8354]: conn=3574 op=0 BIND
dn="uid=ladmin,ou=verwaltung,o=example,c=de" method=128
Oct 20 09:53:25 ldapma01 slapd[8354]: conn=3574 op=0 BIND
dn="uid=ladmin,ou=Verwaltung,o=example,c=de" mech=SIMPLE ssf=0
Oct 20 09:53:25 ldapma01 slapd[8354]: conn=3574 op=0 RESULT tag=97 err=0 text=
Oct 20 09:53:25 ldapma01 slapd[8354]: conn=3574 op=1 DEL
dn="cn=460,ou=slamdtest,o=example,c=de"
Oct 20 09:53:25 ldapma01 slapd[8354]: slap_queue_csn: queing 0x9c6e7db8
20091020075325.717023Z#000000#000#000000
Oct 20 09:53:25 ldapma01 slapd[8354]: conn=3574 op=1 RESULT tag=107 err=0 text=
Oct 20 09:53:25 ldapma01 slapd[8354]: slap_graduate_commit_csn: removing
0xa320a6d8 20091020075325.717023Z#000000#000#000000
Oct 20 09:53:25 ldapma01 slapd[8354]: conn=3574 op=2 UNBIND
Oct 20 09:53:25 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=330,csn=20091020075325.717023Z#000000#000#000000
Oct 20 09:53:25 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=332,csn=20091020075325.717023Z#000000#000#000000
Oct 20 09:53:25 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=467,csn=20091020075325.717023Z#000000#000#000000
Oct 20 09:53:25 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=466,csn=20091020075325.717023Z#000000#000#000000
Oct 20 09:53:25 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=442,csn=20091020075325.717023Z#000000#000#000000
Oct 20 09:53:25 ldapma01 slapd[8354]: conn=3574 fd=15 closed
Oct 20 09:53:25 ldapma01 slapd[8354]: conn=3575 fd=15 ACCEPT from
IP=172.26.248.57:55920 (IP=0.0.0.0:389)
Oct 20 09:53:25 ldapma01 slapd[8354]: conn=3575 op=0 BIND
dn="uid=ladmin,ou=verwaltung,o=example,c=de" method=128
Oct 20 09:53:25 ldapma01 slapd[8354]: conn=3575 op=0 BIND
dn="uid=ladmin,ou=Verwaltung,o=example,c=de" mech=SIMPLE ssf=0
Oct 20 09:53:25 ldapma01 slapd[8354]: conn=3575 op=0 RESULT tag=97 err=0 text=
Oct 20 09:53:25 ldapma01 slapd[8354]: conn=3575 op=1 DEL
dn="cn=461,ou=slamdtest,o=example,c=de"
Oct 20 09:53:25 ldapma01 slapd[8354]: slap_queue_csn: queing 0x983f6db8
20091020075325.887748Z#000000#000#000000
Oct 20 09:53:25 ldapma01 slapd[8354]: conn=3576 fd=20 ACCEPT from
IP=172.26.248.57:55921 (IP=0.0.0.0:389)
Oct 20 09:53:25 ldapma01 slapd[8354]: conn=3576 op=0 BIND
dn="uid=ladmin,ou=verwaltung,o=example,c=de" method=128
Oct 20 09:53:25 ldapma01 slapd[8354]: conn=3576 op=0 BIND
dn="uid=ladmin,ou=Verwaltung,o=example,c=de" mech=SIMPLE ssf=0
Oct 20 09:53:25 ldapma01 slapd[8354]: conn=3576 op=0 RESULT tag=97 err=0 text=
Oct 20 09:53:25 ldapma01 slapd[8354]: conn=3576 op=1 DEL
dn="cn=462,ou=slamdtest,o=example,c=de"
Oct 20 09:53:25 ldapma01 slapd[8354]: slap_queue_csn: queing 0x9b4e2db8
20091020075325.930710Z#000000#000#000000
Oct 20 09:53:25 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=466,csn=20091020075325.887748Z#000000#000#000000
Oct 20 09:53:25 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=442,csn=20091020075325.887748Z#000000#000#000000
Oct 20 09:53:25 ldapma01 slapd[8354]: conn=3576 op=1 RESULT tag=107 err=0 text=
Oct 20 09:53:25 ldapma01 slapd[8354]: slap_graduate_commit_csn: removing
0xa320a6d8 20091020075325.930710Z#000000#000#000000
Oct 20 09:53:25 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=466,csn=20091020075325.930710Z#000000#000#000000
Oct 20 09:53:25 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=442,csn=20091020075325.930710Z#000000#000#000000
Oct 20 09:53:25 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=467,csn=20091020075325.930710Z#000000#000#000000
Oct 20 09:53:25 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=330,csn=20091020075325.930710Z#000000#000#000000
Oct 20 09:53:25 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=332,csn=20091020075325.930710Z#000000#000#000000
Oct 20 09:53:25 ldapma01 slapd[8354]: conn=3576 op=2 UNBIND
Oct 20 09:53:25 ldapma01 slapd[8354]: conn=3576 fd=20 closed
Oct 20 09:53:25 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=467,csn=20091020075325.887748Z#000000#000#000000
Oct 20 09:53:25 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=330,csn=20091020075325.887748Z#000000#000#000000
Oct 20 09:53:25 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=332,csn=20091020075325.887748Z#000000#000#000000
Oct 20 09:53:25 ldapma01 slapd[8354]: conn=3575 op=1 RESULT tag=107 err=0 text=
Oct 20 09:53:25 ldapma01 slapd[8354]: slap_graduate_commit_csn: removing
0xa320a5e8 20091020075325.887748Z#000000#000#000000
Oct 20 09:53:25 ldapma01 slapd[8354]: conn=3575 op=2 UNBIND
Oct 20 09:53:25 ldapma01 slapd[8354]: conn=3575 fd=15 closed
Oct 20 09:53:26 ldapma01 slapd[8354]: conn=3577 fd=15 ACCEPT from
IP=172.26.248.57:55922 (IP=0.0.0.0:389)
Oct 20 09:53:26 ldapma01 slapd[8354]: conn=3577 op=0 BIND
dn="uid=ladmin,ou=verwaltung,o=example,c=de" method=128
Oct 20 09:53:26 ldapma01 slapd[8354]: conn=3577 op=0 BIND
dn="uid=ladmin,ou=Verwaltung,o=example,c=de" mech=SIMPLE ssf=0
Oct 20 09:53:26 ldapma01 slapd[8354]: conn=3577 op=0 RESULT tag=97 err=0 text=
Oct 20 09:53:26 ldapma01 slapd[8354]: conn=3577 op=1 DEL
dn="cn=463,ou=slamdtest,o=example,c=de"
Oct 20 09:53:26 ldapma01 slapd[8354]: slap_queue_csn: queing 0xa24fbdb8
20091020075326.244684Z#000000#000#000000
Oct 20 09:53:26 ldapma01 slapd[8354]: conn=3577 op=1 RESULT tag=107 err=0 text=
Oct 20 09:53:26 ldapma01 slapd[8354]: slap_graduate_commit_csn: removing
0xa320edb0 20091020075326.244684Z#000000#000#000000
Oct 20 09:53:26 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=466,csn=20091020075326.244684Z#000000#000#000000
Oct 20 09:53:26 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=442,csn=20091020075326.244684Z#000000#000#000000
Oct 20 09:53:26 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=467,csn=20091020075326.244684Z#000000#000#000000
Oct 20 09:53:26 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=330,csn=20091020075326.244684Z#000000#000#000000
Oct 20 09:53:26 ldapma01 slapd[8354]: syncprov_sendresp:
cookie=rid=332,csn=20091020075326.244684Z#000000#000#000000
Oct 20 09:53:26 ldapma01 slapd[8354]: conn=3577 op=2 UNBIND
Oct 20 09:53:26 ldapma01 slapd[8354]: conn=3577 fd=15 closed
slave.log:
Oct 20 09:53:25 ldapsl01 slapd[11608]: do_syncrep2:
cookie=rid=467,csn=20091020075325.717023Z#000000#000#000000
Oct 20 09:53:25 ldapsl01 slapd[11608]: syncrepl_entry: rid=467
LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_DELETE)
Oct 20 09:53:25 ldapsl01 slapd[11608]: syncrepl_entry: rid=467 be_search (0)
Oct 20 09:53:25 ldapsl01 slapd[11608]: syncrepl_entry: rid=467
cn=460,ou=slamdtest,o=example,c=de
Oct 20 09:53:25 ldapsl01 slapd[11608]: slap_queue_csn: queing 0x1210a9d8
20091020075325.717023Z#000000#000#000000
Oct 20 09:53:25 ldapsl01 slapd[11608]: slap_graduate_commit_csn: removing
0x122416d0 20091020075325.717023Z#000000#000#000000
Oct 20 09:53:25 ldapsl01 slapd[11608]: syncrepl_entry: rid=467 be_delete
cn=460,ou=slamdtest,o=example,c=de (0)
Oct 20 09:53:25 ldapsl01 slapd[11608]: slap_queue_csn: queing 0x1210a9d8
20091020075325.717023Z#000000#000#000000
Oct 20 09:53:25 ldapsl01 slapd[11608]: slap_graduate_commit_csn: removing
0x12238750 20091020075325.717023Z#000000#000#000000
Oct 20 09:53:25 ldapsl01 slapd[11608]: do_syncrep2:
cookie=rid=467,csn=20091020075325.930710Z#000000#000#000000
Oct 20 09:53:25 ldapsl01 slapd[11608]: syncrepl_entry: rid=467
LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_DELETE)
Oct 20 09:53:25 ldapsl01 slapd[11608]: syncrepl_entry: rid=467 be_search (0)
Oct 20 09:53:25 ldapsl01 slapd[11608]: syncrepl_entry: rid=467
cn=462,ou=slamdtest,o=example,c=de
Oct 20 09:53:25 ldapsl01 slapd[11608]: slap_queue_csn: queing 0x1222b320
20091020075325.930710Z#000000#000#000000
Oct 20 09:53:25 ldapsl01 slapd[11608]: slap_graduate_commit_csn: removing
0x12238750 20091020075325.930710Z#000000#000#000000
Oct 20 09:53:25 ldapsl01 slapd[11608]: syncrepl_entry: rid=467 be_delete
cn=462,ou=slamdtest,o=example,c=de (0)
Oct 20 09:53:25 ldapsl01 slapd[11608]: slap_queue_csn: queing 0x1222b320
20091020075325.930710Z#000000#000#000000
Oct 20 09:53:25 ldapsl01 slapd[11608]: slap_graduate_commit_csn: removing
0x12240cf0 20091020075325.930710Z#000000#000#000000
Oct 20 09:53:25 ldapsl01 slapd[11608]: do_syncrep2:
cookie=rid=467,csn=20091020075325.887748Z#000000#000#000000
Oct 20 09:53:25 ldapsl01 slapd[11608]: do_syncrep2: rid=467 CSN too old,
ignoring 20091020075325.887748Z#000000#000#000000
Oct 20 09:53:26 ldapsl01 slapd[11608]: do_syncrep2:
cookie=rid=467,csn=20091020075326.244684Z#000000#000#000000
Oct 20 09:53:26 ldapsl01 slapd[11608]: syncrepl_entry: rid=467
LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_DELETE)
Oct 20 09:53:26 ldapsl01 slapd[11608]: syncrepl_entry: rid=467 be_search (0)
Oct 20 09:53:26 ldapsl01 slapd[11608]: syncrepl_entry: rid=467
cn=463,ou=slamdtest,o=example,c=de
Oct 20 09:53:26 ldapsl01 slapd[11608]: slap_queue_csn: queing 0x12235c68
20091020075326.244684Z#000000#000#000000
Oct 20 09:53:26 ldapsl01 slapd[11608]: slap_graduate_commit_csn: removing
0x12240cf0 20091020075326.244684Z#000000#000#000000
Oct 20 09:53:26 ldapsl01 slapd[11608]: syncrepl_entry: rid=467 be_delete
cn=463,ou=slamdtest,o=example,c=de (0)
Oct 20 09:53:26 ldapsl01 slapd[11608]: slap_queue_csn: queing 0x12235c68
20091020075326.244684Z#000000#000#000000
Oct 20 09:53:26 ldapsl01 slapd[11608]: slap_graduate_commit_csn: removing
0x12139a10 20091020075326.244684Z#000000#000#000000
regards
Christoph