Merge ~jasonzio/cloud-init:dhcpLeaseRace into cloud-init:master

[Jason Zions]

net: Wait for dhclient to daemonize before reading lease file

cloud-init uses dhclient to fetch the DHCP lease so it can extract
DHCP options. dhclient creates the leasefile, then writes to it;
simply waiting for the leasefile to appear creates a race between
dhclient and cloud-init. Instead, wait for dhclient to be parented by
init. At that point, we know it has written to the leasefile, so it's
safe to copy the file and kill the process.

cloud-init creates a temporary directory in which to execute dhclient,
and deletes that directory after it has killed the process. If
cloud-init abandons waiting for dhclient to daemonize, it will still
attempt to delete the temporary directory, but will not report an
exception should that attempt fail.

LP: #1794399

[Ryan Harper (raharper)]

A couple of inline comments.

review: Needs Fixing

[Jason Zions (jasonzio)]

I addressed your change to temp_utils.tempdir() a little differently than you suggested. To be honest, the code I initially proposed does exactly the same thing (peels the 'suppress_rmtree_errors' argument, if specified, out of the kwargs, capturing it in a separate variable), but it does so by not even putting it into kwargs in the first place. Python supports the syntax I used precisely for this very scenario. The code I replaced it with (popping the value from the kwargs dict if present, supplying a default if not present) is a pretty blunt thing.

All of this is required due to tempfile.mkstemp() complaining if it's supplied with an option (suppress_rmtree_errors) it does not expect. I can't just leave that keyword param in kwargs.

review: Needs Resubmitting

[Jason Zions (jasonzio)]

> I addressed your change to temp_utils.tempdir() a little differently than you
> suggested. To be honest, the code I initially proposed does exactly the same
> thing (peels the 'suppress_rmtree_errors' argument, if specified, out of the
> kwargs, capturing it in a separate variable), but it does so by not even
> putting it into kwargs in the first place. Python supports the syntax I used
> precisely for this very scenario. The code I replaced it with (popping the
> value from the kwargs dict if present, supplying a default if not present) is
> a pretty blunt thing.
>
> All of this is required due to tempfile.mkstemp() complaining if it's supplied
> with an option (suppress_rmtree_errors) it does not expect. I can't just leave
> that keyword param in kwargs.

