printing the error stream of the dhclient process before killing it (#369)

This introduces a way to log the dhclient error stream, and uses it for the Azure datasource (where we have a specific requirement for this data to be logged).

6 files changed, 73 insertions, 16 deletions

diff --git a/cloudinit/net/dhcp.py b/cloudinit/net/dhcp.py
index d03baeab..9e004688 100644
--- a/cloudinit/net/dhcp.py
+++ b/cloudinit/net/dhcp.py
@@ -40,10 +40,11 @@ class NoDHCPLeaseError(Exception):
 
 
 class EphemeralDHCPv4(object):
-    def __init__(self, iface=None, connectivity_url=None):
+    def __init__(self, iface=None, connectivity_url=None, dhcp_log_func=None):
         self.iface = iface
         self._ephipv4 = None
         self.lease = None
+        self.dhcp_log_func = dhcp_log_func
         self.connectivity_url = connectivity_url
 
     def __enter__(self):
@@ -81,7 +82,8 @@ class EphemeralDHCPv4(object):
         if self.lease:
             return self.lease
         try:
-            leases = maybe_perform_dhcp_discovery(self.iface)
+            leases = maybe_perform_dhcp_discovery(
+                self.iface, self.dhcp_log_func)
         except InvalidDHCPLeaseFileError:
             raise NoDHCPLeaseError()
         if not leases:
@@ -131,13 +133,15 @@ class EphemeralDHCPv4(object):
                 result[internal_mapping] = self.lease.get(different_names)
 
 
-def maybe_perform_dhcp_discovery(nic=None):
+def maybe_perform_dhcp_discovery(nic=None, dhcp_log_func=None):
     """Perform dhcp discovery if nic valid and dhclient command exists.
 
     If the nic is invalid or undiscoverable or dhclient command is not found,
     skip dhcp_discovery and return an empty dict.
 
     @param nic: Name of the network interface we want to run dhclient on.
+    @param dhcp_log_func: A callable accepting the dhclient output and error
+        streams.
     @return: A list of dicts representing dhcp options for each lease obtained
         from the dhclient discovery if run, otherwise an empty list is
         returned.
@@ -159,7 +163,7 @@ def maybe_perform_dhcp_discovery(nic=None):
                             prefix='cloud-init-dhcp-',
                             needs_exe=True) as tdir:
         # Use /var/tmp because /run/cloud-init/tmp is mounted noexec
-        return dhcp_discovery(dhclient_path, nic, tdir)
+        return dhcp_discovery(dhclient_path, nic, tdir, dhcp_log_func)
 
 
 def parse_dhcp_lease_file(lease_file):
@@ -193,13 +197,15 @@ def parse_dhcp_lease_file(lease_file):
     return dhcp_leases
 
 
-def dhcp_discovery(dhclient_cmd_path, interface, cleandir):
+def dhcp_discovery(dhclient_cmd_path, interface, cleandir, dhcp_log_func=None):
     """Run dhclient on the interface without scripts or filesystem artifacts.
 
     @param dhclient_cmd_path: Full path to the dhclient used.
     @param interface: Name of the network inteface on which to dhclient.
     @param cleandir: The directory from which to run dhclient as well as store
         dhcp leases.
+    @param dhcp_log_func: A callable accepting the dhclient output and error
+        streams.
 
     @return: A list of dicts of representing the dhcp leases parsed from the
         dhcp.leases file or empty list.
@@ -223,7 +229,7 @@ def dhcp_discovery(dhclient_cmd_path, interface, cleandir):
     subp.subp(['ip', 'link', 'set', 'dev', interface, 'up'], capture=True)
     cmd = [sandbox_dhclient_cmd, '-1', '-v', '-lf', lease_file,
            '-pf', pid_file, interface, '-sf', '/bin/true']
-    subp.subp(cmd, capture=True)
+    out, err = subp.subp(cmd, capture=True)
 
     # Wait for pid file and lease file to appear, and for the process
     # named by the pid file to daemonize (have pid 1 as its parent). If we
@@ -240,6 +246,7 @@ def dhcp_discovery(dhclient_cmd_path, interface, cleandir):
         return []
 
     ppid = 'unknown'
+    daemonized = False
     for _ in range(0, 1000):
         pid_content = util.load_file(pid_file).strip()
         try:
@@ -251,13 +258,17 @@ def dhcp_discovery(dhclient_cmd_path, interface, cleandir):
             if ppid == 1:
                 LOG.debug('killing dhclient with pid=%s', pid)
                 os.kill(pid, signal.SIGKILL)
-                return parse_dhcp_lease_file(lease_file)
+                daemonized = True
+                break
         time.sleep(0.01)
 
-    LOG.error(
-        'dhclient(pid=%s, parentpid=%s) failed to daemonize after %s seconds',
-        pid_content, ppid, 0.01 * 1000
-    )
+    if not daemonized:
+        LOG.error(
+            'dhclient(pid=%s, parentpid=%s) failed to daemonize after %s '
+            'seconds', pid_content, ppid, 0.01 * 1000
+        )
+    if dhcp_log_func is not None:
+        dhcp_log_func(out, err)
     return parse_dhcp_lease_file(lease_file)
 
 
diff --git a/cloudinit/net/tests/test_dhcp.py b/cloudinit/net/tests/test_dhcp.py
index d4881592..7987f9d1 100644
--- a/cloudinit/net/tests/test_dhcp.py
+++ b/cloudinit/net/tests/test_dhcp.py
@@ -309,6 +309,7 @@ class TestDHCPDiscoveryClean(CiTestCase):
 
         Lease processing still occurs and no proc kill is attempted.
         """
+        m_subp.return_value = ('', '')
         tmpdir = self.tmp_dir()
         dhclient_script = os.path.join(tmpdir, 'dhclient.orig')
         script_content = '#!/bin/bash\necho fake-dhclient'
@@ -344,6 +345,7 @@ class TestDHCPDiscoveryClean(CiTestCase):
                                                                   m_kill,
                                                                   m_getppid):
         """dhcp_discovery waits for the presence of pidfile and dhcp.leases."""
+        m_subp.return_value = ('', '')
         tmpdir = self.tmp_dir()
         dhclient_script = os.path.join(tmpdir, 'dhclient.orig')
         script_content = '#!/bin/bash\necho fake-dhclient'
@@ -370,6 +372,7 @@ class TestDHCPDiscoveryClean(CiTestCase):
 
         It also returns the parsed dhcp.leases file generated in the sandbox.
         """
+        m_subp.return_value = ('', '')
         tmpdir = self.tmp_dir()
         dhclient_script = os.path.join(tmpdir, 'dhclient.orig')
         script_content = '#!/bin/bash\necho fake-dhclient'
@@ -406,6 +409,41 @@ class TestDHCPDiscoveryClean(CiTestCase):
                  'eth9', '-sf', '/bin/true'], capture=True)])
         m_kill.assert_has_calls([mock.call(my_pid, signal.SIGKILL)])
 
