changed notes changed state Open to Test moved from Incoming to Software Bugs
Full_Name: Quanah Gibson-Mount Version: 2.4.21 OS: Linux 2.6 URL: ftp://ftp.openldap.org/incoming/ Submission from: (NULL) (75.111.45.108) When the accesslog database is purged, the syncprov overlay sends a bogus cookie response to open syncrepl clients, causing them to drop connection. This bogus cookie should never have been sent. From the slapd log on the provider, we have the initial connection: Apr 13 13:16:43 freelancer slapd[4276]: conn=1013 fd=18 ACCEPT from IP=10.18.97.26:60034 (IP=10.18.97.79:389) Apr 13 13:16:43 freelancer slapd[4276]: conn=1013 op=0 EXT oid=1.3.6.1.4.1.1466.20037 Apr 13 13:16:43 freelancer slapd[4276]: conn=1013 op=0 STARTTLS Apr 13 13:16:43 freelancer slapd[4276]: conn=1013 op=0 RESULT oid= err=0 text= Apr 13 13:16:43 freelancer slapd[4276]: conn=1013 fd=18 TLS established tls_ssf=256 ssf=256 Apr 13 13:16:43 freelancer slapd[4276]: conn=1013 op=1 BIND dn="uid=zmreplica,cn=admins,cn=zimbra" method=128 Apr 13 13:16:43 freelancer slapd[4276]: conn=1013 op=1 BIND dn="uid=zmreplica,cn=admins,cn=zimbra" mech=SIMPLE ssf=0 Apr 13 13:16:43 freelancer slapd[4276]: conn=1013 op=1 RESULT tag=97 err=0 text= Apr 13 13:16:43 freelancer slapd[4276]: conn=1013 op=2 SRCH base="cn=accesslog" scope=2 deref=0 filter="(&(objectClass=auditWriteObject)(reqResult=0))" Apr 13 13:16:43 freelancer slapd[4276]: conn=1013 op=2 SRCH attr=reqDN reqType reqMod reqNewRDN reqDeleteOldRDN reqNewSuperior entryCSN Approximately 30 minutes later (which is my setting), the purge takes place: Apr 13 13:45:54 freelancer slapd[4276]: slap_queue_csn: queing 0x446a7200 20100413204554.501961Z#000000#000#000000 Apr 13 13:45:54 freelancer slapd[4276]: slap_queue_csn: queing 0x395e788 20100413204554.501961Z#000000#000#000000 Apr 13 13:45:54 freelancer slapd[4276]: slap_graduate_commit_csn: removing 0x3f94690 20100413204554.501961Z#000000#000#000000 Apr 13 13:45:54 freelancer slapd[4276]: syncprov_sendresp: cookie=rid=100,csn=20100413204554.501961Z#000000#000#000000 Apr 13 13:45:54 freelancer slapd[4276]: conn=2605 op=2 RESULT tag=105 err=0 text= Apr 13 13:45:54 freelancer slapd[4276]: slap_graduate_commit_csn: removing 0x3f80030 20100413204554.501961Z#000000#000#000000 Apr 13 13:45:54 freelancer slapd[4276]: conn=2605 op=3 SRCH base="" scope=2 deref=3 filter="(&(zimbraId=58a68771-fded-4aa2-baab-e1ac349e0028)(objectClass=zimbraAccount))" Apr 13 13:45:54 freelancer slapd[4276]: conn=2605 op=3 SEARCH RESULT tag=101 err=0 nentries=1 text= Apr 13 13:45:54 freelancer slapd[4276]: conn=2605 fd=20 closed (connection lost) Apr 13 13:45:54 freelancer slapd[4276]: conn=2603 fd=38 closed (connection lost) Apr 13 13:45:54 freelancer slapd[4276]: conn=2602 fd=37 closed (connection lost) Apr 13 13:45:56 freelancer slapd[4276]: syncprov_sendresp: cookie= Apr 13 13:45:56 freelancer slapd[4276]: conn=1013 op=3 UNBIND Apr 13 13:45:56 freelancer slapd[4276]: conn=1013 fd=18 closed As you can see, an empty cookie is sent, and the consumer immediately closes connection, re-establishing it shortly thereafter: Apr 13 13:46:56 freelancer slapd[4276]: conn=2671 fd=18 ACCEPT from IP=10.18.97.26:36796 (IP=10.18.97.79:389) Apr 13 13:46:56 freelancer slapd[4276]: conn=2671 op=0 EXT oid=1.3.6.1.4.1.1466.20037 Apr 13 13:46:56 freelancer slapd[4276]: conn=2671 op=0 STARTTLS Apr 13 13:46:56 freelancer slapd[4276]: conn=2671 op=0 RESULT oid= err=0 text= Apr 13 13:46:56 freelancer slapd[4276]: conn=2671 fd=18 TLS established tls_ssf=256 ssf=256 Apr 13 13:46:56 freelancer slapd[4276]: conn=2671 op=1 BIND dn="uid=zmreplica,cn=admins,cn=zimbra" method=128 Apr 13 13:46:56 freelancer slapd[4276]: conn=2671 op=1 BIND dn="uid=zmreplica,cn=admins,cn=zimbra" mech=SIMPLE ssf=0 Apr 13 13:46:56 freelancer slapd[4276]: conn=2671 op=1 RESULT tag=97 err=0 text= Apr 13 13:46:56 freelancer slapd[4276]: conn=2671 op=2 SRCH base="cn=accesslog" scope=2 deref=0 filter="(&(objectClass=auditWriteObject)(reqResult=0))" Apr 13 13:46:56 freelancer slapd[4276]: conn=2671 op=2 SRCH attr=reqDN reqType reqMod reqNewRDN reqDeleteOldRDN reqNewSuperior entryCSN Apr 13 13:46:56 freelancer slapd[4276]: Entry reqStart=20100413204554.000009Z,cn=accesslog CSN 20100413204554.501961Z#000000#000#000000 older or equal to ctx 20100413204554.501961Z#000000#000#000000 Apr 13 13:46:56 freelancer slapd[4276]: syncprov_search_response: cookie=rid=100,csn=20100413204656.794873Z#000000#000#000000
--On Tuesday, April 13, 2010 9:07 PM +0000 openldap-its@OpenLDAP.org wrote: Here is the -d -1 output from the provider during this time period. You can clearly see part way through where the empty cookie is sent after a delete operation is completed. 01c0: 69 6c 31 24 04 22 75 73 65 72 2e 32 37 36 40 66 il1$."user.276@f 01d0: 72 65 65 6c 61 6e 63 65 72 2e 6c 61 62 2e 7a 69 reelancer.lab.zi 01e0: 6d 62 72 61 2e 63 6f 6d 30 11 04 03 75 69 64 31 mbra.com0...uid1 01f0: 0a 04 08 75 73 65 72 2e 32 37 36 30 43 04 0b 6f ...user.2760C..o 0200: 62 6a 65 63 74 43 6c 61 73 73 31 34 04 14 6f 72 bjectClass14..or 0210: 67 61 6e 69 7a 61 74 69 6f 6e 61 6c 50 65 72 73 ganizationalPers 0220: 6f 6e 04 0d 7a 69 6d 62 72 61 41 63 63 6f 75 6e on..zimbraAccoun 0230: 74 04 0d 61 6d 61 76 69 73 41 63 63 6f 75 6e 74 t..amavisAccount 0240: 30 2f 04 1a 7a 69 6d 62 72 61 50 61 73 73 77 6f 0/..zimbraPasswo 0250: 72 64 4d 6f 64 69 66 69 65 64 54 69 6d 65 31 11 rdModifiedTime1. 0260: 04 0f 32 30 31 30 30 34 31 33 32 30 34 35 35 34 ..20100413204554 0270: 5a 30 10 04 02 63 6e 31 0a 04 08 75 73 65 72 2e Z0...cn1...user. 0280: 32 37 36 30 2d 04 0e 7a 69 6d 62 72 61 4d 61 69 2760-..zimbraMai 0290: 6c 48 6f 73 74 31 1b 04 19 66 72 65 65 6c 61 6e lHost1...freelan 02a0: 63 65 72 2e 6c 61 62 2e 7a 69 6d 62 72 61 2e 63 cer.lab.zimbra.c 02b0: 6f 6d om <= send_search_entry: conn 2605 exit. send_ldap_result: conn=2605 op=3 p=3 send_ldap_result: err=0 matched="" text="" send_ldap_response: msgid=4 tag=101 err=0 ber_flush2: 14 bytes to sd 20 0000: 30 0c 02 01 04 65 07 0a 01 00 04 00 04 00 0....e........ tls_write: want=35, written=35 0000: 17 03 01 00 1e 59 2c c6 87 d7 64 fe a5 b5 74 e9 .....Y,...d...t. 0010: ff cf e6 00 22 30 dc 8b ed 0f c2 c9 aa d7 64 43 ...."0........dC 0020: 9a d2 3a ..: ldap_write: want=14, written=14 0000: 30 0c 02 01 04 65 07 0a 01 00 04 00 04 00 0....e........ conn=2605 op=3 SEARCH RESULT tag=101 err=0 nentries=1 text= daemon: activity on 1 descriptor daemon: activity on: 20r daemon: read active on 20 daemon: epoll: listen=7 active_threads=0 tvp=zero daemon: epoll: listen=8 active_threads=0 tvp=zero connection_get(20) connection_get(20): got connid=2605 connection_read(20): checking for input on id=2605 ber_get_next tls_read: want=5, got=5 0000: 15 03 01 00 12 ..... tls_read: want=18, got=18 0000: 07 3e f1 34 3c 74 48 e4 2d 64 da bf 16 b2 f0 e3 .>.4<tH.-d...... 0010: 82 1f .. TLS trace: SSL3 alert read:warning:close notify ldap_read: want=8, got=0 ber_get_next on fd 20 failed errno=0 (Success) connection_read(20): input error=-2 id=2605, closing. connection_closing: readying conn=2605 sd=20 for close connection_close: conn=2605 sd=20 daemon: activity on 1 descriptor daemon: activity on: daemon: epoll: listen=7 active_threads=0 tvp=zero daemon: epoll: listen=8 active_threads=0 tvp=zero daemon: removing 20 tls_write: want=23, written=23 0000: 15 03 01 00 12 d7 55 9d 59 8c 18 96 64 bf e7 f9 ......U.Y...d... 0010: 9e 2c 0a 91 c4 9d ba .,..... TLS trace: SSL3 alert write:warning:close notify conn=2605 fd=20 closed (connection lost) daemon: activity on 1 descriptor daemon: activity on: 38r daemon: read active on 38 daemon: epoll: listen=7 active_threads=0 tvp=zero daemon: epoll: listen=8 active_threads=0 tvp=zero connection_get(38) connection_get(38): got connid=2603 connection_read(38): checking for input on id=2603 ber_get_next tls_read: want=5, got=5 0000: 15 03 01 00 12 ..... tls_read: want=18, got=18 0000: 81 9f e4 91 64 6e bc c8 ba 53 be e0 5e 5e 75 f9 ....dn...S..^^u. 0010: ac e4 .. TLS trace: SSL3 alert read:warning:close notify ldap_read: want=8, got=0 ber_get_next on fd 38 failed errno=0 (Success) connection_read(38): input error=-2 id=2603, closing. connection_closing: readying conn=2603 sd=38 for close connection_close: conn=2603 sd=38 daemon: removing 38 tls_write: want=23, written=23 0000: 15 03 01 00 12 50 be 29 9e e3 e6 b8 88 55 46 64 .....P.).....UFd 0010: 08 d4 83 45 e4 df b1 ...E... TLS trace: SSL3 alert write:warning:close notify conn=2603 fd=38 closed (connection lost) daemon: activity on 1 descriptor daemon: activity on: daemon: epoll: listen=7 active_threads=0 tvp=zero daemon: epoll: listen=8 active_threads=0 tvp=zero daemon: activity on 1 descriptor daemon: activity on: 37r daemon: read active on 37 daemon: epoll: listen=7 active_threads=0 tvp=zero daemon: epoll: listen=8 active_threads=0 tvp=zero connection_get(37) connection_get(37): got connid=2602 connection_read(37): checking for input on id=2602 ber_get_next tls_read: want=5, got=5 0000: 15 03 01 00 12 ..... tls_read: want=18, got=18 0000: b8 e7 6e 24 27 de cc 33 fd 77 b9 29 8a a4 5e 79 ..n$'..3.w.)..^y 0010: 53 7c S| TLS trace: SSL3 alert read:warning:close notify ldap_read: want=8, got=0 ber_get_next on fd 37 failed errno=0 (Success) connection_read(37): input error=-2 id=2602, closing. connection_closing: readying conn=2602 sd=37 for close connection_close: conn=2602 sd=37 daemon: removing 37 tls_write: want=23, written=23 0000: 15 03 01 00 12 7c e4 28 fb 15 b4 f9 dc 69 44 4d .....|.(.....iDM 0010: 40 21 1b 78 7f 41 35 @!.x.A5 TLS trace: SSL3 alert write:warning:close notify conn=2602 fd=37 closed (connection lost) daemon: activity on 1 descriptor daemon: activity on: daemon: epoll: listen=7 active_threads=0 tvp=zero daemon: epoll: listen=8 active_threads=0 tvp=zero daemon: epoll: listen=7 active_threads=0 tvp=zero daemon: epoll: listen=8 active_threads=0 tvp=zero => hdb_search bdb_dn2entry("cn=accesslog") => access_allowed: search access to "cn=accesslog" "entry" requested <= root access granted => access_allowed: search access granted by manage(=mwrscxd) search_candidates: base="cn=accesslog" (0x00000001) scope=1 => hdb_dn2idl("cn=accesslog") => bdb_filter_candidates AND => bdb_list_candidates 0xa0 => bdb_filter_candidates OR => bdb_list_candidates 0xa1 => bdb_filter_candidates EQUALITY => bdb_equality_candidates (objectClass) => key_read bdb_idl_fetch_key: [b49d1940] <= bdb_index_read: failed (-30988) <= bdb_equality_candidates: id=0, first=0, last=0 <= bdb_filter_candidates: id=0 first=0 last=0 => bdb_filter_candidates LE => bdb_inequality_candidates (reqStart) => key_read bdb_idl_fetch_key: <= bdb_index_read 2 candidates => key_read bdb_idl_fetch_key: <= bdb_index_read: failed (-30988) <= bdb_inequality_candidates: id=2, first=9, last=10 <= bdb_filter_candidates: id=2 first=9 last=10 <= bdb_list_candidates: id=2 first=9 last=10 <= bdb_filter_candidates: id=2 first=9 last=10 <= bdb_list_candidates: id=2 first=9 last=10 <= bdb_filter_candidates: id=2 first=9 last=10 bdb_search_candidates: id=2 first=9 last=10 entry_decode: "" <= entry_decode() => test_filter LE => access_allowed: search access to "reqStart=20100413191807.000004Z,cn=accesslog" "reqStart" requested <= root access granted => access_allowed: search access granted by manage(=mwrscxd) <= test_filter 6 entry_decode: "" <= entry_decode() => test_filter LE => access_allowed: search access to "reqStart=20100413191807.000009Z,cn=accesslog" "reqStart" requested <= root access granted => access_allowed: search access granted by manage(=mwrscxd) <= test_filter 6 send_ldap_result: conn=-1 op=0 p=0 send_ldap_result: err=0 matched="" text="" => bdb_entry_get: ndn: "reqStart=20100413191807.000004Z,cn=accesslog" => bdb_entry_get: oc: "(null)", at: "(null)" bdb_dn2entry("reqStart=20100413191807.000004Z,cn=accesslog") => bdb_entry_get: found entry: "reqStart=20100413191807.000004Z,cn=accesslog" bdb_entry_get: rc=0 => test_filter AND => test_filter_and => test_filter EQUALITY => access_allowed: search access to "reqStart=20100413191807.000004Z,cn=accesslog" "objectClass" requested => dn: [1] cn=accesslog => acl_get: [1] matched => acl_get: [1] attr objectClass => acl_mask: access to entry "reqStart=20100413191807.000004Z,cn=accesslog", attr "objectClass" requested => acl_mask: to value by "uid=zmreplica,cn=admins,cn=zimbra", (=0) <= check a_dn_pat: uid=zimbra,cn=admins,cn=zimbra <= check a_dn_pat: cn=config <= check a_dn_pat: uid=zmreplica,cn=admins,cn=zimbra <= acl_mask: [3] applying read(=rscxd) (stop) <= acl_mask: [3] mask: read(=rscxd) => slap_access_allowed: search access granted by read(=rscxd) => access_allowed: search access granted by read(=rscxd) <= test_filter 6 => test_filter EQUALITY => access_allowed: search access to "reqStart=20100413191807.000004Z,cn=accesslog" "reqResult" requested => dn: [1] cn=accesslog => acl_get: [1] matched => acl_get: [1] attr reqResult => acl_mask: access to entry "reqStart=20100413191807.000004Z,cn=accesslog", attr "reqResult" requested => acl_mask: to value by "uid=zmreplica,cn=admins,cn=zimbra", (=0) <= check a_dn_pat: uid=zimbra,cn=admins,cn=zimbra <= check a_dn_pat: cn=config <= check a_dn_pat: uid=zmreplica,cn=admins,cn=zimbra <= acl_mask: [3] applying read(=rscxd) (stop) <= acl_mask: [3] mask: read(=rscxd) => slap_access_allowed: search access granted by read(=rscxd) => access_allowed: search access granted by read(=rscxd) <= test_filter 6 <= test_filter_and 6 <= test_filter 6 syncprov_matchops: sid ffffffff fscope 1 rc 6 ==> hdb_delete: reqStart=20100413191807.000004Z,cn=accesslog bdb_dn2entry("reqStart=20100413191807.000004Z,cn=accesslog") => access_allowed: delete access to "cn=accesslog" "children" requested <= root access granted => access_allowed: delete access granted by manage(=mwrscxd) => access_allowed: delete access to "reqStart=20100413191807.000004Z,cn=accesslog" "entry" requested <= root access granted => access_allowed: delete access granted by manage(=mwrscxd) => hdb_dn2id_delete 0x9: "reqStart=20100413191807.000004Z,cn=accesslog" <= hdb_dn2id_delete 0x9: 0 => index_entry_del( 9, "reqStart=20100413191807.000004Z,cn=accesslog" ) => key_change(DELETE,9) bdb_idl_delete_key: 9 [66ec5701] <= key_change 0 => key_change(DELETE,9) bdb_idl_delete_key: 9 [98599c51] <= key_change 0 => key_change(DELETE,9) bdb_idl_delete_key: 9 [61e2b421] <= key_change 0 => key_change(DELETE,9) bdb_idl_delete_key: 9 [0096defd] <= key_change 0 => key_change(DELETE,9) bdb_idl_delete_key: 9 <= key_change 0 => key_change(DELETE,9) bdb_idl_delete_key: 9 <= key_change 0 => key_change(DELETE,9) bdb_idl_delete_key: 9 [80000000] <= key_change 0 => key_change(DELETE,9) bdb_idl_delete_key: 9 <= key_change 0 <= index_entry_del( 9, "reqStart=20100413191807.000004Z,cn=accesslog" ) success ====> bdb_cache_delete( 9 ) hdb_delete: deleted id=00000009 dn="reqStart=20100413191807.000004Z,cn=accesslog" send_ldap_result: conn=-1 op=0 p=0 send_ldap_result: err=0 matched="" text="" syncprov_sendresp: cookie= => send_search_entry: conn 1013 dn="reqStart=20100413191807.000004Z,cn=accesslog" => access_allowed: read access to "reqStart=20100413191807.000004Z,cn=accesslog" "entry" requested => dn: [1] cn=accesslog => acl_get: [1] matched => acl_get: [1] attr entry => acl_mask: access to entry "reqStart=20100413191807.000004Z,cn=accesslog", attr "entry" requested => acl_mask: to all values by "uid=zmreplica,cn=admins,cn=zimbra", (=0) <= check a_dn_pat: uid=zimbra,cn=admins,cn=zimbra <= check a_dn_pat: cn=config <= check a_dn_pat: uid=zmreplica,cn=admins,cn=zimbra <= acl_mask: [3] applying read(=rscxd) (stop) <= acl_mask: [3] mask: read(=rscxd) => slap_access_allowed: read access granted by read(=rscxd) => access_allowed: read access granted by read(=rscxd) conn=1013 op=2 ENTRY dn="reqStart=20100413191807.000004Z,cn=accesslog" ber_flush2: 112 bytes to sd 18 0000: 30 6e 02 01 03 64 30 04 2c 72 65 71 53 74 61 72 0n...d0.,reqStar 0010: 74 3d 32 30 31 30 30 34 31 33 31 39 31 38 30 37 t=20100413191807 0020: 2e 30 30 30 30 30 34 5a 2c 63 6e 3d 61 63 63 65 .000004Z,cn=acce 0030: 73 73 6c 6f 67 30 00 a0 37 30 35 04 18 31 2e 33 sslog0..705..1.3 0040: 2e 36 2e 31 2e 34 2e 31 2e 34 32 30 33 2e 31 2e .6.1.4.1.4203.1. 0050: 39 2e 31 2e 32 04 19 30 17 0a 01 03 04 10 43 30 9.1.2..0......C0 0060: b3 35 9f 63 47 af b6 f3 66 1b e4 76 6c 54 04 00 .5.cG...f..vlT.. tls_write: want=186, written=186 0000: 17 03 01 00 20 77 40 e5 e4 99 b3 f0 07 5a 3d c9 .... w@......Z=. 0010: 11 4b 1d c2 97 45 d2 d1 d6 52 c9 89 74 37 b7 c9 .K...E...R..t7.. 0020: fd 72 3d cf 8d 17 03 01 00 90 f3 dc 6b 91 cd f5 .r=.........k... 0030: 6a 87 21 7c 61 fa 8e 69 ea f8 21 9e ec ea 85 a2 j.!|a..i..!..... 0040: 9d f0 8a 32 82 66 62 9c bf 15 00 02 ef c0 d0 34 ...2.fb........4 0050: 16 4e 2d a6 25 e3 5f 0d 95 68 2d 7b 74 8f 41 a8 .N-.%._..h-{t.A. 0060: 4b 51 93 78 46 d6 8e 44 33 12 44 05 6c 37 09 03 KQ.xF..D3.D.l7.. 0070: b5 d3 13 58 c2 7a 82 9e 3e 0e 4d 6f f0 90 a7 3d ...X.z..>.Mo...= 0080: 4b 5f 44 5f 7d 3a cc 28 93 b6 3f 37 05 c8 c6 77 K_D_}:.(..?7...w 0090: f4 40 72 97 ea a9 0e a0 ab 98 09 5c b8 08 54 a7 .@r........\..T. 00a0: 7d 2e 72 6f 5f 14 db e4 0b bc 0b ca 1f 3e ae 83 }.ro_........>.. 00b0: 37 51 c5 82 44 b7 b4 00 9a 35 7Q..D....5 ldap_write: want=112, written=112 0000: 30 6e 02 01 03 64 30 04 2c 72 65 71 53 74 61 72 0n...d0.,reqStar 0010: 74 3d 32 30 31 30 30 34 31 33 31 39 31 38 30 37 t=20100413191807 0020: 2e 30 30 30 30 30 34 5a 2c 63 6e 3d 61 63 63 65 .000004Z,cn=acce 0030: 73 73 6c 6f 67 30 00 a0 37 30 35 04 18 31 2e 33 sslog0..705..1.3 0040: 2e 36 2e 31 2e 34 2e 31 2e 34 32 30 33 2e 31 2e .6.1.4.1.4203.1. 0050: 39 2e 31 2e 32 04 19 30 17 0a 01 03 04 10 43 30 9.1.2..0......C0 0060: b3 35 9f 63 47 af b6 f3 66 1b e4 76 6c 54 04 00 .5.cG...f..vlT.. <= send_search_entry: conn 1013 exit. => bdb_entry_get: ndn: "reqStart=20100413191807.000009Z,cn=accesslog" => bdb_entry_get: oc: "(null)", at: "(null)" bdb_dn2entry("reqStart=20100413191807.000009Z,cn=accesslog") => bdb_entry_get: found entry: "reqStart=20100413191807.000009Z,cn=accesslog" bdb_entry_get: rc=0 => test_filter AND => test_filter_and => test_filter EQUALITY => access_allowed: search access to "reqStart=20100413191807.000009Z,cn=accesslog" "objectClass" requested => dn: [1] cn=accesslog => acl_get: [1] matched => acl_get: [1] attr objectClass => acl_mask: access to entry "reqStart=20100413191807.000009Z,cn=accesslog", attr "objectClass" requested => acl_mask: to value by "uid=zmreplica,cn=admins,cn=zimbra", (=0) <= check a_dn_pat: uid=zimbra,cn=admins,cn=zimbra <= check a_dn_pat: cn=config <= check a_dn_pat: uid=zmreplica,cn=admins,cn=zimbra <= acl_mask: [3] applying read(=rscxd) (stop) <= acl_mask: [3] mask: read(=rscxd) => slap_access_allowed: search access granted by read(=rscxd) => access_allowed: search access granted by read(=rscxd) <= test_filter 6 => test_filter EQUALITY => access_allowed: search access to "reqStart=20100413191807.000009Z,cn=accesslog" "reqResult" requested => dn: [1] cn=accesslog => acl_get: [1] matched => acl_get: [1] attr reqResult => acl_mask: access to entry "reqStart=20100413191807.000009Z,cn=accesslog", attr "reqResult" requested => acl_mask: to value by "uid=zmreplica,cn=admins,cn=zimbra", (=0) <= check a_dn_pat: uid=zimbra,cn=admins,cn=zimbra <= check a_dn_pat: cn=config <= check a_dn_pat: uid=zmreplica,cn=admins,cn=zimbra <= acl_mask: [3] applying read(=rscxd) (stop) <= acl_mask: [3] mask: read(=rscxd) => slap_access_allowed: search access granted by read(=rscxd) => access_allowed: search access granted by read(=rscxd) <= test_filter 6 <= test_filter_and 6 <= test_filter 6 syncprov_matchops: sid ffffffff fscope 1 rc 6 ==> hdb_delete: reqStart=20100413191807.000009Z,cn=accesslog bdb_dn2entry("reqStart=20100413191807.000009Z,cn=accesslog") => access_allowed: delete access to "cn=accesslog" "children" requested <= root access granted => access_allowed: delete access granted by manage(=mwrscxd) => access_allowed: delete access to "reqStart=20100413191807.000009Z,cn=accesslog" "entry" requested <= root access granted => access_allowed: delete access granted by manage(=mwrscxd) => hdb_dn2id_delete 0xa: "reqStart=20100413191807.000009Z,cn=accesslog" <= hdb_dn2id_delete 0xa: 0 => index_entry_del( 10, "reqStart=20100413191807.000009Z,cn=accesslog" ) => key_change(DELETE,a) bdb_idl_delete_key: a [66ec5701] <= key_change 0 => key_change(DELETE,a) bdb_idl_delete_key: a [98599c51] <= key_change 0 => key_change(DELETE,a) bdb_idl_delete_key: a [61e2b421] <= key_change 0 => key_change(DELETE,a) bdb_idl_delete_key: a [0096defd] <= key_change 0 => key_change(DELETE,a) bdb_idl_delete_key: a <= key_change 0 => key_change(DELETE,a) bdb_idl_delete_key: a <= key_change 0 => key_change(DELETE,a) bdb_idl_delete_key: a [80000000] <= key_change 0 => key_change(DELETE,a) bdb_idl_delete_key: a <= key_change 0 <= index_entry_del( 10, "reqStart=20100413191807.000009Z,cn=accesslog" ) success ====> bdb_cache_delete( 10 ) daemon: activity on 1 descriptor daemon: activity on: 18r daemon: read active on 18 daemon: epoll: listen=7 active_threads=0 tvp=zero daemon: epoll: listen=8 active_threads=0 tvp=zero connection_get(18) connection_get(18): got connid=1013 connection_read(18): checking for input on id=1013 ber_get_next tls_read: want=5, got=5 0000: 17 03 01 00 20 .... tls_read: want=32, got=32 0000: d7 e0 2b 7c 92 57 a1 11 a4 0b d8 76 81 f5 15 e7 ..+|.W.....v.... 0010: b3 58 97 b6 10 65 aa 30 9d 38 e3 2c 90 63 a5 9d .X...e.0.8.,.c.. tls_read: want=5, got=5 0000: 17 03 01 00 20 .... tls_read: want=32, got=32 0000: 2a bd 8d 49 d2 58 87 51 8f b4 32 e7 70 07 8c 13 *..I.X.Q..2.p... 0010: 1d d2 19 c8 43 a1 fb 28 89 4f cf df a8 58 6c 2a ....C..(.O...Xl* ldap_read: want=8, got=7 0000: 30 05 02 01 04 42 00 0....B. ber_get_next: tag 0x30 len 5 contents: ber_dump: buf=0x3f69170 ptr=0x3f69170 end=0x3f69175 len=5 0000: 02 01 04 42 00 ...B. op tag 0x42, time 1271191556 ber_get_next tls_read: want=5, got=5 0000: 15 03 01 00 20 .... tls_read: want=32, got=32 0000: 04 7f 9e 27 41 7e af b2 de ec b2 b5 e9 b5 15 d7 ...'A~.......... 0010: 5f 1a 9a 5f 64 8e cf d5 8e a6 d4 e2 8b 4e 27 6e _.._d........N'n TLS trace: SSL3 alert read:warning:close notify ldap_read: want=8, got=0 ber_get_next on fd 18 failed errno=0 (Success) connection_read(18): input error=-2 id=1013, closing. connection_closing: readying conn=1013 sd=18 for close hdb_delete: deleted id=0000000a dn="reqStart=20100413191807.000009Z,cn=accesslog" daemon: activity on 1 descriptor daemon: activity on: send_ldap_result: conn=-1 op=0 p=0 connection_close: deferring conn=1013 sd=18 send_ldap_result: err=0 matched="" text="" daemon: epoll: listen=7 active_threads=0 tvp=zero daemon: epoll: listen=8 active_threads=0 tvp=zero conn=1013 op=3 do_unbind conn=1013 op=3 UNBIND hdb_modify: cn=accesslog bdb_dn2entry("cn=accesslog") bdb_modify_internal: 0x00000001: cn=accesslog <= acl_access_allowed: granted to database root bdb_modify_internal: replace entryCSN connection_resched: attempting closing conn=1013 sd=18 connection_close: conn=1013 sd=18 => key_change(DELETE,1) bdb_idl_delete_key: 1 daemon: removing 18 <= key_change 0 tls_write: want=37, written=37 0000: 15 03 01 00 20 32 b4 ef e6 42 1b 72 80 46 e6 b5 .... 2...B.r.F.. 0010: d5 f4 ad 44 4f 37 eb c5 03 75 69 29 17 f3 be ac ...DO7...ui).... 0020: 4e 60 80 e2 4e N`..N => key_change(ADD,1) bdb_idl_insert_key: 1 TLS trace: SSL3 alert write:warning:close notify <= key_change 0 => entry_encode(0x00000001): <= entry_encode(0x00000001): conn=1013 fd=18 closed --Quanah -- Quanah Gibson-Mount Principal Software Engineer Zimbra, Inc -------------------- Zimbra :: the leader in open source messaging and collaboration
--On Tuesday, April 13, 2010 9:22 PM +0000 quanah@zimbra.com wrote: > --On Tuesday, April 13, 2010 9:07 PM +0000 openldap-its@OpenLDAP.org > wrote: > > Here is the -d -1 output from the provider during this time period. You > can clearly see part way through where the empty cookie is sent after a > delete operation is completed. I can confirm Update of /repo/OpenLDAP/pkg/ldap/servers/slapd/overlays Modified Files: accesslog.c 1.105 -> 1.106 Log Message: ITS#6519 don't replicate purge deletes CVS Web URLs: http://www.openldap.org/devel/cvsweb.cgi/servers/slapd/overlays/ http://www.openldap.org/devel/cvsweb.cgi/servers/slapd/overlays/accesslog.c Changes are generally available on cvs.openldap.org (and CVSweb) within 30 minutes of being committed. fixes the issue. --Quanah -- Quanah Gibson-Mount Principal Software Engineer Zimbra, Inc -------------------- Zimbra :: the leader in open source messaging and collaboration
changed notes
changed state Test to Release
changed notes changed state Release to Closed
fixed in HEAD fixed in RE24