This seems like a ldap driver issue.

It seem like DS problem more than bind-dyndb-ldap problem.

bind-dyndb-ldap reports "LDAP query timed out" - for some reason DS is not able to answer a LDAP query.

Technically: ldap_search_ext_s() returned an error and LDAP_OPT_RESULT_CODE was LDAP_TIMEOUT.

Scott, can you confirm if DS is really not able to reply to LDAP query during replica-manage-process (you can query for anything in cn=dns subtree)?

Unfortunatelly there is no automatic way to recover from this situation. When DS is not functional, then bind-dyndb-ldap can't do any name translation.

You can specify another DNS server in /etc/resolv.conf before changing local DS configuration.

OR - Hypothetically - ipa-replica-manage script can do all DNS queries before any action in DS. In that case all necessary DNS data will be cached inside bind-dyndb-ldap for 120 seconds (by default) and then it is not necessary to contact DS for name translation.

Why does re-initialize do a force-sync? This is not necessary.

        repl = replication.ReplicationManager(realm, fromhost, dirman_passwd)
        agreement = repl.get_replication_agreement(thishost)
        repl.force_sync(repl.conn, thishost)

        repl.initialize_replication(agreement.dn, repl.conn)
        repl.wait_for_repl_init(repl.conn, agreement.dn)

force_sync is a waste of time in this case.

With the DNS issue, I'm not sure what's going on. What DNS server does replica2 use? Nothing is happening to bind on replica2, correct? So replica2 should look up the hostname for replica1 in its DNS, which should be up and running. Or is bind configured such that the DNS on replica2 doesn't know anything about replica1 and has to contact DNS running on replica1 to get that information? I'm not sure why replica2 would have problems looking up replica1.

I don't have the same servers up at this time to reproduce readily. I am looking at trying to get something else setup where I can reproduce. I've uploaded the named.conf from replica1/2 to the BZ though.

Each replica though is pointing to itself for DNS and was installed with setup-dns. bind on replica2 should know about replica1 because the info is replicated in the directory...right? There's no custom DNS config outside of IPA here.

If I can reproduce on another environment, I will check with an ldapsearch to see if I can access cn=dns. In the mean time, let me know if you think of anything else I should look for there too.

Thanks,
Scott

I guess maybe the DNS information about replica1 was not in the DNS database for replica2? Was it ever in there?

