DS 6.1 replication error 900

Find here an extract from the logs of ldap01

ldap01 is 10.8.20.117

ldap02 is 10.8.20.118

Initializing suffix from ldap01 with data contains on ldap01 with non secured connection requested!

ldap02 is the destination

access on ldap02 (password is not valid as I can see)

[13/Jul/2007:13:23:41 +0200] conn=37 op=-1 msgId=-1 - fd=31 slot=31 LDAP connect ion from 10.8.20.117:55614 to 10.8.20.118

[13/Jul/2007:13:23:41 +0200] conn=37 op=0 msgId=1 - BIND dn="cn=replication mana ger,cn=replication,cn=config" method=128 version=3

[13/Jul/2007:13:23:41 +0200] conn=37 op=0 msgId=1 - RESULT err=1 tag=97 nentries =0 etime=0

[13/Jul/2007:13:23:41 +0200] conn=37 op=0 msgId=1 - RESULT err=0 tag=97 nentries =0 etime=0 dn="cn=replication manager,cn=replication,cn=config"

[13/Jul/2007:13:23:41 +0200] conn=37 op=1 msgId=2 - UNBIND

[13/Jul/2007:13:23:41 +0200] conn=37 op=1 msgId=-1 - closing from 10.8.20.117:55 614 - U1 - Connection closed by unbind client -

[13/Jul/2007:13:23:42 +0200] conn=37 op=-1 msgId=-1 - closed.

Errors on ldap01

[13/Jul/2007:13:23:41 +0200] - INFORMATION - NSMMReplicationPlugin - conn=-1 op=-1 msgId=-1 - Replication bind to consumer ldap02.xxxx.lan:60389 failed:

[13/Jul/2007:13:23:41 +0200] - INFORMATION - NSMMReplicationPlugin - conn=-1 op=-1 msgId=-1 - Failed to connect to replication consumer ldap02.xxxx.lan:60389

[13/Jul/2007:13:23:41 +0200] - ERROR<8318> - Repl. Transport - conn=-1 op=-1 msgId=-1 - [S] Bind failed with response: Failed to bind to remote (900).

Access on ldap01

[13/Jul/2007:13:23:25 +0200] conn=0 op=723 msgId=724 - SRCH base="" scope=0 filter="(objectClass=*)" attrs="1.1"

[13/Jul/2007:13:23:25 +0200] conn=0 op=723 msgId=724 - RESULT err=0 tag=101 nentries=1 etime=0

[13/Jul/2007:13:23:25 +0200] conn=0 op=724 msgId=725 - SRCH base="cn=config" scope=0 filter="(objectClass=*)" attrs="nsslapd-config-magic"

[13/Jul/2007:13:23:25 +0200] conn=0 op=724 msgId=725 - RESULT err=0 tag=101 nentries=1 etime=0

[13/Jul/2007:13:23:25 +0200] conn=0 op=725 msgId=726 - SRCH base="cn=mapping tree,cn=config" scope=2 filter="(&(objectClass=nsds5replicationAgreement)(nsDS5ReplicaRoot=dc=xxxx, dc=lan)(nsDS5ReplicaHost=ldap02.xxxx.lan)(nsDS5ReplicaPort=60389))" attrs=ALL

[13/Jul/2007:13:23:25 +0200] conn=0 op=725 msgId=726 - RESULT err=0 tag=101 nentries=1 etime=0

[13/Jul/2007:13:23:25 +0200] conn=0 op=726 msgId=727 - MOD dn="cn=ldap02.xxxx.lan:60389,cn=replica,cn=dc=xxxx\5c,dc=lan,cn=mapping tree,cn=config"

[13/Jul/2007:13:23:26 +0200] conn=0 op=726 msgId=727 - RESULT err=0 tag=103 nentries=0 etime=1,

[13/Jul/2007:13:23:26 +0200] conn=0 op=727 msgId=728 - SRCH base="cn=mapping tree,cn=config" scope=2 filter="(&(objectClass=nsds5replicationAgreement)(nsDS5ReplicaRoot=dc=xxxx, dc=lan)(nsDS5ReplicaHost=ldap02.xxxx.lan)(nsDS5ReplicaPort=60389))" attrs=ALL

[13/Jul/2007:13:23:26 +0200] conn=0 op=727 msgId=728 - RESULT err=0 tag=101 nentries=1 etime=0

