ldap replication problem

[Christian Rößler]

Hallo,

I have a bit of a ldap replication problem. Most entries do replicate as
they should; but some won't. I have the feeling that at least part of
this problem is due to a clock running wild - the replication server
(kolab-slave) is virtualized, and it's clock went by way too fast. Both
clocks are synchronized now.

By the way: Both Kolabs are 2.2.2; both are updated from below,
following the update procedures as usual.

For example this object (just for testing, so I don't care about these
password hashes):

dn: cn=test 2,dc=kolab,dc=fuhintern,dc=de
userPassword:: e1NTSEF9UEJ0OVhUZ1R0OXZkeTRNRUJ6WERZNGVpeWxlZWlTTUg=
kolabHomeServer: kolab.fuhintern.de
objectClass: top
objectClass: person
objectClass: inetOrgPerson
objectClass: kolabInetOrgPerson
sn: 2
cn: test 2
givenName: test
mail: tst2 at kolab.fuhintern.de
uid: tst2
telephoneNumber: 1
kolabInvitationPolicy: ACT_MANUAL

won't replicate (I have shortened this log file snippet to not clutter
this mail, of course I will submit the full log if wanted):

*** Logfilesnippet start **********************************
[a lot of similar 'replaces' snipped]
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: replace: modifyTimestamp
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: one value, length 15
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: slap_global_control:
unavailable control: 2.16.840.1.113730.3.4.2
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: ==> unique_modify
<cn=test1 test1,dc=kolab,dc=fuhintern,dc=de>
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: => unique_modify
(|(mail=test1 at kolab.fuhintern.de)(uid=test1))
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: str2filter
"(|(mail=test1 at kolab.fuhintern.de)(uid=test1))"
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: begin get_filter
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: OR
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: begin get_filter_list
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: begin get_filter
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: EQUALITY
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: end get_filter 0
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: begin get_filter
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: EQUALITY
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: end get_filter 0
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: end get_filter_list
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: end get_filter 0
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: => bdb_search
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]:
bdb_dn2entry("dc=kolab,dc=fuhintern,dc=de")
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: search_candidates:
base="dc=kolab,dc=fuhintern,dc=de" (0x00000001) scope=2
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: =>
bdb_dn2idl("dc=kolab,dc=fuhintern,dc=de")
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: => bdb_filter_candidates
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]:       AND
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: => bdb_list_candidates
0xa0
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: => bdb_filter_candidates
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]:       OR
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: => bdb_list_candidates
0xa1
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: => bdb_filter_candidates
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]:       EQUALITY
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: =>
bdb_equality_candidates (mail)
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: => key_read
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: bdb_idl_fetch_key:
[c8dff408]
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: <= bdb_index_read:
failed (-30989)
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: <=
bdb_equality_candidates: id=0, first=0, last=0
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: <=
bdb_filter_candidates: id=0 first=0 last=0
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: => bdb_filter_candidates
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]:       EQUALITY
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: =>
bdb_equality_candidates (uid)
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: => key_read
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: bdb_idl_fetch_key:
[36e55cac]
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: <= bdb_index_read:
failed (-30989)
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: <=
bdb_equality_candidates: id=0, first=0, last=0
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: <=
bdb_filter_candidates: id=0 first=0 last=0
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: <=
bdb_list_candidates: id=0 first=0 last=0
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: <=
bdb_filter_candidates: id=0 first=0 last=0
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: <=
bdb_list_candidates: id=0 first=1 last=0
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: <=
bdb_filter_candidates: id=0 first=1 last=0
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: bdb_search_candidates:
id=0 first=1 last=0
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: bdb_search: no candidates
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: send_ldap_result:
conn=23 op=1 p=3
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: send_ldap_result:
err=0 matched="" text=""
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: => unique_search found
0 records
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: bdb_modify: cn=test1
test1,dc=kolab,dc=fuhintern,dc=de
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: bdb_dn2entry("cn=test1
test1,dc=kolab,dc=fuhintern,dc=de")
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: => bdb_dn2id("cn=test1
test1,dc=kolab,dc=fuhintern,dc=de")
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: <= bdb_dn2id: get
failed: DB_NOTFOUND: No matching key/data pair found (-30989)
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: bdb_modify: dn2entry
failed (-30989)
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: send_ldap_result:
conn=23 op=1 p=3
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: send_ldap_result:
err=10 matched="dc=kolab,dc=fuhintern,dc=de" text=""
Aug 31 15:08:20 kolab-slave <debug> slapd[12483]: send_ldap_response:
msgid=2 tag=103 err=32
*** Logfilesnippet start **********************************

Well, tag=103 means 'result from a modify operation', err=32 'no such
object'. Does anyone know what 'msgid=2' means - and if so, would that
be meaningful?

On the other side this one replicates as it should:

dn: cn=test 2,dc=kolab,dc=fuhintern,dc=de
userPassword:: e1NTSEF9UEJ0OVhUZ1R0OXZkeTRNRUJ6WERZNGVpeWxlZWlTTUg=
kolabHomeServer: kolab.fuhintern.de
objectClass: top
objectClass: person
objectClass: inetOrgPerson
objectClass: kolabInetOrgPerson
sn: 2
cn: test 2
givenName: test
mail: tst2 at kolab.fuhintern.de
uid: tst2
telephoneNumber: 1
kolabInvitationPolicy: ACT_MANUAL


Has anyone experienced similar problems? Any hints, please? Do you think
this problem may be caused by the slave clock being in the future for
some time?

Of course I will submit any information one deems to be useful for this.
I just wanted to ask relatively uncluttered at first...

Best regards, Christian