In case of missing information bind-dyndb-ldap simply returns NXDOMAIN (name doesn't exist). "LDAP query timed out" points to a problem with DS, but I don't have an idea why DS refuses to reply to a query. I'm trying to reproduce it also.

I've done a small test - set up two masters - init one from the other - on the one that is the supplier for the init, perform some searches - the searches work. So I'm not sure what's going on. If you can reproduce it, please provide the access and error logs from the 389 supplier so we can confirm that the search attempts are occurring during the init.

There is something really strange going on. Looks like replicaA is attempting to re-init replica B:

[13/Jun/2012:09:32:01 -0400] conn=47 op=4 MOD dn="cn=meToreplicaB.testrelm.com,cn=replica,cn=dc\3Dtestrelm\2Cdc\3Dcom,cn=mapping tree,cn=config"
[13/Jun/2012:09:32:01 -0400] conn=47 op=4 RESULT err=0 tag=103 nentries=0 etime=0
[13/Jun/2012:09:32:02 -0400] conn=47 op=5 MOD dn="cn=meToreplicaB,cn=replica,cn=dc\3Dtestrelm\2Cdc\3Dcom,cn=mapping tree,cn=config"
[13/Jun/2012:09:32:02 -0400] conn=47 op=5 RESULT err=0 tag=103 nentries=0 etime=0
[13/Jun/2012:09:32:02 -0400] conn=47 op=6 MOD dn="cn=meToreplicaB.testrelm.com,cn=replica,cn=dc\3Dtestrelm\2Cdc\3Dcom,cn=mapping tree,cn=config"
[13/Jun/2012:09:32:03 -0400] conn=47 op=6 RESULT err=0 tag=103 nentries=0 etime=1

This is the usual force sync followed by re-init that ipa-replica-manage re-initialize does. From the consumer:

[13/Jun/2012:09:32:03 -0400] conn=57 fd=72 slot=72 connection from replicaA to replicaB
[13/Jun/2012:09:32:03 -0400] conn=57 op=0 BIND dn="" method=sasl version=3 mech=GSSAPI
[13/Jun/2012:09:32:06 -0400] conn=57 op=0 RESULT err=14 tag=97 nentries=0 etime=3, SASL bind in progress
[13/Jun/2012:09:32:08 -0400] conn=14 op=7714 SRCH base="cn=dns,dc=testrelm,dc=com" scope=2 filter="(objectClass=idnsConfigObject)" attrs="idnsForwardPolicy idnsForwarders idnsAllowSyncPTR idnsZoneRefresh idnsPersistentSearch"
[13/Jun/2012:09:32:08 -0400] conn=14 op=7714 RESULT err=0 tag=101 nentries=1 etime=0
[13/Jun/2012:09:32:08 -0400] conn=14 op=7715 SRCH base="cn=dns,dc=testrelm,dc=com" scope=2 filter="(&(objectClass=idnsZone)(idnsZoneActive=TRUE))" attrs="idnsName idnsUpdatePolicy idnsAllowQuery idnsAllowTransfer idnsForwardPolicy idnsForwarders"
[13/Jun/2012:09:32:08 -0400] conn=14 op=7715 RESULT err=0 tag=101 nentries=4 etime=0
[13/Jun/2012:09:32:26 -0400] conn=57 op=1 UNBIND
[13/Jun/2012:09:32:26 -0400] conn=57 op=1 fd=72 closed - U1

conn=57 starts a SASL/GSSAPI bind, then nothing for 20 seconds, then it does an UNBIND and closes the connection. From replicaA, I can see what looks to be BIND traffic:

[13/Jun/2012:09:32:04 -0400] conn=15 op=7709 SRCH base="cn=dns,dc=testrelm,dc=com" scope=2 filter="(objectClass=idnsConfigObject)" attrs="idnsForwardPolicy idnsForwarders idnsAllowSyncPTR idnsZoneRefresh idnsPersistentSearch"
[13/Jun/2012:09:32:04 -0400] conn=15 op=7709 RESULT err=0 tag=101 nentries=1 etime=1
[13/Jun/2012:09:32:04 -0400] conn=15 op=7710 SRCH base="cn=dns,dc=testrelm,dc=com" scope=2 filter="(&(objectClass=idnsZone)(idnsZoneActive=TRUE))" attrs="idnsName idnsUpdatePolicy idnsAllowQuery idnsAllowTransfer idnsForwardPolicy idnsForwarders"
[13/Jun/2012:09:32:04 -0400] conn=15 op=7710 RESULT err=0 tag=101 nentries=4 etime=0

Then a lot of search requests from the ipa-replica-manage client to get the status, then this:

[13/Jun/2012:09:32:26 -0400] conn=15 op=7712 SRCH base="idnsname=testrelm.com,cn=dns,dc=testrelm,dc=com" scope=0 filter="(objectClass=idnsRecord)" attrs=ALL
[13/Jun/2012:09:32:26 -0400] conn=16 op=21 SRCH base="idnsname=testrelm.com,cn=dns,dc=testrelm,dc=com" scope=0 filter="(objectClass=idnsRecord)" attrs=ALL
[13/Jun/2012:09:32:26 -0400] conn=15 op=7712 RESULT err=0 tag=101 nentries=1 etime=20
[13/Jun/2012:09:32:26 -0400] conn=15 op=7713 SRCH base="idnsname=testrelm.com,cn=dns,dc=testrelm,dc=com" scope=0 filter="(objectClass=idnsRecord)" attrs=ALL
[13/Jun/2012:09:32:26 -0400] conn=16 op=21 RESULT err=0 tag=101 nentries=1 etime=20
[13/Jun/2012:09:32:26 -0400] conn=15 op=7713 RESULT err=0 tag=101 nentries=1 etime=0

Two strange things here:
1) there was no op=7711 - it goes from conn=15 op=7710 to op=7712 - what happened to op=7711???
2) etime=20 - the search took 20 seconds to complete - this is very bad

It looks as though the initial lookup of the consumer hostname by the supplier worked - the supplier was able to open a connection to the consumer - but something during the kerberos handshake also attempted to lookup the hostname, and that failed. I don't see anything from the krb5kdc log at this time.

Could be some sort of deadlock inside the server that gets resolved by the BIND connection timeout.

I will keep trying to reproduce.

If you want to prolong BIND timeout, you can change timeout value in /etc/named.conf to some very high value (in seconds):

Relevant part of /etc/named.conf follows:

dynamic-db "ipa" {
         library "ldap.so";
         arg "uri ldapi://%2fvar%2frun%2fslapd-E-ORG.socket";
         arg "timeout 86400";
};

Petr, the searches like

[13/Jun/2012:09:32:04 -0400] conn=15 op=7709 SRCH base="cn=dns,dc=testrelm,dc=com" scope=2 filter="(objectClass=idnsConfigObject)" attrs="idnsForwardPolicy idnsForwarders idnsAllowSyncPTR idnsZoneRefresh idnsPersistentSearch"
[13/Jun/2012:09:32:04 -0400] conn=15 op=7709 RESULT err=0 tag=101 nentries=1 etime=1
[13/Jun/2012:09:32:04 -0400] conn=15 op=7710 SRCH base="cn=dns,dc=testrelm,dc=com" scope=2 filter="(&(objectClass=idnsZone)(idnsZoneActive=TRUE))" attrs="idnsName idnsUpdatePolicy idnsAllowQuery idnsAllowTransfer idnsForwardPolicy idnsForwarders"
[13/Jun/2012:09:32:04 -0400] conn=15 op=7710 RESULT err=0 tag=101 nentries=4 etime=0

