Merge lp:~raharper/curtin/trunk.md-retry-stop-resync into lp:~curtin-dev/curtin/trunk

[Ryan Harper]

mdadm_stop: Add retry and additional steps to halt a resync

In our vmtest (as well as seen in real deployments) after a reboot of a system with mdadm arrays already configured on disk, md may start a 'resync' operation to bring an array online. The resync operation sometimes prevents mdadm from stopping the array. This patch applies a few known methods to halt the resync, namely writing 'idle' to md/sync_action and changing the sync_max and sync_min values to 0.

Add additional unittests to exercise the retry path now taken to help ensure we can reliably shutdown a mdadm array even while in 'resync' state.

[Ryan Harper (raharper)]

Started a vmtest run here:
https://jenkins.ubuntu.com/server/job/curtin-vmtest-devel-debug/43/

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

PASSED: Continuous integration, rev:501
https://jenkins.ubuntu.com/server/job/curtin-ci/489/
Executed test runs:
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=metal-amd64/489
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=metal-arm64/489
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=metal-ppc64el/489
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=vm-i386/489

Click here to trigger a rebuild:
https://jenkins.ubuntu.com/server/job/curtin-ci/489/rebuild

review: Approve (continuous-integration)

[Scott Moser (smoser)]

one small comment. other than that, i approve. the proof is really in the racey mdadm pudding.

[Scott Moser (smoser)]

review: Approve

[lp:~raharper/curtin/trunk.md-retry-stop-resync]

502. By Ryan Harper on 2017-05-12

Add docstring as requested

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

PASSED: Continuous integration, rev:502
https://jenkins.ubuntu.com/server/job/curtin-ci/504/
Executed test runs:
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=metal-amd64/504
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=metal-arm64/504
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=metal-ppc64el/504
    SUCCESS: https://jenkins.ubuntu.com/server/job/curtin-ci/nodes=vm-i386/504

Click here to trigger a rebuild:
https://jenkins.ubuntu.com/server/job/curtin-ci/504/rebuild

review: Approve (continuous-integration)

[lp:~raharper/curtin/trunk.md-retry-stop-resync]

503. By Ryan Harper on 2017-05-15

merge from trunk

=== modified file 'curtin/block/__init__.py'
--- curtin/block/__init__.py	2017-03-21 18:05:24 +0000
+++ curtin/block/__init__.py	2017-05-15 15:47:54 +0000
@@ -94,7 +94,6 @@
     # cciss devices need to have 'cciss!' prepended
     if path.startswith('/dev/cciss'):
         dev_kname = 'cciss!' + dev_kname
-    LOG.debug("path_to_kname input: '{}' output: '{}'".format(path, dev_kname))
     return dev_kname
 
 
@@ -106,7 +105,6 @@
     # if given something that is already a dev path, return it
     if os.path.exists(kname) and is_valid_device(kname):
         path = kname
-        LOG.debug("kname_to_path input: '{}' output: '{}'".format(kname, path))
         return os.path.realpath(path)
     # adding '/dev' to path is not sufficient to handle cciss devices and
     # possibly other special devices which have not been encountered yet
@@ -114,7 +112,6 @@
     # make sure path we get is correct
     if not (os.path.exists(path) and is_valid_device(path)):
         raise OSError('could not get path to dev from kname: {}'.format(kname))
-    LOG.debug("kname_to_path input: '{}' output: '{}'".format(kname, path))
     return path
 
 
 
=== modified file 'curtin/block/mdadm.py'
--- curtin/block/mdadm.py	2017-05-03 02:05:22 +0000
+++ curtin/block/mdadm.py	2017-05-15 15:47:54 +0000
@@ -26,6 +26,7 @@
 import re
 import shlex
 from subprocess import CalledProcessError
+import time
 
 from curtin.block import (dev_short, dev_path, is_valid_device, sys_block_path)
 from curtin.block import get_holders
@@ -253,13 +254,59 @@
     return data
 
 
-def mdadm_stop(devpath):
+def mdadm_stop(devpath, retries=None):
     assert_valid_devpath(devpath)
+    if not retries:
+        retries = [0.2] * 60
+
+    sync_action = md_sysfs_attr_path(devpath, 'sync_action')
+    sync_max = md_sysfs_attr_path(devpath, 'sync_max')
+    sync_min = md_sysfs_attr_path(devpath, 'sync_min')
 
     LOG.info("mdadm stopping: %s" % devpath)
