schema replication problems with test059-slave-config

[Christopher Strider Cook <ccook@pandora.com>]

I have a setup based on the one created in test059-slave-config, but 
complicating matters, the providers are a mirrormode pair. Running 
2.4.25 under Debian Squeeze.

On this pair I have cn=config,cn=slave created as laid out in 
test059-slave-config, with additional syncing to allow mirrormode operation.

dn: olcDatabase={2}ldif,cn=config
objectClass: olcConfig
objectClass: olcDatabaseConfig
objectClass: olcLdifConfig
objectClass: top
olcDatabase: {2}ldif
olcDbDirectory: /var/lib/ldap-slave-config
olcAccess: {0}to * by dn.exact=gidNumber=0+uidNumber=0,cn=peercred,cn=extern
 al,cn=auth manage by * break
olcAccess: {1}to * by dn.base="cn=admin,dc=savagebeast,dc=com"
olcAccess: {2}to * by dn.base="cn=repl,dc=savagebeast,dc=com"
olcAccess: {3}to dn.base="" by * write
olcMirrorMode: TRUE
olcRootDN: cn=admin,cn=config,cn=slave
olcRootPW: {SHA}xxx
olcSuffix: cn=config,cn=slave
olcSyncrepl: {0}rid=006 provider=ldaps://guess.savagebeast.com bindmethod=si
 mple binddn="cn=admin,cn=config" credentials=xxx searchbase="cn=schema,cn
 =config" schemachecking=off type=refreshAndPersist retry="60 +" 
suffixmassa
 ge="cn=schema,cn=config,cn=slave"
olcSyncrepl: {1}rid=005 provider=ldaps://who.savagebeast.com bindmethod=simp
 le binddn="cn=admin,cn=config" credentials=xxx searchbase="cn=schema,cn=c
 onfig" schemachecking=off type=refreshAndPersist retry="60 +" 
suffixmassage
 ="cn=schema,cn=config,cn=slave"
olcSyncrepl: {2}rid=007 provider=ldaps://who.savagebeast.com bindmethod=simp
 le binddn="cn=admin,cn=config,cn=slave" credentials=xxx searchbase="cn=co
 nfig,cn=slave" schemachecking=on type=refreshAndPersist retry="60 +"
olcSyncrepl: {3}rid=008 provider=ldaps://guess.savagebeast.com bindmethod=si
 mple binddn="cn=admin,cn=config,cn=slave" credentials=xxx searchbase="cn=
 config,cn=slave" schemachecking=on type=refreshAndPersist retry="60 +"
createTimestamp: 20110609185532Z
creatorsName: cn=admin,cn=config
entryCSN: 20110616183041.867322Z#000000#002#000000
entryDN: olcDatabase={2}ldif,cn=config
entryUUID:: Y2JmNTE3MTAtMjcxNS0xMDMwLThkMGYtNWY4MDFiNjU0MGFl
modifiersName: cn=admin,cn=config
modifyTimestamp: 20110616183041Z
structuralObjectClass: olcLdifConfig
subschemaSubentry: cn=Subschema

{NB: To future google searchers; I originally had this database setup as 
a HDB. After a week of use, this failed to allow new consumers to sync 
with it because <ASSUMING> the database ordering dictates how the 
initial sync is ordered, which normally wouldn't be a problem, but since 
the cn=config database is interpreted as it's loaded ordering became 
important. IE: defining a database before the back_ module used was 
loaded; Moving to the ldif database format seems to provide a consistent 
top down ordering.}

RID 7 and 8 work fine and configurations changes propagate between the 
Mirrormode providers and the remote consumers.

RID 5 and 6 performed the initial sync properly but have since started 
issuing errors on both masters:

Jun 16 12:02:41 who slapd[9589]: do_syncrep2: rid=006 
LDAP_RES_SEARCH_RESULT (53) Server is unwilling to perform
Jun 16 12:02:41 who slapd[9589]: do_syncrep2: rid=006 (53) Server is 
unwilling to perform
Jun 16 12:02:41 who slapd[9589]: do_syncrepl: rid=006 rc -2 retrying
Jun 16 12:02:59 who slapd[9589]: do_syncrep2: rid=005 
LDAP_RES_SEARCH_RESULT (53) Server is unwilling to perform
Jun 16 12:02:59 who slapd[9589]: do_syncrep2: rid=005 (53) Server is 
unwilling to perform
Jun 16 12:02:59 who slapd[9589]: do_syncrepl: rid=005 rc -2 retrying


