Improve autodiscovery logging

Track the source of discovered values (e.g. from option, interactive,
retrieved from DNS), and show it in the log in the configuration
overview and on erorrs involving the value.

Add additional log messages explaining the autodiscovery process.

For domains the discovery tries to get LDAP SRV records from, log
reasons explaining why the domain was chosen. Also, prevent the
same domain from being searched multiple times.

Add names for error codes, and show them in the log.

Also, modernize the discovery code a bit: move away from the
Java-style accessors, don't needlessly pre-declare variables, make
IPADiscovery a new-style class.

https://fedorahosted.org/freeipa/ticket/2553

2 files changed, 150 insertions, 65 deletions

diff --git a/ipa-client/ipa-install/ipa-client-install b/ipa-client/ipa-install/ipa-client-install
index 8dfe1db6..9a8600d5 100755
--- a/ipa-client/ipa-install/ipa-client-install
+++ b/ipa-client/ipa-install/ipa-client-install
@@ -1112,18 +1112,21 @@ def install(options, env, fstore, statestore):
 
     cli_domain = None
     cli_server = None
-    cli_realm = None
-    cli_basedn = None
     subject_base = None
 
+    cli_domain_source = 'Unknown source'
+    cli_server_source = 'Unknown source'
+
     if options.unattended and (options.password is None and options.principal is None and options.prompt_password is False) and not options.on_master:
         root_logger.error("One of password and principal are required.")
         return CLIENT_INSTALL_ERROR
 
     if options.hostname:
         hostname = options.hostname
+        hostname_source = 'Provided as option'
     else:
         hostname = socket.getfqdn()
+        hostname_source = "Machine's FQDN"
     if hostname != hostname.lower():
         root_logger.error(
             "Invalid hostname '%s', must be lower-case.", hostname)
@@ -1153,10 +1156,22 @@ def install(options, env, fstore, statestore):
         root_logger.error("%s is not a fully-qualified hostname", hostname)
         return CLIENT_INSTALL_ERROR
     if ret in (ipadiscovery.NO_LDAP_SERVER, ipadiscovery.NOT_IPA_SERVER) \
-            or not ds.getDomainName():
-        root_logger.debug("Domain not found")
+            or not ds.domain:
+        if ret == ipadiscovery.NO_LDAP_SERVER:
+            if ds.server:
+                root_logger.debug("%s is not an LDAP server" % ds.server)
+            else:
+                root_logger.debug("No LDAP server found")
+        elif ret == ipadiscovery.NOT_IPA_SERVER:
+            if ds.server:
+                root_logger.debug("%s is not an IPA server" % ds.server)
+            else:
+                root_logger.debug("No IPA server found")
+        else:
+            root_logger.debug("Domain not found")
         if options.domain:
             cli_domain = options.domain
+            cli_domain_source = 'Provided as option'
         elif options.unattended:
             root_logger.error(
                 "Unable to discover domain, not provided on command line")
@@ -1165,38 +1180,45 @@ def install(options, env, fstore, statestore):
             root_logger.info(
                 "DNS discovery failed to determine your DNS domain")
             cli_domain = user_input("Provide the domain name of your IPA server (ex: example.com)", allow_empty = False)
-            root_logger.debug("will use domain: %s", cli_domain)
+            cli_domain_source = 'Provided interactively'
+            root_logger.debug(
+                "will use interactively provided domain: %s", cli_domain)
         ret = ds.search(domain=cli_domain, server=options.server, hostname=hostname)
 
     if not cli_domain:
-        if ds.getDomainName():
-            cli_domain = ds.getDomainName()
-            root_logger.debug("will use domain: %s", cli_domain)
+        if ds.domain:
+            cli_domain = ds.domain
+            cli_domain_source = ds.domain_source
+            root_logger.debug("will use discovered domain: %s", cli_domain)
 
     client_domain = hostname[hostname.find(".")+1:]
 
     if ret in (ipadiscovery.NO_LDAP_SERVER, ipadiscovery.NOT_IPA_SERVER) \
-            or not ds.getServerName():
+            or not ds.server:
         root_logger.debug("IPA Server not found")
         if options.server:
             cli_server = options.server
