[Date Prev][Date Next]
[Chronological]
[Thread]
[Top]
OL 2.3.19, delta-syncrepl issue
Hi All,
I am testing delta-syncrepl with two Debian Sarge Linux boxes running OL
2.3.19 + 2 patches (ITS #4369 and #4376).
Here the configuration on the provider:
# Accesslog DB definition (slapo-accesslog)
database bdb
suffix "cn=accesslog"
rootdn "cn=root,cn=accesslog"
directory /var/lib/ldap/accesslog
index default eq
index entryCSN,objectClass,reqEnd,reqResult,reqStart
# Let the replica DN have limitless searches
limits dn.exact="cn=syncrepl,ou=Accounts,ou=Apps,dc=example,dc=com"
time.soft=unlimited
time.hard=unlimited size.soft=unlimited size.hard=unlimited
# Primary AMNH database definition
database bdb
suffix "dc=example,dc=com"
rootdn "cn=Manager,dc=example,dc=com"
# syncprov specific indexing
index entryUUID,entryCSN eq
# Let the replica DN have limitless searches
limits dn.exact="cn=syncrepl,ou=Accounts,ou=Apps,dc=example,dc=com"
time.soft=unlimited
time.hard=unlimited size.soft=unlimited size.hard=unlimited
#############################################################
# Syncrepl - Provider configuration
#############################################################
overlay syncprov
syncprov-checkpoint 100 30
syncprov-sessionlog 100
syncprov-nopresent TRUE
syncprov-reloadhint TRUE
#############################################################
# Accesslog - Access Logging overlay (required for delta syncrepl)
#############################################################
overlay accesslog
logdb cn=accesslog
logops writes
# scan the accesslog DB every day, and purge entries older than 28 days
logpurge 28+00:00 01+00:00
Here the configuration on the consumer:
#############################################################
# Syncrepl - Consumer configuration
#############################################################
syncrepl rid=121
provider=ldaps://info-ldap-001.example.com:636
type=refreshAndPersist
retry="5 +"
searchbase="dc=example,dc=com"
bindmethod=simple
binddn="cn=syncrepl,ou=Accounts,ou=Apps,dc=example,dc=com"
credentials=xxxxxxxxxxxx
logbase="cn=accesslog"
schemachecking=on
syncdata=accesslog
The consumer is in a DMZ with a public IP address while the provider is
in the internal network with a private IP address. Traffic from the
consumer to the provider is allowed on port 636.
I modified some entries on the provider. I can see the changes in the
accesslog db. But no synchronization on the consumer.
I do see some strange messages in the provider's log:
[snip]
Feb 3 14:09:51 info-ldap-001 slapd[8424]: conn=43 op=0 BIND
dn="cn=syncrepl,ou=Accounts,ou=Apps,dc=example,dc=com" mech=SIMPLE ssf=0
Feb 3 14:09:51 info-ldap-001 slapd[8424]: do_bind: v3 bind:
"cn=syncrepl,ou=Accounts,ou=Apps,dc=example,dc=com" to
"cn=syncrepl,ou=Accounts,ou=Apps,dc=ex
ample,dc=com"
Feb 3 14:09:51 info-ldap-001 slapd[8424]: send_ldap_result: conn=43
op=0 p=3
Feb 3 14:09:51 info-ldap-001 slapd[8424]: send_ldap_result: err=0
matched="" text=""
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => bdb_entry_get: ndn:
"cn=syncrepl,ou=accounts,ou=apps,dc=example,dc=com"
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => bdb_entry_get: oc:
"(null)", at: "(null)"
Feb 3 14:09:51 info-ldap-001 slapd[8424]:
bdb_dn2entry("cn=syncrepl,ou=accounts,ou=apps,dc=example,dc=com")
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => bdb_entry_get: found
entry: "cn=syncrepl,ou=accounts,ou=apps,dc=example,dc=com"
Feb 3 14:09:51 info-ldap-001 slapd[8424]: bdb_entry_get: rc=0
Feb 3 14:09:51 info-ldap-001 slapd[8424]: send_ldap_response: msgid=1
tag=97 err=0
Feb 3 14:09:51 info-ldap-001 slapd[8424]: conn=43 op=0 RESULT tag=97
err=0 text=
Feb 3 14:09:51 info-ldap-001 slapd[8424]: daemon: activity on 1
descriptor
Feb 3 14:09:51 info-ldap-001 slapd[8424]: daemon: activity on:
Feb 3 14:09:51 info-ldap-001 slapd[8424]: 18r
Feb 3 14:09:51 info-ldap-001 slapd[8424]:
Feb 3 14:09:51 info-ldap-001 slapd[8424]: daemon: read active on 18
Feb 3 14:09:51 info-ldap-001 slapd[8424]: connection_get(18)
Feb 3 14:09:51 info-ldap-001 slapd[8424]: connection_get(18): got
connid=43
Feb 3 14:09:51 info-ldap-001 slapd[8424]: connection_read(18): checking
for input on id=43
Feb 3 14:09:51 info-ldap-001 slapd[8424]: ber_get_next on fd 18 failed
errno=11 (Resource temporarily unavailable)
Feb 3 14:09:51 info-ldap-001 slapd[8424]: daemon: select: listen=7
active_threads=0 tvp=zero
Feb 3 14:09:51 info-ldap-001 slapd[8424]: daemon: select: listen=8
active_threads=0 tvp=zero
Feb 3 14:09:51 info-ldap-001 slapd[8424]: daemon: activity on 1
descriptor
Feb 3 14:09:51 info-ldap-001 slapd[8424]: daemon: activity on:
Feb 3 14:09:51 info-ldap-001 slapd[8424]:
Feb 3 14:09:51 info-ldap-001 slapd[8424]: daemon: select: listen=7
active_threads=0 tvp=zero
Feb 3 14:09:51 info-ldap-001 slapd[8424]: daemon: select: listen=8
active_threads=0 tvp=zero
Feb 3 14:09:51 info-ldap-001 slapd[8424]: do_search
Feb 3 14:09:51 info-ldap-001 slapd[8424]: >>> dnPrettyNormal:
<cn=accesslog>
Feb 3 14:09:51 info-ldap-001 slapd[8424]: <<< dnPrettyNormal:
<cn=accesslog>, <cn=accesslog>
Feb 3 14:09:51 info-ldap-001 slapd[8424]: SRCH "cn=accesslog" 2 0
Feb 3 14:09:51 info-ldap-001 slapd[8424]: 0 0 0
Feb 3 14:09:51 info-ldap-001 slapd[8424]: begin get_filter
Feb 3 14:09:51 info-ldap-001 slapd[8424]: PRESENT
Feb 3 14:09:51 info-ldap-001 slapd[8424]: end get_filter 0
Feb 3 14:09:51 info-ldap-001 slapd[8424]: filter: (objectClass=*)
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => get_ctrls
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => get_ctrls:
oid="1.3.6.1.4.1.4203.1.9.1.1" (noncritical)
Feb 3 14:09:51 info-ldap-001 slapd[8424]: <= get_ctrls: n=1 rc=0 err=""
Feb 3 14:09:51 info-ldap-001 slapd[8424]: attrs:
Feb 3 14:09:51 info-ldap-001 slapd[8424]: reqDN
Feb 3 14:09:51 info-ldap-001 slapd[8424]: reqType
Feb 3 14:09:51 info-ldap-001 slapd[8424]: reqMod
Feb 3 14:09:51 info-ldap-001 slapd[8424]: reqNewRDN
Feb 3 14:09:51 info-ldap-001 slapd[8424]: reqDeleteOldRDN
Feb 3 14:09:51 info-ldap-001 slapd[8424]: reqNewSuperior
Feb 3 14:09:51 info-ldap-001 slapd[8424]: entryCSN
Feb 3 14:09:51 info-ldap-001 slapd[8424]:
Feb 3 14:09:51 info-ldap-001 slapd[8424]: conn=43 op=1 SRCH
base="cn=accesslog" scope=2 deref=0 filter="(objectClass=*)"
Feb 3 14:09:51 info-ldap-001 slapd[8424]: conn=43 op=1 SRCH attr=reqDN
reqType reqMod reqNewRDN reqDeleteOldRDN reqNewSuperior entryCSN
Feb 3 14:09:51 info-ldap-001 slapd[8424]: slap_global_control:
unavailable control: 1.3.6.1.4.1.4203.1.9.1.1
Feb 3 14:09:51 info-ldap-001 slapd[8424]: ==> limits_get: conn=43 op=1
dn="cn=syncrepl,ou=accounts,ou=apps,dc=example,dc=com"
Feb 3 14:09:51 info-ldap-001 slapd[8424]: <== limits_get: type=DN
match=EXACT dn="cn=syncrepl,ou=accounts,ou=apps,dc=example,dc=com"
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => bdb_search
Feb 3 14:09:51 info-ldap-001 slapd[8424]: bdb_dn2entry("cn=accesslog")
Feb 3 14:09:51 info-ldap-001 slapd[8424]: search_candidates:
base="cn=accesslog" (0x00000001) scope=2
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => bdb_dn2idl("cn=accesslog")
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => bdb_filter_candidates
Feb 3 14:09:51 info-ldap-001 slapd[8424]: ^IAND
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => bdb_list_candidates 0xa0
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => bdb_filter_candidates
Feb 3 14:09:51 info-ldap-001 slapd[8424]: ^IPRESENT
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => bdb_presence_candidates
(objectClass)
Feb 3 14:09:51 info-ldap-001 slapd[8424]: <= bdb_filter_candidates:
id=-1 first=1 last=904
Feb 3 14:09:51 info-ldap-001 slapd[8424]: <= bdb_list_candidates: id=-1
first=1 last=904
Feb 3 14:09:51 info-ldap-001 slapd[8424]: <= bdb_filter_candidates:
id=-1 first=1 last=904
Feb 3 14:09:51 info-ldap-001 slapd[8424]: bdb_search_candidates: id=-1
first=1 last=904
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => test_filter
Feb 3 14:09:51 info-ldap-001 slapd[8424]: PRESENT
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => access_allowed: search
access to "cn=accesslog" "objectClass" requested
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => access_allowed: backend
default search access granted to
"cn=syncrepl,ou=Accounts,ou=Apps,dc=example,dc=com"
Feb 3 14:09:51 info-ldap-001 slapd[8424]: <= test_filter 6
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => send_search_entry: conn 43
dn="cn=accesslog"
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => access_allowed: read
access to "cn=accesslog" "entry" requested
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => access_allowed: backend
default read access granted to
"cn=syncrepl,ou=Accounts,ou=Apps,dc=example,dc=com"
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => access_allowed: read
access to "cn=accesslog" "entryCSN" requested
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => access_allowed: backend
default read access granted to
"cn=syncrepl,ou=Accounts,ou=Apps,dc=example,dc=com"
Feb 3 14:09:51 info-ldap-001 slapd[8424]: conn=43 op=1 ENTRY
dn="cn=accesslog"
Feb 3 14:09:51 info-ldap-001 slapd[8424]: <= send_search_entry: conn 43
exit.
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => test_filter
Feb 3 14:09:51 info-ldap-001 slapd[8424]: PRESENT
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => access_allowed: search
access to "cn=root,cn=accesslog" "objectClass" requested
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => access_allowed: backend
default search access granted to
"cn=syncrepl,ou=Accounts,ou=Apps,dc=example,dc=com"
Feb 3 14:09:51 info-ldap-001 slapd[8424]: <= test_filter 6
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => send_search_entry: conn 43
dn="cn=root,cn=accesslog"
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => access_allowed: read
access to "cn=root,cn=accesslog" "entry" requested
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => access_allowed: backend
default read access granted to
"cn=syncrepl,ou=Accounts,ou=Apps,dc=example,dc=com"
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => access_allowed: read
access to "cn=root,cn=accesslog" "entryCSN" requested
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => access_allowed: backend
default read access granted to
"cn=syncrepl,ou=Accounts,ou=Apps,dc=example,dc=com"
Feb 3 14:09:51 info-ldap-001 slapd[8424]: conn=43 op=1 ENTRY
dn="cn=root,cn=accesslog"
Feb 3 14:09:51 info-ldap-001 slapd[8424]: <= send_search_entry: conn 43
exit.
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => test_filter
Feb 3 14:09:51 info-ldap-001 slapd[8424]: PRESENT
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => access_allowed: search
access to "reqStart=20051227213506.000001Z,cn=accesslog" "objectClass"
requested
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => access_allowed: backend
default search access granted to
"cn=syncrepl,ou=Accounts,ou=Apps,dc=example,dc=com"
Feb 3 14:09:51 info-ldap-001 slapd[8424]: <= test_filter 6
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => send_search_entry: conn 43
dn="reqStart=20051227213506.000001Z,cn=accesslog"
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => access_allowed: read
access to "reqStart=20051227213506.000001Z,cn=accesslog" "entry"
requested
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => access_allowed: backend
default read access granted to
"cn=syncrepl,ou=Accounts,ou=Apps,dc=example,dc=com"
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => access_allowed: read
access to "reqStart=20051227213506.000001Z,cn=accesslog" "reqType"
requested
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => access_allowed: backend
default read access granted to
"cn=syncrepl,ou=Accounts,ou=Apps,dc=example,dc=com"
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => access_allowed: read
access to "reqStart=20051227213506.000001Z,cn=accesslog" "reqDN"
requested
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => access_allowed: backend
default read access granted to
"cn=syncrepl,ou=Accounts,ou=Apps,dc=example,dc=com"
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => access_allowed: read
access to "reqStart=20051227213506.000001Z,cn=accesslog" "entryCSN"
requested
Feb 3 14:09:51 info-ldap-001 slapd[8424]: => access_allowed: backend
default read access granted to
"cn=syncrepl,ou=Accounts,ou=Apps,dc=example,dc=com"
Feb 3 14:09:51 info-ldap-001 slapd[8424]: ber_flush failed errno=32
reason="Broken pipe"
Feb 3 14:09:51 info-ldap-001 slapd[8424]: connection_closing: readying
conn=43 sd=18 for close
Feb 3 14:09:51 info-ldap-001 slapd[8424]: send_search_entry: conn 43
ber write failed.
Feb 3 14:09:51 info-ldap-001 slapd[8424]: connection_resched:
attempting closing conn=43 sd=18
Feb 3 14:09:51 info-ldap-001 slapd[8424]: connection_close: conn=43
sd=18
Feb 3 14:09:51 info-ldap-001 slapd[8424]: daemon: removing 18
Feb 3 14:09:51 info-ldap-001 slapd[8424]: conn=43 fd=18 closed
(connection lost on write)
Feb 3 14:09:51 info-ldap-001 slapd[8424]: daemon: activity on 1
descriptor
Feb 3 14:09:51 info-ldap-001 slapd[8424]: daemon: activity on:
Feb 3 14:09:51 info-ldap-001 slapd[8424]: 18r
Feb 3 14:09:51 info-ldap-001 slapd[8424]:
I am not sure what that "broken pipe" error means.
Does someone have an idea? Any help would be much appreciated.
Thanks.
Sam