Update `cleaning_error_handler`

Update `cleaning_error_handler` to match with
`deploying_error_handler` that logs all errors and optionally
separates between logged message and `last_error`.

Logged message usually contains node's uuid as there is no
context for node in stream of log entries. `last_error`
usually does not contain node's uuid as it is already
displayed in the context of node.

Impact:
* There were messages that were only added to node's last_error.
Now they are going to be logged too.
* No need to log explicitly before `cleaning_error_handler`. Such
occurrences have been removed.
* Where there were different message for log and last_error it
is kept. Where there was only 1 message, it is left as it is to
be both logged and updated in `last_error`.
* Exception logging is replaced with error logging with traceback.

Story: 2008307
Task: 41198
Change-Id: I813228fb47a51ee6c45b420322acabdf565ff752

6 files changed, 50 insertions, 29 deletions

diff --git a/ironic/tests/unit/conductor/test_cleaning.py b/ironic/tests/unit/conductor/test_cleaning.py
index a079af408..0ed561201 100644
--- a/ironic/tests/unit/conductor/test_cleaning.py
+++ b/ironic/tests/unit/conductor/test_cleaning.py
@@ -870,7 +870,7 @@ class DoNodeCleanTestCase(db_base.DbTestCase):
         mock_execute.assert_called_once_with(
             mock.ANY, mock.ANY, self.clean_steps[0])
 
-    @mock.patch.object(cleaning, 'LOG', autospec=True)
+    @mock.patch.object(conductor_utils, 'LOG', autospec=True)
     @mock.patch('ironic.drivers.modules.fake.FakeDeploy.execute_clean_step',
                 autospec=True)
     @mock.patch('ironic.drivers.modules.fake.FakePower.execute_clean_step',
@@ -918,9 +918,9 @@ class DoNodeCleanTestCase(db_base.DbTestCase):
             mock.call(mock.ANY, mock.ANY, self.clean_steps[1]),
         ]
         self.assertEqual(power_exec_calls, power_exec_mock.call_args_list)
-        log_mock.exception.assert_called_once_with(
+        log_mock.error.assert_called_once_with(
             'Failed to tear down from cleaning for node {}, reason: boom'
-            .format(node.uuid))
+            .format(node.uuid), exc_info=True)
 
     def test__do_next_clean_step_automated_fail_in_tear_down_cleaning(self):
         self._do_next_clean_step_fail_in_tear_down_cleaning()
diff --git a/ironic/tests/unit/conductor/test_utils.py b/ironic/tests/unit/conductor/test_utils.py
index c096a5426..a41559898 100644
--- a/ironic/tests/unit/conductor/test_utils.py
+++ b/ironic/tests/unit/conductor/test_utils.py
@@ -1066,14 +1066,19 @@ class ErrorHandlersTestCase(tests_base.TestCase):
     @mock.patch.object(conductor_utils, 'cleaning_error_handler',
                        autospec=True)
     def test_cleanup_cleanwait_timeout_handler_call(self, mock_error_handler):
+        self.task.node.uuid = '18c95393-b775-4887-a274-c45be47509d5'
         self.node.clean_step = {}
         conductor_utils.cleanup_cleanwait_timeout(self.task)
 
         mock_error_handler.assert_called_once_with(
             self.task,
-            msg="Timeout reached while cleaning the node. Please "
-                "check if the ramdisk responsible for the cleaning is "
-                "running on the node. Failed on step {}.",
+            logmsg="Cleaning for node 18c95393-b775-4887-a274-c45be47509d5 "
+                   "failed. Timeout reached while cleaning the node. Please "
+                   "check if the ramdisk responsible for the cleaning is "
+                   "running on the node. Failed on step {}.",
+            errmsg="Timeout reached while cleaning the node. Please "
+                   "check if the ramdisk responsible for the cleaning is "
+                   "running on the node. Failed on step {}.",
             set_fail_state=False)
 
     def test_cleanup_cleanwait_timeout(self):
@@ -1096,7 +1101,9 @@ class ErrorHandlersTestCase(tests_base.TestCase):
         self.assertEqual(clean_error, self.node.maintenance_reason)
         self.assertEqual('clean failure', self.node.fault)
 
-    def _test_cleaning_error_handler(self, prov_state=states.CLEANING):
+    @mock.patch.object(conductor_utils.LOG, 'error', autospec=True)
+    def _test_cleaning_error_handler(self, mock_log_error,
+                                     prov_state=states.CLEANING):
         self.node.provision_state = prov_state
         target = 'baz'
         self.node.target_provision_state = target
