Add logging to driver vendor_passthru functions

Since the drivers' vendor_passthru are async. calls, any exceptions
raised by them won't be handled. So all exceptions, even non-Ironic
exceptions should be logged.

This patch adds a decorator that can be used to wrap passthru function
calls and ensure that any exceptions get logged correctly, also adds
unit tests to ensure decorators functionality.

Change-Id: I17006611fd59d5f4dc78fdaefdf802e9fb7caff2
Implements: blueprint extended-vendor-passthru
Closes-Bug: 1372979

ironic/conductor/task_manager.py

@@ -96,6 +96,8 @@ code when the spawned task generates an exception:
 
 """
 
+import functools
+
 from oslo.config import cfg
 from oslo.utils import excutils
 import retrying
@@ -119,6 +121,7 @@ def require_exclusive_lock(f):
     as the first parameter after "self".
 
     """
+    @functools.wraps(f)
     def wrapper(*args, **kwargs):
         task = args[0] if isinstance(args[0], TaskManager) else args[1]
         if task.shared:

ironic/drivers/base.py

@@ -18,11 +18,17 @@ Abstract base classes for drivers.
 """
 
 import abc
+import functools
 
+from oslo.utils import excutils
 import six
 
 from ironic.common import exception
 from ironic.common.i18n import _
+from ironic.common.i18n import _LE
+from ironic.openstack.common import log as logging
+
+LOG = logging.getLogger(__name__)
 
 
 @six.add_metaclass(abc.ABCMeta)
@@ -349,6 +355,40 @@ class RescueInterface(object):
         """
 
 
+def passthru(method=None):
+    """A decorator for registering a function as a passthru function.
+
+    Decorator ensures function is ready to catch any ironic exceptions
+    and reraise them after logging the issue. It also catches non-ironic
+    exceptions reraising them as a VendorPassthruException after writing
+    a log.
+
+    Logs need to be added because even though the exception is being
+    reraised, it won't be handled if it is an async. call.
+
+    :param method: an arbitrary string describing the action to be taken.
+    """
+    def handle_passthru(func):
+        api_method = method
+        if api_method is None:
+            api_method = func.__name__
+        passthru_logmessage = _LE('vendor_passthru failed with method %s')
+
+        @functools.wraps(func)
+        def passthru_handler(*args, **kwargs):
+            try:
+                return func(*args, **kwargs)
+            except exception.IronicException as e:
+                with excutils.save_and_reraise_exception():
+                    LOG.exception(passthru_logmessage, api_method)
+            except Exception as e:
+                # catch-all in case something bubbles up here
+                LOG.exception(passthru_logmessage, api_method)
+                raise exception.VendorPassthruException(message=e)
+        return passthru_handler
+    return handle_passthru
+
+
 @six.add_metaclass(abc.ABCMeta)
 class VendorInterface(object):
     """Interface for all vendor passthru functionality.

ironic/drivers/modules/agent.py

@@ -307,7 +307,7 @@ class AgentDeploy(base.DeployInterface):
 class AgentVendorInterface(base.VendorInterface):
     def __init__(self):
         self.vendor_routes = {
-            'heartbeat': self._heartbeat
+            'heartbeat': self.heartbeat
         }
         self.driver_routes = {
             'lookup': self._lookup,
@@ -356,22 +356,10 @@ class AgentVendorInterface(base.VendorInterface):
             raise exception.InvalidParameterValue(_('No handler for method '
                                                     '%s') % method)
         func = self.vendor_routes[method]
-        try:
-            return func(task, **kwargs)
-        except exception.IronicException as e:
-            with excutils.save_and_reraise_exception():
-                # log this because even though the exception is being
-                # reraised, it won't be handled if it is an async. call.
-                LOG.exception(_LE('vendor_passthru failed with method %s'),
-                              method)
-        except Exception as e:
-            # catch-all in case something bubbles up here
-            # log this because even though the exception is being
-            # reraised, it won't be handled if it is an async. call.
-            LOG.exception(_LE('vendor_passthru failed with method %s'), method)
-            raise exception.VendorPassthruException(message=e)
+        return func(task, **kwargs)
 
-    def _heartbeat(self, task, **kwargs):
+    @base.passthru()
+    def heartbeat(self, task, **kwargs):
         """Method for agent to periodically check in.
 
         The agent should be sending its agent_url (so Ironic can talk back)