+    @mock.patch('cloudinit.net.dhcp.util.get_proc_ppid')
+    @mock.patch('cloudinit.net.dhcp.os.kill')
+    @mock.patch('cloudinit.net.dhcp.subp.subp')
+    def test_dhcp_output_error_stream(self, m_subp, m_kill, m_getppid):
+        """"dhcp_log_func is called with the output and error streams of
+        dhclinet when the callable is passed."""
+        dhclient_err = 'FAKE DHCLIENT ERROR'
+        dhclient_out = 'FAKE DHCLIENT OUT'
+        m_subp.return_value = (dhclient_out, dhclient_err)
+        tmpdir = self.tmp_dir()
+        dhclient_script = os.path.join(tmpdir, 'dhclient.orig')
+        script_content = '#!/bin/bash\necho fake-dhclient'
+        write_file(dhclient_script, script_content, mode=0o755)
+        lease_content = dedent("""
+                lease {
+                  interface "eth9";
+                  fixed-address 192.168.2.74;
+                  option subnet-mask 255.255.255.0;
+                  option routers 192.168.2.1;
+                }
+            """)
+        lease_file = os.path.join(tmpdir, 'dhcp.leases')
+        write_file(lease_file, lease_content)
+        pid_file = os.path.join(tmpdir, 'dhclient.pid')
+        my_pid = 1
+        write_file(pid_file, "%d\n" % my_pid)
+        m_getppid.return_value = 1  # Indicate that dhclient has daemonized
+
+        def dhcp_log_func(out, err):
+            self.assertEqual(out, dhclient_out)
+            self.assertEqual(err, dhclient_err)
+
+        dhcp_discovery(
+            dhclient_script, 'eth9', tmpdir, dhcp_log_func=dhcp_log_func)
+
 
 class TestSystemdParseLeases(CiTestCase):
 
