Add rootwrap daemon mode support

Add a configuration option 'use_rootwrap_daemon' to
switch on the rootwrap daemon mode support. This
option is switched off by default to keep the current
behavior as is.

The code honors the various options available in
processutils.execute() like 'attempts', 'delay_on_retry'
etc to ensure that we don't regress any current behavior.

DocImpact

Part of blueprint nova-rootwrap-daemon-mode

Depends-On: I80c7b9dd8e9e0f940aa4e54a95b241dfc40d3574
Change-Id: I57dc2efa39b86fa1fa20730ad70d056e87617c96

2 files changed, 326 insertions, 6 deletions

diff --git a/nova/tests/unit/test_utils.py b/nova/tests/unit/test_utils.py
index e86d7acf36..f4482b19a2 100644
--- a/nova/tests/unit/test_utils.py
+++ b/nova/tests/unit/test_utils.py
@@ -16,6 +16,7 @@ import datetime
 import functools
 import hashlib
 import importlib
+import logging
 import os
 import os.path
 import socket
@@ -34,7 +35,6 @@ from oslo_utils import timeutils
 from oslo_utils import units
 import six
 
-
 import nova
 from nova import context
 from nova import exception
@@ -192,6 +192,21 @@ class GenericUtilsTestCase(test.NoDBTestCase):
         cmd = utils.get_root_helper()
         self.assertEqual('sudo nova-rootwrap foo', cmd)
 
+    @mock.patch('nova.utils.RootwrapProcessHelper')
+    def test_get_root_helper_proc(self, mock_proc_helper):
+        self.flags(use_rootwrap_daemon=False)
+        self.flags(rootwrap_config="/path/to/conf")
+        utils._get_rootwrap_helper()
+        mock_proc_helper.assert_called_once_with()
+
+    @mock.patch('nova.utils.RootwrapDaemonHelper')
+    def test_get_root_helper_daemon(self, mock_daemon_helper):
+        conf_path = '/path/to/conf'
+        self.flags(use_rootwrap_daemon=True)
+        self.flags(rootwrap_config=conf_path)
+        utils._get_rootwrap_helper()
+        mock_daemon_helper.assert_called_once_with(conf_path)
+
     def test_use_sudo(self):
         self.flags(disable_rootwrap=True, group='workarounds')
         cmd = utils.get_root_helper()
@@ -248,6 +263,171 @@ class TestCachedFile(test.NoDBTestCase):
         self.assertNotIn(filename, utils._FILE_CACHE)
 
 
