Hi, I've been trying to use syncrepl to replicate my cn=config tree
and have been running into some issues. After running into a number
of things not working I completely stripped everything down and
attempted to follow test049 by building it from scratch. I've gotten
it to work by running two instances of slapd on the same machine, on
both machines, but I still can't get it to work between the two
machines.
System info
Provider:
FreeBSD 7.1-PRERELEASE FreeBSD 7.1-PRERELEASE #0: Sat Nov 15 18:38:32 EST 2008
OpenLDAP 2.4.16
Consumer:
FreeBSD 7.2-STABLE FreeBSD 7.2-STABLE #1: Mon Jun 1 12:29:14 EDT 2009
OpenLDAP 2.4.16
My process is this:
First I create slapd.d directories for both servers and populate them
with a basic config
mkdir slapd.d
slapadd -n 0 -F slapd.d <<END
dn: cn=config
objectClass: olcGlobal
cn: config
olcLogLevel: Trace
olcLogLevel: Config
olcLogLevel: Stats
olcLogLevel: Sync
olcLogLevel: Args
olcLogLevel: Conns
dn: olcDatabase={0}config,cn=config
objectClass: olcDatabaseConfig
olcRootDN: $MANAGER
olcRootPW: $CONFIGPW
olcDatabase: {0}config
dn: olcOverlay=syncprov,olcDatabase={0}config,cn=config
objectClass: olcOverlayConfig
objectClass: olcSyncProvConfig
olcOverlay: syncprov
END
chown -R ldap:ldap slapd.d
Then I launch slapd with:
/usr/local/libexec/slapd -h $URI -u ldap -g ldap
on both machines.
At this point I can do ldapsearch on both servers and get back the
correct results. I then do:
ldapmodify -D "$MANAGER" -x -w "$CONFIGPW" <<END
dn: olcDatabase={0}config,cn=config
changetype: modify
add: olcSyncRepl
olcSyncRepl: rid=001 provider=$PROVIDER_URI binddn="$MANAGER" bindmethod=simple
credentials=$CONFIGPW searchbase="cn=config" type=refreshAndPersist
retry="3 5 300 5" timeout=3
-
add: olcUpdateRef
olcUpdateRef: $PROVIDER_URI
END
At this point I start logging the same error over and over. Here are
the log messages I get:
Consumer:
Jun 3 19:55:35 jet slapd[51003]: =>do_syncrepl rid=001
Jun 3 19:55:35 jet slapd[51003]: =>do_syncrep2 rid=001
Jun 3 19:55:35 jet slapd[51003]: connection_get(7)
Jun 3 19:55:35 jet slapd[51003]: connection_get(7): got connid=0
Jun 3 19:55:35 jet slapd[51003]: =>do_syncrepl rid=001
Jun 3 19:55:35 jet slapd[51003]: =>do_syncrep2 rid=001
Jun 3 19:55:35 jet slapd[51003]: >>> dnPrettyNormal: <cn=config>
Jun 3 19:55:35 jet slapd[51003]: <<< dnPrettyNormal: <cn=config>, <cn=config>
Jun 3 19:55:35 jet slapd[51003]: >>> dnPretty: <cn=config>
Jun 3 19:55:35 jet slapd[51003]: <<< dnPretty: <cn=config>
Jun 3 19:55:35 jet slapd[51003]: >>> dnNormalize: <cn=config>
Jun 3 19:55:35 jet slapd[51003]: <<< dnNormalize: <cn=config>
Jun 3 19:55:35 jet slapd[51003]: >>> dnPretty: <cn=config>
Jun 3 19:55:35 jet slapd[51003]: <<< dnPretty: <cn=config>
Jun 3 19:55:35 jet slapd[51003]: >>> dnNormalize: <cn=config>
Jun 3 19:55:35 jet slapd[51003]: <<< dnNormalize: <cn=config>
Jun 3 19:55:35 jet slapd[51003]: >>> dnPretty: <cn=config>
Jun 3 19:55:35 jet slapd[51003]: <<< dnPretty: <cn=config>
Jun 3 19:55:35 jet slapd[51003]: >>> dnNormalize: <cn=config>
Jun 3 19:55:35 jet slapd[51003]: <<< dnNormalize: <cn=config>
Jun 3 19:55:35 jet slapd[51003]: >>> dnPretty: <cn=Subschema>
Jun 3 19:55:35 jet slapd[51003]: <<< dnPretty: <cn=Subschema>
Jun 3 19:55:35 jet slapd[51003]: >>> dnNormalize: <cn=Subschema>
Jun 3 19:55:35 jet slapd[51003]: <<< dnNormalize: <cn=subschema>
Jun 3 19:55:35 jet slapd[51003]: syncrepl_entry: rid=001
LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_ADD)
Jun 3 19:55:35 jet slapd[51003]: dn_callback : entries have identical
CSN cn=config 20090603203325.264042Z#000000#000#000000
Jun 3 19:55:35 jet slapd[51003]: send_ldap_result: conn=-1 op=0 p=0
Jun 3 19:55:35 jet slapd[51003]: send_ldap_result: err=0 matched="" text=""
Jun 3 19:55:35 jet slapd[51003]: syncrepl_entry: rid=001 be_search (0)
Jun 3 19:55:35 jet slapd[51003]: syncrepl_entry: rid=001 cn=config
Jun 3 19:55:35 jet slapd[51003]: syncrepl_entry: rid=001 entry
unchanged, ignored (cn=config)
Jun 3 19:55:35 jet slapd[51003]: connection_get(7)
Jun 3 19:55:35 jet slapd[51003]: connection_get(7): got connid=0
Jun 3 19:55:35 jet slapd[51003]: =>do_syncrepl rid=001
Jun 3 19:55:35 jet slapd[51003]: =>do_syncrep2 rid=001
Jun 3 19:55:35 jet slapd[51003]: connection_get(7)
Jun 3 19:55:35 jet slapd[51003]: connection_get(7): got connid=0
Jun 3 19:55:35 jet slapd[51003]: =>do_syncrepl rid=001
Jun 3 19:55:35 jet slapd[51003]: =>do_syncrep2 rid=001
Jun 3 19:55:35 jet slapd[51003]: connection_get(7)
Jun 3 19:55:35 jet slapd[51003]: connection_get(7): got connid=0
Jun 3 19:55:35 jet slapd[51003]: =>do_syncrepl rid=001
Jun 3 19:55:35 jet slapd[51003]: =>do_syncrep2 rid=001
Jun 3 19:55:35 jet slapd[51003]: >>> dnPrettyNormal: <cn=schema,cn=config>
Jun 3 19:55:35 jet slapd[51003]: <<< dnPrettyNormal:
<cn=schema,cn=config>, <cn=schema,cn=config>
Jun 3 19:55:35 jet slapd[51003]: >>> dnPretty: <cn=config>
Jun 3 19:55:35 jet slapd[51003]: <<< dnPretty: <cn=config>
Jun 3 19:55:35 jet slapd[51003]: >>> dnNormalize: <cn=config>
Jun 3 19:55:35 jet slapd[51003]: <<< dnNormalize: <cn=config>
Jun 3 19:55:35 jet slapd[51003]: >>> dnPretty: <cn=config>
Jun 3 19:55:35 jet slapd[51003]: <<< dnPretty: <cn=config>
Jun 3 19:55:35 jet slapd[51003]: >>> dnNormalize: <cn=config>
Jun 3 19:55:35 jet slapd[51003]: <<< dnNormalize: <cn=config>
Jun 3 19:55:35 jet slapd[51003]: >>> dnPretty: <cn=schema,cn=config>
Jun 3 19:55:35 jet slapd[51003]: <<< dnPretty: <cn=schema,cn=config>
Jun 3 19:55:35 jet slapd[51003]: >>> dnNormalize: <cn=schema,cn=config>
Jun 3 19:55:35 jet slapd[51003]: <<< dnNormalize: <cn=schema,cn=config>
Jun 3 19:55:35 jet slapd[51003]: >>> dnPretty: <cn=Subschema>
Jun 3 19:55:35 jet slapd[51003]: <<< dnPretty: <cn=Subschema>
Jun 3 19:55:35 jet slapd[51003]: >>> dnNormalize: <cn=Subschema>
Jun 3 19:55:35 jet slapd[51003]: <<< dnNormalize: <cn=subschema>
Jun 3 19:55:35 jet slapd[51003]: syncrepl_entry: rid=001
LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_ADD)
Jun 3 19:55:35 jet slapd[51003]: send_ldap_result: conn=-1 op=0 p=0
Jun 3 19:55:35 jet slapd[51003]: send_ldap_result: err=0 matched="" text=""
Jun 3 19:55:35 jet slapd[51003]: syncrepl_entry: rid=001 be_search (0)
Jun 3 19:55:35 jet slapd[51003]: syncrepl_entry: rid=001 cn=schema,cn=config
Jun 3 19:55:35 jet slapd[51003]: conn=-1 op=0: config_add_internal:
DN="cn=schema,cn=config" already exists
Jun 3 19:55:35 jet slapd[51003]: send_ldap_result: conn=-1 op=0 p=0
Jun 3 19:55:35 jet slapd[51003]: send_ldap_result: err=68 matched="" text=""
Jun 3 19:55:35 jet slapd[51003]: syncrepl_entry: rid=001 be_add
cn=schema,cn=config (68)
Jun 3 19:55:35 jet slapd[51003]: send_ldap_result: conn=-1 op=0 p=0
Jun 3 19:55:35 jet slapd[51003]: send_ldap_result: err=0 matched="" text=""
Jun 3 19:55:35 jet slapd[51003]: send_ldap_result: conn=-1 op=0 p=0
Jun 3 19:55:35 jet slapd[51003]: send_ldap_result: err=1 matched="" text=""
Jun 3 19:55:35 jet slapd[51003]: null_callback : error code 0x1
Jun 3 19:55:35 jet slapd[51003]: syncrepl_entry: rid=001 be_modify
cn=schema,cn=config (1)
Jun 3 19:55:35 jet slapd[51003]: syncrepl_entry: rid=001 be_modify failed (1)
Jun 3 19:55:35 jet slapd[51003]: connection_get(7)
Jun 3 19:55:35 jet slapd[51003]: connection_get(7): got connid=0
Jun 3 19:55:35 jet slapd[51003]: do_syncrepl: rid=001 rc 1 retrying
(4 retries left)
Provider:
Jun 3 17:02:36 rock slapd[75268]: slap_listener_activate(6):
Jun 3 17:02:36 rock slapd[75268]: >>> slap_listener($PROV_URI)
Jun 3 17:02:36 rock slapd[75268]: conn=391 fd=8 ACCEPT from
IP=$CONS_IP:56003 (IP=$PROV_IP:389)
Jun 3 17:02:36 rock slapd[75268]: connection_get(8): got connid=391
Jun 3 17:02:36 rock slapd[75268]: connection_read(8): checking for
input on id=391
Jun 3 17:02:36 rock slapd[75268]: conn=391 op=0 do_bind
Jun 3 17:02:36 rock slapd[75268]: >>> dnPrettyNormal: <cn=manager,cn=config>
Jun 3 17:02:36 rock slapd[75268]: <<< dnPrettyNormal:
<cn=manager,cn=config>, <cn=manager,cn=config>
Jun 3 17:02:36 rock slapd[75268]: conn=391 op=0 BIND
dn="cn=manager,cn=config" method=128
Jun 3 17:02:36 rock slapd[75268]: do_bind: version=3
dn="cn=manager,cn=config" method=128
Jun 3 17:02:36 rock slapd[75268]: conn=391 op=0 BIND
dn="cn=manager,cn=config" mech=SIMPLE ssf=0
Jun 3 17:02:36 rock slapd[75268]: do_bind: v3 bind:
"cn=manager,cn=config" to "cn=manager,cn=config"
Jun 3 17:02:36 rock slapd[75268]: send_ldap_result: conn=391 op=0 p=3
Jun 3 17:02:36 rock slapd[75268]: send_ldap_response: msgid=1 tag=97 err=0
Jun 3 17:02:36 rock slapd[75268]: conn=391 op=0 RESULT tag=97 err=0 text=
Jun 3 17:02:36 rock slapd[75268]: connection_get(8): got connid=391
Jun 3 17:02:36 rock slapd[75268]: connection_read(8): checking for
input on id=391
Jun 3 17:02:36 rock slapd[75268]: conn=391 op=1 do_search
Jun 3 17:02:36 rock slapd[75268]: >>> dnPrettyNormal: <cn=config>
Jun 3 17:02:36 rock slapd[75268]: <<< dnPrettyNormal: <cn=config>, <cn=config>
Jun 3 17:02:36 rock slapd[75268]: => get_ctrls
Jun 3 17:02:36 rock slapd[75268]: => get_ctrls:
oid="1.3.6.1.4.1.4203.1.9.1.1" (noncritical)
Jun 3 17:02:36 rock slapd[75268]: => get_ctrls:
oid="2.16.840.1.113730.3.4.2" (critical)
Jun 3 17:02:36 rock slapd[75268]: <= get_ctrls: n=2 rc=0 err=""
Jun 3 17:02:36 rock slapd[75268]: conn=391 op=1 SRCH base="cn=config"
scope=2 deref=0 filter="(objectClass=*)"
Jun 3 17:02:36 rock slapd[75268]: conn=391 op=1 SRCH attr=* +
Jun 3 17:02:36 rock slapd[75268]: send_ldap_result: conn=391 op=1 p=3
Jun 3 17:02:36 rock last message repeated 2 times
Jun 3 17:02:36 rock slapd[75268]: => send_search_entry: conn 391 dn="cn=config"
Jun 3 17:02:36 rock slapd[75268]: <= send_search_entry: conn 391 exit.
Jun 3 17:02:36 rock slapd[75268]: => send_search_entry: conn 391
dn="cn=schema,cn=config"
Jun 3 17:02:36 rock slapd[75268]: connection_get(8): got connid=391
Jun 3 17:02:36 rock slapd[75268]: connection_write(8): waking output for id=391
Jun 3 17:02:36 rock slapd[75268]: <= send_search_entry: conn 391 exit.
Jun 3 17:02:36 rock slapd[75268]: => send_search_entry: conn 391
dn="cn={0}core,cn=schema,cn=config"
Jun 3 17:02:36 rock slapd[75268]: connection_get(8): got connid=391
Jun 3 17:02:36 rock slapd[75268]: connection_write(8): waking output for id=391
Jun 3 17:02:36 rock slapd[75268]: <= send_search_entry: conn 391 exit.
Jun 3 17:02:36 rock slapd[75268]: => send_search_entry: conn 391
dn="cn={1}cosine,cn=schema,cn=config"
Jun 3 17:02:36 rock slapd[75268]: connection_get(8): got connid=391
Jun 3 17:02:36 rock slapd[75268]: connection_write(8): waking output for id=391
Jun 3 17:02:36 rock slapd[75268]: <= send_search_entry: conn 391 exit.
Jun 3 17:02:36 rock slapd[75268]: => send_search_entry: conn 391
dn="cn={2}inetorgperson,cn=schema,cn=config"
Jun 3 17:02:36 rock slapd[75268]: <= send_search_entry: conn 391 exit.
Jun 3 17:02:36 rock slapd[75268]: => send_search_entry: conn 391
dn="cn={3}nis,cn=schema,cn=config"
Jun 3 17:02:36 rock slapd[75268]: <= send_search_entry: conn 391 exit.
Jun 3 17:02:36 rock slapd[75268]: => send_search_entry: conn 391
dn="olcDatabase={-1}frontend,cn=config"
Jun 3 17:02:36 rock slapd[75268]: <= send_search_entry: conn 391 exit.
Jun 3 17:02:36 rock slapd[75268]: => send_search_entry: conn 391
dn="olcDatabase={0}config,cn=config"
Jun 3 17:02:36 rock slapd[75/: <= send_search_entry: conn 391 exit.
Jun 3 17:02:36 rock slapd[75268]: => send_search_entry: conn 391
dn="olcOverlay={0}syncprov,olcDatabase={0}config,cn=config"
Jun 3 17:02:36 rock slapd[75268]: <= send_search_entry: conn 391 exit.
Jun 3 17:02:36 rock slapd[75268]: send_ldap_result: conn=391 op=1 p=3
Jun 3 17:02:36 rock slapd[75268]: send_ldap_intermediate: err=0
oid=1.3.6.1.4.1.4203.1.9.1.4 len=56
Jun 3 17:02:36 rock slapd[75268]: send_ldap_response: msgid=2 tag=121 err=0
Jun 3 17:02:36 rock slapd[75268]: connection_get(8): got connid=391
Jun 3 17:02:36 rock slapd[75268]: connection_read(8): checking for
input on id=391
Jun 3 17:02:36 rock slapd[75268]: ber_get_next on fd 8 failed errno=0
(Undefined error: 0)
Jun 3 17:02:36 rock slapd[75268]: conn=391 op=2 do_unbind
Jun 3 17:02:36 rock slapd[75268]: conn=391 op=2 UNBIND
Jun 3 17:02:36 rock slapd[75268]: connection_close: conn=391 sd=8
Jun 3 17:02:36 rock slapd[75268]: conn=391 fd=8 closed
As I said it works perfectly if it's two slapd instances on the same
machine on different ports. The machines can talk to each other and
can both ldapsearch the other one. Also the firewall is reporting no
blocks.
If anybody has seen this before or has some insight into what the
problem might be it would be very much apprectiated.
Thank you in advance,
Matt Edlefsen
Earlham College