hi-
i've recently set up delta-syncrepl, with one provider and one consumer. things seemed to be generally working, but i recently noticed that member attributes in group entries were not getting replicated. after a bit of testing, i also found that new groups added to the provider appear to not be replicated to the consumer. it also appears that the operation of adding a group is not being written to the accesslog. on a possibly related note, i'm using the memberof overlay, and the memberof attribute modifications which occur as a result of adding a group are written to the accesslog, and are replicated to the consumer. i'm using 2.4.25, courtesy of ubuntu 11.10. what can i do to better understand what is happening, and why? below is some preliminary data, and log entries using olcloglevel: any
thanks -ben
cat add_group.ldif
dn: cn=test_group,ou=general,ou=groups,dc=example,dc=net changetype: add objectClass: top objectClass: groupOfNames description: test group cn: test_group member: uid=dummy_default,ou=dummy_accounts,ou=other,ou=accounts,dc=example,dc=net
ldapadd -xZZD 'uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=net' -w 'xxxxxxxxxxxx' -f add_group.ldif
adding new entry "cn=test_group,ou=general,ou=groups,dc=example,dc=net"
subsequent ldapsearch on provider:
ldapsearch -xLLLZZD 'uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=net' -w 'xxxxxxxxxxxx' -b 'cn=test_group,ou=general,ou=groups,dc=example,dc=net' -s base '*' '+'
dn: cn=test_group,ou=general,ou=groups,dc=example,dc=net objectClass: top objectClass: groupOfNames description: test group cn: test_group member: uid=dummy_default,ou=dummy_accounts,ou=other,ou=accounts,dc=example, dc=net structuralObjectClass: groupOfNames entryUUID: d68c73e4-10c1-1031-8246-9dfa8daa46e0 creatorsName: uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=net createTimestamp: 20120402034404Z entryCSN: 20120402034404.808333Z#000000#000#000000 modifiersName: uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=net modifyTimestamp: 20120402034404Z entryDN: cn=test_group,ou=general,ou=groups,dc=example,dc=net subschemaSubentry: cn=Subschema hasSubordinates: FALSE
subsequent ldapsearch on consumer:
ldapsearch -xLLLZZD 'uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=net' -w 'xxxxxxxxxxxx' -b 'cn=test_group,ou=general,ou=groups,dc=example,dc=net' -s base '*' '+'
No such object (32) Matched DN: ou=general,ou=groups,dc=example,dc=net
provider log entries:
Apr 1 23:44:04 flip slapd[9255]: daemon: activity on 1 descriptor Apr 1 23:44:04 flip slapd[9255]: daemon: activity on: Apr 1 23:44:04 flip slapd[9255]: Apr 1 23:44:04 flip slapd[9255]: slap_listener_activate(8): Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=8 busy Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=9 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=10 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=11 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: >>> slap_listener(ldap:///) Apr 1 23:44:04 flip slapd[9255]: daemon: listen=8, new connection on 54 Apr 1 23:44:04 flip slapd[9255]: daemon: added 54r (active) listener=(nil) Apr 1 23:44:04 flip slapd[9255]: conn=1378 fd=54 ACCEPT from IP=192.168.1.1:47610 (IP=0.0.0.0:389) Apr 1 23:44:04 flip slapd[9255]: daemon: activity on 2 descriptors Apr 1 23:44:04 flip slapd[9255]: daemon: activity on: Apr 1 23:44:04 flip slapd[9255]: 54r Apr 1 23:44:04 flip slapd[9255]: Apr 1 23:44:04 flip slapd[9255]: daemon: read active on 54 Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=8 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=9 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=10 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=11 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: connection_get(54) Apr 1 23:44:04 flip slapd[9255]: connection_get(54): got connid=1378 Apr 1 23:44:04 flip slapd[9255]: connection_read(54): checking for input on id=1378 Apr 1 23:44:04 flip slapd[9255]: op tag 0x77, time 1333338244 Apr 1 23:44:04 flip slapd[9255]: daemon: activity on 1 descriptor Apr 1 23:44:04 flip slapd[9255]: daemon: activity on: Apr 1 23:44:04 flip slapd[9255]: Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=8 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=9 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=10 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=11 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: conn=1378 op=0 do_extended Apr 1 23:44:04 flip slapd[9255]: conn=1378 op=0 EXT oid=1.3.6.1.4.1.1466.20037 Apr 1 23:44:04 flip slapd[9255]: do_extended: oid=1.3.6.1.4.1.1466.20037 Apr 1 23:44:04 flip slapd[9255]: conn=1378 op=0 STARTTLS Apr 1 23:44:04 flip slapd[9255]: send_ldap_extended: err=0 oid= len=0 Apr 1 23:44:04 flip slapd[9255]: send_ldap_response: msgid=1 tag=120 err=0 Apr 1 23:44:04 flip slapd[9255]: conn=1378 op=0 RESULT oid= err=0 text= Apr 1 23:44:04 flip slapd[9255]: daemon: activity on 1 descriptor Apr 1 23:44:04 flip slapd[9255]: daemon: activity on: Apr 1 23:44:04 flip slapd[9255]: 54r Apr 1 23:44:04 flip slapd[9255]: Apr 1 23:44:04 flip slapd[9255]: daemon: read active on 54 Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=8 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=9 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=10 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=11 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: connection_get(54) Apr 1 23:44:04 flip slapd[9255]: connection_get(54): got connid=1378 Apr 1 23:44:04 flip slapd[9255]: connection_read(54): checking for input on id=1378 Apr 1 23:44:04 flip slapd[9255]: daemon: activity on 1 descriptor Apr 1 23:44:04 flip slapd[9255]: daemon: activity on: Apr 1 23:44:04 flip slapd[9255]: Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=8 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=9 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=10 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=11 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: activity on 1 descriptor Apr 1 23:44:04 flip slapd[9255]: daemon: activity on: Apr 1 23:44:04 flip slapd[9255]: 54r Apr 1 23:44:04 flip slapd[9255]: Apr 1 23:44:04 flip slapd[9255]: daemon: read active on 54 Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=8 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=9 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: connection_get(54) Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=10 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: connection_get(54): got connid=1378 Apr 1 23:44:04 flip slapd[9255]: connection_read(54): checking for input on id=1378 Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=11 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: activity on 1 descriptor Apr 1 23:44:04 flip slapd[9255]: daemon: activity on: Apr 1 23:44:04 flip slapd[9255]: Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=8 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=9 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=10 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=11 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: activity on 1 descriptor Apr 1 23:44:04 flip slapd[9255]: daemon: activity on: Apr 1 23:44:04 flip slapd[9255]: 54r Apr 1 23:44:04 flip slapd[9255]: Apr 1 23:44:04 flip slapd[9255]: daemon: read active on 54 Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=8 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=9 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=10 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=11 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: connection_get(54) Apr 1 23:44:04 flip slapd[9255]: connection_get(54): got connid=1378 Apr 1 23:44:04 flip slapd[9255]: connection_read(54): checking for input on id=1378 Apr 1 23:44:04 flip slapd[9255]: connection_read(54): unable to get TLS client DN, error=49 id=1378 Apr 1 23:44:04 flip slapd[9255]: conn=1378 fd=54 TLS established tls_ssf=128 ssf=128 Apr 1 23:44:04 flip slapd[9255]: daemon: activity on 1 descriptor Apr 1 23:44:04 flip slapd[9255]: daemon: activity on: Apr 1 23:44:04 flip slapd[9255]: Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=8 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=9 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=10 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=11 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: activity on 1 descriptor Apr 1 23:44:04 flip slapd[9255]: daemon: activity on: Apr 1 23:44:04 flip slapd[9255]: 54r Apr 1 23:44:04 flip slapd[9255]: Apr 1 23:44:04 flip slapd[9255]: daemon: read active on 54 Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=8 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=9 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=10 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=11 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: connection_get(54) Apr 1 23:44:04 flip slapd[9255]: connection_get(54): got connid=1378 Apr 1 23:44:04 flip slapd[9255]: connection_read(54): checking for input on id=1378 Apr 1 23:44:04 flip slapd[9255]: op tag 0x60, time 1333338244 Apr 1 23:44:04 flip slapd[9255]: conn=1378 op=1 do_bind Apr 1 23:44:04 flip slapd[9255]: >>> dnPrettyNormal: <uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=net> Apr 1 23:44:04 flip slapd[9255]: <<< dnPrettyNormal: <uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=net>, <uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=net> Apr 1 23:44:04 flip slapd[9255]: conn=1378 op=1 BIND dn="uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=net" method=128 Apr 1 23:44:04 flip slapd[9255]: do_bind: version=3 dn="uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=net" method=128 Apr 1 23:44:04 flip slapd[9255]: ==> hdb_bind: dn: uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=net Apr 1 23:44:04 flip slapd[9255]: bdb_dn2entry("uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=net") Apr 1 23:44:04 flip slapd[9255]: => access_allowed: result not in cache (userPassword) Apr 1 23:44:04 flip slapd[9255]: => access_allowed: auth access to "uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=net" "userPassword" requested Apr 1 23:44:04 flip slapd[9255]: => acl_get: [1] attr userPassword Apr 1 23:44:04 flip slapd[9255]: => acl_mask: access to entry "uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=net", attr "userPassword" requested Apr 1 23:44:04 flip slapd[9255]: => acl_mask: to value by "", (=0) Apr 1 23:44:04 flip slapd[9255]: <= check a_dn_pat: anonymous Apr 1 23:44:04 flip slapd[9255]: <= acl_mask: [1] applying auth(=xd) (stop) Apr 1 23:44:04 flip slapd[9255]: <= acl_mask: [1] mask: auth(=xd) Apr 1 23:44:04 flip slapd[9255]: => slap_access_allowed: auth access granted by auth(=xd) Apr 1 23:44:04 flip slapd[9255]: => access_allowed: auth access granted by auth(=xd) Apr 1 23:44:04 flip slapd[9255]: conn=1378 op=1 BIND dn="uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=net" mech=SIMPLE ssf=0 Apr 1 23:44:04 flip slapd[9255]: do_bind: v3 bind: "uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=net" to "uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=net" Apr 1 23:44:04 flip slapd[9255]: send_ldap_result: conn=1378 op=1 p=3 Apr 1 23:44:04 flip slapd[9255]: send_ldap_result: err=0 matched="" text="" Apr 1 23:44:04 flip slapd[9255]: send_ldap_response: msgid=2 tag=97 err=0 Apr 1 23:44:04 flip slapd[9255]: daemon: activity on 1 descriptor Apr 1 23:44:04 flip slapd[9255]: daemon: activity on: Apr 1 23:44:04 flip slapd[9255]: Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=8 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=9 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=10 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=11 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: activity on 1 descriptor Apr 1 23:44:04 flip slapd[9255]: daemon: activity on: Apr 1 23:44:04 flip slapd[9255]: 54r Apr 1 23:44:04 flip slapd[9255]: Apr 1 23:44:04 flip slapd[9255]: daemon: read active on 54 Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=8 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=9 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=10 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: daemon: epoll: listen=11 active_threads=0 tvp=zero Apr 1 23:44:04 flip slapd[9255]: connection_get(54) Apr 1 23:44:04 flip slapd[9255]: conn=1378 op=1 RESULT tag=97 err=0 text= Apr 1 23:44:04 flip slapd[9255]: connection_get(54): got connid=1378 Apr 1 23:44:04 flip slapd[9255]: connection_read(54): checking for input on id=1378 Apr 1 23:44:04 flip slapd[9255]: op tag 0x68, time 1333338244 Apr 1 23:44:04 flip slapd[9255]: conn=1378 op=2 do_add Apr 1 23:44:04 flip slapd[9255]: conn=1378 op=2 do_add: dn (cn=test_group,ou=general,ou=groups,dc=example,dc=net) Apr 1 23:44:04 flip slapd[9255]: >>> dnPrettyNormal: <cn=test_group,ou=general,ou=groups,dc=example,dc=net> Apr 1 23:44:04 flip slapd[9255]: <<< dnPrettyNormal: <cn=test_group,ou=general,ou=groups,dc=example,dc=net>, <cn=test_group,ou=general,ou=groups,dc=example,dc=net> Apr 1 23:44:04 flip slapd[9255]: conn=1378 op=2 ADD dn="cn=test_group,ou=general,ou=groups,dc=example,dc=net" Apr 1 23:44:04 flip slapd[9255]: >>> dnPretty: <uid=dummy_default,ou=dummy_accounts,ou=other,ou=accounts,dc=example,dc=net> Apr 1 23:44:04 flip slapd[9255]: <<< dnPretty: <uid=dummy_default,ou=dummy_accounts,ou=other,ou=accounts,dc=example,dc=net> Apr 1 23:44:04 flip slapd[9255]: >>> dnNormalize: <uid=dummy_default,ou=dummy_accounts,ou=other,ou=accounts,dc=example,dc=net> Apr 1 23:44:04 flip slapd[9255]: <<< dnNormalize: <uid=dummy_default,ou=dummy_accounts,ou=other,ou=accounts,dc=example,dc=net> Apr 1 23:44:04 flip slapd[9255]: bdb_dn2entry("cn=test_group,ou=general,ou=groups,dc=example,dc=net") Apr 1 23:44:04 flip slapd[9255]: => hdb_dn2id("cn=test_group,ou=general,ou=groups,dc=example,dc=net") Apr 1 23:44:04 flip slapd[9255]: <= hdb_dn2id: get failed: DB_NOTFOUND: No matching key/data pair found (-30988) Apr 1 23:44:04 flip slapd[9255]: hdb_referrals: tag=104 target="cn=test_group,ou=general,ou=groups,dc=example,dc=net" matched="ou=general,ou=groups,dc=example,dc=net" Apr 1 23:44:04 flip slapd[9255]: ==> unique_add <cn=test_group,ou=general,ou=groups,dc=example,dc=net> Apr 1 23:44:04 flip slapd[9255]: ==> hdb_add: cn=test_group,ou=general,ou=groups,dc=example,dc=net Apr 1 23:44:04 flip slapd[9255]: oc_check_required entry (cn=test_group,ou=general,ou=groups,dc=example,dc=net), objectClass "groupOfNames" Apr 1 23:44:04 flip slapd[9255]: oc_check_allowed type "objectClass" Apr 1 23:44:04 flip slapd[9255]: oc_check_allowed type "description" Apr 1 23:44:04 flip slapd[9255]: oc_check_allowed type "cn" Apr 1 23:44:04 flip slapd[9255]: oc_check_allowed type "member" Apr 1 23:44:04 flip slapd[9255]: oc_check_allowed type "structuralObjectClass" Apr 1 23:44:04 flip slapd[9255]: slap_queue_csn: queing 0xb2fcd8ce 20120402034404.808333Z#000000#000#000000 Apr 1 23:44:04 flip slapd[9255]: bdb_dn2entry("cn=test_group,ou=general,ou=groups,dc=example,dc=net") Apr 1 23:44:04 flip slapd[9255]: => hdb_dn2id("cn=test_group,ou=general,ou=groups,dc=example,dc=net") Apr 1 23:44:04 flip slapd[9255]: <= hdb_dn2id: get failed: DB_NOTFOUND: No matching key/data pair found (-30988) Apr 1 23:44:04 flip slapd[9255]: => access_allowed: add access to "ou=general,ou=groups,dc=example,dc=net" "children" requested Apr 1 23:44:04 flip slapd[9255]: <= root access granted Apr 1 23:44:04 flip slapd[9255]: => access_allowed: add access granted by manage(=mwrscxd) Apr 1 23:44:04 flip slapd[9255]: => access_allowed: add access to "cn=test_group,ou=general,ou=groups,dc=example,dc=net" "entry" requested Apr 1 23:44:04 flip slapd[9255]: <= root access granted Apr 1 23:44:04 flip slapd[9255]: => access_allowed: add access granted by manage(=mwrscxd) Apr 1 23:44:04 flip slapd[9255]: => hdb_dn2id_add 0xe8: "cn=test_group,ou=general,ou=groups,dc=example,dc=net" Apr 1 23:44:04 flip slapd[9255]: <= hdb_dn2id_add 0xe8: 0 Apr 1 23:44:04 flip slapd[9255]: => index_entry_add( 232, "cn=test_group,ou=general,ou=groups,dc=example,dc=net" ) Apr 1 23:44:04 flip slapd[9255]: => key_change(ADD,e8) Apr 1 23:44:04 flip slapd[9255]: bdb_idl_insert_key: e8 [0096defd] Apr 1 23:44:04 flip slapd[9255]: <= key_change 0 Apr 1 23:44:04 flip slapd[9255]: => key_change(ADD,e8) Apr 1 23:44:04 flip slapd[9255]: bdb_idl_insert_key: e8 [c14a3e76] Apr 1 23:44:04 flip slapd[9255]: <= key_change 0 Apr 1 23:44:04 flip slapd[9255]: => key_change(ADD,e8) Apr 1 23:44:04 flip slapd[9255]: bdb_idl_insert_key: e8 [943e86da] Apr 1 23:44:04 flip slapd[9255]: <= key_change 0 Apr 1 23:44:04 flip slapd[9255]: => key_change(ADD,e8) Apr 1 23:44:04 flip slapd[9255]: bdb_idl_insert_key: e8 [c866ab14] Apr 1 23:44:04 flip slapd[9255]: <= key_change 0
consumer log entries:
Apr 1 23:44:04 exo slapd[8007]: daemon: activity on 1 descriptor Apr 1 23:44:04 exo slapd[8007]: daemon: activity on: Apr 1 23:44:04 exo slapd[8007]: 12r Apr 1 23:44:04 exo slapd[8007]: Apr 1 23:44:04 exo slapd[8007]: daemon: read active on 12 Apr 1 23:44:04 exo slapd[8007]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Apr 1 23:44:04 exo slapd[8007]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Apr 1 23:44:04 exo slapd[8007]: connection_get(12) Apr 1 23:44:04 exo slapd[8007]: connection_get(12): got connid=0 Apr 1 23:44:04 exo slapd[8007]: =>do_syncrepl rid=000 Apr 1 23:44:04 exo slapd[8007]: =>do_syncrep2 rid=000 Apr 1 23:44:04 exo slapd[8007]: do_syncrep2: rid=000 cookie=rid=000,csn=20120402034404.869559Z#000000#000#000000 Apr 1 23:44:04 exo slapd[8007]: >>> dnPrettyNormal: <uid=dummy_default,ou=dummy_accounts,ou=other,ou=accounts,dc=example,dc=net> Apr 1 23:44:04 exo slapd[8007]: <<< dnPrettyNormal: <uid=dummy_default,ou=dummy_accounts,ou=other,ou=accounts,dc=example,dc=net>, <uid=dummy_default,ou=dummy_accounts,ou=other,ou=accounts,dc=example,dc=net> Apr 1 23:44:04 exo slapd[8007]: slap_queue_csn: queing 0x7f6bd2694710 20120402034404.869559Z#000000#000#000000 Apr 1 23:44:04 exo slapd[8007]: >>> dnPretty: <cn=test_group,ou=general,ou=groups,dc=example,dc=net> Apr 1 23:44:04 exo slapd[8007]: <<< dnPretty: <cn=test_group,ou=general,ou=groups,dc=example,dc=net> Apr 1 23:44:04 exo slapd[8007]: >>> dnNormalize: <cn=test_group,ou=general,ou=groups,dc=example,dc=net> Apr 1 23:44:04 exo slapd[8007]: <<< dnNormalize: <cn=test_group,ou=general,ou=groups,dc=example,dc=net> Apr 1 23:44:04 exo slapd[8007]: >>> dnPretty: <uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=net> Apr 1 23:44:04 exo slapd[8007]: <<< dnPretty: <uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=net> Apr 1 23:44:04 exo slapd[8007]: >>> dnNormalize: <uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=net> Apr 1 23:44:04 exo slapd[8007]: <<< dnNormalize: <uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=net> Apr 1 23:44:04 exo slapd[8007]: => bdb_entry_get: ndn: "uid=dummy_default,ou=dummy_accounts,ou=other,ou=accounts,dc=example,dc=net" Apr 1 23:44:04 exo slapd[8007]: => bdb_entry_get: oc: "(null)", at: "(null)" Apr 1 23:44:04 exo slapd[8007]: bdb_dn2entry("uid=dummy_default,ou=dummy_accounts,ou=other,ou=accounts,dc=example,dc=net") Apr 1 23:44:04 exo slapd[8007]: => bdb_entry_get: found entry: "uid=dummy_default,ou=dummy_accounts,ou=other,ou=accounts,dc=example,dc=net" Apr 1 23:44:04 exo slapd[8007]: bdb_entry_get: rc=0 Apr 1 23:44:04 exo slapd[8007]: hdb_modify: uid=dummy_default,ou=dummy_accounts,ou=other,ou=accounts,dc=example,dc=net Apr 1 23:44:04 exo slapd[8007]: bdb_dn2entry("uid=dummy_default,ou=dummy_accounts,ou=other,ou=accounts,dc=example,dc=net") Apr 1 23:44:04 exo slapd[8007]: bdb_modify_internal: 0x0000001a: uid=dummy_default,ou=dummy_accounts,ou=other,ou=accounts,dc=example,dc=net Apr 1 23:44:04 exo slapd[8007]: <= acl_access_allowed: granted to database root Apr 1 23:44:04 exo slapd[8007]: bdb_modify_internal: add memberOf Apr 1 23:44:04 exo slapd[8007]: dnMatch 17#012#011"cn=dummy_default,ou=dummy_groups,ou=other,ou=groups,dc=example,dc=net"#012#011"cn=test_group,ou=general,ou=groups,dc=example,dc=net" Apr 1 23:44:04 exo slapd[8007]: dnMatch -19#012#011"cn=all_people,ou=general,ou=groups,dc=example,dc=net"#012#011"cn=test_group,ou=general,ou=groups,dc=example,dc=net" Apr 1 23:44:04 exo slapd[8007]: dnMatch 2#012#011"cn=docs,ou=flip,ou=servers,ou=groups,dc=example,dc=net"#012#011"cn=test_group,ou=general,ou=groups,dc=example,dc=net" Apr 1 23:44:04 exo slapd[8007]: dnMatch 5#012#011"cn=monitor,ou=flip,ou=servers,ou=groups,dc=example,dc=net"#012#011"cn=test_group,ou=general,ou=groups,dc=example,dc=net" Apr 1 23:44:04 exo slapd[8007]: dnMatch 5#012#011"cn=systems,ou=flip,ou=servers,ou=groups,dc=example,dc=net"#012#011"cn=test_group,ou=general,ou=groups,dc=example,dc=net" Apr 1 23:44:04 exo slapd[8007]: dnMatch 14#012#011"cn=mail_submitters-non_auth,ou=general,ou=groups,dc=example,dc=net"#012#011"cn=test_group,ou=general,ou=groups,dc=example,dc=net" Apr 1 23:44:04 exo slapd[8007]: bdb_modify_internal: replace modifiersName Apr 1 23:44:04 exo slapd[8007]: bdb_modify_internal: replace entryCSN Apr 1 23:44:04 exo slapd[8007]: bdb_modify_internal: replace modifyTimestamp Apr 1 23:44:04 exo slapd[8007]: oc_check_required entry (uid=dummy_default,ou=dummy_accounts,ou=other,ou=accounts,dc=example,dc=net), objectClass "inetOrgPerson" Apr 1 23:44:04 exo slapd[8007]: oc_check_allowed type "uid" Apr 1 23:44:04 exo slapd[8007]: oc_check_allowed type "objectClass" Apr 1 23:44:04 exo slapd[8007]: oc_check_allowed type "sn" Apr 1 23:44:04 exo slapd[8007]: oc_check_allowed type "cn" Apr 1 23:44:04 exo slapd[8007]: oc_check_allowed type "structuralObjectClass" Apr 1 23:44:04 exo slapd[8007]: oc_check_allowed type "entryUUID" Apr 1 23:44:04 exo slapd[8007]: oc_check_allowed type "creatorsName" Apr 1 23:44:04 exo slapd[8007]: oc_check_allowed type "createTimestamp" Apr 1 23:44:04 exo slapd[8007]: oc_check_allowed type "memberOf" Apr 1 23:44:04 exo slapd[8007]: oc_check_allowed type "modifiersName" Apr 1 23:44:04 exo slapd[8007]: oc_check_allowed type "entryCSN" Apr 1 23:44:04 exo slapd[8007]: oc_check_allowed type "modifyTimestamp" Apr 1 23:44:04 exo slapd[8007]: => key_change(DELETE,1a) Apr 1 23:44:04 exo slapd[8007]: bdb_idl_delete_key: 1a Apr 1 23:44:04 exo slapd[8007]: <= key_change 0 Apr 1 23:44:04 exo slapd[8007]: => key_change(ADD,1a) Apr 1 23:44:04 exo slapd[8007]: bdb_idl_insert_key: 1a [768b75dc] Apr 1 23:44:04 exo slapd[8007]: <= key_change 0 Apr 1 23:44:04 exo slapd[8007]: => key_change(ADD,1a) Apr 1 23:44:04 exo slapd[8007]: bdb_idl_insert_key: 1a [7f0c99d1] Apr 1 23:44:04 exo slapd[8007]: <= key_change 0 Apr 1 23:44:04 exo slapd[8007]: => key_change(ADD,1a) Apr 1 23:44:04 exo slapd[8007]: bdb_idl_insert_key: 1a [0f345f5f] Apr 1 23:44:04 exo slapd[8007]: <= key_change 0 Apr 1 23:44:04 exo slapd[8007]: => key_change(ADD,1a) Apr 1 23:44:04 exo slapd[8007]: bdb_idl_insert_key: 1a [86c8d479] Apr 1 23:44:04 exo slapd[8007]: <= key_change 0 Apr 1 23:44:04 exo slapd[8007]: => key_change(ADD,1a) Apr 1 23:44:04 exo slapd[8007]: bdb_idl_insert_key: 1a [da3d54f3] Apr 1 23:44:04 exo slapd[8007]: <= key_change 0 Apr 1 23:44:04 exo slapd[8007]: => key_change(ADD,1a) Apr 1 23:44:04 exo slapd[8007]: bdb_idl_insert_key: 1a [8d6b497f] Apr 1 23:44:04 exo slapd[8007]: <= key_change 0 Apr 1 23:44:04 exo slapd[8007]: => key_change(ADD,1a) Apr 1 23:44:04 exo slapd[8007]: bdb_idl_insert_key: 1a [144a6a9d] Apr 1 23:44:04 exo slapd[8007]: <= key_change 0 Apr 1 23:44:04 exo slapd[8007]: => key_change(ADD,1a) Apr 1 23:44:04 exo slapd[8007]: bdb_idl_insert_key: 1a Apr 1 23:44:04 exo slapd[8007]: <= key_change 0 Apr 1 23:44:04 exo slapd[8007]: => entry_encode(0x0000001a): Apr 1 23:44:04 exo slapd[8007]: <= entry_encode(0x0000001a): Apr 1 23:44:04 exo slapd[8007]: hdb_modify: updated id=0000001a dn="uid=dummy_default,ou=dummy_accounts,ou=other,ou=accounts,dc=example,dc=net" Apr 1 23:44:04 exo slapd[8007]: send_ldap_result: conn=-1 op=0 p=0 Apr 1 23:44:04 exo slapd[8007]: send_ldap_result: err=0 matched="" text="" Apr 1 23:44:04 exo slapd[8007]: slap_graduate_commit_csn: removing 0x7f6bd267ec10 20120402034404.869559Z#000000#000#000000 Apr 1 23:44:04 exo slapd[8007]: syncrepl_message_to_op: rid=000 be_modify uid=dummy_default,ou=dummy_accounts,ou=other,ou=accounts,dc=example,dc=net (0) Apr 1 23:44:04 exo slapd[8007]: slap_queue_csn: queing 0x7f6bd268f8c0 20120402034404.869559Z#000000#000#000000 Apr 1 23:44:04 exo slapd[8007]: => bdb_entry_get: ndn: "dc=example,dc=net" Apr 1 23:44:04 exo slapd[8007]: => bdb_entry_get: oc: "(null)", at: "(null)" Apr 1 23:44:04 exo slapd[8007]: bdb_dn2entry("dc=example,dc=net") Apr 1 23:44:04 exo slapd[8007]: => bdb_entry_get: found entry: "dc=example,dc=net" Apr 1 23:44:04 exo slapd[8007]: bdb_entry_get: rc=0 Apr 1 23:44:04 exo slapd[8007]: hdb_modify: dc=example,dc=net Apr 1 23:44:04 exo slapd[8007]: bdb_dn2entry("dc=example,dc=net") Apr 1 23:44:04 exo slapd[8007]: bdb_modify_internal: 0x00000001: dc=example,dc=net Apr 1 23:44:04 exo slapd[8007]: <= acl_access_allowed: granted to database root Apr 1 23:44:04 exo slapd[8007]: bdb_modify_internal: replace contextCSN Apr 1 23:44:04 exo slapd[8007]: oc_check_required entry (dc=example,dc=net), objectClass "organization" Apr 1 23:44:04 exo slapd[8007]: oc_check_required entry (dc=example,dc=net), objectClass "dcObject" Apr 1 23:44:04 exo slapd[8007]: oc_check_allowed type "dc" Apr 1 23:44:04 exo slapd[8007]: oc_check_allowed type "objectClass" Apr 1 23:44:04 exo slapd[8007]: oc_check_allowed type "o" Apr 1 23:44:04 exo slapd[8007]: oc_check_allowed type "structuralObjectClass" Apr 1 23:44:04 exo slapd[8007]: oc_check_allowed type "entryUUID" Apr 1 23:44:04 exo slapd[8007]: oc_check_allowed type "creatorsName" Apr 1 23:44:04 exo slapd[8007]: oc_check_allowed type "createTimestamp" Apr 1 23:44:04 exo slapd[8007]: oc_check_allowed type "l" Apr 1 23:44:04 exo slapd[8007]: oc_check_allowed type "st" Apr 1 23:44:04 exo slapd[8007]: oc_check_allowed type "postalCode" Apr 1 23:44:04 exo slapd[8007]: oc_check_allowed type "entryCSN" Apr 1 23:44:04 exo slapd[8007]: oc_check_allowed type "modifiersName" Apr 1 23:44:04 exo slapd[8007]: oc_check_allowed type "modifyTimestamp" Apr 1 23:44:04 exo slapd[8007]: oc_check_allowed type "contextCSN" Apr 1 23:44:04 exo slapd[8007]: => entry_encode(0x00000001): Apr 1 23:44:04 exo slapd[8007]: <= entry_encode(0x00000001): Apr 1 23:44:04 exo slapd[8007]: hdb_modify: updated id=00000001 dn="dc=example,dc=net" Apr 1 23:44:04 exo slapd[8007]: send_ldap_result: conn=-1 op=0 p=0 Apr 1 23:44:04 exo slapd[8007]: send_ldap_result: err=0 matched="" text="" Apr 1 23:44:04 exo slapd[8007]: slap_graduate_commit_csn: removing 0x7f6bd2674970 20120402034404.869559Z#000000#000#000000 Apr 1 23:44:04 exo slapd[8007]: daemon: activity on 1 descriptor Apr 1 23:44:04 exo slapd[8007]: daemon: activity on: Apr 1 23:44:04 exo slapd[8007]: Apr 1 23:44:04 exo slapd[8007]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Apr 1 23:44:04 exo slapd[8007]: daemon: epoll: listen=9 active_threads=0 tvp=NULL
a bit of additional data which may be relevant:
the consumer synrepl config:
{0}rid=0 provider=ldap://dsa.example.net starttls=critical bindmethod=simple binddn="cn=repl- content,ou=exo,ou=services,ou=accounts,dc=example,dc=net" credentials="xxxxx" searchbase="dc=example,dc=net" logbase="cn=accesslog" logfilter="(&(objectClass=auditWriteObject)(reqResult=0))" schemachecking=on type=refreshAndPersist retry="15 +" syncdata=accesslog
using ldapsearch on the consumer, against the provider, the replication dn is able to see the entry in question:
ldapsearch -xLLLZZH 'ldap://dsa.example.net' -D 'cn=repl-content,ou=exo,ou=services,ou=accounts,dc=example,dc=net' -w 'xxxxx' -b 'cn=test_group,ou=general,ou=groups,dc=example,dc=net' -s base '*' '+'
dn: cn=test_group,ou=general,ou=groups,dc=example,dc=net objectClass: top objectClass: groupOfNames description: test group cn: test_group member: uid=dummy_default,ou=dummy_accounts,ou=other,ou=accounts,dc=example, dc=net structuralObjectClass: groupOfNames entryUUID: d68c73e4-10c1-1031-8246-9dfa8daa46e0 creatorsName: uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=net createTimestamp: 20120402034404Z entryCSN: 20120402034404.808333Z#000000#000#000000 modifiersName: uid=dit_admin,ou=role_accounts,ou=accounts,dc=example,dc=net modifyTimestamp: 20120402034404Z entryDN: cn=test_group,ou=general,ou=groups,dc=example,dc=net subschemaSubentry: cn=Subschema hasSubordinates: FALSE
--On Monday, April 02, 2012 12:00 AM -0400 btb@bitrate.net wrote:
hi-
i've recently set up delta-syncrepl, with one provider and one consumer. things seemed to be generally working, but i recently noticed that member attributes in group entries were not getting replicated. after a bit of testing, i also found that new groups added to the provider appear to not be replicated to the consumer. it also appears that the operation of adding a group is not being written to the accesslog. on a possibly related note, i'm using the memberof overlay, and the memberof attribute modifications which occur as a result of adding a group are written to the accesslog, and are replicated to the consumer. i'm using 2.4.25, courtesy of ubuntu 11.10. what can i do to better understand what is happening, and why? below is some preliminary data, and log entries using olcloglevel: any
When you are spending your time using a significantly out of date version of OpenLDAP, and you don't bother to take the time to read the CHANGES file that is publicly available to everyone to see if your issue has already been addressed, you waste everyone's time, but most significantly, your own time. A quick perusal of http://www.openldap.org/software/release/changes.html shows specifically that this was fixed in 2.4.26.
OpenLDAP 2.4.26 Release (2011/06/30) Fixed slapo-memberof with accesslog (ITS#6329,ITS#6766,ITS#6915)
As usual, using vendor built OpenLDAP packages is generally not recommended. http://www.openldap.org/faq/data/cache/1456.html
Also, using Debian/Ubuntu builds that link against GnuTLS are a known security and stability risk.
--Quanah
--
Quanah Gibson-Mount Sr. Member of Technical Staff Zimbra, Inc A Division of VMware, Inc. -------------------- Zimbra :: the leader in open source messaging and collaboration
On Apr 02, 2012, at 14.34, Quanah Gibson-Mount wrote:
A quick perusal of http://www.openldap.org/software/release/changes.html shows specifically that this was fixed in 2.4.26.
ah, of course. you're right. admittedly, i sometimes forget to think about checking change logs - especially when i'm expecting that i've not configured things properly rather than there being a bug. thanks for the reminder. i'll try again after upgrading.
-b
openldap-technical@openldap.org