[Date Prev][Date Next] [Chronological] [Thread] [Top]

RE: Syncrepl and mmr

To: Quanah Gibson-Mount <quanah@zimbra.com>, "openldap-technical@openldap.org" <openldap-technical@openldap.org>
Subject: RE: Syncrepl and mmr
From: "Borresen, John - 0442 - MITLL" <John.Borresen@ll.mit.edu>
Date: Mon, 3 Feb 2014 09:57:40 -0500
Accept-language: en-US
Acceptlanguage: en-US
Content-language: en-US
In-reply-to: <89C7F52021B10496CDC11C3B@[192.168.1.2]>
References: <1BB724A73E57084D89F6F28ED9E651920AD3170DFB@LLE2K7-BE02.mitll.ad.local> <201401301252.s0UCqYiG032646@boole.openldap.org> <BB8429D49E4807C586371E61@[192.168.1.2]> <20140130202839.1351AA624A@edge02.zimbra.com> <2B630E28DF38ECE010CBD25A@[192.168.1.2]> <20140130212629.B2597A6250@edge02.zimbra.com> <DB1FEF6327E2B46EC94F873B@[192.168.1.2]> <20140130213534.84D20A6263@edge02.zimbra.com> <395A5E98A0BA923103457A7D@[192.168.1.2]> <20140130215154.21246A6250@edge02.zimbra.com> <E05E339BB9E6991AE1EE9034@[192.168.1.2]> <20140131135522.883144425D@edge01.zimbra.com> <8B2D174F182D2F00973C48E7@[192.168.1.2]> <20140131182111.1FCCDA6244@edge02.zimbra.com> <DA81C395D0AF170D0D2E8E2A@[192.168.1.2]> <52EBF648.2030003@stroeder.com> <20140131192626.8EDCB44260@edge01.zimbra.com> <70B15C25BB69C8535EA2BF2E@[192.168.1.2]> <20140131193800.428F9A624B@edge02.zimbra.com> <4555DA4EB27A62A899B751DB@[192.168.1.2]> <20140131213521.0E815A626E@edge02.zimbra.com> <89C7F52021B10496CDC11C3B@[192.168.1.2]>
Thread-index: Ac8ezJPR7QbvL+MyT/KroKb4kv5GbACH3SeA
Thread-topic: Syncrepl and mmr

All,

I turned off TLS on both MMR machines, so I could more easily troubleshoot Syncrepl/MMR configuration.  Once over this hurdle, I'll re-incorporate TLS.

The following is a snippet of the SLAPD output-log file:

<MM-SERVER2>
52efa558 => bdb_dn2id("cn=replicator,cn=accesslog")
52efa558 <= bdb_dn2id: get failed: DB_NOTFOUND: No matching key/data pair found (-30989)
52efa558 send_ldap_result: conn=5226 op=0 p=3
52efa558 send_ldap_result: err=49 matched="" text=""
52efa558 send_ldap_response: msgid=1 tag=97 err=49
ber_flush2: 14 bytes to sd 30
  0000:  30 0c 02 01 01 61 07 0a  01 31 04 00 04 00         0....a...1....    
ldap_write: want=14, written=14
  0000:  30 0c 02 01 01 61 07 0a  01 31 04 00 04 00         0....a...1....    
52efa558 conn=5226 op=0 RESULT tag=97 err=49 text=
52efa558 daemon: activity on 1 descriptor
52efa558 daemon: activity on:52efa558 
52efa558 daemon: epoll: listen=7 active_threads=0 tvp=zero
52efa558 daemon: activity on 1 descriptor
52efa558 daemon: activity on:52efa558  30r52efa558 
52efa558 daemon: read active on 30
52efa558 daemon: epoll: listen=7 active_threads=0 tvp=zero
52efa558 connection_get(30)
52efa558 connection_get(30): got connid=5226
52efa558 connection_read(30): checking for input on id=5226
ber_get_next
ldap_read: want=8, got=7
  0000:  30 05 02 01 02 42 00                               0....B.           
ber_get_next: tag 0x30 len 5 contents:
ber_dump: buf=0x1ba86150 ptr=0x1ba86150 end=0x1ba86155 len=5
  0000:  02 01 02 42 00                                     ...B.             
52efa558 op tag 0x42, time 1391437144
ber_get_next
ldap_read: want=8, got=0

