Issue 6519 - syncprov sends bogus cookie on accesslog purge
Summary: syncprov sends bogus cookie on accesslog purge
Status: VERIFIED FIXED
Alias: None
Product: OpenLDAP
Classification: Unclassified
Component: slapd (show other issues)
Version: 2.4.21
Hardware: All All
: --- normal
Target Milestone: ---
Assignee: OpenLDAP project
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2010-04-13 21:07 UTC by Quanah Gibson-Mount
Modified: 2014-08-01 21:04 UTC (History)
0 users

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this issue.
Description Howard Chu 2010-04-13 16:45:43 UTC
changed notes
changed state Open to Test
moved from Incoming to Software Bugs
Comment 1 Quanah Gibson-Mount 2010-04-13 21:07:35 UTC
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
Comment 2 Quanah Gibson-Mount 2010-04-13 21:21:16 UTC
--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

Comment 3 Quanah Gibson-Mount 2010-04-14 17:19:58 UTC
--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

Comment 4 Quanah Gibson-Mount 2010-04-15 14:42:05 UTC
changed notes
Comment 5 Quanah Gibson-Mount 2010-04-15 14:42:06 UTC
changed state Test to Release
Comment 6 Quanah Gibson-Mount 2010-04-29 08:35:09 UTC
changed notes
changed state Release to Closed
Comment 7 OpenLDAP project 2014-08-01 21:04:28 UTC
fixed in HEAD
fixed in RE24