ironic/drivers/modules/fake.py

@@ -108,7 +108,8 @@ class FakeVendorA(base.VendorInterface):
             return
         _raise_unsupported_error(method)
 
-    def _private_method(self, task, bar):
+    @base.passthru()
+    def first_method(self, task, bar):
         return True if bar == 'baz' else False
 
     def vendor_passthru(self, task, **kwargs):
@@ -136,7 +137,8 @@ class FakeVendorB(base.VendorInterface):
             return
         _raise_unsupported_error(method)
 
-    def _private_method(self, task, bar):
+    @base.passthru()
+    def second_method(self, task, bar):
         return True if bar == 'kazoo' else False
 
     def vendor_passthru(self, task, **kwargs):

ironic/drivers/modules/ilo/deploy.py

@@ -565,6 +565,10 @@ class IloConsoleInterface(ipmitool.IPMIShellinaboxConsole):
 
 class IloPXEVendorPassthru(pxe.VendorPassthru):
 
+    @base.passthru()
+    def pass_deploy_info(self, *args, **kwargs):
+        ilo_common.set_boot_device(*args, **kwargs)
+
     def vendor_passthru(self, task, **kwargs):
         """Calls a valid vendor passthru method.
 
@@ -574,8 +578,7 @@ class IloPXEVendorPassthru(pxe.VendorPassthru):
         """
         method = kwargs['method']
         if method == 'pass_deploy_info':
-            ilo_common.set_boot_device(task.node, 'NETWORK', True)
-
+            self.pass_deploy_info(task.node, 'NETWORK', True)
         return super(IloPXEVendorPassthru, self).vendor_passthru(task,
                                                                  **kwargs)
 
@@ -608,6 +611,7 @@ class VendorPassthru(base.VendorInterface):
                 "Unsupported method (%s) passed to iLO driver.")
                 % method)
 
+    @base.passthru('pass_deploy_info')
     @task_manager.require_exclusive_lock
     def _continue_deploy(self, task, **kwargs):
         """Continues the iSCSI deployment from where ramdisk left off.

ironic/drivers/modules/ipmitool.py

@@ -792,8 +792,9 @@ class VendorPassthru(base.VendorInterface):
                 reason=_("Unable to locate usable ipmitool command in "
                          "the system path when checking ipmitool version"))
 
+    @base.passthru()
     @task_manager.require_exclusive_lock
-    def _send_raw_bytes(self, task, raw_bytes):
+    def send_raw(self, task, raw_bytes):
         """Send raw bytes to the BMC. Bytes should be a string of bytes.
 
         :param task: a TaskManager instance.
@@ -820,8 +821,9 @@ class VendorPassthru(base.VendorInterface):
                           {'node_id': node_uuid, 'error': e})
             raise exception.IPMIFailure(cmd=cmd)
 
+    @base.passthru()
     @task_manager.require_exclusive_lock