-    out, err = util.subp(["mdadm", "--manage", "--stop", devpath],
-                         capture=True)
-    LOG.debug("mdadm stop:\n%s\n%s", out, err)
+    for (attempt, wait) in enumerate(retries):
+        try:
+            LOG.debug('mdadm: stop on %s attempt %s', devpath, attempt)
+            # An array in 'resync' state may not be stoppable, attempt to
+            # cancel an ongoing resync
+            val = md_sysfs_attr(devpath, 'sync_action')
+            LOG.debug('%s/sync_max = %s', sync_action, val)
+            if val != "idle":
+                LOG.debug("mdadm: setting array sync_action=idle")
+                util.write_file(sync_action, content="idle")
+
+            # Setting the sync_{max,min} may can help prevent the array from
+            # changing back to 'resync' which may prevent the array from being
+            # stopped
+            val = md_sysfs_attr(devpath, 'sync_max')
+            LOG.debug('%s/sync_max = %s', sync_max, val)
+            if val != "0":
+                LOG.debug("mdadm: setting array sync_{min,max}=0")
+                try:
+                    util.write_file(sync_max, content="0")
+                    util.write_file(sync_min, content="0")
+                except IOError:
+                    LOG.warning('mdadm: failed to set sync_{max,min} values')
+                    pass
+
+            # one wonders why this command doesn't do any of the above itself?
+            out, err = util.subp(["mdadm", "--manage", "--stop", devpath],
+                                 capture=True)
+            LOG.debug("mdadm stop command output:\n%s\n%s", out, err)
+            LOG.info("mdadm: successfully stopped %s after %s attempt(s)",
+                     devpath, attempt+1)
+            return
+
+        except util.ProcessExecutionError:
+            LOG.warning("mdadm stop failed, retrying ")
+            if os.path.isfile('/proc/mdstat'):
+                LOG.critical("/proc/mdstat:\n%s",
+                             util.load_file('/proc/mdstat'))
+            LOG.debug("mdadm: stop failed, retrying in %s seconds", wait)
+            time.sleep(wait)
+            pass
+
+    raise OSError('Failed to stop mdadm device %s', devpath)
 
 
 def mdadm_remove(devpath):
@@ -341,16 +388,22 @@
         raise ValueError("Invalid devpath: '%s'" % devpath)
 
 
+def md_sysfs_attr_path(md_devname, attrname):
+    """ Return the path to a md device attribute under the 'md' dir """
+    # build /sys/class/block/<md_short>/md
+    sysmd = sys_block_path(md_devname, "md")
+
+    # append attrname
+    return os.path.join(sysmd, attrname)
+
+
 def md_sysfs_attr(md_devname, attrname):
+    """ Return the attribute str of an md device found under the 'md' dir """
+    attrdata = ''
     if not valid_mdname(md_devname):
         raise ValueError('Invalid md devicename: [{}]'.format(md_devname))
 
-    attrdata = ''
-    #  /sys/class/block/<md_short>/md
-    sysmd = sys_block_path(md_devname, "md")
-
-    #  /sys/class/block/<md_short>/md/attrname
-    sysfs_attr_path = os.path.join(sysmd, attrname)
+    sysfs_attr_path = md_sysfs_attr_path(md_devname, attrname)
     if os.path.isfile(sysfs_attr_path):
         attrdata = util.load_file(sysfs_attr_path).strip()
 
 
=== modified file 'tests/unittests/test_block_mdadm.py'
--- tests/unittests/test_block_mdadm.py	2017-05-03 02:07:45 +0000
+++ tests/unittests/test_block_mdadm.py	2017-05-15 15:47:54 +0000
@@ -331,27 +331,168 @@
 class TestBlockMdadmStop(MdadmTestBase):
     def setUp(self):
         super(TestBlockMdadmStop, self).setUp()
-        self.add_patch('curtin.block.mdadm.util', 'mock_util')
+        self.add_patch('curtin.block.mdadm.util.lsb_release', 'mock_util_lsb')
+        self.add_patch('curtin.block.mdadm.util.subp', 'mock_util_subp')
+        self.add_patch('curtin.block.mdadm.util.write_file',
+                       'mock_util_write_file')
+        self.add_patch('curtin.block.mdadm.util.load_file',
+                       'mock_util_load_file')
         self.add_patch('curtin.block.mdadm.is_valid_device', 'mock_valid')
+        self.add_patch('curtin.block.mdadm.sys_block_path',
+                       'mock_sys_block_path')
+        self.add_patch('curtin.block.mdadm.os.path.isfile', 'mock_path_isfile')
 
         # Common mock settings
         self.mock_valid.return_value = True
-        self.mock_util.lsb_release.return_value = {'codename': 'xenial'}
-        self.mock_util.subp.side_effect = [
+        self.mock_util_lsb.return_value = {'codename': 'xenial'}
+        self.mock_util_subp.side_effect = iter([
             ("", ""),  # mdadm stop device
-        ]
+        ])
+        self.mock_path_isfile.return_value = True
+        self.mock_util_load_file.side_effect = iter([
+            "idle", "max",
+        ])
+
+    def _set_sys_path(self, md_device):
+        self.sys_path = '/sys/class/block/%s/md' % md_device.split("/")[-1]
+        self.mock_sys_block_path.return_value = self.sys_path
 
     def test_mdadm_stop_no_devpath(self):
         with self.assertRaises(ValueError):
             mdadm.mdadm_stop(None)
 
     def test_mdadm_stop(self):
