Add additional logging and return results for IPA extensions

Some of the extensions in IPA currently do not return any values
from their respective command methods. This results in a lack of a
paper trail of the command_result value to the point where it is
not possible to know more information than a boolean result of if
a command succeeded or failed.

This change adds more logging to the extensions and provides return
values which are used in the command_result property on
(Async|Sync)CommandResult instances to provide useful debug info.

While creating this patch several unit tests for *CommandResult objects
were found to be using invalid data that would not pass validation
if returned in API results. Those have been corrected in this patch.

Change-Id: I23bae25a83881e7013c93d73f858c622ea941253
Closes-Bug: 1408080

ironic_python_agent/extensions/base.py

@@ -78,6 +78,11 @@ class SyncCommandResult(BaseCommandResult):
 
         super(SyncCommandResult, self).__init__(command_name,
                                                 command_params)
+
+        if type(result_or_error) in (str, unicode):
+            result_key = 'result' if success else 'error'
+            result_or_error = {result_key: result_or_error}
+
         if success:
             self.command_status = AgentCommandStatus.SUCCEEDED
             self.command_result = result_or_error
@@ -141,6 +146,10 @@ class AsyncCommandResult(BaseCommandResult):
         """Run a command."""
         try:
             result = self.execute_method(**self.command_params)
+
+            if type(result) in (str, unicode):
+                result = {'result': '{}: {}'.format(self.command_name, result)}
+
             with self.command_state_lock:
                 self.command_result = result
                 self.command_status = AgentCommandStatus.SUCCEEDED
@@ -239,6 +248,8 @@ def async_command(command_name, validator=None):
     """Will run the command in an AsyncCommandResult in its own thread.
     command_name is set based on the func name and command_params will
     be whatever args/kwargs you pass into the decorated command.
+    Return values of type `str` or `unicode` are prefixed with the
+    `command_name` parameter when returned for consistency.
     """
     def async_decorator(func):
         func.command_name = command_name

ironic_python_agent/extensions/decom.py

@@ -20,3 +20,5 @@ class DecomExtension(base.BaseAgentExtension):
     @base.async_command('erase_hardware')
     def erase_hardware(self):
         hardware.dispatch_to_managers('erase_devices')
+
+        return 'finished'

ironic_python_agent/extensions/standby.py

@@ -210,10 +210,15 @@ class StandbyExtension(base.BaseAgentExtension):
     def cache_image(self, image_info=None, force=False):
         device = hardware.dispatch_to_managers('get_os_install_device')
 
+        result_msg = 'image ({0}) already present on device {1}'
+
         if self.cached_image_id != image_info['id'] or force:
             _download_image(image_info)
             _write_image(image_info, device)
             self.cached_image_id = image_info['id']
+            result_msg = 'image ({0}) cached to device {1}'
+
+        return result_msg.format(image_info['id'], device)
 
     @base.async_command('prepare_image', _validate_image_info)
     def prepare_image(self,
@@ -230,6 +235,9 @@ class StandbyExtension(base.BaseAgentExtension):
         if configdrive is not None:
             _write_configdrive_to_partition(configdrive, device)
 
+        return 'image ({0}) written to device {1}'.format(image_info['id'],
+                                                          device)
+
     @base.async_command('run_image')
     def run_image(self):
         script = _path_to_script('shell/reboot.sh')

ironic_python_agent/tests/agent.py

@@ -267,7 +267,8 @@ class TestBaseAgent(test_base.BaseTestCase):
         result.join()
 
         expected_result['command_status'] = 'SUCCEEDED'
-        expected_result['command_result'] = 'command execution succeeded'
+        expected_result['command_result'] = {'result': ('foo_command: command '
+                                                        'execution succeeded')}
 
         self.assertEqualEncoded(result, expected_result)
 

ironic_python_agent/tests/extensions/base.py

@@ -114,7 +114,7 @@ class TestExecuteCommandMixin(test_base.BaseTestCase):
         )
         self.assertEqual(result.command_status,
                          base.AgentCommandStatus.FAILED)
-        self.assertEqual(result.command_error, msg)
+        self.assertEqual(result.command_error, {'error': msg})
 
 
 class TestExtensionDecorators(test_base.BaseTestCase):
@@ -133,7 +133,8 @@ class TestExtensionDecorators(test_base.BaseTestCase):
         self.assertEqual(base.AgentCommandStatus.SUCCEEDED,
                          result.command_status)
         self.assertEqual(None, result.command_error)
-        self.assertEqual('v1', result.command_result)
+        self.assertEqual({'result': 'fake_async_command: v1'},
+                          result.command_result)
         self.agent.force_heartbeat.assert_called_once_with()
 
     def test_async_command_success_without_agent(self):
@@ -146,7 +147,8 @@ class TestExtensionDecorators(test_base.BaseTestCase):
         self.assertEqual(base.AgentCommandStatus.SUCCEEDED,
                          result.command_status)
         self.assertEqual(None, result.command_error)