-    def _bmc_reset(self, task, warm=True):
+    def bmc_reset(self, task, warm=True):
         """Reset BMC with IPMI command 'bmc reset (warm|cold)'.
 
         :param task: a TaskManager instance.
@@ -908,11 +910,9 @@ class VendorPassthru(base.VendorInterface):
 
         method = kwargs['method']
         if method == 'send_raw':
-            return self._send_raw_bytes(task,
-                                        kwargs.get('raw_bytes'))
+            return self.send_raw(task, kwargs.get('raw_bytes'))
         elif method == 'bmc_reset':
-            return self._bmc_reset(task,
-                                   warm=kwargs.get('warm', True))
+            return self.bmc_reset(task, warm=kwargs.get('warm', True))
 
 
 class IPMIShellinaboxConsole(base.ConsoleInterface):

ironic/drivers/modules/pxe.py

@@ -451,6 +451,7 @@ class VendorPassthru(base.VendorInterface):
                 "Unsupported method (%s) passed to PXE driver.")
                 % method)
 
+    @base.passthru('pass_deploy_info')
     @task_manager.require_exclusive_lock
     def _continue_deploy(self, task, **kwargs):
         """Continues the deployment of baremetal node over iSCSI.

ironic/drivers/modules/seamicro.py

@@ -427,9 +427,10 @@ class VendorPassthru(base.VendorInterface):
         """Dispatch vendor specific method calls."""
         method = kwargs['method']
         if method in VENDOR_PASSTHRU_METHODS:
-            return getattr(self, "_" + method)(task, **kwargs)
+            return getattr(self, method)(task, **kwargs)
 
-    def _set_node_vlan_id(self, task, **kwargs):
+    @base.passthru()
+    def set_node_vlan_id(self, task, **kwargs):
         """Sets a untagged vlan id for NIC 0 of node.
 
         @kwargs vlan_id: id of untagged vlan for NIC 0 of node
@@ -457,7 +458,8 @@ class VendorPassthru(base.VendorInterface):
         node.properties = properties
         node.save()
 
-    def _attach_volume(self, task, **kwargs):
+    @base.passthru()
+    def attach_volume(self, task, **kwargs):
         """Attach a volume to a node.
 
         Attach volume from SeaMicro storage pools for ironic to node.

ironic/tests/drivers/test_agent.py

@@ -21,6 +21,7 @@ from ironic.common import keystone
 from ironic.common import pxe_utils
 from ironic.common import states
 from ironic.conductor import task_manager
+from ironic.drivers import base as driver_base
 from ironic.drivers.modules import agent
 from ironic import objects
 from ironic.tests.conductor import utils as mgr_utils
@@ -325,35 +326,37 @@ class TestAgentVendor(db_base.DbTestCase):
         }
         with task_manager.acquire(
                 self.context, self.node['uuid'], shared=True) as task:
-            self.passthru._heartbeat(task, **kwargs)
+            self.passthru.heartbeat(task, **kwargs)
 
     def test_heartbeat_bad(self):
         kwargs = {}
         with task_manager.acquire(
                 self.context, self.node['uuid'], shared=True) as task:
             self.assertRaises(exception.MissingParameterValue,
-                              self.passthru._heartbeat, task, **kwargs)
+                              self.passthru.heartbeat, task, **kwargs)
 
     @mock.patch('ironic.drivers.modules.agent.AgentVendorInterface'
-                '._heartbeat')
+                '.heartbeat', autospec=True)
     def test_vendor_passthru_heartbeat(self, mock_heartbeat):
         kwargs = {
             'method': 'heartbeat',
         }
-        self.passthru.vendor_routes['heartbeat'] = mock_heartbeat
+        self.passthru.vendor_routes['heartbeat'] = (
+            driver_base.passthru('heartbeat')(mock_heartbeat))
         with task_manager.acquire(
                 self.context, self.node['uuid'], shared=True) as task:
             self.passthru.vendor_passthru(task, **kwargs)
             mock_heartbeat.assert_called_once_with(task, **kwargs)
 
     @mock.patch('ironic.drivers.modules.agent.AgentVendorInterface'
-                '._heartbeat')
+                '.heartbeat', autospec=True)
     def test_vendor_passthru_heartbeat_ironic_exc(self, mock_heartbeat):
         mock_heartbeat.side_effect = exception.IronicException()
         kwargs = {
             'method': 'heartbeat',
         }