@@ -1108,7 +1115,9 @@ class ErrorHandlersTestCase(tests_base.TestCase):
             'clean_step_index': 0,
             'agent_url': 'url'}
         msg = 'error bar'
-        conductor_utils.cleaning_error_handler(self.task, msg)
+        last_error = "last error"
+        conductor_utils.cleaning_error_handler(self.task, msg,
+                                               errmsg=last_error)
         self.node.save.assert_called_once_with()
         self.assertEqual({}, self.node.clean_step)
         self.assertNotIn('clean_step_index', self.node.driver_internal_info)
@@ -1116,9 +1125,9 @@ class ErrorHandlersTestCase(tests_base.TestCase):
         self.assertNotIn('cleaning_polling', self.node.driver_internal_info)
         self.assertNotIn('skip_current_clean_step',
                          self.node.driver_internal_info)
-        self.assertEqual(msg, self.node.last_error)
+        self.assertEqual(last_error, self.node.last_error)
         self.assertTrue(self.node.maintenance)
-        self.assertEqual(msg, self.node.maintenance_reason)
+        self.assertEqual(last_error, self.node.maintenance_reason)
         self.assertEqual('clean failure', self.node.fault)
         driver = self.task.driver.deploy
         driver.tear_down_cleaning.assert_called_once_with(self.task)
@@ -1128,6 +1137,7 @@ class ErrorHandlersTestCase(tests_base.TestCase):
             self.task.process_event.assert_called_once_with('fail',
                                                             target_state=None)
         self.assertNotIn('agent_url', self.node.driver_internal_info)
+        mock_log_error.assert_called_once_with(msg, exc_info=False)
 
     def test_cleaning_error_handler(self):
         self._test_cleaning_error_handler()
@@ -1172,6 +1182,7 @@ class ErrorHandlersTestCase(tests_base.TestCase):
         msg = 'foo'
         driver.tear_down_cleaning.side_effect = _side_effect
         conductor_utils.cleaning_error_handler(self.task, msg)
+        log_mock.error.assert_called_once_with(msg, exc_info=False)
         self.assertTrue(log_mock.exception.called)
         self.assertIn(msg, self.node.last_error)
         self.assertIn(msg, self.node.maintenance_reason)
diff --git a/ironic/tests/unit/drivers/modules/ilo/test_management.py b/ironic/tests/unit/drivers/modules/ilo/test_management.py
index 03cca5a78..1616f8ca0 100644
--- a/ironic/tests/unit/drivers/modules/ilo/test_management.py
+++ b/ironic/tests/unit/drivers/modules/ilo/test_management.py
@@ -1669,12 +1669,11 @@ class Ilo5ManagementTestCase(db_base.DbTestCase):
                               task.driver.management.erase_devices,
                               task, erase_pattern={'ssd': 'xyz'})
 
-    @mock.patch.object(ilo_management.LOG, 'error', autospec=True)
     @mock.patch.object(ilo_common, 'get_ilo_object', autospec=True)
     @mock.patch.object(manager_utils, 'cleaning_error_handler',
                        autospec=True)
     def test_erase_devices_hdd_ilo_error(self, clean_err_handler_mock,
-                                         ilo_mock, log_mock):
+                                         ilo_mock):
         ilo_mock_object = ilo_mock.return_value
         ilo_mock_object.get_available_disk_types.return_value = ['HDD']
         exc = ilo_error.IloError('error')
@@ -1692,8 +1691,11 @@ class Ilo5ManagementTestCase(db_base.DbTestCase):
                              task.node.driver_internal_info)
             self.assertNotIn('skip_current_clean_step',
                              task.node.driver_internal_info)
-            self.assertTrue(log_mock.called)
-            clean_err_handler_mock.assert_called_once_with(task, exc)
+            clean_err_handler_mock.assert_called_once_with(
+                task,
+                ("Out-of-band sanitize disk erase job failed for node %s. "
+                 "Message: 'error'." % task.node.uuid),
+                errmsg=exc)
 
     @mock.patch.object(manager_utils, 'node_power_action', autospec=True)
     @mock.patch.object(ilo_common, 'get_ilo_object', autospec=True)
@@ -1711,12 +1713,11 @@ class Ilo5ManagementTestCase(db_base.DbTestCase):
             mock_power.assert_called_once_with(task, states.REBOOT)
             self.assertEqual(task.node.maintenance, True)
 
