Full_Name: Quanah Gibson-Mount Version: 2.4.21 OS: Linux 2.6 URL: ftp://ftp.openldap.org/incoming/ Submission from: (NULL) (75.111.45.108)
When the accesslog database is purged, the syncprov overlay sends a bogus cookie response to open syncrepl clients, causing them to drop connection. This bogus cookie should never have been sent.
From the slapd log on the provider, we have the initial connection:
Apr 13 13:16:43 freelancer slapd[4276]: conn=1013 fd=18 ACCEPT from IP=10.18.97.26:60034 (IP=10.18.97.79:389) Apr 13 13:16:43 freelancer slapd[4276]: conn=1013 op=0 EXT oid=1.3.6.1.4.1.1466.20037 Apr 13 13:16:43 freelancer slapd[4276]: conn=1013 op=0 STARTTLS Apr 13 13:16:43 freelancer slapd[4276]: conn=1013 op=0 RESULT oid= err=0 text= Apr 13 13:16:43 freelancer slapd[4276]: conn=1013 fd=18 TLS established tls_ssf=256 ssf=256 Apr 13 13:16:43 freelancer slapd[4276]: conn=1013 op=1 BIND dn="uid=zmreplica,cn=admins,cn=zimbra" method=128 Apr 13 13:16:43 freelancer slapd[4276]: conn=1013 op=1 BIND dn="uid=zmreplica,cn=admins,cn=zimbra" mech=SIMPLE ssf=0 Apr 13 13:16:43 freelancer slapd[4276]: conn=1013 op=1 RESULT tag=97 err=0 text= Apr 13 13:16:43 freelancer slapd[4276]: conn=1013 op=2 SRCH base="cn=accesslog" scope=2 deref=0 filter="(&(objectClass=auditWriteObject)(reqResult=0))" Apr 13 13:16:43 freelancer slapd[4276]: conn=1013 op=2 SRCH attr=reqDN reqType reqMod reqNewRDN reqDeleteOldRDN reqNewSuperior entryCSN
Approximately 30 minutes later (which is my setting), the purge takes place:
Apr 13 13:45:54 freelancer slapd[4276]: slap_queue_csn: queing 0x446a7200 20100413204554.501961Z#000000#000#000000 Apr 13 13:45:54 freelancer slapd[4276]: slap_queue_csn: queing 0x395e788 20100413204554.501961Z#000000#000#000000 Apr 13 13:45:54 freelancer slapd[4276]: slap_graduate_commit_csn: removing 0x3f94690 20100413204554.501961Z#000000#000#000000 Apr 13 13:45:54 freelancer slapd[4276]: syncprov_sendresp: cookie=rid=100,csn=20100413204554.501961Z#000000#000#000000 Apr 13 13:45:54 freelancer slapd[4276]: conn=2605 op=2 RESULT tag=105 err=0 text= Apr 13 13:45:54 freelancer slapd[4276]: slap_graduate_commit_csn: removing 0x3f80030 20100413204554.501961Z#000000#000#000000 Apr 13 13:45:54 freelancer slapd[4276]: conn=2605 op=3 SRCH base="" scope=2 deref=3 filter="(&(zimbraId=58a68771-fded-4aa2-baab-e1ac349e0028)(objectClass=zimbraAccount))" Apr 13 13:45:54 freelancer slapd[4276]: conn=2605 op=3 SEARCH RESULT tag=101 err=0 nentries=1 text= Apr 13 13:45:54 freelancer slapd[4276]: conn=2605 fd=20 closed (connection lost) Apr 13 13:45:54 freelancer slapd[4276]: conn=2603 fd=38 closed (connection lost) Apr 13 13:45:54 freelancer slapd[4276]: conn=2602 fd=37 closed (connection lost) Apr 13 13:45:56 freelancer slapd[4276]: syncprov_sendresp: cookie= Apr 13 13:45:56 freelancer slapd[4276]: conn=1013 op=3 UNBIND Apr 13 13:45:56 freelancer slapd[4276]: conn=1013 fd=18 closed
As you can see, an empty cookie is sent, and the consumer immediately closes connection, re-establishing it shortly thereafter:
Apr 13 13:46:56 freelancer slapd[4276]: conn=2671 fd=18 ACCEPT from IP=10.18.97.26:36796 (IP=10.18.97.79:389) Apr 13 13:46:56 freelancer slapd[4276]: conn=2671 op=0 EXT oid=1.3.6.1.4.1.1466.20037 Apr 13 13:46:56 freelancer slapd[4276]: conn=2671 op=0 STARTTLS Apr 13 13:46:56 freelancer slapd[4276]: conn=2671 op=0 RESULT oid= err=0 text= Apr 13 13:46:56 freelancer slapd[4276]: conn=2671 fd=18 TLS established tls_ssf=256 ssf=256 Apr 13 13:46:56 freelancer slapd[4276]: conn=2671 op=1 BIND dn="uid=zmreplica,cn=admins,cn=zimbra" method=128 Apr 13 13:46:56 freelancer slapd[4276]: conn=2671 op=1 BIND dn="uid=zmreplica,cn=admins,cn=zimbra" mech=SIMPLE ssf=0 Apr 13 13:46:56 freelancer slapd[4276]: conn=2671 op=1 RESULT tag=97 err=0 text= Apr 13 13:46:56 freelancer slapd[4276]: conn=2671 op=2 SRCH base="cn=accesslog" scope=2 deref=0 filter="(&(objectClass=auditWriteObject)(reqResult=0))" Apr 13 13:46:56 freelancer slapd[4276]: conn=2671 op=2 SRCH attr=reqDN reqType reqMod reqNewRDN reqDeleteOldRDN reqNewSuperior entryCSN Apr 13 13:46:56 freelancer slapd[4276]: Entry reqStart=20100413204554.000009Z,cn=accesslog CSN 20100413204554.501961Z#000000#000#000000 older or equal to ctx 20100413204554.501961Z#000000#000#000000 Apr 13 13:46:56 freelancer slapd[4276]: syncprov_search_response: cookie=rid=100,csn=20100413204656.794873Z#000000#000#000000