Re: (ITS#5465) Delta-Syncrepl cookie problems

[quanah@zimbra.com]

--On Friday, April 11, 2008 9:33 PM +0000 quanah@zimbra.com wrote:

> I have a replica spitting out the following error in its logs (master and
> replica running OpenLDAP 2.3.41):

This is happening again.  With loglevel = sync, I see:

Apr 15 13:06:36 neo-ldap-3 slapd[13469]: syncrepl_message_to_op: rid 100 
be_modify uid=A-B-C,ou=people,dc=abc,dc=123,dc=edu (0)
Apr 15 13:06:36 neo-ldap-3 slapd[13469]: syncrepl_message_to_op: rid 100 
be_modify uid=XXXXX,ou=people,dc=neo,dc=tamu,dc=edu (0)
Apr 15 13:06:36 neo-ldap-3 slapd[13469]: do_syncrep2: rid 100 
LDAP_RES_INTERMEDIATE - REFRESH_DELETE
Apr 15 13:06:36 neo-ldap-3 slapd[13469]: null_callback: error code 0x14
Apr 15 13:06:36 neo-ldap-3 slapd[13469]: syncrepl_message_to_op: rid 100 
be_modify uid=XXXXX,ou=people,dc=abc,dc=123,dc=edu (20)
Apr 15 13:06:36 neo-ldap-3 slapd[13469]: do_syncrepl: rid 100 retrying

and then it forever more retries:

Apr 15 13:07:36 neo-ldap-3 slapd[13469]: null_callback: error code 0x14
Apr 15 13:07:36 neo-ldap-3 slapd[13469]: syncrepl_message_to_op: rid 100 
be_modify uid=XXXXX,ou=people,dc=abc,dc=123,dc=edu (20)
Apr 15 13:07:36 neo-ldap-3 slapd[13469]: do_syncrepl: rid 100 retrying



On the master, we see:

Apr 15 13:06:34 neo-ldap-1 slapd[18587]: conn=313538 op=1 MOD 
dn="uid=XXXXX,ou=people,dc=abc,dc=123,dc=edu"
Apr 15 13:06:34 neo-ldap-1 slapd[18587]: conn=313538 op=1 MOD 
attr=zimbraPasswordLockoutFailureTime
Apr 15 13:06:34 neo-ldap-1 slapd[18587]: conn=313538 op=1 MOD 
attr=zimbraPasswordLockoutFailureTime
Apr 15 13:06:35 neo-ldap-1 slapd[18587]: conn=313539 fd=24 ACCEPT from 
IP=10.1.15.23:52299 (IP=10.1.15.21:389)
Apr 15 13:06:35 neo-ldap-1 slapd[18587]: conn=313539 op=0 STARTTLS
Apr 15 13:06:35 neo-ldap-1 slapd[18587]: conn=313539 op=0 RESULT oid= err=0 
text=
Apr 15 13:06:35 neo-ldap-1 slapd[18587]: conn=313539 fd=24 TLS established 
tls_ssf=256 ssf=256
Apr 15 13:06:35 neo-ldap-1 slapd[18587]: conn=313539 op=1 BIND 
dn="uid=zmreplica,cn=admins,cn=zimbra" method=128
Apr 15 13:06:35 neo-ldap-1 slapd[18587]: conn=313539 op=1 BIND 
dn="uid=zmreplica,cn=admins,cn=zimbra" mech=SIMPLE ssf=0
Apr 15 13:06:35 neo-ldap-1 slapd[18587]: conn=313539 op=1 RESULT tag=97 
err=0 text=
Apr 15 13:06:35 neo-ldap-1 slapd[18587]: conn=313539 op=2 SRCH 
base="cn=accesslog" scope=2 deref=0 
filter="(&(objectClass=auditWriteObject)(reqResult=0))"
Apr 15 13:06:35 neo-ldap-1 slapd[18587]: conn=313539 op=2 SRCH attr=reqDN 
reqType reqMod reqNewRDN reqDeleteOldRDN reqNewSuperior entryCSN
Apr 15 13:06:35 neo-ldap-1 slapd[18587]: conn=313538 op=1 RESULT tag=103 
err=0 text=
Apr 15 13:06:35 neo-ldap-1 slapd[18587]: Entry 
reqStart=20080415180532.000001Z,cn=accesslog CSN 
20080415180532Z#000000#00#000000 matches ctx 
20080415180532Z#000000#00#000000
Apr 15 13:06:35 neo-ldap-1 slapd[18587]: conn=313538 op=2 SRCH 
base="uid=XXXXX,ou=people,dc=abc,dc=123,dc=edu" scope=0 deref=3 
filter="(objectClass=*)"
Apr 15 13:06:35 neo-ldap-1 slapd[18587]: conn=313538 op=2 SEARCH RESULT 
tag=101 err=0 nentries=1 text=
Apr 15 13:06:35 neo-ldap-1 slapd[18587]: conn=313538 op=3 UNBIND
Apr 15 13:06:35 neo-ldap-1 slapd[18587]: conn=313538 fd=23 closed




So what I think is of particular interest here, is that the replica hits 
the master right as the modification has started, but before it has 
finished.

--Quanah

--

Quanah Gibson-Mount
Principal Software Engineer
Zimbra, Inc
--------------------
Zimbra ::  the leader in open source messaging and collaboration