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
--On Wednesday, October 21, 2009 4:03 PM +0200 Christoph Herrmann C.Herrmann@science-computing.de wrote:
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:
Please file an ITS at http://www.openldap.org/its with all of this information.
--Quanah
--
Quanah Gibson-Mount Principal Software Engineer Zimbra, Inc -------------------- Zimbra :: the leader in open source messaging and collaboration
Christoph Herrmann C.Herrmann@science-computing.de writes:
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:
[...]
this is our syncrepl config:
master/provider:
overlay syncprov syncprov-checkpoint 100 10 syncprov-sessionlog 100slave/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:389During 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?
I found that disable logging on provider and consumers solved most of my problems. in addition you should check the number of waiters and increase the number of threads if required.
-Dieter
--On Wednesday, October 21, 2009 10:48 PM +0200 Dieter Kluenter dieter@dkluenter.de wrote:
I found that disable logging on provider and consumers solved most of my problems. in addition you should check the number of waiters and increase the number of threads if required.
This is not a solution, this is a workaround. The underlying problem should be investigated and resolved. If you've seen this, you should have filed an ITS.
--Quanah
--
Quanah Gibson-Mount Principal Software Engineer Zimbra, Inc -------------------- Zimbra :: the leader in open source messaging and collaboration
openldap-software@openldap.org
-
Christoph Herrmann -
Dieter Kluenter -
Quanah Gibson-Mount