Stop waiting for power off to happen after introspection

There is no reason not to trust Ironic in doing its job, and
this wait loop will cause false negative, if service restart
happens in the middle.

Also move call to finished() before updating node.extra with
newly_discovered for the same reason.

Change-Id: I601b2660635783c8f0c59e17ca3392c347eafa53
Partial-Bug: #1421678

ironic_discoverd/process.py

@@ -14,13 +14,11 @@
 """Handling introspection data from the ramdisk."""
 
 import logging
-import time
 
 import eventlet
 from ironicclient import exceptions
 
 from ironic_discoverd.common.i18n import _, _LI, _LW
-from ironic_discoverd import conf
 from ironic_discoverd import firewall
 from ironic_discoverd import node_cache
 from ironic_discoverd.plugins import base as plugins_base
@@ -31,7 +29,6 @@ LOG = logging.getLogger("ironic_discoverd.process")
 
 _CREDENTIALS_WAIT_RETRIES = 10
 _CREDENTIALS_WAIT_PERIOD = 3
-_POWER_OFF_CHECK_PERIOD = 5
 
 
 def process(node_info):
@@ -158,7 +155,7 @@ def _finish_set_ipmi_credentials(ironic, node, cached_node, node_info,
     raise utils.Error(msg)
 
 
-def _force_power_off(ironic, cached_node):
+def _finish(ironic, cached_node):
     LOG.debug('Forcing power off of node %s', cached_node.uuid)
     try:
         utils.retry_on_conflict(ironic.node.set_power_state,
@@ -170,29 +167,11 @@ def _force_power_off(ironic, cached_node):
         cached_node.finished(error=msg)
         raise utils.Error(msg)
 
-    deadline = cached_node.started_at + conf.getint('discoverd', 'timeout')
-    while time.time() < deadline:
-        node = ironic.node.get(cached_node.uuid)
-        if (node.power_state or '').lower() == 'power off':
-            return
-        LOG.info(_LI('Waiting for node %(node)s to power off,'
-                     ' current state is %(power_state)s') %
-                 {'node': cached_node.uuid, 'power_state': node.power_state})
-        eventlet.greenthread.sleep(_POWER_OFF_CHECK_PERIOD)
-
-    msg = (_('Timeout waiting for node %s to power off after introspection') %
-           cached_node.uuid)
-    cached_node.finished(error=msg)
-    raise utils.Error(msg)
-
-
-def _finish(ironic, cached_node):
-    _force_power_off(ironic, cached_node)
+    cached_node.finished()
 
     patch = [{'op': 'add', 'path': '/extra/newly_discovered', 'value': 'true'},
              {'op': 'remove', 'path': '/extra/on_discovery'}]
     utils.retry_on_conflict(ironic.node.update, cached_node.uuid, patch)
 
-    cached_node.finished()
     LOG.info(_LI('Introspection finished successfully for node %s'),
              cached_node.uuid)

ironic_discoverd/test/test_process.py

@@ -297,7 +297,6 @@ class TestProcessNode(BaseTest):
         conf.CONF.set('discoverd', 'processing_hooks',
                       'ramdisk_error,scheduler,validate_interfaces,example')
         self.validate_attempts = 5
-        self.power_off_attempts = 2
         self.data['macs'] = self.macs  # validate_interfaces hook
         self.ports = self.all_ports
         self.cached_node = node_cache.NodeInfo(uuid=self.uuid,
@@ -325,10 +324,6 @@ class TestProcessNode(BaseTest):
             [RuntimeError()] * self.validate_attempts + [None])
         self.cli.port.create.side_effect = self.ports
         self.cli.node.update.return_value = self.node
-        # Simulate longer power off
-        self.cli.node.get.side_effect = (
-            [self.node] * self.power_off_attempts
-            + [mock.Mock(power_state='power off')])
 
     def call(self):
         return process._process_node(self.cli, self.node, self.data,
@@ -346,8 +341,6 @@ class TestProcessNode(BaseTest):
         self.cli.node.update.assert_any_call(self.uuid, self.patch_after)
         self.cli.node.set_power_state.assert_called_once_with(self.uuid, 'off')
         self.assertFalse(self.cli.node.validate.called)
-        self.assertEqual(self.power_off_attempts + 1,
-                         self.cli.node.get.call_count)
 
         post_hook_mock.assert_called_once_with(self.node, mock.ANY,
                                                self.data)
@@ -397,23 +390,6 @@ class TestProcessNode(BaseTest):
         self.cli.node.set_power_state.assert_called_with(self.uuid, 'off')
         self.assertEqual(2, self.cli.node.set_power_state.call_count)
 
-    @mock.patch.object(node_cache.NodeInfo, 'finished', autospec=True)
-    @mock.patch.object(time, 'time')
-    def test_power_off_timeout(self, time_mock, finished_mock, filters_mock,
-                               post_hook_mock):
-        conf.CONF.set('discoverd', 'timeout', '100')
-        time_mock.return_value = self.started_at + 1000
-        self.cli.node.get.return_value = self.node
-
-        self.assertRaisesRegexp(utils.Error, 'power off', self.call)
-
-        self.cli.node.update.assert_called_once_with(self.uuid,
-                                                     self.patch_before)
-        finished_mock.assert_called_once_with(
-            mock.ANY,
-            error='Timeout waiting for node %s to power off '
-            'after introspection' % self.uuid)
-
     def test_port_failed(self, filters_mock, post_hook_mock):
         self.ports[0] = exceptions.Conflict()