addons: dchp: add debug logs and retry mechanism for dhclient (controled by policy)

ifupdown2 now tries to monitor the dhclient call to see if an ip address was
successfully assigned on the requested device. The number of retry can be
customized using the "dhclient_retry_on_failure" policy variable (which defaults to 0)

This commit also add debugging capabilities by automatically enabling sysloging when
configuring dhcp at boot (with PERFMODE option).

Signed-off-by: Julien Fortin <julien@cumulusnetworks.com>

diff --git a/debian/changelog b/debian/changelog
index b183916aea2ac02bb9310108b8647631deda93a3..6e79051686607909ea9f70c210cde9a7d9daca26 100644 (file)
--- a/debian/changelog
+++ b/debian/changelog
@@ -1,6 +1,7 @@
 ifupdown2 (3.0.1-1) unstable; urgency=medium
 
    * New. Enabled: ES bond with "es-sys-mac" attribute
+   * New. Enabled: dhcp policy: dhclient_retry_on_failure
    * Fix: start-networking script is back to handle mgmt & hotplug cases
 
  -- Julien Fortin <julien@cumulusnetworks.com>  Tue, 14 Apr 2020 23:42:42 +0200

diff --git a/ifupdown2/addons/dhcp.py b/ifupdown2/addons/dhcp.py
index 1e84a8b83d1923f6dd9dc269504a28c1b04225db..dfbae425a6cacbfb0020d5e917627923c909494f 100644 (file)
--- a/ifupdown2/addons/dhcp.py
+++ b/ifupdown2/addons/dhcp.py
@@ -10,6 +10,7 @@ import socket
 
 try:
     from ifupdown2.lib.addon import Addon
+    from ifupdown2.lib.log import LogManager
 
     import ifupdown2.ifupdown.policymanager as policymanager
     import ifupdown2.ifupdown.ifupdownflags as ifupdownflags
@@ -21,6 +22,7 @@ try:
     from ifupdown2.ifupdownaddons.modulebase import moduleBase
 except (ImportError, ModuleNotFoundError):
     from lib.addon import Addon
+    from lib.log import LogManager
 
     import ifupdown.policymanager as policymanager
     import ifupdown.ifupdownflags as ifupdownflags
@@ -35,6 +37,11 @@ except (ImportError, ModuleNotFoundError):
 class dhcp(Addon, moduleBase):
     """ ifupdown2 addon module to configure dhcp on interface """
 
+    # by default we won't perform any dhcp retry
+    # this can be changed by setting the module global
+    # policy: dhclient_retry_on_failure
+    DHCLIENT_RETRY_ON_FAILURE = 0
+
     def __init__(self, *args, **kargs):
         Addon.__init__(self)
         moduleBase.__init__(self, *args, **kargs)
@@ -47,6 +54,21 @@ class dhcp(Addon, moduleBase):
             self.mgmt_vrf_context = False
         self.logger.info('mgmt vrf_context = %s' %self.mgmt_vrf_context)
 
+        try:
+            self.dhclient_retry_on_failure = int(
+                policymanager.policymanager_api.get_module_globals(
+                    module_name=self.__class__.__name__,
+                    attr="dhclient_retry_on_failure"
+                )
+            )
+        except:
+            self.dhclient_retry_on_failure = self.DHCLIENT_RETRY_ON_FAILURE
+
+        if self.dhclient_retry_on_failure < 0:
+            self.dhclient_retry_on_failure = 0
+
+        self.logger.info("dhclient: dhclient_retry_on_failure set to %s" % self.dhclient_retry_on_failure)
+
     def syntax_check(self, ifaceobj, ifaceobj_getfunc):
         return self.is_dhcp_allowed_on(ifaceobj, syntax_check=True)
 
@@ -55,6 +77,58 @@ class dhcp(Addon, moduleBase):
             return utils.is_addr_ip_allowed_on(ifaceobj, syntax_check=True)
         return True
 