+            cli_server_source = 'Provided as option'
         elif options.unattended:
             root_logger.error("Unable to find IPA Server to join")
             return CLIENT_INSTALL_ERROR
         else:
             root_logger.debug("DNS discovery failed to find the IPA Server")
             cli_server = user_input("Provide your IPA server name (ex: ipa.example.com)", allow_empty = False)
-            root_logger.debug("will use server: %s", cli_server)
+            cli_server_source = 'Provided interactively'
+            root_logger.debug("will use interactively provided server: %s", cli_server)
         ret = ds.search(domain=cli_domain, server=cli_server, hostname=hostname)
     else:
         dnsok = True
     if not cli_server:
-        if ds.getServerName():
-            cli_server = ds.getServerName()
-            root_logger.debug("will use server: %s", cli_server)
+        if ds.server:
+            cli_server = ds.server
+            cli_server_source = ds.server_source
+            root_logger.debug("will use discovered server: %s", cli_server)
 
     if ret == ipadiscovery.NOT_IPA_SERVER:
         root_logger.error("%s is not an IPA v2 Server.", cli_server)
+        root_logger.debug("(%s: %s)", cli_server, cli_server_source)
         return CLIENT_INSTALL_ERROR
 
     if ret == ipadiscovery.NO_ACCESS_TO_LDAP:
@@ -1211,12 +1233,14 @@ def install(options, env, fstore, statestore):
             cli_server)
         root_logger.error("This may mean that the remote server is not up " +
             "or is not reachable due to network or firewall settings.")
+        root_logger.debug("(%s: %s)", cli_server, cli_server_source)
         return CLIENT_INSTALL_ERROR
 
-    cli_kdc = ds.getKDCName()
+    cli_kdc = ds.kdc
     if dnsok and not cli_kdc:
         root_logger.error("DNS domain '%s' is not configured for automatic " +
-            "KDC address lookup.", ds.getRealmName().lower())
+            "KDC address lookup.", ds.realm.lower())
+        root_logger.debug("(%s: %s)", ds.realm, ds.realm_source)
         root_logger.error("KDC address will be set to fixed value.")
 
     if dnsok:
@@ -1233,23 +1257,32 @@ def install(options, env, fstore, statestore):
         if not user_input("Proceed with fixed values and no DNS discovery?", False):
             return CLIENT_INSTALL_ERROR
 
-    if options.realm_name and options.realm_name != ds.getRealmName():
+    cli_realm = ds.realm
+    cli_realm_source = ds.realm_source
+    root_logger.debug("will use discovered realm: %s", cli_realm)
+
+    if options.realm_name and options.realm_name != cli_realm:
         root_logger.error(
             "The provided realm name [%s] does not match discovered one [%s]",
-            options.realm_name, ds.getRealmName())
+            options.realm_name, cli_realm)
+        root_logger.debug("(%s: %s)", cli_realm, cli_realm_source)
         return CLIENT_INSTALL_ERROR
 
-    cli_realm = ds.getRealmName()
-    root_logger.info("Will use cli_realm: %s", cli_realm)
-    cli_basedn = ds.getBaseDN()
-    root_logger.info("will use cli_basedn: %s", cli_basedn)
-    subject_base = "O=%s" % ds.getRealmName()
+    cli_basedn = ds.basedn
+    cli_basedn_source = ds.basedn_source
+    root_logger.debug("will use discovered basedn: %s", cli_basedn)
+    subject_base = "O=%s" % cli_realm
 
     root_logger.info("Hostname: %s", hostname)
+    root_logger.debug("Hostname source: %s", hostname_source)
     root_logger.info("Realm: %s", cli_realm)
+    root_logger.debug("Realm source: %s", cli_realm_source)
     root_logger.info("DNS Domain: %s", cli_domain)
+    root_logger.debug("DNS Domain source: %s", cli_domain_source)
     root_logger.info("IPA Server: %s", cli_server)
+    root_logger.debug("IPA Server source: %s", cli_server_source)
     root_logger.info("BaseDN: %s", cli_basedn)
+    root_logger.debug("BaseDN source: %s", cli_basedn_source)
 
     print
     if not options.unattended and not user_input("Continue to configure the system with these values?", False):