It looks like bind is doing these every 30 seconds?

What about the searches like this:

[13/Jun/2012:09:32:26 -0400] conn=15 op=7712 SRCH base="idnsname=testrelm.com,cn=dns,dc=testrelm,dc=com" scope=0 filter="(objectClass=idnsRecord)" attrs=ALL
[13/Jun/2012:09:32:26 -0400] conn=16 op=21 SRCH base="idnsname=testrelm.com,cn=dns,dc=testrelm,dc=com" scope=0 filter="(objectClass=idnsRecord)" attrs=ALL
[13/Jun/2012:09:32:26 -0400] conn=15 op=7712 RESULT err=0 tag=101 nentries=1 etime=20
[13/Jun/2012:09:32:26 -0400] conn=15 op=7713 SRCH base="idnsname=testrelm.com,cn=dns,dc=testrelm,dc=com" scope=0 filter="(objectClass=idnsRecord)" attrs=ALL
[13/Jun/2012:09:32:26 -0400] conn=16 op=21 RESULT err=0 tag=101 nentries=1 etime=20
[13/Jun/2012:09:32:26 -0400] conn=15 op=7713 RESULT err=0 tag=101 nentries=1 etime=0

1) Is bind doing these searches? Why? What I mean is, is bind doing these searches because some client of bind is asking for DNS information? Or is it some sort of heartbeat/cache refresh like the conn=15 op=7709 and conn=15 op=7710 searches above?
2) Why are there two separate connections doing these searches? Does bind open two connections? Is there some other client doing these idnsname searches?

The problem does not necessarily seem to be replication related. I have seen named LDAP timeouts when the only clients are sssd, kdc, and named - no replication at all. I'm trying to find out what causes this named traffic.

Rich,

1) Is bind doing these searches? Why? What I mean is, is bind doing these searches because some client of bind is asking for DNS information? Or is it some sort of heartbeat/cache refresh like the conn=15 op=7709 and conn=15 op=7710 searches above?

searches as

[13/Jun/2012:09:32:04 -0400] conn=15 op=7709 SRCH base="cn=dns,dc=testrelm,dc=com" scope=2 filter="(objectClass=idnsConfigObject)" attrs="idnsForwardPolicy idnsForwarders idnsAllowSyncPTR idnsZoneRefresh idnsPersistentSearch"

[13/Jun/2012:09:32:04 -0400] conn=15 op=7710 SRCH base="cn=dns,dc=testrelm,dc=com" scope=2 filter="(&(objectClass=idnsZone)(idnsZoneActive=TRUE))" attrs="idnsName idnsUpdatePolicy idnsAllowQuery idnsAllowTransfer idnsForwardPolicy idnsForwarders"

are done periodically to fetch new configuration (op 7709) and new DNS zones (op 7710). The period is configurable by "zone_refresh" argument in /etc/named.conf. It is 30 seconds in default IPA install.

An other "kind" of searches is

[13/Jun/2012:09:32:26 -0400] conn=15 op=7713 SRCH base="idnsname=testrelm.com,cn=dns,dc=testrelm,dc=com" scope=0 filter="(objectClass=idnsRecord)" attrs=ALL

Searches as in op 7713 are done when specific DNS record was requested. It is done in two basic situations:

a. A DNS client asked for an record.
b. A new DNS zone was found (during op 7710) and plugin needs to access some basic records (SOA, NS, A/AAAA in zone root record) from new DNS zone.

Basic "search flow" after BIND startup is
1. op 7709 (fetch plugin configuration)
2. op 7710 (fetch list of all active DNS zones)
3. One or more individual search operations for some DNS record objects. It consists from "op 7713" searches. The plugin looks for one or more objects with (objectClass=idnsRecord) belonging to each active DNS zone.

(Active DNS zone = object which matches (&(objectClass=idnsZone)(idnsZoneActive=TRUE)) in cn=dns subtree).

2) Why are there two separate connections doing these searches? Does bind open two connections? Is there some other client doing these idnsname searches?

BIND opens multiple connections to DS (count is configurable by "connections" argument in /etc/named.conf). It was designed before I started, but I think it was mainly for performance reasons.

There are structural/code reasons also, but I have a ticket for plugin structural improvements. The plugin will be able to work with single connection in a future. (For now it is not a priority. Without persistent search required minimum is 2 connections.)

There should be no other client doing searches in cn=dns subtree (if nobody accesses IPA interfaces).

Is principle of operation understandable from this text? Please ask if something unclear.

Reassigning from me, because I really don't have anything to do with the issue.

This issue is not reproducible any more. Closing the ticket.