[Date Prev][Date Next] [Chronological] [Thread] [Top]
syncrepl problem with 2.4.19

To: openldap-software@openldap.org
Subject: syncrepl problem with 2.4.19
From: Christoph Herrmann <C.Herrmann@science-computing.de>
Date: Wed, 21 Oct 2009 16:03:42 +0200
Cc: Michael Weiser <weiser@science-computing.de>, Mark Proehl <proehl@science-computing.de>
Content-disposition: inline
User-agent: Mutt/1.5.18 (2008-05-17)
Dear all,

we want to update our openldap-2.3.39 infrastructure to openldap 2.4.19.
For that 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, the the master send the syncreplrequests out of sync,
and all slaves reject syncing with the message: CSN too old, ignoring ... 

What can we do, to solve that problem?


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


--

Thanks

    Christoph





-- 
Vorstand/Board of Management:
Dr. Bernd Finkbeiner, Dr. Roland Niemeier, 
Dr. Arno Steitz, Dr. Ingrid Zech
Vorsitzender des Aufsichtsrats/
Chairman of the Supervisory Board:
Michel Lepert
Sitz/Registered Office: Tuebingen
Registergericht/Registration Court: Stuttgart
Registernummer/Commercial Register No.: HRB 382196
Follow-Ups:
- Re: syncrepl problem with 2.4.19
  - From: Quanah Gibson-Mount <quanah@zimbra.com>
- Re: syncrepl problem with 2.4.19
  - From: "Dieter Kluenter" <dieter@dkluenter.de>
Prev by Date: Re: MirrorMode/N-Way Multi-Master Replication Clarification
Next by Date: Re: syncrepl problem with 2.4.19
Index(es):
- Chronological
- Thread