@@ -1279,7 +1312,8 @@ def install(options, env, fstore, statestore):
     if not options.unattended:
         if options.principal is None and options.password is None and options.prompt_password is False:
             options.principal = user_input("User authorized to enroll computers", allow_empty=False)
-            root_logger.debug("will use principal: %s\n", options.principal)
+            root_logger.debug(
+                "will use principal provided as option: %s", options.principal)
 
     # Get the CA certificate
     try:
diff --git a/ipa-client/ipaclient/ipadiscovery.py b/ipa-client/ipaclient/ipadiscovery.py
index 281daf42..f8c8b5c6 100644
--- a/ipa-client/ipaclient/ipadiscovery.py
+++ b/ipa-client/ipaclient/ipadiscovery.py
@@ -38,7 +38,18 @@ NO_ACCESS_TO_LDAP = -5
 BAD_HOST_CONFIG = -10
 UNKNOWN_ERROR = -15
 
-class IPADiscovery:
+error_names = {
+    0: 'Success',
+    NOT_FQDN: 'NOT_FQDN',
+    NO_LDAP_SERVER: 'NO_LDAP_SERVER',
+    REALM_NOT_FOUND: 'REALM_NOT_FOUND',
+    NOT_IPA_SERVER: 'NOT_IPA_SERVER',
+    NO_ACCESS_TO_LDAP: 'NO_ACCESS_TO_LDAP',
+    BAD_HOST_CONFIG: 'BAD_HOST_CONFIG',
+    UNKNOWN_ERROR: 'UNKNOWN_ERROR',
+}
+
+class IPADiscovery(object):
 
     def __init__(self):
         self.realm = None
@@ -46,12 +57,18 @@ class IPADiscovery:
         self.server = None
         self.basedn = None
 
+        self.realm_source = None
+        self.domain_source = None
+        self.server_source = None
+        self.basedn_source = None
+
     def __get_resolver_domains(self):
         """
         Read /etc/resolv.conf and return all the domains found in domain and
         search.
 
-        Returns a list
+        Returns a list of (domain, info) pairs. The info contains a reason why
+        the domain is returned.
         """
         domains = []
         domain = None
@@ -62,12 +79,14 @@ class IPADiscovery:
 
             for line in lines:
                 if line.lower().startswith('domain'):
-                    domain = line.split(None)[-1]
+                    domain = (line.split()[-1],
+                        'local domain from /etc/resolv.conf')
                 elif line.lower().startswith('search'):
-                    domains = domains + line.split(None)[1:]
+                    domains += [(d, 'search domain from /etc/resolv.conf') for
+                        d in line.split()[1:]]
         except:
             pass
-        if domain and not domain in domains:
+        if domain:
             domains = [domain] + domains
         return domains
 
@@ -86,18 +105,26 @@ class IPADiscovery:
     def getBaseDN(self):
         return self.basedn
 
-    def check_domain(self, domain):
+    def check_domain(self, domain, tried, reason):
         """
         Given a domain search it for SRV records, breaking it down to search
         all subdomains too.
 
         Returns a tuple (server, domain) or (None,None) if a SRV record
         isn't found.
+
+        :param tried: A set of domains that were tried already
+        :param reason: Reason this domain is searched (included in the log)
         """
         server = None
-        root_logger.debug("Start searching for LDAP SRV record in %s and"
-                          " its sub-domains", domain)
+        root_logger.debug('Start searching for LDAP SRV record in "%s" (%s) ' +
+                          'and its sub-domains', domain, reason)
         while not server:
+            if domain in tried:
+                root_logger.debug("Already searched %s; skipping", domain)
+                break
+            tried.add(domain)
+
             server = self.ipadns_search_srv(domain, '_ldap._tcp', 389)
             if server:
                 return (server[0], domain)
@@ -109,11 +136,10 @@ class IPADiscovery:
         return (None, None)
 
     def search(self, domain = "", server = "", hostname=None):
-        qname = ""
-        results = []
-        result = []
-        krbret = []
-        ldapret = []
+        root_logger.debug("[IPA Discovery]")
+        root_logger.debug(
+            'Starting IPA discovery with domain=%s, server=%s, hostname=%s',
+            domain, server, hostname)
 
         if not server:
 
