Wipe agent token on inspection completion to fix cleaning failures

The backport of f734efb ("Set node alive when inspection finished")
causes a regression in 4.15 where ironic-inspector is still used.
The patch makes nodes appear fast-trackable after inspection when the
agent is dead and boot media is detached, causing the
AgentConnectionFailed handler to park nodes in clean wait indefinitely.

This happens because 4.15 uses ironic-inspector, which powers off the
node after inspection. The f734efb fix was designed for 4.16 where
built-in agent inspection keeps IPA running across the
inspection-to-cleaning transition.

Revert 0feaa17 and instead fix the root cause: the agent_secret_token
persists from inspection into cleaning. When IPA reboots for cleaning,
it cannot get a new token because Ironic refuses to generate one when
one already exists, causing repeated lookup loops without heartbeats
until clean_callback_timeout fires.

The fix adds wipe_token_and_url() when inspection finishes successfully,
both in the synchronous path (inspect_hardware) and the
ironic-inspector callback path (continue_inspection). This follows the
same pattern already used on inspection start and abort.

Author: elfosardo

ironic/conductor/cleaning.py

@@ -98,12 +98,6 @@ def do_node_clean(task, clean_steps=None, disable_ramdisk=False):
                      'out-of-band only cleaning has been requested for node '
                      '%s', node.uuid)
             prepare_result = None
-    except exception.AgentConnectionFailed:
-        LOG.info('Agent is not yet running on node %(node)s, waiting for'
-                 ' agent to come up for fast track', {'node': node.uuid})
-        target_state = states.MANAGEABLE if manual_clean else None
-        task.process_event('wait', target_state=target_state)
-        return
     except Exception as e:
         msg = (_('Failed to prepare node %(node)s for cleaning: %(e)s')
                % {'node': node.uuid, 'e': e})

ironic/conductor/deployments.py