diff --git a/cloudinit/sources/DataSourceAzure.py b/cloudinit/sources/DataSourceAzure.py
index 6d569057..41431a7a 100755
--- a/cloudinit/sources/DataSourceAzure.py
+++ b/cloudinit/sources/DataSourceAzure.py
@@ -35,7 +35,8 @@ from cloudinit.sources.helpers.azure import (
     get_system_info,
     report_diagnostic_event,
     EphemeralDHCPv4WithReporting,
-    is_byte_swapped)
+    is_byte_swapped,
+    dhcp_log_cb)
 
 LOG = logging.getLogger(__name__)
 
@@ -636,7 +637,8 @@ class DataSourceAzure(sources.DataSource):
                         name="obtain-dhcp-lease",
                         description="obtain dhcp lease",
                         parent=azure_ds_reporter):
-                    self._ephemeral_dhcp_ctx = EphemeralDHCPv4()
+                    self._ephemeral_dhcp_ctx = EphemeralDHCPv4(
+                        dhcp_log_func=dhcp_log_cb)
                     lease = self._ephemeral_dhcp_ctx.obtain_lease()
 
                 if vnet_switched:
diff --git a/cloudinit/sources/helpers/azure.py b/cloudinit/sources/helpers/azure.py
index 7bace8ca..7afa7ed8 100755
--- a/cloudinit/sources/helpers/azure.py
+++ b/cloudinit/sources/helpers/azure.py
@@ -626,10 +626,16 @@ def get_metadata_from_fabric(fallback_lease_file=None, dhcp_opts=None,
         shim.clean_up()
 
 
+def dhcp_log_cb(out, err):
+    report_diagnostic_event("dhclient output stream: %s" % out)
+    report_diagnostic_event("dhclient error stream: %s" % err)
+
+
 class EphemeralDHCPv4WithReporting(object):
     def __init__(self, reporter, nic=None):
         self.reporter = reporter
-        self.ephemeralDHCPv4 = EphemeralDHCPv4(iface=nic)
+        self.ephemeralDHCPv4 = EphemeralDHCPv4(
+            iface=nic, dhcp_log_func=dhcp_log_cb)
 
     def __enter__(self):
         with events.ReportEventStack(
diff --git a/tests/unittests/test_datasource/test_ec2.py b/tests/unittests/test_datasource/test_ec2.py
index 80e69c03..a93f2195 100644
--- a/tests/unittests/test_datasource/test_ec2.py
+++ b/tests/unittests/test_datasource/test_ec2.py
@@ -744,7 +744,7 @@ class TestEc2(test_helpers.HttprettyTestCase):
 
         ret = ds.get_data()
         self.assertTrue(ret)
-        m_dhcp.assert_called_once_with('eth9')
+        m_dhcp.assert_called_once_with('eth9', None)
         m_net.assert_called_once_with(
             broadcast='192.168.2.255', interface='eth9', ip='192.168.2.9',
             prefix_or_mask='255.255.255.0', router='192.168.2.1',
diff --git a/tests/unittests/test_datasource/test_openstack.py b/tests/unittests/test_datasource/test_openstack.py
index b534457c..3cfba74d 100644
--- a/tests/unittests/test_datasource/test_openstack.py
+++ b/tests/unittests/test_datasource/test_openstack.py
@@ -279,7 +279,7 @@ class TestOpenStackDataSource(test_helpers.HttprettyTestCase):
         self.assertEqual(2, len(ds_os_local.files))
         self.assertEqual(VENDOR_DATA, ds_os_local.vendordata_pure)
         self.assertIsNone(ds_os_local.vendordata_raw)
-        m_dhcp.assert_called_with('eth9')
+        m_dhcp.assert_called_with('eth9', None)
 
     def test_bad_datasource_meta(self):
         os_files = copy.deepcopy(OS_FILES)