@@ -122,6 +148,7 @@ class IPADiscovery:
                 # get the local host name
                 if not hostname:
                     hostname = socket.getfqdn()
+                    root_logger.debug('Hostname: %s', hostname)
                 if not hostname:
                     return BAD_HOST_CONFIG
 
@@ -135,20 +162,24 @@ class IPADiscovery:
                 domain = hostname[p+1:]
 
                 # Get the list of domains from /etc/resolv.conf, we'll search
-                # them all. We search the domain of our hostname first though,
-                # even if that means searching it twice. This is to avoid the
-                # situation where domain isn't set in /etc/resolv.conf and
-                # the search list has the hostname domain not first. We could
-                # end up with the wrong SRV record.
+                # them all. We search the domain of our hostname first though.
+                # This is to avoid the situation where domain isn't set in
+                # /etc/resolv.conf and the search list has the hostname domain
+                # not first. We could end up with the wrong SRV record.
                 domains = self.__get_resolver_domains()
-                domains = [domain] + domains
-                for domain in domains:
-                    (server, domain) = self.check_domain(domain)
+                domains = [(domain, 'domain of the hostname')] + domains
+                tried = set()
+                for domain, reason in domains:
+                    server, domain = self.check_domain(domain, tried, reason)
                     if server:
                         self.server = server
                         self.domain = domain
+                        self.server_source = self.domain_source = (
+                            'Discovered LDAP SRV records from %s (%s)' %
+                                (domain, reason))
                         break
                 if not self.domain: #no ldap server found
+                    root_logger.debug('No LDAP server found')
                     return NO_LDAP_SERVER
             else:
                 root_logger.debug("Search for LDAP SRV record in %s", domain)
@@ -156,25 +187,34 @@ class IPADiscovery:
                 if server:
                     self.server = server[0]
                     self.domain = domain
+                    self.server_source = self.domain_source = (
+                        'Discovered LDAP SRV records from %s' % domain)
                 else:
                     self.server = None
+                    root_logger.debug('No LDAP server found')
                     return NO_LDAP_SERVER
 
-        else: #server forced on us, this means DNS doesn't work :/
+        else:
 
+            root_logger.debug("Server and domain forced")
             self.domain = domain
             self.server = server
+            self.domain_source = self.server_source = 'Forced'
 
         #search for kerberos
-        root_logger.debug("[ipadnssearchkrb]")
-        krbret = self.ipadnssearchkrb(self.domain)
-        if not server and not krbret[0]:
+        root_logger.debug("[Kerberos realm search]")
+        krb_realm, kdc = self.ipadnssearchkrb(self.domain)
+        if not server and not krb_realm:
             return REALM_NOT_FOUND
 
-        self.realm = krbret[0]
-        self.kdc = krbret[1]
+        self.realm = krb_realm
+        self.kdc = kdc
+        self.realm_source = self.kdc_source = (
+            'Discovered Kerberos DNS records from %s' % self.domain)
 
-        root_logger.debug("[ipacheckldap]")
+        root_logger.debug("[LDAP server check]")
+        root_logger.debug('Verifying that %s (realm %s) is an IPA server',
+            self.server, self.realm)
         # We may have received multiple servers corresponding to the domain
         # Iterate through all of those to check if it is IPA LDAP server
         ldapret = [NOT_IPA_SERVER]
@@ -186,10 +226,12 @@ class IPADiscovery:
             if ldapret[0] == 0:
                 self.server = ldapret[1]
                 self.realm = ldapret[2]
+                self.server_source = self.realm_source = (
+                    'Discovered from LDAP DNS records in %s' % self.server)
             elif ldapret[0] == NO_ACCESS_TO_LDAP:
                 ldapaccess = False
 
-        # If one of LDAP servers checked rejects access (may be anonymous
+        # If one of LDAP servers checked rejects access (maybe anonymous
         # bind is disabled), assume realm and basedn generated off domain.
         # Note that in case ldapret[0] == 0 and ldapaccess == False (one of
         # servers didn't provide access but another one succeeded), self.realm
