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

3 files changed, 36 insertions, 12 deletions

diff --git a/ironic_python_agent/tests/extensions/base.py b/ironic_python_agent/tests/extensions/base.py
index 30ce34a0..b033314c 100644
--- a/ironic_python_agent/tests/extensions/base.py
+++ b/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)
 
diff --git a/ironic_python_agent/tests/extensions/decom.py b/ironic_python_agent/tests/extensions/decom.py
index cfa01dd4..751c5804 100644
--- a/ironic_python_agent/tests/extensions/decom.py
+++ b/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'])
diff --git a/ironic_python_agent/tests/extensions/standby.py b/ironic_python_agent/tests/extensions/standby.py
index 2e1079eb..73d63aad 100644
--- a/ironic_python_agent/tests/extensions/standby.py
+++ b/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):