[Freeipa-users] Freeipa 4.3.0 replica installation fails with DuplicateEntry: This entry already exists

Wed Jan 20 19:41:32 UTC 2016

On 01/20/2016 12:24 PM, Nathan Peters wrote:
> Now we are starting to get somewhere (although a resolution still is not visible) :)
>
> First, thank you Petr and Rob for your help on this issue.  I apologize for our hard to parse server names.  I'm not a fan of them myself and in earlier reports I had been reformatting everything nicely with dc1, dc2, dc3 etc.  After having to submit so many reports I started to get lazy an thought it may be more helpful to see data closer to what we are actually using.
>
> Petr hit the nail on the head with the "does everyone who binds get the same result" question, which although it has not revealed a resolution, has revealed a bunch of really interesting facts about the process.
>
> Going back to the original logs that were running on the remote master during the replica installation attempt I see the following :
>
> [18/Jan/2016:09:28:32 -0800] conn=18732 fd=77 slot=77 connection from 10.21.0.98 to 10.178.0.98
>> [18/Jan/2016:09:28:32 -0800] conn=18732 op=0 BIND dn="" method=sasl version=3 mech=GSSAPI
>> [18/Jan/2016:09:28:32 -0800] conn=18732 op=0 RESULT err=14 tag=97 nentries=0 etime=0, SASL bind in progress
>> [18/Jan/2016:09:28:32 -0800] conn=18732 op=1 BIND dn="" method=sasl version=3 mech=GSSAPI
>> [18/Jan/2016:09:28:32 -0800] conn=18732 op=1 RESULT err=14 tag=97 nentries=0 etime=0, SASL bind in progress
>> [18/Jan/2016:09:28:32 -0800] conn=18732 op=2 BIND dn="" method=sasl version=3 mech=GSSAPI
>> [18/Jan/2016:09:28:32 -0800] conn=18732 op=2 RESULT err=0 tag=97 nentries=0 etime=0 dn="fqdn=dc2-ipa-dev-van.mydomain.net,cn=computers,cn=accounts,dc=mydomain,dc=net"
>> [18/Jan/2016:09:28:32 -0800] conn=18732 op=3 SRCH base="cn=replication,cn=etc,dc=mydomain,dc=net" scope=0 filter="(objectClass=*)" attrs=ALL
>> [18/Jan/2016:09:28:32 -0800] conn=18732 op=3 RESULT err=0 tag=101 nentries=1 etime=0
>> [18/Jan/2016:09:28:32 -0800] conn=18732 op=4 SRCH base="cn=schema" scope=0 filter="(objectClass=*)" attrs="attributeTypes objectClasses"
>> [18/Jan/2016:09:28:32 -0800] conn=18732 op=4 RESULT err=0 tag=101 nentries=1 etime=0
> So, conn18732 was opened with a bind dn of "" ?  Is this supposed to happen?

Yes.  GSSAPI/SASL binds are multi-stage binds.  You'll notice that the 
last stage is op=2, and the result has the full bind DN to which the 
kerberos principals mapped to.  The dn="" until the last stage at which 
time the mapped DN is known and logged.

>
> Here is what I see when I search that base using the same empty bind dn :

nack - you have to first use "kinit myusername at MYDOMAIN", then use 
ldapsearch -Y GSSAPI ...., to do the bind in the same way to use GSSAPI.

