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

[quanah@zimbra.com]

More data on another occurrence of this problem, this time with some packet level logging.


15:56:55 is when the replica's disconnect:

May  7 15:56:55 neo-ldap-1 slapd[7732]: conn=1463287 op=1 MOD dn="uid=xxxxx,ou=people,dc=xxx,dc=xxxx,dc=xxx"
May  7 15:56:55 neo-ldap-1 slapd[7732]: conn=1463287 op=1 MOD attr=zimbraPasswordLockoutFailureTime zimbraPasswordLockoutFailureTime
May  7 15:56:55 neo-ldap-1 slapd[7732]: conn=1463286 op=1 RESULT tag=103 err=0 text=
May  7 15:56:55 neo-ldap-1 slapd[7732]: conn=1463286 op=2 SRCH base="uid=yyyyyy,ou=people,dc=xxx,dc=xxxx,dc=xxxx" scope=0 deref=3 filter="(objectClass=*)"
May  7 15:56:55 neo-ldap-1 slapd[7732]: conn=1463286 op=2 SEARCH RESULT tag=101 err=0 nentries=1 text=
May  7 15:56:55 neo-ldap-1 slapd[7732]: conn=1463286 op=3 UNBIND
May  7 15:56:55 neo-ldap-1 slapd[7732]: conn=1463286 fd=27 closed
May  7 15:56:55 neo-ldap-1 slapd[7732]: conn=1463287 op=1 RESULT tag=103 err=0 text=
May  7 15:56:55 neo-ldap-1 slapd[7732]: conn=1463287 op=2 SRCH base="uid=xxxxx,ou=people,dc=xxx,dc=xxxx,dc=xxx" scope=0 deref=3 filter="(objectClass=*)"
May  7 15:56:55 neo-ldap-1 slapd[7732]: conn=1463287 op=2 SEARCH RESULT tag=101 err=0 nentries=1 text=
May  7 15:56:55 neo-ldap-1 slapd[7732]: conn=1463287 op=3 UNBIND
May  7 15:56:55 neo-ldap-1 slapd[7732]: conn=1463287 fd=28 closed
May  7 15:56:55 neo-ldap-1 slapd[7732]: conn=1443587 op=3 UNBIND
May  7 15:56:55 neo-ldap-1 slapd[7732]: conn=1443587 fd=25 closed
May  7 15:56:55 neo-ldap-1 slapd[7732]: conn=1443455 op=3 UNBIND
May  7 15:56:55 neo-ldap-1 slapd[7732]: conn=1443455 fd=40 closed
May  7 15:56:55 neo-ldap-1 slapd[7732]: conn=1367867 op=3 UNBIND
May  7 15:56:55 neo-ldap-1 slapd[7732]: conn=1367867 fd=24 closed


1443587, 1443455 are the connections from the two replicas.

In the packet log for the replica, I see:

l
  0000:  30 0d 02 02 3c da 65 07  0a 01 00 04 00 04 00      0...<.e........
ldap_write: want=15, written=15
  0000:  30 0d 02 02 3c da 65 07  0a 01 00 04 00 04 00      0...<.e........
ldap_read: want=8, got=0

ldap_read: want=8, got=0

ldap_read: want=8, got=8
  0000:  30 7a 02 01 03 64 30 04                            0z...d0.
ldap_read: want=116, got=116
  0000:  2c 72 65 71 53 74 61 72  74 3d 32 30 30 38 30 34   ,reqStart=200804
  0010:  32 39 32 30 35 36 32 30  2e 30 30 30 30 30 31 5a   29205620.000001Z
  0020:  2c 63 6e 3d 61 63 63 65  73 73 6c 6f 67 30 00 a0   ,cn=accesslog0..
  0030:  43 30 41 04 18 31 2e 33  2e 36 2e 31 2e 34 2e 31   C0A..1.3.6.1.4.1
  0040:  2e 34 32 30 33 2e 31 2e  39 2e 31 2e 32 04 25 30   .4203.1.9.1.2.%0
  0050:  23 0a 01 03 04 10 76 89  f9 82 aa 7a 10 2c 8e 1b   #.....v....z.,..
  0060:  05 5f 81 eb fa ec 04 0c  63 73 6e 3d 2c 72 69 64   ._......csn=,rid
  0070:  3d 31 30 30                                        =100
  0000:  30 05 02 01 04 42 00                               0....B.
ldap_write: want=7, written=7
  0000:  30 05 02 01 04 42 00                               0....B.

do_syncrepl: rid 100 retrying


This looks to be due to expiry, as that timestamp is approximately 7 days before the current time.

--Quanah

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