+    def get_current_ip_configured(self, ifname, family):
+        ips = set()
+        try:
+            a = utils.exec_commandl(["ip", "-o", "addr", "show", ifname]).split("\n")
+
+            for entry in a:
+                family_index = entry.find(family)
+
+                if family_index < 0:
+                    continue
+
+                tmp = entry[entry.find(family) + len(family) + 1:]
+                ip = tmp[:tmp.find(" ")]
+
+                if ip:
+                    ips.add(ip)
+        except:
+            pass
+        return ips
+
+    def dhclient_start_and_check(self, ifname, family, handler, **handler_kwargs):
+        ip_config_before = self.get_current_ip_configured(ifname, family)
+        retry = self.dhclient_retry_on_failure
+
+        while retry >= 0:
+            handler(ifname, **handler_kwargs)
+            retry = self.dhclient_check(ifname, family, ip_config_before, retry, handler_kwargs.get("cmd_prefix"))
+
+    def dhclient_check(self, ifname, family, ip_config_before, retry, dhclient_cmd_prefix):
+        retry -= 1
+        diff = self.get_current_ip_configured(ifname, family).difference(ip_config_before)
+
+        if diff:
+            self.logger.info(
+                "%s: dhclient: new address%s detected: %s"
+                % (ifname, "es" if len(diff) > 1 else "", ", ".join(diff))
+            )
+            return -1
+        else:
+            try:
+                if retry > 0:
+                    self.logger.error(
+                        "%s: dhclient: couldn't detect new ip address, retrying %s more times..."
+                        % (ifname, retry)
+                    )
+                else:
+                    raise Exception("%s: dhclient: timeout failed to detect new ip addresses" % ifname)
+            finally:
+                self.logger.info("%s: releasing expired dhcp lease..." % ifname)
+                self.dhclientcmd.release(ifname, dhclient_cmd_prefix)
+        return retry
+
     def _up(self, ifaceobj):
         # if dhclient is already running do not stop and start it
         dhclient4_running = self.dhclientcmd.is_running(ifaceobj.name)
@@ -99,8 +173,15 @@ class dhcp(Addon, moduleBase):
                             self.dhclientcmd.stop(ifaceobj.name)
                     except:
                         pass
-                    self.dhclientcmd.start(ifaceobj.name, wait=wait,
-                                           cmd_prefix=dhclient_cmd_prefix)
+
+                    self.dhclient_start_and_check(
+                        ifaceobj.name,
+                        "inet",
+                        self.dhclientcmd.start,
+                        wait=wait,
+                        cmd_prefix=dhclient_cmd_prefix
+                    )
+
             if 'inet6' in ifaceobj.addr_family:
                 if dhclient6_running:
                     self.logger.info('dhclient6 already running on %s. '
@@ -136,9 +217,9 @@ class dhcp(Addon, moduleBase):
                         timeout -= 1
                         if timeout:
                             time.sleep(1)
-
         except Exception as e:
-            self.log_error(str(e), ifaceobj)
+            self.logger.error("%s: %s" % (ifaceobj.name, str(e)))
+            ifaceobj.set_status(ifaceStatus.ERROR)
 
     def _down_stale_dhcp_config(self, ifaceobj, family, dhclientX_running):
         addr_family = ifaceobj.addr_family
@@ -242,7 +323,18 @@ class dhcp(Addon, moduleBase):
             return
         if not self.is_dhcp_allowed_on(ifaceobj, syntax_check=False):
             return
-        if operation == 'query-checkcurr':
-            op_handler(self, ifaceobj, query_ifaceobj)
-        else:
-            op_handler(self, ifaceobj)
+
+        disable_syslog_on_exit = False
+        try:
+            if not ifupdownflags.flags.PERFMODE:
+                disable_syslog_on_exit = not LogManager.get_instance().is_syslog_enabled_syslog()
+                LogManager.get_instance().enable_syslog()
+                self.logger.info("%s: enabling syslog for dhcp configuration" % ifaceobj.name)
+
+            if operation == 'query-checkcurr':
+                op_handler(self, ifaceobj, query_ifaceobj)
+            else:
+                op_handler(self, ifaceobj)
+        finally:
+            if disable_syslog_on_exit:
+                LogManager.get_instance().disable_syslog()

diff --git a/ifupdown2/lib/log.py b/ifupdown2/lib/log.py
index 0768716bfe9836d878f0f27b6ed19d90470b0c99..574190016dedb9a9cd5e43d0a5ae5bef66236e14 100644 (file)
--- a/ifupdown2/lib/log.py
+++ b/ifupdown2/lib/log.py
@@ -133,7 +133,7 @@ class LogManager:
 
     def enable_syslog(self):
         """ Add syslog handler to root logger """
-        if self.__syslog_handler:
+        if self.__syslog_handler and self.__syslog_handler not in self.__root_logger.handlers:
             self.__root_logger.addHandler(self.__syslog_handler)
 
     def disable_syslog(self):
@@ -141,6 +141,9 @@ class LogManager:
         if self.__syslog_handler:
             self.__root_logger.removeHandler(self.__syslog_handler)
 
+    def is_syslog_enabled_syslog(self):
+        return self.__syslog_handler in self.__root_logger.handlers
+
     def close_log_stream(self):
         """ Close socket to disconnect client.
         We first have to perform this little hack: it seems like the socket is