(Ignore the "review: resubmit" thing; I'm still learning launchpad.)

[Jason Zions (jasonzio)]

review: Needs Fixing

[Ryan Harper (raharper)]

Hi Jason,

I'm sorry. I now see why you had suppress_rmtree_errors separate; it was only for the rmtree command itself. Now that I understand that it does indeed make sense to keep it out of the kwargs.

Could we update the variable to:

def tempdir(rmtree_ignore_errors=False, **kwargs)

I think that helps indicate that the parameter is for the rmtree call.

sorry again for missing this the first time.

[Jason Zions (jasonzio)]

> Could we update the variable to:
>
> def tempdir(rmtree_ignore_errors=False, **kwargs)
>
>
> I think that helps indicate that the parameter is for the rmtree call.

Done.

[Ryan Harper (raharper)]

Pointing CI at this:

https://jenkins.ubuntu.com/server/job/cloud-init-ci/514/

[Server Team CI bot (server-team-bot)]

PASSED: Continuous integration, rev:d8c760069378e9a096b91e655df17767ffb51f0d
https://jenkins.ubuntu.com/server/job/cloud-init-ci/514/
Executed test runs:
    SUCCESS: Checkout
    SUCCESS: Unit & Style Tests
    SUCCESS: Ubuntu LTS: Build
    SUCCESS: Ubuntu LTS: Integration
    IN_PROGRESS: Declarative: Post Actions

Click here to trigger a rebuild:
https://jenkins.ubuntu.com/server/job/cloud-init-ci/514/rebuild

review: Approve (continuous-integration)

[Ryan Harper (raharper)]

review: Approve

[Server Team CI bot (server-team-bot)]

Commit message lints:
 - Line #2 has 307 too many characters. Line starts with: "cloud-init uses dhclient"... - Line #4 has 230 too many characters. Line starts with: "cloud-init creates a"...

review: Needs Fixing

[Jason Zions (jasonzio)]

review: Approve

[Server Team CI bot (server-team-bot)]

review: Approve (continuous-integration)

[Server Team CI bot (server-team-bot)]

Commit message lints:
 - Line #8 has 4 too many characters. Line starts with: " "...

review: Needs Fixing

[Server Team CI bot (server-team-bot)]

review: Approve (continuous-integration)

[Server Team CI bot (server-team-bot)]

Commit message lints:
 - Line #8 has 4 too many characters. Line starts with: " "...

review: Needs Fixing

[Server Team CI bot (server-team-bot)]

review: Approve (continuous-integration)

diff --git a/cloudinit/net/dhcp.py b/cloudinit/net/dhcp.py
index 0db991d..c98a97c 100644
--- a/cloudinit/net/dhcp.py
+++ b/cloudinit/net/dhcp.py
@@ -9,6 +9,7 @@ import logging
 import os
 import re
 import signal
+import time
 
 from cloudinit.net import (
     EphemeralIPv4Network, find_fallback_nic, get_devicelist,
@@ -127,7 +128,9 @@ def maybe_perform_dhcp_discovery(nic=None):
     if not dhclient_path:
         LOG.debug('Skip dhclient configuration: No dhclient command found.')
         return []
-    with temp_utils.tempdir(prefix='cloud-init-dhcp-', needs_exe=True) as tdir:
+    with temp_utils.tempdir(rmtree_ignore_errors=True,
+                            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)
 
@@ -195,24 +198,39 @@ def dhcp_discovery(dhclient_cmd_path, interface, cleandir):
            '-pf', pid_file, interface, '-sf', '/bin/true']
     util.subp(cmd, capture=True)
 
-    # dhclient doesn't write a pid file until after it forks when it gets a
-    # proper lease response. Since cleandir is a temp directory that gets
-    # removed, we need to wait for that pidfile creation before the
-    # cleandir is removed, otherwise we get FileNotFound errors.
+    # 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
+    # try to read the lease file before daemonization happens, we might try
+    # to read it before the dhclient has actually written it. We also have
+    # to wait until the dhclient has become a daemon so we can be sure to
+    # kill the correct process, thus freeing cleandir to be deleted back
+    # up the callstack.
     missing = util.wait_for_files(
         [pid_file, lease_file], maxwait=5, naplen=0.01)
     if missing:
         LOG.warning("dhclient did not produce expected files: %s",
                     ', '.join(os.path.basename(f) for f in missing))
         return []
-    pid_content = util.load_file(pid_file).strip()
-    try:
-        pid = int(pid_content)
-    except ValueError:
-        LOG.debug(
-            "pid file contains non-integer content '%s'", pid_content)
-    else:
-        os.kill(pid, signal.SIGKILL)
+
+    ppid = 'unknown'
+    for _ in range(0, 1000):
+        pid_content = util.load_file(pid_file).strip()
+        try:
+            pid = int(pid_content)
+        except ValueError:
+            pass
+        else:
+            ppid = util.get_proc_ppid(pid)
+            if ppid == 1:
+                LOG.debug('killing dhclient with pid=%s', pid)
+                os.kill(pid, signal.SIGKILL)
+                return parse_dhcp_lease_file(lease_file)
+        time.sleep(0.01)
+
+    LOG.error(
+        'dhclient(pid=%s, parentpid=%s) failed to daemonize after %s seconds',
+        pid_content, ppid, 0.01 * 1000
+    )
     return parse_dhcp_lease_file(lease_file)
 
 
diff --git a/cloudinit/net/tests/test_dhcp.py b/cloudinit/net/tests/test_dhcp.py
index cd3e732..79e8842 100644
--- a/cloudinit/net/tests/test_dhcp.py
+++ b/cloudinit/net/tests/test_dhcp.py
@@ -145,16 +145,20 @@ class TestDHCPDiscoveryClean(CiTestCase):
               'subnet-mask': '255.255.255.0', 'routers': '192.168.2.1'}],
             dhcp_discovery(dhclient_script, 'eth9', tmpdir))
         self.assertIn(
-            "pid file contains non-integer content ''", self.logs.getvalue())
+            "dhclient(pid=, parentpid=unknown) failed "
+            "to daemonize after 10.0 seconds",
+            self.logs.getvalue())
         m_kill.assert_not_called()
 
+    @mock.patch('cloudinit.net.dhcp.util.get_proc_ppid')
     @mock.patch('cloudinit.net.dhcp.os.kill')
     @mock.patch('cloudinit.net.dhcp.util.wait_for_files')
     @mock.patch('cloudinit.net.dhcp.util.subp')
     def test_dhcp_discovery_run_in_sandbox_waits_on_lease_and_pid(self,
                                                                   m_subp,
                                                                   m_wait,
-                                                                  m_kill):
+                                                                  m_kill,
+                                                                  m_getppid):
         """dhcp_discovery waits for the presence of pidfile and dhcp.leases."""
         tmpdir = self.tmp_dir()
         dhclient_script = os.path.join(tmpdir, 'dhclient.orig')
@@ -164,6 +168,7 @@ class TestDHCPDiscoveryClean(CiTestCase):
         pidfile = self.tmp_path('dhclient.pid', tmpdir)
         leasefile = self.tmp_path('dhcp.leases', tmpdir)
         m_wait.return_value = [pidfile]  # Return the missing pidfile wait for
+        m_getppid.return_value = 1  # Indicate that dhclient has daemonized
         self.assertEqual([], dhcp_discovery(dhclient_script, 'eth9', tmpdir))
         self.assertEqual(
             mock.call([pidfile, leasefile], maxwait=5, naplen=0.01),
@@ -173,9 +178,10 @@ class TestDHCPDiscoveryClean(CiTestCase):
             self.logs.getvalue())
         m_kill.assert_not_called()
 