52efa558 ber_get_next on fd 30 failed errno=0 (Success)
52efa558 connection_read(30): input error=-2 id=5226, closing.
52efa558 connection_closing: readying conn=5226 sd=30 for close
52efa558 connection_close: deferring conn=5226 sd=30
52efa558 conn=5226 op=1 do_unbind
52efa558 conn=5226 op=1 UNBIND
52efa558 connection_resched: attempting closing conn=5226 sd=30
52efa558 connection_close: conn=5226 sd=30
52efa558 daemon: removing 30
52efa558 conn=5226 fd=30 closed
52efa558 daemon: activity on 1 descriptor
52efa558 daemon: activity on:52efa558 
52efa558 daemon: epoll: listen=7 active_threads=0 tvp=zero
52efa57c daemon: epoll: listen=7 active_threads=0 tvp=zero
52efa57c =>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: 30
ldap_prepare_socket: 30
ldap_connect_to_host: Trying mm-server1-IP_Addr:389
ldap_pvt_connect: fd: 30 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=0x1ba7fb60 ptr=0x1ba7fb60 end=0x1ba7fb93 len=51
  0000:  30 31 02 01 01 60 2c 02  01 03 04 1a 63 6e 3d 72   01...`,.....cn=r  
  0010:  65 70 6c 69 63 61 74 6f  72 2c 63 6e 3d 61 63 63   eplicator,cn=acc  
  0020:  65 73 73 6c 6f 67 80 0b  47 72 70 34 32 2d 41 64   esslog..<replicator-password>
  0030:  6d 31 6e                                           m1n               
ber_scanf fmt ({i) ber:
ber_dump: buf=0x1ba7fb60 ptr=0x1ba7fb65 end=0x1ba7fb93 len=46
  0000:  60 2c 02 01 03 04 1a 63  6e 3d 72 65 70 6c 69 63   `,.....cn=replic  
  0010:  61 74 6f 72 2c 63 6e 3d  61 63 63 65 73 73 6c 6f   ator,cn=accesslo  
  0020:  67 80 0b 47 72 70 34 32  2d 41 64 6d 31 6e         g..<replicator-password>    
ber_flush2: 51 bytes to sd 30
  0000:  30 31 02 01 01 60 2c 02  01 03 04 1a 63 6e 3d 72   01...`,.....cn=r  
  0010:  65 70 6c 69 63 61 74 6f  72 2c 63 6e 3d 61 63 63   eplicator,cn=acc  
  0020:  65 73 73 6c 6f 67 80 0b  47 72 70 34 32 2d 41 64   esslog..<replicator-password>
  0030:  6d 31 6e                                           m1n               
ldap_write: want=51, written=51
  0000:  30 31 02 01 01 60 2c 02  01 03 04 1a 63 6e 3d 72   01...`,.....cn=r  
  0010:  65 70 6c 69 63 61 74 6f  72 2c 63 6e 3d 61 63 63   eplicator,cn=acc  
  0020:  65 73 73 6c 6f 67 80 0b  47 72 70 34 32 2d 41 64   esslog..<replicator-password>
  0030:  6d 31 6e                                           m1n               
ldap_result ld 0x1ba7b1c0 msgid 1
wait4msg ld 0x1ba7b1c0 msgid 1 (infinite timeout)
wait4msg continue ld 0x1ba7b1c0 msgid 1 all 1
** ld 0x1ba7b1c0 Connections:
* host: mm-server1.example.ldap  port: 389  (default)
  refcnt: 2  status: Connected
  last used: Mon Feb  3 09:19:40 2014


** ld 0x1ba7b1c0 Outstanding Requests:
 * msgid 1,  origid 1, status InProgress
   outstanding referrals 0, parent count 0
  ld 0x1ba7b1c0 request count 1 (abandoned 0)
** ld 0x1ba7b1c0 Response Queue:
   Empty
  ld 0x1ba7b1c0 response count 0
ldap_chkResponseList ld 0x1ba7b1c0 msgid 1 all 1
ldap_chkResponseList returns ld 0x1ba7b1c0 NULL
ldap_int_select
read1msg: ld 0x1ba7b1c0 msgid 1 all 1
ber_get_next
ldap_read: want=8, got=8
  0000:  30 0c 02 01 01 61 07 0a                            0....a..          
ldap_read: want=6, got=6
  0000:  01 31 04 00 04 00                                  .1....            
ber_get_next: tag 0x30 len 12 contents:
ber_dump: buf=0x1ba0dc60 ptr=0x1ba0dc60 end=0x1ba0dc6c len=12
  0000:  02 01 01 61 07 0a 01 31  04 00 04 00               ...a...1....      