[13/Jul/2007:13:23:26 +0200] conn=0 op=728 msgId=729 - SRCH base="cn=ldap02.xxxx.lan:60389,cn=replica,cn=dc=xxxx\5c,dc=lan,cn=mapping tree,cn=config" scope=0 filter="(objectClass=*)" attrs="nsds5replicaChangesSentSinceStartup ds5ReplicaTransportCompressionLevel nsds5replicaLastInitStatus nsDS5ReplicaTransportInfo ds5replicaunackedchangessent nsDS5ReplicaHost nsDS5ReplicaBindDN nsds5replicaLastUpdateStart ds5replicabusycounter dsReplFractionalExclude ds5AgreementEnable dsReplFractionalInclude ds5ReplicaTransportWindowSize nsds5replicaUpdateInProgress nsDS5ReplicaUpdateSchedule nsds5replicaLastUpdateEnd ds5replicatotalentriessent nsDS5ReplicaBindMethod nsds5replicaLastUpdateStatus ds5ReplicaTransportGroupSize nsds5replicaLastInitStart nsDS5ReplicaPort ds5replicapendingchangescount nsds5replicaLastInitEnd description ds5maxreplicabusyduration nsDS5ReplicaRoot nsds5BeginReplicaRefresh nsDS5ReplicaCredentials"

[13/Jul/2007:13:23:26 +0200] conn=0 op=728 msgId=729 - RESULT err=0 tag=101 nentries=1 etime=0

[13/Jul/2007:13:27:01 +0200] conn=51 op=-1 msgId=-1 - fd=26 slot=26 LDAP connection from 10.8.20.113:62875 to 10.8.20.117

[13/Jul/2007:13:27:01 +0200] conn=51 op=0 msgId=1 - EXT oid="1.3.6.1.4.1.1466.20037"

[13/Jul/2007:13:27:01 +0200] conn=51 op=0 msgId=1 - RESULT err=0 tag=120 nentries=0 etime=0, Start TLS request accepted.Server willing to negotiate SSL.

[13/Jul/2007:13:27:01 +0200] conn=51 op=-1 msgId=-1 - SSL 128-bit RC4

[13/Jul/2007:13:27:01 +0200] conn=51 op=1 msgId=2 - BIND dn="cn=admin,cn=Administrators,cn=dscc" method=128 version=3

[13/Jul/2007:13:27:01 +0200] conn=51 op=1 msgId=2 - RESULT err=0 tag=97 nentries=0 etime=0 dn="cn=admin,cn=administrators,cn=dscc"

[13/Jul/2007:13:27:01 +0200] conn=51 op=2 msgId=3 - SRCH base="" scope=0 filter="(objectClass=*)" attrs="subschemaSubentry"

[13/Jul/2007:13:27:01 +0200] conn=51 op=2 msgId=3 - RESULT err=0 tag=101 nentries=1 etime=0

[13/Jul/2007:13:27:01 +0200] conn=51 op=3 msgId=4 - ABANDON targetop=NOTFOUND msgid=3

[13/Jul/2007:13:27:01 +0200] conn=51 op=4 msgId=5 - SRCH base="cn=schema" scope=0 filter="(objectClass=subschema)" attrs="objectClasses attributeTypes matchingRules ldapSyntaxes objectClass javaSerializedData javaClassName javaFactory javaCodebase javaReferenceAddress javaClassNames javaremotelocation"

[13/Jul/2007:13:27:01 +0200] conn=51 op=4 msgId=5 - RESULT err=0 tag=101 nentries=1 etime=0

[13/Jul/2007:13:27:01 +0200] conn=52 op=-1 msgId=-1 - fd=27 slot=27 LDAP connection from 10.8.20.113:62876 to 10.8.20.117

[13/Jul/2007:13:27:01 +0200] conn=52 op=0 msgId=1 - EXT oid="1.3.6.1.4.1.1466.20037"

[13/Jul/2007:13:27:01 +0200] conn=52 op=0 msgId=1 - RESULT err=0 tag=120 nentries=0 etime=0, Start TLS request accepted.Server willing to negotiate SSL.

[13/Jul/2007:13:27:02 +0200] conn=52 op=-1 msgId=-1 - SSL 128-bit RC4

[13/Jul/2007:13:27:02 +0200] conn=52 op=1 msgId=2 - BIND dn="cn=admin,cn=Administrators,cn=dscc" method=128 version=3