+    @mock.patch('cloudinit.net.dhcp.util.get_proc_ppid')
     @mock.patch('cloudinit.net.dhcp.os.kill')
     @mock.patch('cloudinit.net.dhcp.util.subp')
-    def test_dhcp_discovery_run_in_sandbox(self, m_subp, m_kill):
+    def test_dhcp_discovery_run_in_sandbox(self, m_subp, m_kill, m_getppid):
         """dhcp_discovery brings up the interface and runs dhclient.
 
         It also returns the parsed dhcp.leases file generated in the sandbox.
@@ -197,6 +203,7 @@ class TestDHCPDiscoveryClean(CiTestCase):
         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
 
         self.assertItemsEqual(
             [{'interface': 'eth9', 'fixed-address': '192.168.2.74',
@@ -355,3 +362,5 @@ class TestEphemeralDhcpNoNetworkSetup(HttprettyTestCase):
             self.assertEqual(fake_lease, lease)
         # Ensure that dhcp discovery occurs
         m_dhcp.called_once_with()
+
+# vi: ts=4 expandtab
diff --git a/cloudinit/temp_utils.py b/cloudinit/temp_utils.py
index c98a1b5..346276e 100644
--- a/cloudinit/temp_utils.py
+++ b/cloudinit/temp_utils.py
@@ -81,7 +81,7 @@ def ExtendedTemporaryFile(**kwargs):
 
 
 @contextlib.contextmanager
-def tempdir(**kwargs):
+def tempdir(rmtree_ignore_errors=False, **kwargs):
     # This seems like it was only added in python 3.2
     # Make it since its useful...
     # See: http://bugs.python.org/file12970/tempdir.patch
@@ -89,7 +89,7 @@ def tempdir(**kwargs):
     try:
         yield tdir
     finally:
-        shutil.rmtree(tdir)
+        shutil.rmtree(tdir, ignore_errors=rmtree_ignore_errors)
 
 
 def mkdtemp(**kwargs):
diff --git a/cloudinit/tests/test_temp_utils.py b/cloudinit/tests/test_temp_utils.py
index ffbb92c..4a52ef8 100644
--- a/cloudinit/tests/test_temp_utils.py
+++ b/cloudinit/tests/test_temp_utils.py
@@ -2,8 +2,9 @@
 
 """Tests for cloudinit.temp_utils"""
 
-from cloudinit.temp_utils import mkdtemp, mkstemp
+from cloudinit.temp_utils import mkdtemp, mkstemp, tempdir
 from cloudinit.tests.helpers import CiTestCase, wrap_and_call
+import os
 
 
 class TestTempUtils(CiTestCase):
@@ -98,4 +99,19 @@ class TestTempUtils(CiTestCase):
         self.assertEqual('/fake/return/path', retval)
         self.assertEqual([{'dir': '/run/cloud-init/tmp'}], calls)
 
+    def test_tempdir_error_suppression(self):
+        """test tempdir suppresses errors during directory removal."""
+
+        with self.assertRaises(OSError):
+            with tempdir(prefix='cloud-init-dhcp-') as tdir:
+                os.rmdir(tdir)
+                # As a result, the directory is already gone,
+                # so shutil.rmtree should raise OSError
+
+        with tempdir(rmtree_ignore_errors=True,
+                     prefix='cloud-init-dhcp-') as tdir:
+            os.rmdir(tdir)
+            # Since the directory is already gone, shutil.rmtree would raise
+            # OSError, but we suppress that
+
 # vi: ts=4 expandtab
diff --git a/cloudinit/util.py b/cloudinit/util.py
index 7800f7b..a8a232b 100644
--- a/cloudinit/util.py
+++ b/cloudinit/util.py
@@ -2876,4 +2876,20 @@ def udevadm_settle(exists=None, timeout=None):
     return subp(settle_cmd)
 
 
+def get_proc_ppid(pid):
+    """
+    Return the parent pid of a process.
+    """
+    ppid = 0
+    try:
+        contents = load_file("/proc/%s/stat" % pid, quiet=True)
+    except IOError as e:
+        LOG.warning('Failed to load /proc/%s/stat. %s', pid, e)
+    if contents:
+        parts = contents.split(" ", 4)
+        # man proc says
+        #  ppid %d     (4) The PID of the parent.
+        ppid = int(parts[3])
+    return ppid
+
 # vi: ts=4 expandtab
diff --git a/tests/unittests/test_util.py b/tests/unittests/test_util.py
index 5a14479..0e71db8 100644
--- a/tests/unittests/test_util.py
+++ b/tests/unittests/test_util.py
@@ -1171,4 +1171,10 @@ class TestGetProcEnv(helpers.TestCase):
         self.assertEqual({}, util.get_proc_env(1))
         self.assertEqual(1, m_load_file.call_count)
 
+    def test_get_proc_ppid(self):
+        """get_proc_ppid returns correct parent pid value."""
+        my_pid = os.getpid()
+        my_ppid = os.getppid()
+        self.assertEqual(my_ppid, util.get_proc_ppid(my_pid))
+
 # vi: ts=4 expandtab