From 8f051c978e2a3cf40ba6cc9c84652ae049d978ab Mon Sep 17 00:00:00 2001 From: Petr Viktorin Date: Wed, 13 Jun 2012 11:44:06 -0400 Subject: 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 --- ipa-client/ipa-install/ipa-client-install | 80 +++++++++++++----- ipa-client/ipaclient/ipadiscovery.py | 135 ++++++++++++++++++++---------- 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 8dfe1db68..9a8600d55 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 281daf42a..f8c8b5c6d 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 -- cgit