-        self.assertEqual('v1', result.command_result)
+        self.assertEqual({'result': 'fake_async_command: v1'},
+                          result.command_result)
 
     def test_async_command_validation_failure(self):
         self.assertRaises(errors.InvalidCommandParamsError,
@@ -181,7 +183,7 @@ class TestExtensionDecorators(test_base.BaseTestCase):
         self.assertEqual(base.AgentCommandStatus.SUCCEEDED,
                          result.command_status)
         self.assertEqual(None, result.command_error)
-        self.assertEqual('v1', result.command_result)
+        self.assertEqual({'result': 'v1'}, result.command_result)
         # no need to force heartbeat on a sync command
         self.assertEqual(0, self.agent.force_heartbeat.call_count)
 

ironic_python_agent/tests/extensions/decom.py

@@ -29,3 +29,6 @@ class TestDecomExtension(test_base.BaseTestCase):
         result = self.agent_extension.erase_hardware()
         result.join()
         mocked_dispatch.assert_called_once_with('erase_devices')
+        self.assertTrue('result' in result.command_result.keys())
+        cmd_result_text = 'erase_hardware: finished'
+        self.assertEqual(cmd_result_text, result.command_result['result'])

ironic_python_agent/tests/extensions/standby.py

@@ -276,7 +276,8 @@ class TestStandbyExtension(test_base.BaseTestCase):
                 autospec=True)
     @mock.patch('ironic_python_agent.extensions.standby._download_image',
                 autospec=True)
-    def test_cache_image(self, download_mock, write_mock, dispatch_mock):
+    def test_cache_image(self, download_mock, write_mock,
+                         dispatch_mock):
         image_info = self._build_fake_image_info()
         download_mock.return_value = None
         write_mock.return_value = None
@@ -289,7 +290,10 @@ class TestStandbyExtension(test_base.BaseTestCase):
         self.assertEqual(self.agent_extension.cached_image_id,
                          image_info['id'])
         self.assertEqual('SUCCEEDED', async_result.command_status)
-        self.assertEqual(None, async_result.command_result)
+        self.assertTrue('result' in async_result.command_result.keys())
+        cmd_result = ('cache_image: image ({0}) cached to device {1}'
+                      ).format(image_info['id'], 'manager')
+        self.assertEqual(cmd_result, async_result.command_result['result'])
 
     @mock.patch('ironic_python_agent.hardware.dispatch_to_managers',
                 autospec=True)
@@ -298,7 +302,7 @@ class TestStandbyExtension(test_base.BaseTestCase):
     @mock.patch('ironic_python_agent.extensions.standby._download_image',
                 autospec=True)
     def test_cache_image_force(self, download_mock, write_mock,
-            dispatch_mock):
+                               dispatch_mock):
         image_info = self._build_fake_image_info()
         self.agent_extension.cached_image_id = image_info['id']
         download_mock.return_value = None
@@ -314,7 +318,10 @@ class TestStandbyExtension(test_base.BaseTestCase):
         self.assertEqual(self.agent_extension.cached_image_id,
                          image_info['id'])
         self.assertEqual('SUCCEEDED', async_result.command_status)
-        self.assertEqual(None, async_result.command_result)
+        self.assertTrue('result' in async_result.command_result.keys())
+        cmd_result = ('cache_image: image ({0}) cached to device {1}'
+                      ).format(image_info['id'], 'manager')
+        self.assertEqual(cmd_result, async_result.command_result['result'])
 
     @mock.patch('ironic_python_agent.hardware.dispatch_to_managers',
                 autospec=True)
@@ -337,7 +344,10 @@ class TestStandbyExtension(test_base.BaseTestCase):
         self.assertEqual(self.agent_extension.cached_image_id,
                          image_info['id'])
         self.assertEqual('SUCCEEDED', async_result.command_status)
-        self.assertEqual(None, async_result.command_result)
+        self.assertTrue('result' in async_result.command_result.keys())
+        cmd_result = ('cache_image: image ({0}) already present on device {1}'
+                      ).format(image_info['id'], 'manager')
+        self.assertEqual(cmd_result, async_result.command_result['result'])
 
     @mock.patch(('ironic_python_agent.extensions.standby.'
                  '_write_configdrive_to_partition'),
@@ -376,7 +386,10 @@ class TestStandbyExtension(test_base.BaseTestCase):
                                                       'manager')
 
         self.assertEqual('SUCCEEDED', async_result.command_status)
-        self.assertEqual(None, async_result.command_result)
+        self.assertTrue('result' in async_result.command_result.keys())
+        cmd_result = ('prepare_image: image ({0}) written to device {1}'
+                      ).format(image_info['id'], 'manager')
+        self.assertEqual(cmd_result, async_result.command_result['result'])
 
         download_mock.reset_mock()
         write_mock.reset_mock()
@@ -394,7 +407,10 @@ class TestStandbyExtension(test_base.BaseTestCase):
                                                       'manager')
 
         self.assertEqual('SUCCEEDED', async_result.command_status)
-        self.assertEqual(None, async_result.command_result)
+        self.assertTrue('result' in async_result.command_result.keys())
+        cmd_result = ('prepare_image: image ({0}) written to device {1}'
+                      ).format(image_info['id'], 'manager')
+        self.assertEqual(cmd_result, async_result.command_result['result'])
 
     @mock.patch(('ironic_python_agent.extensions.standby.'
                  '_write_configdrive_to_partition'),
@@ -428,7 +444,10 @@ class TestStandbyExtension(test_base.BaseTestCase):
 
         self.assertEqual(configdrive_copy_mock.call_count, 0)
         self.assertEqual('SUCCEEDED', async_result.command_status)
-        self.assertEqual(None, async_result.command_result)
+        self.assertTrue('result' in async_result.command_result.keys())
+        cmd_result = ('prepare_image: image ({0}) written to device {1}'
+                      ).format(image_info['id'], 'manager')
+        self.assertEqual(cmd_result, async_result.command_result['result'])
 
     @mock.patch('ironic_python_agent.utils.execute', autospec=True)
     def test_run_image(self, execute_mock):