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

2 files changed, 21 insertions, 10 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)