+class RootwrapDaemonTesetCase(test.TestCase):
+    @mock.patch('oslo_rootwrap.client.Client')
+    def test_get_client(self, mock_client):
+        mock_conf = mock.MagicMock()
+        utils.RootwrapDaemonHelper(mock_conf)
+        mock_client.assert_called_once_with(
+            ["sudo", "nova-rootwrap-daemon", mock_conf])
+
+    @mock.patch('nova.utils.LOG.info')
+    def test_execute(self, mock_info):
+        mock_conf = mock.MagicMock()
+        daemon = utils.RootwrapDaemonHelper(mock_conf)
+        daemon.client = mock.MagicMock()
+        daemon.client.execute = mock.Mock(return_value=(0, None, None))
+
+        daemon.execute('a', 1, foo='bar', run_as_root=True)
+        daemon.client.execute.assert_called_once_with(['a', '1'], None)
+        mock_info.assert_has_calls([mock.call(
+            u'Executing RootwrapDaemonHelper.execute cmd=[%(cmd)r] '
+            u'kwargs=[%(kwargs)r]',
+            {'cmd': u'a 1', 'kwargs': {'run_as_root': True, 'foo': 'bar'}})])
+
+    def test_execute_with_kwargs(self):
+        mock_conf = mock.MagicMock()
+        daemon = utils.RootwrapDaemonHelper(mock_conf)
+        daemon.client = mock.MagicMock()
+        daemon.client.execute = mock.Mock(return_value=(0, None, None))
+
+        daemon.execute('a', 1, foo='bar', run_as_root=True, process_input=True)
+        daemon.client.execute.assert_called_once_with(['a', '1'], True)
+
+    def test_execute_fail(self):
+        mock_conf = mock.MagicMock()
+        daemon = utils.RootwrapDaemonHelper(mock_conf)
+        daemon.client = mock.MagicMock()
+        daemon.client.execute = mock.Mock(return_value=(-2, None, None))
+
+        self.assertRaises(processutils.ProcessExecutionError,
+                          daemon.execute, 'b', 2)
+
+    def test_execute_pass_with_check_exit_code(self):
+        mock_conf = mock.MagicMock()
+        daemon = utils.RootwrapDaemonHelper(mock_conf)
+        daemon.client = mock.MagicMock()
+        daemon.client.execute = mock.Mock(return_value=(-2, None, None))
+        daemon.execute('b', 2, check_exit_code=[-2])
+
+    def test_execute_fail_with_retry(self):
+        mock_conf = mock.MagicMock()
+        daemon = utils.RootwrapDaemonHelper(mock_conf)
+        daemon.client = mock.MagicMock()
+        daemon.client.execute = mock.Mock(return_value=(-2, None, None))
+
+        self.assertRaises(processutils.ProcessExecutionError,
+                          daemon.execute, 'b', 2, attempts=2)
+        daemon.client.execute.assert_has_calls(
+            [mock.call(['b', '2'], None),
+             mock.call(['b', '2'], None)])
+
+    @mock.patch('nova.utils.LOG.log')
+    def test_execute_fail_and_logging(self, mock_log):
+        mock_conf = mock.MagicMock()
+        daemon = utils.RootwrapDaemonHelper(mock_conf)
+        daemon.client = mock.MagicMock()
+        daemon.client.execute = mock.Mock(return_value=(-2, None, None))
+
+        self.assertRaises(processutils.ProcessExecutionError,
+                          daemon.execute, 'b', 2,
+                          attempts=2,
+                          loglevel=logging.CRITICAL,
+                          log_errors=processutils.LOG_ALL_ERRORS)
+        mock_log.assert_has_calls(
+            [
+                mock.call(logging.CRITICAL, u'Running cmd (subprocess): %s',
+                          u'b 2'),
+                mock.call(logging.CRITICAL,
+                          'CMD "%(sanitized_cmd)s" returned: %(return_code)s '
+                          'in %(end_time)0.3fs',
+                          {'sanitized_cmd': u'b 2', 'return_code': -2,
+                           'end_time': mock.ANY}),
+                mock.call(logging.CRITICAL,
+                          u'%(desc)r\ncommand: %(cmd)r\nexit code: %(code)r'
+                          u'\nstdout: %(stdout)r\nstderr: %(stderr)r',
+                          {'code': -2, 'cmd': u'b 2', 'stdout': u'None',
+                           'stderr': u'None', 'desc': None}),
+                mock.call(logging.CRITICAL, u'%r failed. Retrying.', u'b 2'),
+                mock.call(logging.CRITICAL, u'Running cmd (subprocess): %s',
+                          u'b 2'),
+                mock.call(logging.CRITICAL,
+                          'CMD "%(sanitized_cmd)s" returned: %(return_code)s '
+                          'in %(end_time)0.3fs',
+                          {'sanitized_cmd': u'b 2', 'return_code': -2,
+                           'end_time': mock.ANY}),
+                mock.call(logging.CRITICAL,
+                          u'%(desc)r\ncommand: %(cmd)r\nexit code: %(code)r'
+                          u'\nstdout: %(stdout)r\nstderr: %(stderr)r',
+                          {'code': -2, 'cmd': u'b 2', 'stdout': u'None',
+                           'stderr': u'None', 'desc': None}),
+                mock.call(logging.CRITICAL, u'%r failed. Not Retrying.',
+                          u'b 2')]
+        )
+
+    def test_trycmd(self):
+        mock_conf = mock.MagicMock()
+        daemon = utils.RootwrapDaemonHelper(mock_conf)
+        daemon.client = mock.MagicMock()
+        daemon.client.execute = mock.Mock(return_value=(0, None, None))
+
+        daemon.trycmd('a', 1, foo='bar', run_as_root=True)
+        daemon.client.execute.assert_called_once_with(['a', '1'], None)
+
+    def test_trycmd_with_kwargs(self):
+        mock_conf = mock.MagicMock()
+        daemon = utils.RootwrapDaemonHelper(mock_conf)
+        daemon.execute = mock.Mock(return_value=('out', 'err'))
+
+        daemon.trycmd('a', 1, foo='bar', run_as_root=True,
+                      loglevel=logging.WARN,
+                      log_errors=True,
+                      process_input=True,
+                      delay_on_retry=False,
+                      attempts=5,
+                      check_exit_code=[200])
+        daemon.execute.assert_called_once_with('a', 1, attempts=5,
+                                               check_exit_code=[200],
+                                               delay_on_retry=False, foo='bar',
+                                               log_errors=True, loglevel=30,
+                                               process_input=True,
+                                               run_as_root=True)
+
+    def test_trycmd_fail(self):
+        mock_conf = mock.MagicMock()
+        daemon = utils.RootwrapDaemonHelper(mock_conf)
+        daemon.client = mock.MagicMock()
+        daemon.client.execute = mock.Mock(return_value=(-2, None, None))
+
+        expected_err = six.text_type('''\
+Unexpected error while running command.
+Command: a 1
+Exit code: -2''')
+
+        out, err = daemon.trycmd('a', 1, foo='bar', run_as_root=True)
+        daemon.client.execute.assert_called_once_with(['a', '1'], None)
+        self.assertIn(expected_err, err)
+
+    def test_trycmd_fail_with_rety(self):
+        mock_conf = mock.MagicMock()
+        daemon = utils.RootwrapDaemonHelper(mock_conf)
+        daemon.client = mock.MagicMock()
+        daemon.client.execute = mock.Mock(return_value=(-2, None, None))
+
+        expected_err = six.text_type('''\
+Unexpected error while running command.
+Command: a 1
+Exit code: -2''')
+
+        out, err = daemon.trycmd('a', 1, foo='bar', run_as_root=True,
+                                 attempts=3)
+        self.assertIn(expected_err, err)
+        daemon.client.execute.assert_has_calls(
+            [mock.call(['a', '1'], None),
+             mock.call(['a', '1'], None),
+             mock.call(['a', '1'], None)])
+
+
 class VPNPingTestCase(test.NoDBTestCase):
     """Unit tests for utils.vpn_ping()."""
     def setUp(self):