-        self.passthru.vendor_routes['heartbeat'] = mock_heartbeat
+        self.passthru.vendor_routes['heartbeat'] = (
+            driver_base.passthru('heartbeat')(mock_heartbeat))
         with task_manager.acquire(
                 self.context, self.node['uuid'], shared=True) as task:
             self.assertRaises(exception.IronicException,
@@ -361,13 +364,14 @@ class TestAgentVendor(db_base.DbTestCase):
             mock_heartbeat.assert_called_once_with(task, **kwargs)
 
     @mock.patch('ironic.drivers.modules.agent.AgentVendorInterface'
-                '._heartbeat')
+                '.heartbeat', autospec=True)
     def test_vendor_passthru_heartbeat_exception(self, mock_heartbeat):
         mock_heartbeat.side_effect = KeyError()
         kwargs = {
             'method': 'heartbeat',
         }
-        self.passthru.vendor_routes['heartbeat'] = mock_heartbeat
+        self.passthru.vendor_routes['heartbeat'] = (
+            driver_base.passthru('heartbeat')(mock_heartbeat))
         with task_manager.acquire(
                 self.context, self.node['uuid'], shared=True) as task:
             self.assertRaises(exception.VendorPassthruException,

ironic/tests/drivers/test_base.py

@@ -0,0 +1,73 @@
+# Copyright 2014 Cisco Systems, Inc.
+# All Rights Reserved.
+#
+#    Licensed under the Apache License, Version 2.0 (the "License"); you may
+#    not use this file except in compliance with the License. You may obtain
+#    a copy of the License at
+#
+#         http://www.apache.org/licenses/LICENSE-2.0
+#
+#    Unless required by applicable law or agreed to in writing, software
+#    distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+#    WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+#    License for the specific language governing permissions and limitations
+#    under the License.
+
+import mock
+
+from ironic.common import exception
+from ironic.drivers import base as driver_base
+from ironic.tests import base
+
+
+class FakeVendorInterface(driver_base.VendorInterface):
+    def get_properties(self):
+        pass
+
+    @driver_base.passthru('noexception')
+    def _noexception(self):
+        return "Fake"
+
+    @driver_base.passthru('ironicexception')
+    def _ironicexception(self):
+        raise exception.IronicException("Fake!")
+
+    @driver_base.passthru('normalexception')
+    def _normalexception(self):
+        raise Exception("Fake!")
+
+    def validate(self, task, **kwargs):
+        pass
+
+    def vendor_passthru(self, task, **kwargs):
+        method = kwargs['method']
+        if method == "noexception":
+            self._noexception()
+        elif method == "ironicexception":
+            self._ironicexception()
+        elif method == "normalexception":
+            self._normalexception()
+
+
+class PassthruDecoratorTestCase(base.TestCase):
+
+    def setUp(self):
+        super(PassthruDecoratorTestCase, self).setUp()
+        self.fvi = FakeVendorInterface()
+        driver_base.LOG = mock.Mock()
+
+    def test_passthru_noexception(self):
+        result = self.fvi._noexception()
+        self.assertEqual("Fake", result)
+
+    def test_passthru_ironicexception(self):
+        self.assertRaises(exception.IronicException,
+            self.fvi.vendor_passthru, mock.ANY, method="ironicexception")
+        driver_base.LOG.exception.assert_called_with(
+            mock.ANY, 'ironicexception')
+
+    def test_passthru_nonironicexception(self):
+        self.assertRaises(exception.VendorPassthruException,
+            self.fvi.vendor_passthru, mock.ANY, method="normalexception")
+        driver_base.LOG.exception.assert_called_with(
+            mock.ANY, 'normalexception')

ironic/tests/drivers/test_ipmitool.py

@@ -960,7 +960,7 @@ class IPMIToolDriverTestCase(db_base.DbTestCase):
 
         with task_manager.acquire(self.context,
                                   self.node['uuid']) as task:
-            self.driver.vendor._send_raw_bytes(task, '0x00 0x01')
+            self.driver.vendor.send_raw(task, '0x00 0x01')
 
         mock_exec.assert_called_once_with(self.info, 'raw 0x00 0x01')
 
@@ -971,7 +971,7 @@ class IPMIToolDriverTestCase(db_base.DbTestCase):
         with task_manager.acquire(self.context,
                                   self.node['uuid']) as task:
             self.assertRaises(exception.IPMIFailure,
-                              self.driver.vendor._send_raw_bytes,
+                              self.driver.vendor.send_raw,
                               task,
                               '0x00 0x01')
 
@@ -981,7 +981,7 @@ class IPMIToolDriverTestCase(db_base.DbTestCase):
 
         with task_manager.acquire(self.context,
                                   self.node['uuid']) as task:
-            self.driver.vendor._bmc_reset(task)
+            self.driver.vendor.bmc_reset(task)
 
         mock_exec.assert_called_once_with(self.info, 'bmc reset warm')
 
@@ -991,7 +991,7 @@ class IPMIToolDriverTestCase(db_base.DbTestCase):
 
         with task_manager.acquire(self.context,
                                   self.node['uuid']) as task:
-            self.driver.vendor._bmc_reset(task, warm=False)
+            self.driver.vendor.bmc_reset(task, warm=False)
 
         mock_exec.assert_called_once_with(self.info, 'bmc reset cold')
 
@@ -1002,7 +1002,7 @@ class IPMIToolDriverTestCase(db_base.DbTestCase):
         with task_manager.acquire(self.context,
                                   self.node['uuid']) as task:
             self.assertRaises(exception.IPMIFailure,
-                              self.driver.vendor._bmc_reset,
+                              self.driver.vendor.bmc_reset,
                               task)
 
     @mock.patch.object(ipmi, '_power_off', autospec=False)
@@ -1070,7 +1070,7 @@ class IPMIToolDriverTestCase(db_base.DbTestCase):
                               self.driver.vendor.validate,
                               task, method='send_raw')
 