[13/Jul/2007:13:27:02 +0200] conn=52 op=1 msgId=2 - RESULT err=0 tag=97 nentries=0 etime=0 dn="cn=admin,cn=administrators,cn=dscc"

[13/Jul/2007:13:27:02 +0200] conn=52 op=2 msgId=3 - UNBIND

[13/Jul/2007:13:27:02 +0200] conn=52 op=2 msgId=-1 - closing from 10.8.20.113:62876 - U1 - Connection closed by unbind client -

[13/Jul/2007:13:27:02 +0200] conn=53 op=-1 msgId=-1 - fd=28 slot=28 LDAP connection from 10.8.20.113:62877 to 10.8.20.117

[13/Jul/2007:13:27:02 +0200] conn=52 op=-1 msgId=-1 - closed.

[13/Jul/2007:13:27:02 +0200] conn=53 op=0 msgId=1 - EXT oid="1.3.6.1.4.1.1466.20037"

[13/Jul/2007:13:27:02 +0200] conn=53 op=0 msgId=1 - RESULT err=0 tag=120 nentries=0 etime=0, Start TLS request accepted.Server willing to negotiate SSL.

[13/Jul/2007:13:27:02 +0200] conn=53 op=-1 msgId=-1 - SSL 128-bit RC4

[13/Jul/2007:13:27:02 +0200] conn=53 op=1 msgId=2 - BIND dn="cn=admin,cn=Administrators,cn=dscc" method=128 version=3

[13/Jul/2007:13:27:02 +0200] conn=53 op=1 msgId=2 - RESULT err=0 tag=97 nentries=0 etime=0 dn="cn=admin,cn=administrators,cn=dscc"

[13/Jul/2007:13:27:02 +0200] conn=53 op=2 msgId=3 - SRCH base="cn=config" scope=0 filter="(objectClass=*)" attrs=ALL

[13/Jul/2007:13:27:02 +0200] conn=53 op=2 msgId=3 - RESULT err=0 tag=101 nentries=1 etime=0

[13/Jul/2007:13:27:02 +0200] conn=53 op=3 msgId=4 - UNBIND

[13/Jul/2007:13:27:02 +0200] conn=53 op=3 msgId=-1 - closing from 10.8.20.113:62877 - U1 - Connection closed by unbind client -

[13/Jul/2007:13:27:03 +0200] conn=53 op=-1 msgId=-1 - closed.

[13/Jul/2007:13:27:09 +0200] conn=54 op=-1 msgId=-1 - fd=27 slot=27 LDAP connection from 10.8.20.118:51517 to 10.8.20.117

[13/Jul/2007:13:27:09 +0200] conn=54 op=0 msgId=1 - SRCH base="uid=monitoring,ou=specialusers,dc=xxxx,dc=lan" scope=0 filter="(|(objectClass=*)(objectClass=ldapSubEntry))" attrs="1.1"

[13/Jul/2007:13:27:09 +0200] conn=54 op=0 msgId=1 - RESULT err=0 tag=101 nentries=0 etime=0

[13/Jul/2007:13:27:09 +0200] conn=54 op=1 msgId=2 - UNBIND

[13/Jul/2007:13:27:09 +0200] conn=54 op=1 msgId=-1 - closing from 10.8.20.118:51517 - U1 - Connection closed by unbind client -

[13/Jul/2007:13:27:10 +0200] conn=54 op=-1 msgId=-1 - closed.

[13/Jul/2007:13:27:13 +0200] conn=55 op=-1 msgId=-1 - fd=27 slot=27 LDAP connection from 10.8.20.117:55626 to 10.8.20.117

[13/Jul/2007:13:27:13 +0200] conn=55 op=0 msgId=1 - SRCH base="uid=monitoring,ou=specialusers,dc=xxxx,dc=lan" scope=0 filter="(|(objectClass=*)(objectClass=ldapSubEntry))" attrs="1.1"

[13/Jul/2007:13:27:13 +0200] conn=55 op=0 msgId=1 - RESULT err=0 tag=101 nentries=0 etime=0

[13/Jul/2007:13:27:13 +0200] conn=55 op=1 msgId=2 - UNBIND

[13/Jul/2007:13:27:13 +0200] conn=55 op=1 msgId=-1 - closing from 10.8.20.117:55626 - U1 - Connection closed by unbind client -

[13/Jul/2007:13:27:14 +0200] conn=55 op=-1 msgId=-1 - closed.