diff --git a/nova/utils.py b/nova/utils.py
index 4290711d99..e5c4922418 100644
--- a/nova/utils.py
+++ b/nova/utils.py
@@ -25,6 +25,7 @@ import functools
 import hashlib
 import hmac
 import inspect
+import logging as std_logging
 import os
 import pyclbr
 import random
@@ -34,6 +35,7 @@ import socket
 import struct
 import sys
 import tempfile
+import time
 from xml.sax import saxutils
 
 import eventlet
@@ -47,13 +49,14 @@ import oslo_messaging as messaging
 from oslo_utils import encodeutils
 from oslo_utils import excutils
 from oslo_utils import importutils
+from oslo_utils import strutils
 from oslo_utils import timeutils
 from oslo_utils import units
 import six
 from six.moves import range
 
 from nova import exception
-from nova.i18n import _, _LE, _LW
+from nova.i18n import _, _LE, _LI, _LW
 
 notify_decorator = 'nova.notifications.notify_decorator'
 
@@ -76,6 +79,11 @@ utils_opts = [
                default='month',
                help='Time period to generate instance usages for.  '
                     'Time period must be hour, day, month or year'),
+    cfg.BoolOpt('use_rootwrap_daemon', default=False,
+                help="Start and use a daemon that can run the commands that "
+                     "need to be run with root privileges. This option is "
+                     "usually enabled on nodes that run nova compute "
+                     "processes"),
     cfg.StrOpt('rootwrap_config',
                default="/etc/nova/rootwrap.conf",
                help='Path to the rootwrap configuration file to use for '
@@ -247,10 +255,138 @@ def get_root_helper():
     return cmd
 
 
+def _get_rootwrap_helper():
+    if CONF.use_rootwrap_daemon:
+        return RootwrapDaemonHelper(CONF.rootwrap_config)
+    else:
+        return RootwrapProcessHelper()
+
+
+class RootwrapProcessHelper(object):
+    def trycmd(self, *cmd, **kwargs):
+        kwargs['root_helper'] = get_root_helper()
+        return processutils.trycmd(*cmd, **kwargs)
+
+    def execute(self, *cmd, **kwargs):
+        kwargs['root_helper'] = get_root_helper()
+        return processutils.execute(*cmd, **kwargs)
+
+
+class RootwrapDaemonHelper(RootwrapProcessHelper):
+    _clients = {}
+
+    @synchronized('daemon-client-lock')
+    def _get_client(cls, rootwrap_config):
+        try:
+            return cls._clients[rootwrap_config]
+        except KeyError:
+            from oslo_rootwrap import client
+            new_client = client.Client([
+                "sudo", "nova-rootwrap-daemon", rootwrap_config])
+            cls._clients[rootwrap_config] = new_client
+            return new_client
+
+    def __init__(self, rootwrap_config):
+        self.client = self._get_client(rootwrap_config)
+
+    def trycmd(self, *args, **kwargs):
+        discard_warnings = kwargs.pop('discard_warnings', False)
+        try:
+            out, err = self.execute(*args, **kwargs)
+            failed = False
+        except processutils.ProcessExecutionError as exn:
+            out, err = '', six.text_type(exn)
+            failed = True
+        if not failed and discard_warnings and err:
+            # Handle commands that output to stderr but otherwise succeed
+            err = ''
+        return out, err
+
+    def execute(self, *cmd, **kwargs):
+        # NOTE(dims): This method is to provide compatibility with the
+        # processutils.execute interface. So that calling daemon or direct
+        # rootwrap to honor the same set of flags in kwargs and to ensure
+        # that we don't regress any current behavior.
+        cmd = [str(c) for c in cmd]
+        loglevel = kwargs.pop('loglevel', std_logging.DEBUG)
+        log_errors = kwargs.pop('log_errors', None)
+        process_input = kwargs.pop('process_input', None)
+        delay_on_retry = kwargs.pop('delay_on_retry', True)
+        attempts = kwargs.pop('attempts', 1)
+        check_exit_code = kwargs.pop('check_exit_code', [0])
+        ignore_exit_code = False
+        if isinstance(check_exit_code, bool):
+            ignore_exit_code = not check_exit_code
+            check_exit_code = [0]
+        elif isinstance(check_exit_code, int):
+            check_exit_code = [check_exit_code]
+
+        sanitized_cmd = strutils.mask_password(' '.join(cmd))
+        LOG.info(_LI('Executing RootwrapDaemonHelper.execute '
+                     'cmd=[%(cmd)r] kwargs=[%(kwargs)r]'),
+                 {'cmd': sanitized_cmd, 'kwargs': kwargs})
+
+        while attempts > 0:
+            attempts -= 1
+            try:
+                start_time = time.time()
+                LOG.log(loglevel, _('Running cmd (subprocess): %s'),
+                        sanitized_cmd)
+
+                (returncode, out, err) = self.client.execute(
+                    cmd, process_input)
+
+                end_time = time.time() - start_time
+                LOG.log(loglevel,
+                        'CMD "%(sanitized_cmd)s" returned: %(return_code)s '
+                        'in %(end_time)0.3fs',
+                        {'sanitized_cmd': sanitized_cmd,
+                         'return_code': returncode,
+                         'end_time': end_time})
+
+                if not ignore_exit_code and returncode not in check_exit_code:
+                    out = strutils.mask_password(out)
+                    err = strutils.mask_password(err)
+                    raise processutils.ProcessExecutionError(
+                        exit_code=returncode,
+                        stdout=out,
+                        stderr=err,
+                        cmd=sanitized_cmd)
+                return (out, err)
+
+            except processutils.ProcessExecutionError as err:
+                # if we want to always log the errors or if this is
+                # the final attempt that failed and we want to log that.
+                if log_errors == processutils.LOG_ALL_ERRORS or (
+                                log_errors == processutils.LOG_FINAL_ERROR and
+                            not attempts):
+                    format = _('%(desc)r\ncommand: %(cmd)r\n'
+                               'exit code: %(code)r\nstdout: %(stdout)r\n'
+                               'stderr: %(stderr)r')
+                    LOG.log(loglevel, format, {"desc": err.description,
+                                               "cmd": err.cmd,
+                                               "code": err.exit_code,
+                                               "stdout": err.stdout,
+                                               "stderr": err.stderr})
+                if not attempts:
+                    LOG.log(loglevel, _('%r failed. Not Retrying.'),
+                            sanitized_cmd)
+                    raise
+                else:
+                    LOG.log(loglevel, _('%r failed. Retrying.'),
+                            sanitized_cmd)
+                    if delay_on_retry:
+                        time.sleep(random.randint(20, 200) / 100.0)
+
+
 def execute(*cmd, **kwargs):
     """Convenience wrapper around oslo's execute() method."""
-    if 'run_as_root' in kwargs and 'root_helper' not in kwargs:
-        kwargs['root_helper'] = get_root_helper()
+    if 'run_as_root' in kwargs and kwargs.get('run_as_root'):
+        if CONF.use_rootwrap_daemon:
+            return RootwrapDaemonHelper(CONF.rootwrap_config).execute(
+                *cmd, **kwargs)
+        else:
+            return RootwrapProcessHelper().execute(*cmd, **kwargs)
     return processutils.execute(*cmd, **kwargs)
 
 
@@ -264,8 +400,12 @@ def ssh_execute(dest, *cmd, **kwargs):
 
 def trycmd(*args, **kwargs):
     """Convenience wrapper around oslo's trycmd() method."""
-    if 'run_as_root' in kwargs and 'root_helper' not in kwargs:
-        kwargs['root_helper'] = get_root_helper()
+    if kwargs.get('run_as_root', False):
+        if CONF.use_rootwrap_daemon:
+            return RootwrapDaemonHelper(CONF.rootwrap_config).trycmd(
+                *args, **kwargs)
+        else:
+            return RootwrapProcessHelper().trycmd(*args, **kwargs)
     return processutils.trycmd(*args, **kwargs)