Running in full debug I see errors about the CSN timestamps:


ber_dump: buf=0x7fae40019d00 ptr=0x7fae40019dea end=0x7fae40019ded len=3
  0000:  00 01 ff                                           ...
=> get_ctrls: oid="2.16.840.1.113730.3.4.2" (critical)
<= get_ctrls: n=2 rc=0 err=""
    attrs: * +
conn=1000 op=1 SRCH base="cn=schema,cn=config" scope=2 deref=0 
filter="(objectClass=*)"
conn=1000 op=1 SRCH attr=* +
send_ldap_result: conn=1000 op=1 p=3
send_ldap_result: err=53 matched="" text="consumer state is newer than 
provider!"
send_ldap_response: msgid=2 tag=101 err=53
ber_flush2: 52 bytes to sd 17
  0000:  30 32 02 01 02 65 2d 0a  01 35 04 00 04 26 63 6f   
02...e-..5...&co
  0010:  6e 73 75 6d 65 72 20 73  74 61 74 65 20 69 73 20   nsumer 
state is
  0020:  6e 65 77 65 72 20 74 68  61 6e 20 70 72 6f 76 69   newer than 
provi
  0030:  64 65 72 21                                        der!
tls_write: want=165, written=165
  0000:  17 03 02 00 a0 0b 68 27  f3 13 cc 34 a9 75 cd 8d   
......h'...4.u..
  0010:  f7 f9 35 d5 b8 4c f5 a8  49 4e e1 fb e2 c5 3b 72   
..5..L..IN....;r
  0020:  df f8 e0 d2 72 34 1e e3  bd 6e 26 ca 25 8a c1 3e   
....r4...n&.%..>
  0030:  20 65 e2 56 f5 f4 b0 60  09 a2 eb ab b5 b7 2f e2    
e.V...`....../.
  0040:  6a bd f3 48 12 c3 59 bb  87 cd 7d bd 99 76 5f 29   
j..H..Y...}..v_)
  0050:  f9 5f 27 d4 09 4f 0e 31  a9 89 b6 33 43 f3 65 ab   
._'..O.1...3C.e.
  0060:  69 bf a1 19 3c 51 70 52  79 3d a6 d1 39 c7 c1 1d   
i...<QpRy=..9...
  0070:  5c 37 ac 89 a4 82 ed 68  cf f4 1a e4 52 90 20 6b   
\7.....h....R. k
  0080:  51 11 db 0e e2 a4 38 04  17 aa 65 b3 e2 38 5a 1e   
Q.....8...e..8Z.
  0090:  00 15 52 2e 75 2f 05 81  86 a0 41 cd 91 ca 5b 92   
..R.u/....A...[.
  00a0:  e5 69 bd 41 d6                                     .i.A.
ldap_write: want=52, written=52
  0000:  30 32 02 01 02 65 2d 0a  01 35 04 00 04 26 63 6f   
02...e-..5...&co
  0010:  6e 73 75 6d 65 72 20 73  74 61 74 65 20 69 73 20   nsumer 
state is
  0020:  6e 65 77 65 72 20 74 68  61 6e 20 70 72 6f 76 69   newer than 
provi
  0030:  64 65 72 21                                        der!
read1msg: ld 0x7fae44100d60 msgid 2 all 0
conn=1000 op=1 SEARCH RESULT tag=101 err=53 nentries=0 text=consumer 
state is newer than provider!
ber_get_next
tls_read: want=5, got=5
  0000:  17 03 02 00 a0                                     .....
tls_read: want=160, got=160
  0000:  0b 68 27 f3 13 cc 34 a9  75 cd 8d f7 f9 35 d5 b8   
.h'...4.u....5..
  0010:  4c f5 a8 49 4e e1 fb e2  c5 3b 72 df f8 e0 d2 72   
L..IN....;r....r
  0020:  34 1e e3 bd 6e 26 ca 25  8a c1 3e 20 65 e2 56 f5   4...n&.%..> 
e.V.
  0030:  f4 b0 60 09 a2 eb ab b5  b7 2f e2 6a bd f3 48 12   
..`....../.j..H.
  0040:  c3 59 bb 87 cd 7d bd 99  76 5f 29 f9 5f 27 d4 09   