[13/Jul/2007:13:27:21 +0200] conn=0 op=729 msgId=730 - SRCH base="" scope=0 filter="(objectClass=*)" attrs="1.1"

[13/Jul/2007:13:27:21 +0200] conn=0 op=729 msgId=730 - RESULT err=0 tag=101 nentries=1 etime=0

[13/Jul/2007:13:27:21 +0200] conn=0 op=730 msgId=731 - SRCH base="cn=config" scope=0 filter="(objectClass=*)" attrs="nsslapd-config-magic"

[13/Jul/2007:13:27:21 +0200] conn=0 op=730 msgId=731 - RESULT err=0 tag=101 nentries=1 etime=0

[13/Jul/2007:13:27:21 +0200] conn=0 op=731 msgId=732 - SRCH base="cn=mapping tree,cn=config" scope=2 filter="(&(objectClass=nsds5replicationAgreement)(nsDS5ReplicaRoot=dc=xxxx, dc=lan)(nsDS5ReplicaHost=ldap02.xxxx.lan)(nsDS5ReplicaPort=60389))" attrs=ALL

[13/Jul/2007:13:27:21 +0200] conn=0 op=731 msgId=732 - RESULT err=0 tag=101 nentries=1 etime=0

[13/Jul/2007:13:27:21 +0200] conn=0 op=732 msgId=733 - MOD dn="cn=ldap02.xxxx.lan:60389,cn=replica,cn=dc=xxxx\5c,dc=lan,cn=mapping tree,cn=config"

[13/Jul/2007:13:27:22 +0200] conn=0 op=732 msgId=733 - RESULT err=0 tag=103 nentries=0 etime=1,

[13/Jul/2007:13:27:22 +0200] conn=0 op=733 msgId=734 - SRCH base="cn=mapping tree,cn=config" scope=2 filter="(&(objectClass=nsds5replicationAgreement)(nsDS5ReplicaRoot=dc=xxxx, dc=lan)(nsDS5ReplicaHost=ldap02.xxxx.lan)(nsDS5ReplicaPort=60389))" attrs=ALL

[13/Jul/2007:13:27:22 +0200] conn=0 op=733 msgId=734 - RESULT err=0 tag=101 nentries=1 etime=0

[13/Jul/2007:13:27:22 +0200] conn=0 op=734 msgId=735 - SRCH base="cn=ldap02.xxxx.lan:60389,cn=replica,cn=dc=xxxx\5c,dc=lan,cn=mapping tree,cn=config" scope=0 filter="(objectClass=*)" attrs="nsds5replicaChangesSentSinceStartup ds5ReplicaTransportCompressionLevel nsds5replicaLastInitStatus nsDS5ReplicaTransportInfo ds5replicaunackedchangessent nsDS5ReplicaHost nsDS5ReplicaBindDN nsds5replicaLastUpdateStart ds5replicabusycounter dsReplFractionalExclude ds5AgreementEnable dsReplFractionalInclude ds5ReplicaTransportWindowSize nsds5replicaUpdateInProgress nsDS5ReplicaUpdateSchedule nsds5replicaLastUpdateEnd ds5replicatotalentriessent nsDS5ReplicaBindMethod nsds5replicaLastUpdateStatus ds5ReplicaTransportGroupSize nsds5replicaLastInitStart nsDS5ReplicaPort ds5replicapendingchangescount nsds5replicaLastInitEnd description ds5maxreplicabusyduration nsDS5ReplicaRoot nsds5BeginReplicaRefresh nsDS5ReplicaCredentials"

[13/Jul/2007:13:27:22 +0200] conn=0 op=734 msgId=735 - RESULT err=0 tag=101 nentries=1 etime=0

So, I confirm the credential issues but I don't know how to fix it

Thanks for your help ludo

Alban_for_SmartWavea at 2007-7-28 17:54:02 >

Hi,

the prebind is a plugin op that check the authentication on an other source. If failed, then the local authentication is used.

Since the last message, I performed the following actions using DSCC console

1) delete ldap02 (sucess)

2) create ldap02 (sucess)

3) replicate ldap01 master to ldap02 master (success then after 10 minites, errors)

4) delete ldap01 (sucess)

5) create ldap02 (sucess)

6) replicate ldap02 master to ldap01 master (success, no errors but entries changes in ldap01 are not reflected in ldap02

7) new replication agreement from source ldap01 master to ldap02 master (the same bind error 900)

