(ITS#6519) syncprov sends bogus cookie on accesslog purge

[quanah@zimbra.com]

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