.Y...}..v_)._'..
  0050:  4f 0e 31 a9 89 b6 33 43  f3 65 ab 69 bf a1 19 3c   
O.1...3C.e.i...<
  0060:  51 70 52 79 3d a6 d1 39  c7 c1 1d 5c 37 ac 89 a4   
QpRy=..9...\7...
  0070:  82 ed 68 cf f4 1a e4 52  90 20 6b 51 11 db 0e e2   ..h....R. 
kQ....
  0080:  a4 38 04 17 aa 65 b3 e2  38 5a 1e 00 15 52 2e 75   
.8...e..8Z...R.u
  0090:  2f 05 81 86 a0 41 cd 91  ca 5b 92 e5 69 bd 41 d6   
/....A...[..i.A.
ldap_read: want=8, got=8
  0000:  30 32 02 01 02 65 2d 0a                            02...e-.
ldap_read: want=44, got=44
  0000:  01 35 04 00 04 26 63 6f  6e 73 75 6d 65 72 20 73   
.5...&consumer s
  0010:  74 61 74 65 20 69 73 20  6e 65 77 65 72 20 74 68   tate is 
newer th
  0020:  61 6e 20 70 72 6f 76 69  64 65 72 21               an provider!
ber_get_next: tag 0x30 len 50 contents:
ber_dump: buf=0x7fae340013a0 ptr=0x7fae340013a0 end=0x7fae340013d2 len=50
  0000:  02 01 02 65 2d 0a 01 35  04 00 04 26 63 6f 6e 73   
...e-..5...&cons
  0010:  75 6d 65 72 20 73 74 61  74 65 20 69 73 20 6e 65   umer state 
is ne
  0020:  77 65 72 20 74 68 61 6e  20 70 72 6f 76 69 64 65   wer than 
provide
  0030:  72 21                                              r!
read1msg: ld 0x7fae44100d60 msgid 2 message type search-result
ber_scanf fmt ({eAA) ber:
ber_dump: buf=0x7fae340013a0 ptr=0x7fae340013a3 end=0x7fae340013d2 len=47
  0000:  65 2d 0a 01 35 04 00 04  26 63 6f 6e 73 75 6d 65   
e-..5...&consume
  0010:  72 20 73 74 61 74 65 20  69 73 20 6e 65 77 65 72   r state is 
newer
  0020:  20 74 68 61 6e 20 70 72  6f 76 69 64 65 72 21       than 
provider!
read1msg: ld 0x7fae44100d60 0 new referrals
read1msg:  mark request completed, ld 0x7fae44100d60 msgid 2
request done: ld 0x7fae44100d60 msgid 2
res_errno: 53, res_error: <consumer state is newer than provider!>, 
res_matched: <>
ldap_free_request (origid 2, msgid 2)
do_syncrep2: rid=005 LDAP_RES_SEARCH_RESULT
ldap_parse_result
ber_scanf fmt ({iAA) ber:
ber_dump: buf=0x7fae340013a0 ptr=0x7fae340013a3 end=0x7fae340013d2 len=47
  0000:  65 2d 0a 01 35 04 00 04  26 63 6f 6e 73 75 6d 65   
e-..5...&consume
  0010:  72 20 73 74 61 74 65 20  69 73 20 6e 65 77 65 72   r state is 
newer
  0020:  20 74 68 61 6e 20 70 72  6f 76 69 64 65 72 21       than 
provider!
ber_scanf fmt (}) ber:
ber_dump: buf=0x7fae340013a0 ptr=0x7fae340013d2 end=0x7fae340013d2 len=0

ldap_err2string
do_syncrep2: rid=005 LDAP_RES_SEARCH_RESULT (53) Server is unwilling to 
perform
ldap_err2string
ldap_err2string
do_syncrep2: rid=005 (53) Server is unwilling to perform
ldap_err2string
ldap_msgfree
ldap_free_connection 1 1
ldap_send_unbind


Any pointers on where to troubleshoot and resolve this?