OpenLDAP
Up to top level
Build   Contrib   Development   Documentation   Historical   Incoming   Software Bugs   Software Enhancements   Web  

Logged in as guest

Viewing Software Bugs/6519
Full headers

From: quanah@zimbra.com
Subject: syncprov sends bogus cookie on accesslog purge
 Compose comment
Download message
State:
0 replies:
2 followups: 1 2

Major security issue: yes  no

Notes:

Notification: 


Date: Tue, 13 Apr 2010 21:07:35 +0000
From: quanah@zimbra.com
To: openldap-its@OpenLDAP.org
Subject: syncprov sends bogus cookie on accesslog purge

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

Followup 1

Download message
Date: Tue, 13 Apr 2010 14:21:16 -0700
From: Quanah Gibson-Mount <quanah@zimbra.com>
To: openldap-its@OpenLDAP.org
Subject: Re: (ITS#6519) syncprov sends bogus cookie on accesslog purge

--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_rea

Message of length 20940 truncated

Followup 2

Download message
Date: Wed, 14 Apr 2010 10:19:58 -0700
From: Quanah Gibson-Mount <quanah@zimbra.com>
To: openldap-its@openldap.org
Subject: Re: (ITS#6519) syncprov sends bogus cookie on accesslog purge

--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
Up to top level
Build   Contrib   Development   Documentation   Historical   Incoming   Software Bugs   Software Enhancements   Web  

Logged in as guest

The OpenLDAP Issue Tracking System uses a hacked version of JitterBug

______________
© Copyright 2013, OpenLDAP Foundation, info@OpenLDAP.org