@@ -180,11 +180,6 @@ def do_node_deploy(task, conductor_id=None, configdrive=None,
 
     try:
         task.driver.deploy.prepare(task)
-    except exception.AgentConnectionFailed:
-        LOG.info('Agent is not yet running on node %(node)s, waiting for agent'
-                 ' to come up for fast track', {'node': node.uuid})
-        task.process_event('wait')
-        return
     except exception.IronicException as e:
         with excutils.save_and_reraise_exception():
             utils.deploying_error_handler(

ironic/conductor/inspection.py

@@ -61,6 +61,7 @@ def handle_failure(e, log_func=LOG.error):
         raise exception.HardwareInspectionFailure(error=error)
 
     if new_state == states.MANAGEABLE:
+        utils.wipe_token_and_url(task)
         task.process_event('done')
         LOG.info('Successfully inspected node %(node)s',
                  {'node': node.uuid})
@@ -151,5 +152,6 @@ def continue_inspection(task, inventory, plugin_data):
                                       error=True)
             task.process_event('fail')
 
+    utils.wipe_token_and_url(task)
     task.process_event('done')
     LOG.info('Successfully finished inspection of node %s', node.uuid)

ironic/conductor/utils.py

@@ -1119,18 +1119,13 @@ def fast_track_able(task):
 def value_within_timeout(value, timeout):
     """Checks if the time is within the previous timeout seconds from now.
 
-    :param value: a datetime or string representing date and time or None.
+    :param value: a string representing date and time or None.
     :param timeout: timeout in seconds.
     """
     # use native datetime objects for conversion and compare
     # slightly odd because py2 compatability :(
-    if isinstance(value, datetime.datetime):
-        # Converts to a offset-naive datetime(as created by timeutils.utcnow())
-        last = value.replace(tzinfo=None)
-    else:
-        defaultdt = '1970-01-01T00:00:00.000000'
-        last = datetime.datetime.strptime(value or defaultdt,
-                                          '%Y-%m-%dT%H:%M:%S.%f')
+    last = datetime.datetime.strptime(value or '1970-01-01T00:00:00.000000',
+                                      "%Y-%m-%dT%H:%M:%S.%f")
     # If we found nothing, we assume that the time is essentially epoch.
     time_delta = datetime.timedelta(seconds=timeout)
     last_valid = timeutils.utcnow() - time_delta
@@ -1147,20 +1142,14 @@ def agent_is_alive(node, timeout=None):
     :param node: A node object.
     :param timeout: Heartbeat timeout, defaults to `fast_track_timeout`.
     """
-
-    timeout = timeout or CONF.deploy.fast_track_timeout
-    if node.power_state == states.POWER_ON and \
-       node.inspection_finished_at and \
-       value_within_timeout(node.inspection_finished_at, timeout):
-        return True
-
     # If no agent_url is present then we have powered down since the
     # last agent heartbeat
     if not node.driver_internal_info.get('agent_url'):
         return False
 
     return value_within_timeout(
-        node.driver_internal_info.get('agent_last_heartbeat'), timeout)
+        node.driver_internal_info.get('agent_last_heartbeat'),
+        timeout or CONF.deploy.fast_track_timeout)
 
 
 def is_fast_track(task):

ironic/drivers/modules/inspector/interface.py

@@ -366,6 +366,7 @@ def clean_up(task, finish=True):
         msg = _('Inspection clean up failed: %s') % errors
         inspection_error_handler(task, msg, raise_exc=False, clean_up=False)
     elif finish:
+        cond_utils.wipe_token_and_url(task)
         LOG.info('Inspection finished successfully for node %s',
                  task.node.uuid)
         task.process_event('done')

ironic/tests/unit/conductor/test_inspection.py

@@ -127,7 +127,9 @@ class TestContinueInspection(db_base.DbTestCase):
     def setUp(self):
         super().setUp()
         self.node = obj_utils.create_test_node(
-            self.context, provision_state=states.INSPECTING)
+            self.context, provision_state=states.INSPECTING,
+            driver_internal_info={'agent_url': 'url',
+                                  'agent_secret_token': 'token'})
         self.inventory = {"test": "inventory"}
         self.plugin_data = {"plugin": "data", "logs": "delete me"}
 
@@ -144,6 +146,9 @@ def test_ok(self, mock_store, mock_continue):
             self.assertNotIn("logs", self.plugin_data)
         self.node.refresh()
         self.assertEqual(states.MANAGEABLE, self.node.provision_state)
+        self.assertNotIn('agent_url', self.node.driver_internal_info)
+        self.assertNotIn('agent_secret_token',
+                         self.node.driver_internal_info)
 
     @mock.patch.object(inspect_utils, 'store_inspection_data', autospec=True)
     def test_ok_asynchronous(self, mock_store, mock_continue):

ironic/tests/unit/conductor/test_utils.py

@@ -2184,18 +2184,6 @@ def test_is_fast_track_no_heartbeat(self, mock_get_power):
                 self.context, self.node.uuid, shared=False) as task:
             self.assertFalse(conductor_utils.is_fast_track(task))
 
-    def test_is_fast_track_inspected_no_heartbeat(self, mock_get_power):
-        mock_get_power.return_value = states.POWER_ON
-        self.node = obj_utils.create_test_node(
-            self.context, driver='fake-hardware',
-            uuid=uuidutils.generate_uuid(),
-            inspection_finished_at=timeutils.utcnow(),
-            power_state=states.POWER_ON
-        )
-        with task_manager.acquire(
-                self.context, self.node.uuid, shared=False) as task:
-            self.assertTrue(conductor_utils.is_fast_track(task))
-
     def test_is_fast_track_powered_after_heartbeat(self, mock_get_power):
         mock_get_power.return_value = states.POWER_ON
         with task_manager.acquire(

ironic/tests/unit/drivers/modules/inspector/test_interface.py

@@ -364,6 +364,9 @@ def test_exception_ignored(self, mock_client):
         self.assertFalse(self.task.process_event.called)
 
     def test_status_ok(self, mock_client):
+        self.node.set_driver_internal_info('agent_url', 'url')
+        self.node.set_driver_internal_info('agent_secret_token', 'token')
+        self.node.save()
         mock_get = mock_client.return_value.get_introspection
         mock_get.return_value = mock.Mock(is_finished=True,
                                           error=None,
@@ -374,10 +377,15 @@ def test_status_ok(self, mock_client):
         self.assertFalse(self.driver.network.remove_inspection_network.called)
         self.assertFalse(self.driver.boot.clean_up_ramdisk.called)
         self.assertFalse(self.driver.power.set_power_state.called)
+        self.assertNotIn('agent_url', self.node.driver_internal_info)
+        self.assertNotIn('agent_secret_token',
+                         self.node.driver_internal_info)
 
     def test_status_ok_managed(self, mock_client):
         utils.set_node_nested_field(self.node, 'driver_internal_info',
                                     'inspector_manage_boot', True)
+        self.node.set_driver_internal_info('agent_url', 'url')
+        self.node.set_driver_internal_info('agent_secret_token', 'token')
         self.node.save()
         mock_get = mock_client.return_value.get_introspection
         mock_get.return_value = mock.Mock(is_finished=True,
@@ -391,6 +399,9 @@ def test_status_ok_managed(self, mock_client):
         self.driver.boot.clean_up_ramdisk.assert_called_once_with(self.task)
         self.driver.power.set_power_state.assert_called_once_with(
             self.task, 'power off', timeout=None)
+        self.assertNotIn('agent_url', self.node.driver_internal_info)
+        self.assertNotIn('agent_secret_token',
+                         self.node.driver_internal_info)
 
     def test_status_ok_managed_no_power_off(self, mock_client):
         CONF.set_override('power_off', False, group='inspector')