So now, i have a one way replica, not a MMR!

Does it help you?

Alban_for_SmartWavea at 2007-7-28 17:54:02 >

new tests on ldap02 show thant it is not possible to bind on ldap01 using a simple ldapsearch

ldapsearch -v -h ldap02 -p 60389 -D uid=toto,ou=specialUsers,dc=xxxx,dc=lan -w password -s one -b dc=xxxx,dc=lan ou=* 1.1

ldapsearch: started Mon Jul 16 14:57:01 2007

ldap_init( ldap02, 60389 )

ldap_simple_bind: Operations error

the error log shows the following lines

[16/Jul/2007:14:57:02 +0200] conn=17 op=-1 msgId=-1 - fd=29 slot=29 LDAP connection from 10.8.23.73:4285 to 10.8.20.118

[16/Jul/2007:14:57:02 +0200] conn=17 op=0 msgId=1 - BIND dn="uid=toto,ou=specialUsers,dc=xxxx,dc=lan" method=128 version=3

[16/Jul/2007:14:57:02 +0200] conn=17 op=0 msgId=1 - RESULT err=1 tag=97 nentries=0 etime=0

[16/Jul/2007:14:57:02 +0200] conn=17 op=0 msgId=1 - RESULT err=0 tag=97 nentries=0 etime=0 dn="uid=toto,ou=specialusers,dc=xxxx,dc=lan"

[16/Jul/2007:14:57:02 +0200] conn=17 op=1 msgId=2 - UNBIND

[16/Jul/2007:14:57:02 +0200] conn=17 op=1 msgId=-1 - closing from 10.8.23.73:4285 - U1 - Connection closed by unbind client -

[16/Jul/2007:14:57:03 +0200] conn=17 op=-1 msgId=-1 - closed.

Alban_for_SmartWavea at 2007-7-28 17:54:02 >

You wrote in a previous post:

>>the prebind is a plugin op that check the authentication on an other source. If failed, then the local authentication is used.

Are you saying that there is a custom plugin?

If so, it appears it is sending an error result to the LDAP client, but not aborting the bind processing, which completes successfully. The first RESULT is causing the LDAP client (including the replication supplier) to consider the bind failed.

[16/Jul/2007:14:57:02 +0200] conn=17 op=-1 msgId=-1 - fd=29 slot=29 LDAP connection from 10.8.23.73:4285 to 10.8.20.118

[16/Jul/2007:14:57:02 +0200] conn=17 op=0 msgId=1 - BIND dn="uid=toto,ou=specialUsers,dc=xxxx,dc=lan" method=128 version=3

[16/Jul/2007:14:57:02 +0200] conn=17 op=0 msgId=1 - RESULT err=1 tag=97 nentries=0 etime=0

[16/Jul/2007:14:57:02 +0200] conn=17 op=0 msgId=1 - RESULT err=0 tag=97 nentries=0 etime=0 dn="uid=toto,ou=specialusers,dc=xxxx,dc=lan"

[16/Jul/2007:14:57:02 +0200] conn=17 op=1 msgId=2 - UNBIND

[16/Jul/2007:14:57:02 +0200] conn=17 op=1 msgId=-1 - closing from 10.8.23.73:4285 - U1 - Connection closed by unbind client -

[16/Jul/2007:14:57:03 +0200] conn=17 op=-1 msgId=-1 - closed.

solaris1a at 2007-7-28 17:54:02 >

Even with the plugin disable, I have the same result.

ldap01 and ldap01 are with the same plug in config.

do you know what DS 6.1 plug in could have side effect or similar pre op?

anonymous and directory manager are OK

Alban_for_SmartWavea at 2007-7-28 17:54:02 >

> Even with the plugin disable, I have the same

> result.

> ldap01 and ldap01 are with the same plug in config.

> do you know what DS 6.1 plug in could have side

> effect or similar pre op?

>

> anonymous and directory manager are OK

Anonymous and DM are not going through the same code path as regular users, as the data is not in the same place. And the plugin would not be called for them.

Ludovic.

ludovicpa at 2007-7-28 17:54:02 >

Hi,

after long investigations, I found the following issues : The plug-in is the root cause. I could observed numerous side effects but you were right.

debugging is in process

Side effects are persistent "error 900" even if replication works now.

I will publish the final result to close the topics.

Thanks every body.

Alban_for_SmartWavea at 2007-7-28 17:54:02 >