-        device = "/dev/vdc"
-        mdadm.mdadm_stop(device)
-        expected_calls = [
-            call(["mdadm", "--manage", "--stop", device], capture=True)
-        ]
-        self.mock_util.subp.assert_has_calls(expected_calls)
+        device = "/dev/md0"
+        self._set_sys_path(device)
+
+        mdadm.mdadm_stop(device)
+
+        expected_calls = [
+            call(["mdadm", "--manage", "--stop", device], capture=True)
+        ]
+        self.mock_util_subp.assert_has_calls(expected_calls)
+
+        expected_reads = [
+            call(self.sys_path + '/sync_action'),
+            call(self.sys_path + '/sync_max'),
+        ]
+        self.mock_util_load_file.assert_has_calls(expected_reads)
+
+    @patch('curtin.block.mdadm.time.sleep')
+    def test_mdadm_stop_retry(self, mock_sleep):
+        device = "/dev/md10"
+        self._set_sys_path(device)
+        self.mock_util_load_file.side_effect = iter([
+            "resync", "max",
+            "proc/mdstat output",
+            "idle", "0",
+        ])
+        self.mock_util_subp.side_effect = iter([
+            util.ProcessExecutionError(),
+            ("mdadm stopped %s" % device, ''),
+        ])
+
+        mdadm.mdadm_stop(device)
+
+        expected_calls = [
+            call(["mdadm", "--manage", "--stop", device], capture=True),
+            call(["mdadm", "--manage", "--stop", device], capture=True)
+        ]
+        self.mock_util_subp.assert_has_calls(expected_calls)
+
+        expected_reads = [
+            call(self.sys_path + '/sync_action'),
+            call(self.sys_path + '/sync_max'),
+            call('/proc/mdstat'),
+            call(self.sys_path + '/sync_action'),
+            call(self.sys_path + '/sync_max'),
+        ]
+        self.mock_util_load_file.assert_has_calls(expected_reads)
+
+        expected_writes = [
+            call(self.sys_path + '/sync_action', content='idle'),
+            call(self.sys_path + '/sync_max', content='0'),
+            call(self.sys_path + '/sync_min', content='0'),
+        ]
+        self.mock_util_write_file.assert_has_calls(expected_writes)
+
+    @patch('curtin.block.mdadm.time.sleep')
+    def test_mdadm_stop_retry_sysfs_write_fail(self, mock_sleep):
+        device = "/dev/md126"
+        self._set_sys_path(device)
+        self.mock_util_load_file.side_effect = iter([
+            "resync", "max",
+            "proc/mdstat output",
+            "idle", "0",
+        ])
+        self.mock_util_subp.side_effect = iter([
+            util.ProcessExecutionError(),
+            ("mdadm stopped %s" % device, ''),
+        ])
+        # sometimes we fail to modify sysfs attrs
+        self.mock_util_write_file.side_effect = iter([
+            "",         # write to sync_action OK
+            IOError(),  # write to sync_max FAIL
+        ])
+
+        mdadm.mdadm_stop(device)
+
+        expected_calls = [
+            call(["mdadm", "--manage", "--stop", device], capture=True),
+            call(["mdadm", "--manage", "--stop", device], capture=True)
+        ]
+        self.mock_util_subp.assert_has_calls(expected_calls)
+
+        expected_reads = [
+            call(self.sys_path + '/sync_action'),
+            call(self.sys_path + '/sync_max'),
+            call('/proc/mdstat'),
+            call(self.sys_path + '/sync_action'),
+            call(self.sys_path + '/sync_max'),
+        ]
+        self.mock_util_load_file.assert_has_calls(expected_reads)
+
+        expected_writes = [
+            call(self.sys_path + '/sync_action', content='idle'),
+        ]
+        self.mock_util_write_file.assert_has_calls(expected_writes)
+
+    @patch('curtin.block.mdadm.time.sleep')
+    def test_mdadm_stop_retry_exhausted(self, mock_sleep):
+        device = "/dev/md/37"
+        retries = 60
+        self._set_sys_path(device)
+        self.mock_util_load_file.side_effect = iter([
+            "resync", "max",
+            "proc/mdstat output",
+        ] * retries)
+        self.mock_util_subp.side_effect = iter([
+            util.ProcessExecutionError(),
+        ] * retries)
+        # sometimes we fail to modify sysfs attrs
+        self.mock_util_write_file.side_effect = iter([
+            "", IOError()] * retries)
+
+        with self.assertRaises(OSError):
+            mdadm.mdadm_stop(device)
+
+        expected_calls = [
+            call(["mdadm", "--manage", "--stop", device], capture=True),
+        ] * retries
+        self.mock_util_subp.assert_has_calls(expected_calls)
+
+        expected_reads = [
+            call(self.sys_path + '/sync_action'),
+            call(self.sys_path + '/sync_max'),
+            call('/proc/mdstat'),
+        ] * retries
+        self.mock_util_load_file.assert_has_calls(expected_reads)
+
+        expected_writes = [
+            call(self.sys_path + '/sync_action', content='idle'),
+            call(self.sys_path + '/sync_max', content='0'),
+        ] * retries
+        self.mock_util_write_file.assert_has_calls(expected_writes)
 
 
 class TestBlockMdadmRemove(MdadmTestBase):