-    @mock.patch.object(ilo_management.LOG, 'error', autospec=True)
     @mock.patch.object(ilo_common, 'get_ilo_object', autospec=True)
     @mock.patch.object(manager_utils, 'cleaning_error_handler',
                        autospec=True)
     def test_one_button_secure_erase_ilo_error(
-            self, clean_err_handler_mock, ilo_mock, log_mock):
+            self, clean_err_handler_mock, ilo_mock):
         ilo_mock_object = ilo_mock.return_value
         self.node.clean_step = {'step': 'one_button_secure_erase',
                                 'interface': 'management'}
@@ -1726,7 +1727,10 @@ class Ilo5ManagementTestCase(db_base.DbTestCase):
         with task_manager.acquire(self.context, self.node.uuid,
                                   shared=False) as task:
             task.driver.management.one_button_secure_erase(task)
-            clean_err_handler_mock.assert_called_once_with(task, exc)
+            clean_err_handler_mock.assert_called_once_with(
+                task,
+                ("One button secure erase job failed for node %s. "
+                 "Message: 'error'." % task.node.uuid),
+                errmsg=exc)
             self.assertTrue(
                 ilo_mock_object.do_one_button_secure_erase.called)
-            self.assertTrue(log_mock.called)
diff --git a/ironic/tests/unit/drivers/modules/ilo/test_raid.py b/ironic/tests/unit/drivers/modules/ilo/test_raid.py
index 76d1ed6aa..ddb6b1d8b 100644
--- a/ironic/tests/unit/drivers/modules/ilo/test_raid.py
+++ b/ironic/tests/unit/drivers/modules/ilo/test_raid.py
@@ -415,6 +415,9 @@ class Ilo5RAIDTestCase(db_base.DbTestCase):
                                  task.node.driver_internal_info)
                 clean_err_handler_mock.assert_called_once_with(
                     task,
+                    ("RAID configuration job failed for node %s. Message: "
+                     "'Failed to create raid configuration on node %s'." %
+                     (self.node.uuid, self.node.uuid)),
                     'Failed to create raid configuration '
                     'on node %s' % self.node.uuid)
             else:
@@ -422,6 +425,9 @@ class Ilo5RAIDTestCase(db_base.DbTestCase):
                                  task.node.driver_internal_info)
                 deploy_err_handler_mock.assert_called_once_with(
                     task,
+                    ("RAID configuration job failed for node %s. Message: "
+                     "'Failed to create raid configuration on node %s'." %
+                     (self.node.uuid, self.node.uuid)),
                     'Failed to create raid configuration '
                     'on node %s' % self.node.uuid)
 
diff --git a/ironic/tests/unit/drivers/modules/redfish/test_management.py b/ironic/tests/unit/drivers/modules/redfish/test_management.py
index f592c0865..a1fb4e8d0 100644
--- a/ironic/tests/unit/drivers/modules/redfish/test_management.py
+++ b/ironic/tests/unit/drivers/modules/redfish/test_management.py
@@ -1093,11 +1093,9 @@ class RedfishManagementTestCase(db_base.DbTestCase):
             self.assertTrue(mock_log.called)
 
     @mock.patch.object(manager_utils, 'cleaning_error_handler', autospec=True)
-    @mock.patch.object(redfish_mgmt.LOG, 'error', autospec=True)
     @mock.patch.object(redfish_utils, 'get_update_service', autospec=True)
     def test__check_node_firmware_update_fail(self,
                                               mock_get_update_service,
-                                              mock_log,
                                               mock_cleaning_error_handler):
         mock_sushy_task = mock.Mock()
         mock_sushy_task.task_state = 'exception'
@@ -1131,7 +1129,6 @@ class RedfishManagementTestCase(db_base.DbTestCase):
             management._check_node_firmware_update(task)
 
             task.upgrade_lock.assert_called_once_with()
-            self.assertTrue(mock_log.called)
             self.assertEqual({'something': 'else'},
                              task.node.driver_internal_info)
             mock_cleaning_error_handler.assert_called_once()
