All,
Hope I am not persona non grata (that is supposed to be funny) based on the responses I received from my last post earlier today.
Tomorrow I am starting from scratch…I have one week to get this working -- afraid to find out what will happen after that.
Anyway, I’ve increased the syslog verbosity on both servers.
mm-server1:
52fbefc2 <= send_search_entry: conn 1013 exit.
52fbefc2 => test_filter
52fbefc2 PRESENT
52fbefc2 => access_allowed: search access to "reqStart=20140211203819.000000Z,cn=accesslog" "objectClass" requested
52fbefc2 => acl_get: [1] attr objectClass
52fbefc2 => acl_mask: access to entry "reqStart=20140211203819.000000Z,cn=accesslog", attr "objectClass" requested
52fbefc2 => acl_mask: to all values by "cn=ldapadmin,dc=group42,dc=ldap", (=0)
52fbefc2 <= check a_dn_pat: uid=replicator,ou=admins,dc=group42,dc=ldap
52fbefc2 <= check a_dn_pat: cn=ldapadmin,dc=group42,dc=ldap
52fbefc2 <= acl_mask: [2] applying write(=wrscxd) (stop)
52fbefc2 <= acl_mask: [2] mask: write(=wrscxd)
52fbefc2 => slap_access_allowed: search access granted by write(=wrscxd)
52fbefc2 => access_allowed: search access granted by write(=wrscxd)
52fbefc2 <= test_filter 6
52fbefc2 => send_search_entry: conn 1013 dn="reqStart=20140211203819.000000Z,cn=accesslog"
52fbefc2 => access_allowed: read access to "reqStart=20140211203819.000000Z,cn=accesslog" "entry" requested
52fbefc2 => acl_get: [1] attr entry
52fbefc2 => acl_mask: access to entry "reqStart=20140211203819.000000Z,cn=accesslog", attr "entry" requested
52fbefc2 => acl_mask: to all values by "cn=ldapadmin,dc=group42,dc=ldap", (=0)
52fbefc2 <= check a_dn_pat: uid=replicator,ou=admins,dc=group42,dc=ldap
52fbefc2 <= check a_dn_pat: cn=ldapadmin,dc=group42,dc=ldap
52fbefc2 <= acl_mask: [2] applying write(=wrscxd) (stop)
52fbefc2 <= acl_mask: [2] mask: write(=wrscxd)
52fbefc2 => slap_access_allowed: read access granted by write(=wrscxd)
52fbefc2 => access_allowed: read access granted by write(=wrscxd)
52fbefc2 => access_allowed: result not in cache (reqType)
52fbefc2 => access_allowed: read access to "reqStart=20140211203819.000000Z,cn=accesslog" "reqType" requested
52fbefc2 => acl_get: [1] attr reqType
52fbefc2 => acl_mask: access to entry "reqStart=20140211203819.000000Z,cn=accesslog", attr "reqType" requested
52fbefc2 => acl_mask: to value by "cn=ldapadmin,dc=group42,dc=ldap", (=0)
52fbefc2 <= check a_dn_pat: uid=replicator,ou=admins,dc=group42,dc=ldap
52fbefc2 <= check a_dn_pat: cn=ldapadmin,dc=group42,dc=ldap
52fbefc2 <= acl_mask: [2] applying write(=wrscxd) (stop)
52fbefc2 <= acl_mask: [2] mask: write(=wrscxd)
52fbefc2 => slap_access_allowed: read access granted by write(=wrscxd)
52fbefc2 => access_allowed: read access granted by write(=wrscxd)
52fbefc2 => access_allowed: result not in cache (reqDN)
52fbefc2 => access_allowed: read access to "reqStart=20140211203819.000000Z,cn=accesslog" "reqDN" requested
52fbefc2 => acl_get: [1] attr reqDN
52fbefc2 => acl_mask: access to entry "reqStart=20140211203819.000000Z,cn=accesslog", attr "reqDN" requested
52fbefc2 => acl_mask: to value by "cn=ldapadmin,dc=group42,dc=ldap", (=0)
52fbefc2 <= check a_dn_pat: uid=replicator,ou=admins,dc=group42,dc=ldap
52fbefc2 <= check a_dn_pat: cn=ldapadmin,dc=group42,dc=ldap
52fbefc2 <= acl_mask: [2] applying write(=wrscxd) (stop)
52fbefc2 <= acl_mask: [2] mask: write(=wrscxd)
52fbefc2 => slap_access_allowed: read access granted by write(=wrscxd)
52fbefc2 => access_allowed: read access granted by write(=wrscxd)
52fbefc2 => access_allowed: result not in cache (reqMod)
52fbefc2 => access_allowed: read access to "reqStart=20140211203819.000000Z,cn=accesslog" "reqMod" requested
52fbefc2 => acl_get: [1] attr reqMod
52fbefc2 => acl_mask: access to entry "reqStart=20140211203819.000000Z,cn=accesslog", attr "reqMod" requested
52fbefc2 => acl_mask: to value by "cn=ldapadmin,dc=group42,dc=ldap", (=0)
52fbefc2 <= check a_dn_pat: uid=replicator,ou=admins,dc=group42,dc=ldap
52fbefc2 <= check a_dn_pat: cn=ldapadmin,dc=group42,dc=ldap
52fbefc2 <= acl_mask: [2] applying write(=wrscxd) (stop)
52fbefc2 <= acl_mask: [2] mask: write(=wrscxd)
52fbefc2 => slap_access_allowed: read access granted by write(=wrscxd)
52fbefc2 => access_allowed: read access granted by write(=wrscxd)
52fbefc2 => access_allowed: result was in cache (reqMod)
52fbefc2 => access_allowed: result was in cache (reqMod)
52fbefc2 => access_allowed: result was in cache (reqMod)
52fbefc2 => access_allowed: result not in cache (entryCSN)
52fbefc2 => access_allowed: read access to "reqStart=20140211203819.000000Z,cn=accesslog" "entryCSN" requested
52fbefc2 => acl_get: [1] attr entryCSN
52fbefc2 => acl_mask: access to entry "reqStart=20140211203819.000000Z,cn=accesslog", attr "entryCSN" requested
52fbefc2 => acl_mask: to value by "cn=ldapadmin,dc=group42,dc=ldap", (=0)
52fbefc2 <= check a_dn_pat: uid=replicator,ou=admins,dc=group42,dc=ldap
52fbefc2 <= check a_dn_pat: cn=ldapadmin,dc=group42,dc=ldap
52fbefc2 <= acl_mask: [2] applying write(=wrscxd) (stop)
52fbefc2 <= acl_mask: [2] mask: write(=wrscxd)
52fbefc2 => slap_access_allowed: read access granted by write(=wrscxd)
52fbefc2 => access_allowed: read access granted by write(=wrscxd)
52fbefc2 conn=1013 op=1 ENTRY dn="reqStart=20140211203819Z,cn=accesslog"
52fbefc2 daemon: activity on 1 descriptor
52fbefc2 daemon: activity on:52fbefc2 18r52fbefc2
52fbefc2 daemon: read active on 18
52fbefc2 daemon: epoll: listen=7 active_threads=0 tvp=zero
52fbefc2 daemon: activity on 1 descriptor
52fbefc2 daemon: activity on:52fbefc2
52fbefc2 daemon: epoll: listen=7 active_threads=0 tvp=zero
52fbefc2 daemon: activity on 1 descriptor
52fbefc2 daemon: activity on:52fbefc2
52fbefc2 daemon: epoll: listen=7 active_threads=0 tvp=zero
52fbefc2 connection_get(18)
52fbefc2 connection_get(18): got connid=1013
52fbefc2 connection_read(18): checking for input on id=1013
ber_get_next
ldap_read: want=8, got=7
0000: 30 05 02 01 03 42 00 0....B.
ber_get_next: tag 0x30 len 5 contents:
ber_dump: buf=0x76a43d0 ptr=0x76a43d0 end=0x76a43d5 len=5
0000: 02 01 03 42 00 ...B.
52fbefc2 op tag 0x42, time 1392242626
ber_get_next
ldap_read: want=8, got=0
mm-server2:
52fbf12a =>do_syncrep2 rid=001
ldap_result ld 0x9715890 msgid 2
wait4msg ld 0x9715890 msgid 2 (infinite timeout)
wait4msg continue ld 0x9715890 msgid 2 all 0
** ld 0x9715890 Connections:
* host: mm-server1.example.ldap port: 389 (default)
refcnt: 2 status: Connected
last used: Wed Feb 12 17:09:46 2014
** ld 0x9715890 Outstanding Requests:
* msgid 2, origid 2, status InProgress
outstanding referrals 0, parent count 0
ld 0x9715890 request count 1 (abandoned 0)
** ld 0x9715890 Response Queue:
Empty
ld 0x9715890 response count 0
ldap_chkResponseList ld 0x9715890 msgid 2 all 0
ldap_chkResponseList returns ld 0x9715890 NULL
ldap_int_select
read1msg: ld 0x9715890 msgid 2 all 0
ber_get_next
ldap_read: want=8, got=8
0000: 30 81 b2 02 01 02 64 48 0.....dH
ldap_read: want=173, got=173
0000: 04 0c 63 6e 3d 61 63 63 65 73 73 6c 6f 67 30 38 ..cn=accesslog08
0010: 30 36 04 08 65 6e 74 72 79 43 53 4e 31 2a 04 28 06..entryCSN1*.(
0020: 32 30 31 34 30 32 30 33 31 38 33 38 33 31 2e 37 20140203183831.7
0030: 35 31 38 33 38 5a 23 30 30 30 30 30 30 23 30 30 51838Z#000000#00
0040: 31 23 30 30 30 30 30 30 a0 63 30 61 04 18 31 2e 1#000000.c0a..1.
0050: 33 2e 36 2e 31 2e 34 2e 31 2e 34 32 30 33 2e 31 3.6.1.4.1.4203.1
0060: 2e 39 2e 31 2e 32 04 45 30 43 0a 01 01 04 00 04 .9.1.2.E0C......
0070: 3c 72 69 64 3d 30 30 31 2c 73 69 64 3d 30 30 31 <rid=001,sid=001
0080: 2c 63 73 6e 3d 32 30 31 34 30 32 30 33 31 38 33 ,csn=20140203183
0090: 38 33 31 2e 37 35 31 38 33 38 5a 23 30 30 30 30 831.751838Z#0000
00a0: 30 30 23 30 30 31 23 30 30 30 30 30 30 00#001#000000
ber_get_next: tag 0x30 len 178 contents:
ber_dump: buf=0x9762840 ptr=0x9762840 end=0x97628f2 len=178
0000: 02 01 02 64 48 04 0c 63 6e 3d 61 63 63 65 73 73 ...dH..cn=access
0010: 6c 6f 67 30 38 30 36 04 08 65 6e 74 72 79 43 53 log0806..entryCS
0020: 4e 31 2a 04 28 32 30 31 34 30 32 30 33 31 38 33 N1*.(20140203183
0030: 38 33 31 2e 37 35 31 38 33 38 5a 23 30 30 30 30 831.751838Z#0000
0040: 30 30 23 30 30 31 23 30 30 30 30 30 30 a0 63 30 00#001#000000.c0
0050: 61 04 18 31 2e 33 2e 36 2e 31 2e 34 2e 31 2e 34 a..1.3.6.1.4.1.4
0060: 32 30 33 2e 31 2e 39 2e 31 2e 32 04 45 30 43 0a 203.1.9.1.2.E0C.
0070: 01 01 04 00 04 3c 72 69 64 3d 30 30 31 2c 73 69 .....<rid=001,si
0080: 64 3d 30 30 31 2c 63 73 6e 3d 32 30 31 34 30 32 d=001,csn=201402
0090: 30 33 31 38 33 38 33 31 2e 37 35 31 38 33 38 5a 03183831.751838Z
00a0: 23 30 30 30 30 30 30 23 30 30 31 23 30 30 30 30 #000000#001#0000
00b0: 30 30 00
read1msg: ld 0x9715890 msgid 2 message type search-entry
ber_scanf fmt ({xx) ber:
ber_dump: buf=0x9762840 ptr=0x9762843 end=0x97628f2 len=175
0000: 64 48 04 0c 63 6e 3d 61 63 63 65 73 73 6c 6f 67 dH..cn=accesslog
0010: 30 38 30 36 04 08 65 6e 74 72 79 43 53 4e 31 2a 0806..entryCSN1*
0020: 04 28 32 30 31 34 30 32 30 33 31 38 33 38 33 31 .(20140203183831
0030: 2e 37 35 31 38 33 38 5a 23 30 30 30 30 30 30 23 .751838Z#000000#
0040: 30 30 31 23 30 30 30 30 30 30 a0 63 30 61 04 18 001#000000.c0a..
0050: 31 2e 33 2e 36 2e 31 2e 34 2e 31 2e 34 32 30 33 1.3.6.1.4.1.4203
0060: 2e 31 2e 39 2e 31 2e 32 04 45 30 43 0a 01 01 04 .1.9.1.2.E0C....
0070: 00 04 3c 72 69 64 3d 30 30 31 2c 73 69 64 3d 30 ..<rid=001,sid=0
0080: 30 31 2c 63 73 6e 3d 32 30 31 34 30 32 30 33 31 01,csn=201402031
0090: 38 33 38 33 31 2e 37 35 31 38 33 38 5a 23 30 30 83831.751838Z#00
00a0: 30 30 30 30 23 30 30 31 23 30 30 30 30 30 30 0000#001#000000
ber_scanf fmt ({a) ber:
ber_dump: buf=0x9762840 ptr=0x976288f end=0x97628f2 len=99
0000: 30 61 04 18 31 2e 33 2e 36 2e 31 2e 34 2e 31 2e 0a..1.3.6.1.4.1.
0010: 34 32 30 33 2e 31 2e 39 2e 31 2e 32 04 45 30 43 4203.1.9.1.2.E0C
0020: 0a 01 01 04 00 04 3c 72 69 64 3d 30 30 31 2c 73 ......<rid=001,s
0030: 69 64 3d 30 30 31 2c 63 73 6e 3d 32 30 31 34 30 id=001,csn=20140
0040: 32 30 33 31 38 33 38 33 31 2e 37 35 31 38 33 38 203183831.751838
0050: 5a 23 30 30 30 30 30 30 23 30 30 31 23 30 30 30 Z#000000#001#000
0060: 30 30 30 000
ber_scanf fmt (o) ber:
ber_dump: buf=0x9762840 ptr=0x97628ab end=0x97628f2 len=71
0000: 04 45 30 43 0a 01 01 04 00 04 3c 72 69 64 3d 30 .E0C......<rid=0
0010: 30 31 2c 73 69 64 3d 30 30 31 2c 63 73 6e 3d 32 01,sid=001,csn=2
0020: 30 31 34 30 32 30 33 31 38 33 38 33 31 2e 37 35 0140203183831.75
0030: 31 38 33 38 5a 23 30 30 30 30 30 30 23 30 30 31 1838Z#000000#001
0040: 23 30 30 30 30 30 30 #000000
ldap_get_dn_ber
ber_scanf fmt ({ml{) ber:
ber_dump: buf=0x9762840 ptr=0x9762843 end=0x97628f2 len=175
0000: 64 48 04 0c 63 6e 3d 61 63 63 65 73 73 6c 6f 67 dH..cn=accesslog
0010: 30 38 30 36 04 08 65 6e 74 72 79 43 53 4e 31 2a 0806..entryCSN1*
0020: 04 28 32 30 31 34 30 32 30 33 31 38 33 38 33 31 .(20140203183831
0030: 2e 37 35 31 38 33 38 5a 23 30 30 30 30 30 30 23 .751838Z#000000#
0040: 30 30 31 23 30 30 30 30 30 30 a0 63 30 61 04 18 001#000000.c0a..
0050: 31 2e 33 2e 36 2e 31 2e 34 2e 31 2e 34 32 30 33 1.3.6.1.4.1.4203
0060: 2e 31 2e 39 2e 31 2e 32 04 45 30 43 0a 01 01 04 .1.9.1.2.E0C....
0070: 00 04 3c 72 69 64 3d 30 30 31 2c 73 69 64 3d 30 ..<rid=001,sid=0
0080: 30 31 2c 63 73 6e 3d 32 30 31 34 30 32 30 33 31 01,csn=201402031
0090: 38 33 38 33 31 2e 37 35 31 38 33 38 5a 23 30 30 83831.751838Z#00
00a0: 30 30 30 30 23 30 30 31 23 30 30 30 30 30 30 0000#001#000000
ber_scanf fmt ({em) ber:
ber_dump: buf=0x9762970 ptr=0x9762970 end=0x97629b5 len=69
0000: 30 43 0a 01 01 04 00 04 3c 72 69 64 3d 30 30 31 0C......<rid=001
0010: 2c 73 69 64 3d 30 30 31 2c 63 73 6e 3d 32 30 31 ,sid=001,csn=201
0020: 34 30 32 30 33 31 38 33 38 33 31 2e 37 35 31 38 40203183831.7518
0030: 33 38 5a 23 30 30 30 30 30 30 23 30 30 31 23 30 38Z#000000#001#0
0040: 30 30 30 30 30 00000
52fbf12a do_syncrep2: rid=001 got empty syncUUID with LDAP_SYNC_ADD (cn=accesslog)
ldap_msgfree
ldap_free_request (origid 2, msgid 2)
ldap_free_connection 1 1
ldap_send_unbind
ber_flush2: 7 bytes to sd 17
0000: 30 05 02 01 03 42 00 0....B.
ldap_write: want=7, written=7
0000: 30 05 02 01 03 42 00 0....B.
ldap_free_connection: actually freed
52fbf12a do_syncrepl: rid=001 rc -1 retrying
52fbf12a daemon: activity on 1 descriptor
52fbf12a daemon: activity on:52fbf12a
52fbf12a daemon: epoll: listen=7 active_threads=0 tvp=zero
52fbf166 daemon: epoll: listen=7 active_threads=0 tvp=zero
52fbf166 =>do_syncrepl rid=001
ldap_create
ldap_url_parse_ext(ldap://mm-server1.example.ldap)
ldap_sasl_bind_s
ldap_sasl_bind
ldap_send_initial_request
ldap_new_connection 1 1 0
ldap_int_open_connection
ldap_connect_to_host: TCP mm-server1.example.ldap:389
ldap_new_socket: 17
ldap_prepare_socket: 17
ldap_connect_to_host: Trying <mm-server1_IP>:389
ldap_pvt_connect: fd: 17 tm: -1 async: 0
attempting to connect:
connect success
ldap_open_defconn: successful
ldap_send_server_request
ber_scanf fmt ({it) ber:
ber_dump: buf=0x9761740 ptr=0x9761740 end=0x9761778 len=56
0000: 30 36 02 01 01 60 31 02 01 03 04 1f 63 6e 3d 6c 06...`1.....cn=l
0010: 64 61 70 61 64 6d 69 6e 2c 64 63 3d 67 72 6f 75 dapadmin,dc=exam
0020: 70 34 32 2c 64 63 3d 6c 64 61 70 80 0b 47 72 70 ple,dc=ldap..<pas
0030: 34 32 2d 41 64 6d 21 6e sword>
ber_scanf fmt ({i) ber:
ber_dump: buf=0x9761740 ptr=0x9761745 end=0x9761778 len=51
0000: 60 31 02 01 03 04 1f 63 6e 3d 6c 64 61 70 61 64 `1.....cn=ldapad
0010: 6d 69 6e 2c 64 63 3d 67 72 6f 75 70 34 32 2c 64 min,dc=example,d
0020: 63 3d 6c 64 61 70 80 0b 47 72 70 34 32 2d 41 64 c=ldap..<passwo
0030: 6d 21 6e rd>
ber_flush2: 56 bytes to sd 17
0000: 30 36 02 01 01 60 31 02 01 03 04 1f 63 6e 3d 6c 06...`1.....cn=l
0010: 64 61 70 61 64 6d 69 6e 2c 64 63 3d 67 72 6f 75 dapadmin,dc=grou
0020: 70 34 32 2c 64 63 3d 6c 64 61 70 80 0b 47 72 70 p42,dc=ldap..<pass
0030: 34 32 2d 41 64 6d 21 6e word>
ldap_write: want=56, written=56
0000: 30 36 02 01 01 60 31 02 01 03 04 1f 63 6e 3d 6c 06...`1.....cn=l
0010: 64 61 70 61 64 6d 69 6e 2c 64 63 3d 67 72 6f 75 dapadmin,dc=grou
0020: 70 34 32 2c 64 63 3d 6c 64 61 70 80 0b 47 72 70 p42,dc=ldap..<pas
0030: 34 32 2d 41 64 6d 21 6e sword>
ldap_result ld 0x950ac90 msgid 1
Thanks in advance…
John D. Borresen (Dave)
Linux/Unix Systems Administrator
MIT Lincoln Laboratory
Surveillance Systems Group
244 Wood St
Lexington, MA 02420
Email: john.borresen@ll.mit.edu