@@ -198,12 +240,20 @@ class IPADiscovery:
         if not ldapaccess and self.realm is None:
             # Assume realm is the same as domain.upper()
             self.realm = self.domain.upper()
-            root_logger.debug("Assuming realm is the same as domain: %s" % self.realm)
+            self.realm_source = 'Assumed same as domain'
+            root_logger.debug(
+                "Assuming realm is the same as domain: %s", self.realm)
 
         if not ldapaccess and self.basedn is None:
             # Generate suffix from realm
             self.basedn = realm_to_suffix(self.realm)
-            root_logger.debug("Generate basedn from realm: %s" % self.basedn)
+            self.basedn_source = 'Generated from Kerberos realm'
+            root_logger.debug("Generated basedn from realm: %s" % self.basedn)
+
+        root_logger.debug(
+            "Discovery result: %s; server=%s, domain=%s, kdc=%s, basedn=%s",
+            error_names.get(ldapret[0], ldapret[0]),
+            self.server, self.domain, self.kdc, self.basedn)
 
         return ldapret[0]
 
@@ -222,10 +272,6 @@ class IPADiscovery:
             2 means the server is certainly not an IPA server
         """
 
-        lret = []
-        lres = []
-        lattr = ""
-        linfo = ""
         lrealms = []
 
         i = 0
@@ -241,13 +287,14 @@ class IPADiscovery:
             run(["/usr/bin/wget", "-O", "%s/ca.crt" % temp_ca_dir, "-T", "15", "-t", "2",
                  "http://%s/ipa/config/ca.crt" % format_netloc(thost)])
         except CalledProcessError, e:
-            root_logger.debug('Retrieving CA from %s failed.\n%s' % (thost, str(e)))
+            root_logger.debug('Retrieving CA from %s failed: %s', thost, str(e))
             return [NOT_IPA_SERVER]
 
         #now verify the server is really an IPA server
         try:
-            root_logger.debug("Init ldap with: ldap://"+format_netloc(thost, 389))
-            lh = ldap.initialize("ldap://"+format_netloc(thost, 389))
+            ldap_url = "ldap://" + format_netloc(thost, 389)
+            root_logger.debug("Init LDAP connection with: %s", ldap_url)
+            lh = ldap.initialize(ldap_url)
             ldap.set_option(ldap.OPT_X_TLS_REQUIRE_CERT, True)
             ldap.set_option(ldap.OPT_X_TLS_CACERTFILE, "%s/ca.crt" % temp_ca_dir)
             lh.set_option(ldap.OPT_PROTOCOL_VERSION, 3)
@@ -260,19 +307,23 @@ class IPADiscovery:
             basedn = get_ipa_basedn(lh)
 
             if basedn is None:
+                root_logger.debug("The server is not an IPA server")
                 return [NOT_IPA_SERVER]
 
             self.basedn = basedn
+            self.basedn_source = 'From IPA server %s' % ldap_url
 
             #search and return known realms
-            root_logger.debug("Search for (objectClass=krbRealmContainer) in "+self.basedn+"(sub)")
+            root_logger.debug(
+                "Search for (objectClass=krbRealmContainer) in %s (sub)",
+                self.basedn)
             lret = lh.search_s("cn=kerberos,"+self.basedn, ldap.SCOPE_SUBTREE, "(objectClass=krbRealmContainer)")
             if not lret:
                 #something very wrong
                 return [REALM_NOT_FOUND]
-            root_logger.debug("Found: "+str(lret))
 
             for lres in lret:
+                root_logger.debug("Found: %s", lres[0])
                 for lattr in lres[1]:
                     if lattr.lower() == "cn":
                         lrealms.append(lres[1][lattr][0])
@@ -316,7 +367,7 @@ class IPADiscovery:
                           break_on_first=True):
         """
         Search for SRV records in given domain. When no record is found,
-        en empty string is returned
+        en empty list is returned
 
         :param domain: Search domain name
         :param srv_record_name: SRV record name, e.g. "_ldap._tcp"
@@ -386,4 +437,4 @@ class IPADiscovery:
                 kdc = None
             kdc = ','.join(kdc)
 
-        return [realm, kdc]
+        return realm, kdc