diff --git a/ironic/tests/unit/drivers/modules/test_agent_base.py b/ironic/tests/unit/drivers/modules/test_agent_base.py
index 73a19c7e3..becd26094 100644
--- a/ironic/tests/unit/drivers/modules/test_agent_base.py
+++ b/ironic/tests/unit/drivers/modules/test_agent_base.py
@@ -597,7 +597,7 @@ class HeartbeatMixinTest(AgentDeployMixinBaseTest):
                 self.deploy.heartbeat(task, 'http://127.0.0.1:8080', '1.0.0')
 
             mock_touch.assert_called_once_with(mock.ANY)
-            mock_handler.assert_called_once_with(task, mock.ANY)
+            mock_handler.assert_called_once_with(task, mock.ANY, mock.ANY)
             for called in before_failed_mocks + [failed_mock]:
                 self.assertTrue(called.called)
             for not_called in after_failed_mocks:
@@ -671,7 +671,7 @@ class HeartbeatMixinTest(AgentDeployMixinBaseTest):
             self.deploy.heartbeat(task, 'http://127.0.0.1:8080', '1.0.0')
 
         mock_continue.assert_called_once_with(mock.ANY, task)
-        mock_handler.assert_called_once_with(task, mock.ANY)
+        mock_handler.assert_called_once_with(task, mock.ANY, mock.ANY)
 
     @mock.patch.object(manager_utils, 'rescuing_error_handler', autospec=True)
     @mock.patch.object(agent_base.HeartbeatMixin, '_finalize_rescue',
@@ -1778,7 +1778,8 @@ class AgentDeployMixinTest(AgentDeployMixinBaseTest):
                                   shared=False) as task:
             agent_base._post_step_reboot(task, 'clean')
             mock_reboot.assert_called_once_with(task, states.REBOOT)
-            mock_handler.assert_called_once_with(task, mock.ANY)
+            mock_handler.assert_called_once_with(task, mock.ANY,
+                                                 traceback=True)
             self.assertNotIn('cleaning_reboot',
                              task.node.driver_internal_info)
 
@@ -1795,7 +1796,8 @@ class AgentDeployMixinTest(AgentDeployMixinBaseTest):
                                   shared=False) as task:
             agent_base._post_step_reboot(task, 'deploy')
             mock_reboot.assert_called_once_with(task, states.REBOOT)
-            mock_handler.assert_called_once_with(task, mock.ANY)
+            mock_handler.assert_called_once_with(task, mock.ANY,
+                                                 traceback=True)
             self.assertNotIn('deployment_reboot',
                              task.node.driver_internal_info)
 
@@ -1913,7 +1915,8 @@ class AgentDeployMixinTest(AgentDeployMixinBaseTest):
 
             get_hook_mock.assert_called_once_with(task.node, 'clean')
             hook_mock.assert_called_once_with(task, command_status)
-            error_handler_mock.assert_called_once_with(task, mock.ANY)
+            error_handler_mock.assert_called_once_with(task, mock.ANY,
+                                                       traceback=True)
             self.assertFalse(notify_mock.called)
             collect_logs_mock.assert_called_once_with(task.node,
                                                       label='cleaning')
@@ -1993,7 +1996,7 @@ class AgentDeployMixinTest(AgentDeployMixinBaseTest):
         with task_manager.acquire(self.context, self.node['uuid'],
                                   shared=False) as task:
             self.deploy.continue_cleaning(task)
-            error_mock.assert_called_once_with(task, mock.ANY)
+            error_mock.assert_called_once_with(task, mock.ANY, traceback=False)
             collect_logs_mock.assert_called_once_with(task.node,
                                                       label='cleaning')
 
@@ -2064,7 +2067,7 @@ class AgentDeployMixinTest(AgentDeployMixinBaseTest):
 
             status_mock.assert_called_once_with(mock.ANY, task.node)
             refresh_steps_mock.assert_called_once_with(mock.ANY, task, 'clean')
-            error_mock.assert_called_once_with(task, mock.ANY)
+            error_mock.assert_called_once_with(task, mock.ANY, traceback=True)
             self.assertFalse(notify_mock.called)
             self.assertFalse(steps_mock.called)
 
@@ -2081,7 +2084,7 @@ class AgentDeployMixinTest(AgentDeployMixinBaseTest):
         with task_manager.acquire(self.context, self.node['uuid'],
                                   shared=False) as task:
             self.deploy.continue_cleaning(task)
-            error_mock.assert_called_once_with(task, mock.ANY)
+            error_mock.assert_called_once_with(task, mock.ANY, traceback=False)
 
     def _test_clean_step_hook(self):
         """Helper method for unit tests related to clean step hooks."""