>
> ---snip---
> [root at dc2-ipa-dev-van ~]# ldapsearch -H ldaps://dc2-ipa-dev-nvan.mydomain.net -b "cn=replica,cn=dc\3Dmydomain\2Cdc\3Dnet,cn=mapping tree,cn=config" -D ""
> # extended LDIF
> #
> # LDAPv3
> # base <cn=replica,cn=dc\3Dmydomain\2Cdc\3Dnet,cn=mapping tree,cn=config> with scope subtree
> # filter: (objectclass=*)
> # requesting: ALL
> #
>
> # search result
> search: 2
> result: 0 Success
>
> # numResponses: 1
> ---snip---
>
> Here is a similar empty looking result when I bind as the admin user
>
> ---snip---
> [root at dc2-ipa-dev-van ~]# ldapsearch -H ldaps://dc2-ipa-dev-nvan.mydomain.net -b "cn=replica,cn=dc\3Dmydomain\2Cdc\3Dnet,cn=mapping tree,cn=config" -D "uid=admin,cn=users,cn=accounts,dc=mydomain,dc=net" -W
> Enter LDAP Password:
> # extended LDIF
> #
> # LDAPv3
> # base <cn=replica,cn=dc\3Dmydomain\2Cdc\3Dnet,cn=mapping tree,cn=config> with scope subtree
> # filter: (objectclass=*)
> # requesting: ALL
> #
>
> # search result
> search: 2
> result: 0 Success
>
> # numResponses: 1
> ---snip---
>
> So we know that for whatever reason, this particular DN cannot be searched from anyone other than directory manager.
>
> So I now have a few new questions...
>
> 1. What user is the ipa-replica-install command supposed to bind as ?  directory manager, admin, or "" ?
>
> 2/3. Should the ACL on that replica DN allow "" to get results?  Isn't that essentially an anonymous bind ? What should the ACL be ?
>
> For reference, here is the result when I search from the new replica against the existing master using directory manager (I get a good result):
>
> [root at dc2-ipa-dev-van ~]# ldapsearch -H ldaps://dc2-ipa-dev-nvan.mydomain.net -b "cn=replica,cn=dc\3Dmydomain\2Cdc\3Dnet,cn=mapping tree,cn=config" -D "cn=directory manager" -W
> Enter LDAP Password:
> # extended LDIF
> #
> # LDAPv3
> # base <cn=replica,cn=dc\3Dmydomain\2Cdc\3Dnet,cn=mapping tree,cn=config> with scope subtree
> # filter: (objectclass=*)
> # requesting: ALL
> #
>
> # replica, dc\3Dmydomain\2Cdc\3Dnet, mapping tree, config
> dn: cn=replica,cn=dc\3Dmydomain\2Cdc\3Dnet,cn=mapping tree,cn=config
> cn: replica
> nsDS5Flags: 1
> nsDS5ReplicaBindDN: cn=replication manager,cn=config
> nsDS5ReplicaBindDN: krbprincipalname=ldap/dc1-ipa-dev-nvan.mydomain.net
>   @mydomain.NET,cn=services,cn=accounts,dc=mydomain,dc=net
> nsDS5ReplicaBindDN: krbprincipalname=ldap/dc1-ipa-dev-van.mydomain.net@
>   mydomain.NET,cn=services,cn=accounts,dc=mydomain,dc=net
> nsDS5ReplicaId: 15
> nsDS5ReplicaName: 74d8b993-bcb911e5-ba5283c7-2a40cd64
> nsDS5ReplicaRoot: dc=mydomain,dc=net
> nsDS5ReplicaType: 3
> nsState:: DwAAAAAAAACJ2p9WAAAAAAAAAAAAAAAAbAEAAAAAAAAFAAAAAAAAAA==
> nsds5ReplicaLegacyConsumer: off
> nsds5replicabinddngroup: cn=replication managers,cn=sysaccounts,cn=etc,dc=mydomain,dc=net
> nsds5replicabinddngroupcheckinterval: 60
> objectClass: nsds5replica
> objectClass: top
> objectClass: extensibleobject
> nsds5ReplicaChangeCount: 91169
> nsds5replicareapactive: 0
>
> # meTodc1-ipa-dev-nvan.mydomain.net, replica, dc\3Dmydomain\2Cdc\
>   3Dnet, mapping tree, config
> dn: cn=meTodc1-ipa-dev-nvan.mydomain.net,cn=replica,cn=dc\3Dmydomain\2Cdc\3Dnet,cn=mapping tree,cn=config
> cn: meTodc1-ipa-dev-nvan.mydomain.net
> description: me to dc1-ipa-dev-nvan.mydomain.net
> nsDS5ReplicaBindMethod: SASL/GSSAPI
> nsDS5ReplicaHost: dc1-ipa-dev-nvan.mydomain.net
> nsDS5ReplicaPort: 389
> nsDS5ReplicaRoot: dc=mydomain,dc=net
> nsDS5ReplicaTransportInfo: LDAP
> nsDS5ReplicatedAttributeList: (objectclass=*) $ EXCLUDE memberof idnssoaserial
>    entryusn krblastsuccessfulauth krblastfailedauth krbloginfailedcount
> nsDS5ReplicatedAttributeListTotal: (objectclass=*) $ EXCLUDE entryusn krblasts
>   uccessfulauth krblastfailedauth krbloginfailedcount
> nsds50ruv: {replicageneration} 553fe9bb000000040000
> nsds50ruv: {replica 16 ldap://dc1-ipa-dev-nvan.mydomain.net:389} 569afd
>   26000000100000 569b9201002200100000
> nsds50ruv: {replica 17 ldap://dc1-ipa-dev-van.mydomain.net:389} 569b124
>   b000000110000 569b91af000d00110000
> nsds50ruv: {replica 15 ldap://dc2-ipa-dev-nvan.mydomain.net:389} 569aee
>   040000000f0000 569b92010002000f0000
> nsds50ruv: {replica 14 ldap://dc2-ipa-dev-van.mydomain.net:389} 569ae7b
>   b0000000e0000 569b91320014000e0000
> nsds5ReplicaEnabled: on
> nsds5ReplicaStripAttrs: modifiersName modifyTimestamp internalModifiersName in
>   ternalModifyTimestamp
> nsds5replicaTimeout: 120
> nsruvReplicaLastModified: {replica 16 ldap://dc1-ipa-dev-nvan.mydomain.
>   net:389} 00000000
> nsruvReplicaLastModified: {replica 17 ldap://dc1-ipa-dev-van.mydomain.n
>   et:389} 00000000
> nsruvReplicaLastModified: {replica 15 ldap://dc2-ipa-dev-nvan.mydomain.
>   net:389} 00000000
> nsruvReplicaLastModified: {replica 14 ldap://dc2-ipa-dev-van.mydomain.n
>   et:389} 00000000
> objectClass: nsds5replicationagreement
> objectClass: top
> objectClass: ipaReplTopoManagedAgreement
> ipaReplTopoManagedAgreementState: managed agreement - controlled by topology p
>   lugin
> nsds5replicareapactive: 0
> nsds5replicaLastUpdateStart: 20160120190605Z
> nsds5replicaLastUpdateEnd: 20160120190605Z
> nsds5replicaChangesSentSinceStartup:: MTU6NjY3LzIyNTk3NTEgMTQ6MS8wIDE3OjIyLzAg
>   MTY6Mi8wIA==
> nsds5replicaLastUpdateStatus: 0 Replica acquired successfully: Incremental upd
>   ate succeeded
> nsds5replicaUpdateInProgress: FALSE
> nsds5replicaLastInitStart: 19700101000000Z
> nsds5replicaLastInitEnd: 19700101000000Z
>
> # meTodc1-ipa-dev-van.mydomain.net, replica, dc\3Dmydomain\2Cdc\3
>   Dnet, mapping tree, config
> dn: cn=meTodc1-ipa-dev-van.mydomain.net,cn=replica,cn=dc\3Dmydomain\2Cdc\3Dnet,cn=mapping tree,cn=config
> cn: meTodc1-ipa-dev-van.mydomain.net
> description: me to dc1-ipa-dev-van.mydomain.net
> nsDS5ReplicaBindMethod: SASL/GSSAPI
> nsDS5ReplicaHost: dc1-ipa-dev-van.mydomain.net
> nsDS5ReplicaPort: 389
> nsDS5ReplicaRoot: dc=mydomain,dc=net
> nsDS5ReplicaTransportInfo: LDAP
> nsDS5ReplicatedAttributeList: (objectclass=*) $ EXCLUDE memberof idnssoaserial
>    entryusn krblastsuccessfulauth krblastfailedauth krbloginfailedcount
> nsDS5ReplicatedAttributeListTotal: (objectclass=*) $ EXCLUDE entryusn krblasts
>   uccessfulauth krblastfailedauth krbloginfailedcount
> nsds5ReplicaStripAttrs: modifiersName modifyTimestamp internalModifiersName in
>   ternalModifyTimestamp
> nsds5replicaTimeout: 120
> objectClass: nsds5replicationagreement
> objectClass: top
> objectClass: ipaReplTopoManagedAgreement
> ipaReplTopoManagedAgreementState: managed agreement - controlled by topology p
>   lugin
> nsds50ruv: {replicageneration} 553fe9bb000000040000
> nsds50ruv: {replica 17 ldap://dc1-ipa-dev-van.mydomain.net:389} 569b124
>   b000000110000 569b9201000500110000
> nsds50ruv: {replica 16 ldap://dc1-ipa-dev-nvan.mydomain.net:389} 569afd
>   26000000100000 569b918d004a00100000
> nsds50ruv: {replica 15 ldap://dc2-ipa-dev-nvan.mydomain.net:389} 569aee
>   040000000f0000 569b92010002000f0000
> nsds50ruv: {replica 14 ldap://dc2-ipa-dev-van.mydomain.net:389} 569ae7b
>   b0000000e0000 569b91320014000e0000
> nsruvReplicaLastModified: {replica 17 ldap://dc1-ipa-dev-van.mydomain.n
>   et:389} 00000000
> nsruvReplicaLastModified: {replica 16 ldap://dc1-ipa-dev-nvan.mydomain.
>   net:389} 00000000
> nsruvReplicaLastModified: {replica 15 ldap://dc2-ipa-dev-nvan.mydomain.
>   net:389} 00000000
> nsruvReplicaLastModified: {replica 14 ldap://dc2-ipa-dev-van.mydomain.n
>   et:389} 00000000
> nsds5replicareapactive: 0
> nsds5replicaLastUpdateStart: 20160120190602Z
> nsds5replicaLastUpdateEnd: 20160120190602Z
> nsds5replicaChangesSentSinceStartup:: MTU6ODgzLzQwNDIwNTcgMTY6MjQzLzAgMTc6Mi8w
>   IDA6MS8wIA==
> nsds5replicaLastUpdateStatus: 0 Replica acquired successfully: Incremental upd
>   ate succeeded
> nsds5replicaUpdateInProgress: FALSE
> nsds5replicaLastInitStart: 19700101000000Z
> nsds5replicaLastInitEnd: 19700101000000Z
>
> # search result
> search: 2
> result: 0 Success
>
> # numResponses: 4
> # numEntries: 3
>
>
> -----Original Message-----
> From: Petr Vobornik [mailto:pvoborni at redhat.com]
> Sent: January-20-16 2:02 AM
> To: Rob Crittenden; Nathan Peters; Ludwig Krispenz
> Cc: freeipa-users at redhat.com
> Subject: Re: [Freeipa-users] Freeipa 4.3.0 replica installation fails with DuplicateEntry: This entry already exists
>
> On 01/20/2016 12:31 AM, Rob Crittenden wrote:
>> Nathan Peters wrote:
>>> [18/Jan/2016:09:28:33 -0800] conn=18732 op=10 ADD dn="cn=replica,cn=dc\3Ddev-globalrelay\2Cdc\3Dnet,cn=mapping tree,cn=config"
>>>    [18/Jan/2016:09:28:33 -0800] conn=18732 op=10 RESULT err=68 tag=105 nentries=0 etime=0
>>>    [18/Jan/2016:09:28:33 -0800] conn=18732 op=11 UNBIND
>>>
>>> Do you mean that log entry ^?  I am seeing that entry on dc2-ipa-dev-nvan, the host that dc1-ipa-dev-van is contacting as its master when we attempt the ipa-replica-install.  Look through my earlier posts in this thread for a full log.
>> Don't assume we have any idea what your hostnames mean, especially
>> when they differ only by a few characters. It is good to list them but
>> I'd also suggest you use terms like existing master and new server or
>> something so we can distinguish the players without having to slowly
>> parse every name.
>>
>>> Yes, of course that DN exists on all my masters.  With a 3 way replication it would have to exist because the current master is replicating to 2 other masters.  Here is the ldapsearch for all 3 existing hosts showing that DN (dn="cn=replica,cn=dc\3Ddev-globalrelay\2Cdc\3Dnet,cn=mapping tree,cn=config") which is apparently failing to be added because it already exists on all my hosts.
>> The important thing here is that cn=config is not replicated. It is
>> configured on each master during replica setup, exactly where it is
>> failing for you. Given that it is failing on ANOTHER server says a lot.
>>
>> It is failing, I think in part, because this search on the remote
>> master is returning no entries:
>>
>> [18/Jan/2016:09:28:33 -0800] conn=18732 op=9 SRCH
>> base="cn=replica,cn=dc\3Dmydomain\2Cdc\3Dnet,cn=mapping tree,cn=config"
>> scope=0 filter="(objectClass=*)" attrs=ALL
>> [18/Jan/2016:09:28:33 -0800] conn=18732 op=9 RESULT err=0 tag=101
>> nentries=0 etime=0
> IMO this is the culprit. It should return the entry if it is in fact there.
>
>> Right after this is the ADD which fails with err=68 which means that
>> in fact, it does exist.
>>
>> I'm not sure why this is happening. I don't immediately see why a
>> NotFound would be raised in this case but I'm guessing it is. It would
>> be interesting to walk through the code using the python debugger, pdb.
>>
>> In any case the duplicate entry is due to the replica setup code
>> trying to configure the remote master for basic replication and this
>> has already been done.
> Yes the replica code works as expected.
>
> Next step is to investigate why the search returns nothing. ACI issue?
> Weird DB state?
>
> Can other user fetch it? E.g. admin?
>
> If so wow does "cn=replica,cn=dc\3Dmydomain\2Cdc\3Dnet,cn=mapping
> tree,cn=config" on the master server looks like?
> --
> Petr Vobornik
>