read1msg: ld 0x1ba7b1c0 msgid 1 message type bind
ber_scanf fmt ({eAA) ber:
ber_dump: buf=0x1ba0dc60 ptr=0x1ba0dc63 end=0x1ba0dc6c len=9
  0000:  61 07 0a 01 31 04 00 04  00                        a...1....         
read1msg: ld 0x1ba7b1c0 0 new referrals
read1msg:  mark request completed, ld 0x1ba7b1c0 msgid 1
request done: ld 0x1ba7b1c0 msgid 1
res_errno: 49, res_error: <>, res_matched: <>
ldap_free_request (origid 1, msgid 1)
ldap_parse_result
ber_scanf fmt ({iAA) ber:
ber_dump: buf=0x1ba0dc60 ptr=0x1ba0dc63 end=0x1ba0dc6c len=9
  0000:  61 07 0a 01 31 04 00 04  00                        a...1....         
ber_scanf fmt (}) ber:
ber_dump: buf=0x1ba0dc60 ptr=0x1ba0dc6c end=0x1ba0dc6c len=0

ldap_msgfree
52efa57c slap_client_connect: URI=ldap://mm-server1.example.ldap DN="cn=replicator,cn=accesslog" ldap_sasl_bind_s failed (49)
ldap_free_connection 1 1
ldap_send_unbind
ber_flush2: 7 bytes to sd 30
  0000:  30 05 02 01 02 42 00                               0....B.           
ldap_write: want=7, written=7
  0000:  30 05 02 01 02 42 00                               0....B.           
ldap_free_connection: actually freed
52efa57c do_syncrepl: rid=001 rc 49 retrying
52efa57c daemon: activity on 1 descriptor
52efa57c daemon: activity on:52efa57c 
52efa57c daemon: epoll: listen=7 active_threads=0 tvp=zero
52efa594 daemon: activity on 1 descriptor
52efa594 daemon: activity on:52efa594 
52efa594 slap_listener_activate(7): 
52efa594 daemon: epoll: listen=7 busy
52efa594 >>> slap_listener(ldap://mm-server2.example.ldap)
52efa594 daemon: listen=7, new connection on 30
52efa594 daemon: added 30r (active) listener=(nil)
52efa594 conn=5227 fd=30 ACCEPT from IP=mm-server1-IP_Addr:56515 (IP=<mm-server2-IP_Addr>:389)
52efa594 daemon: activity on 2 descriptors
52efa594 daemon: activity on:52efa594  30r52efa594 
52efa594 daemon: read active on 30
52efa594 daemon: epoll: listen=7 active_threads=0 tvp=zero
52efa594 connection_get(30)
52efa594 connection_get(30): got connid=5227
52efa594 connection_read(30): checking for input on id=5227
ber_get_next
ldap_read: want=8, got=8
  0000:  30 31 02 01 01 60 2c 02                            01...`,.          
ldap_read: want=43, got=43
  0000:  01 03 04 1a 63 6e 3d 72  65 70 6c 69 63 61 74 6f   ....cn=replicato  
  0010:  72 2c 63 6e 3d 61 63 63  65 73 73 6c 6f 67 80 0b   r,cn=accesslog..  
  0020:  47 72 70 34 32 2d 41 64  6d 31 6e                  <replicator-password>       
ber_get_next: tag 0x30 len 49 contents:
ber_dump: buf=0x1b9fefa0 ptr=0x1b9fefa0 end=0x1b9fefd1 len=49
  0000:  02 01 01 60 2c 02 01 03  04 1a 63 6e 3d 72 65 70   ...`,.....cn=rep  
  0010:  6c 69 63 61 74 6f 72 2c  63 6e 3d 61 63 63 65 73   licator,cn=acces  
  0020:  73 6c 6f 67 80 0b 47 72  70 34 32 2d 41 64 6d 31   slog..<replicator-password>  
  0030:  6e                                                 n                 
52efa594 op tag 0x60, time 1391437204
ber_get_next


I can see that syncrepl is being attempted, but the:
52efa558 <= bdb_dn2id: get failed: DB_NOTFOUND: No matching key/data pair found (-30989)
...
is bothering me...

Thanks in advance
John


-----Original Message-----
From: Quanah Gibson-Mount [mailto:quanah@zimbra.com] 
Sent: Friday, January 31, 2014 4:37 PM
To: Borresen, John - 0442 - MITLL; openldap-technical@openldap.org
Subject: RE: Syncrepl and mmr

--On Friday, January 31, 2014 4:34 PM -0500 "Borresen, John - 0442 - MITLL" 
<John.Borresen@ll.mit.edu> wrote:

> I have turned off TLS for the time being.
>
> Now, I think it is an ACLs issue that I need to figure out...seeing 
> the
> following:
>
> ldap_write: want=531 error=Broken pipe 52ec16ae ber_flush2 failed 
> errno=32 reason="Broken pipe"
> 52ec16ae connection_closing: readying conn=1074 sd=22 for close 
> 52ec16ae send_search_entry: conn 1074  ber write failed.
> 52ec16ae connection_resched: attempting closing conn=1074 sd=22 
> 52ec16ae connection_close: conn=1074 sd=22 52ec16ae daemon: removing 
> 22 52ec16ae conn=1074 fd=22 closed (connection lost on write) 52ec16ae 
> daemon: activity on 1 descriptor 52ec16ae daemon: activity on:52ec16ae 
> 52ec16ae daemon: epoll: listen=7 active_threads=0 tvp=zero

That would not be an acl issue.  broken pipes, flushing problems, etc... I generally see that with firewalls causing problems.

--Quanah

--

Quanah Gibson-Mount
Architect - Server
Zimbra, Inc.
--------------------
Zimbra ::  the leader in open source messaging and collaboration

Prev by Date: Re: Antw: problem with accessing secure ldap --- Low Sensitivity/Aerospace Internal Use Only
Next by Date: Deprecation of back-bdb
Index(es):
- Chronological
- Thread