-    @mock.patch.object(ipmi.VendorPassthru, '_send_raw_bytes')
+    @mock.patch.object(ipmi.VendorPassthru, 'send_raw')
     def test_vendor_passthru_call_send_raw_bytes(self, raw_bytes_mock):
         with task_manager.acquire(self.context, self.node['uuid'],
                                   shared=False) as task:
@@ -1096,7 +1096,7 @@ class IPMIToolDriverTestCase(db_base.DbTestCase):
                                         method='bmc_reset',
                                         warm=False)
 
-    @mock.patch.object(ipmi.VendorPassthru, '_bmc_reset')
+    @mock.patch.object(ipmi.VendorPassthru, 'bmc_reset')
     def test_vendor_passthru_call_bmc_reset(self, bmc_mock):
         with task_manager.acquire(self.context, self.node['uuid'],
                                   shared=False) as task:
@@ -1104,7 +1104,7 @@ class IPMIToolDriverTestCase(db_base.DbTestCase):
                                                method='bmc_reset')
             bmc_mock.assert_called_once_with(task, warm=True)
 
-    @mock.patch.object(ipmi.VendorPassthru, '_bmc_reset')
+    @mock.patch.object(ipmi.VendorPassthru, 'bmc_reset')
     def test_vendor_passthru_call_bmc_reset_warm(self, bmc_mock):
         with task_manager.acquire(self.context, self.node['uuid'],
                                   shared=False) as task:
@@ -1113,7 +1113,7 @@ class IPMIToolDriverTestCase(db_base.DbTestCase):
                                                warm=True)
             bmc_mock.assert_called_once_with(task, warm=True)
 
-    @mock.patch.object(ipmi.VendorPassthru, '_bmc_reset')
+    @mock.patch.object(ipmi.VendorPassthru, 'bmc_reset')
     def test_vendor_passthru_call_bmc_reset_cold(self, bmc_mock):
         with task_manager.acquire(self.context, self.node['uuid'],
                                   shared=False) as task: