Merge "Log which instance event was timed out"

Author: Zuul

nova/compute/manager.py

@@ -402,6 +402,79 @@ def exit_wait_early(self, events):
     def _default_error_callback(self, event_name, instance):
         raise exception.NovaException(_('Instance event failed'))
 
+    class _InstanceEvent:
+        EXPECTED = "expected"
+        WAITING = "waiting"
+        RECEIVED = "received"
+        RECEIVED_EARLY = "received early"
+        TIMED_OUT = "timed out"
+        RECEIVED_NOT_PROCESSED = "received but not processed"
+
+        def __init__(self, name: str, event: eventlet.event.Event) -> None:
+            self.name = name
+            self.event = event
+            self.status = self.EXPECTED
+            self.wait_time = None
+
+        def mark_as_received_early(self) -> None:
+            self.status = self.RECEIVED_EARLY
+
+        def is_received_early(self) -> bool:
+            return self.status == self.RECEIVED_EARLY
+
+        def _update_status_no_wait(self):
+            if self.status == self.EXPECTED and self.event.ready():
+                self.status = self.RECEIVED_NOT_PROCESSED
+
+        def wait(self) -> 'objects.InstanceExternalEvent':
+            self.status = self.WAITING
+            try:
+                with timeutils.StopWatch() as sw:
+                    instance_event = self.event.wait()
+            except eventlet.timeout.Timeout:
+                self.status = self.TIMED_OUT
+                self.wait_time = sw.elapsed()
+
+                raise
+
+            self.status = self.RECEIVED
+            self.wait_time = sw.elapsed()
+            return instance_event
+
+        def __str__(self) -> str:
+            self._update_status_no_wait()
+            if self.status == self.EXPECTED:
+                return f"{self.name}: expected but not received"
+            if self.status == self.RECEIVED:
+                return (
+                    f"{self.name}: received after waiting "
+                    f"{self.wait_time:.2f} seconds")
+            if self.status == self.TIMED_OUT:
+                return (
+                    f"{self.name}: timed out after "
+                    f"{self.wait_time:.2f} seconds")
+            return f"{self.name}: {self.status}"
+
+    @staticmethod
+    def _wait_for_instance_events(
+        instance: 'objects.Instance',
+        events: dict,
+        error_callback: ty.Callable,
+    ) -> None:
+        for event_name, event in events.items():
+            if event.is_received_early():
+                continue
+            else:
+                actual_event = event.wait()
+                if actual_event.status == 'completed':
+                    continue
+            # If we get here, we have an event that was not completed,
+            # nor skipped via exit_wait_early(). Decide whether to
+            # keep waiting by calling the error_callback() hook.
+            decision = error_callback(event_name, instance)
+            if decision is False:
+                break
+
     @contextlib.contextmanager
     def wait_for_instance_event(self, instance, event_names, deadline=300,
                                 error_callback=None):
@@ -454,9 +527,10 @@ def wait_for_instance_event(self, instance, event_names, deadline=300,
             name, tag = event_name
             event_name = objects.InstanceExternalEvent.make_key(name, tag)
             try:
-                events[event_name] = (
+                event = (
                     self._compute.instance_events.prepare_for_instance_event(
                         instance, name, tag))
+                events[event_name] = self._InstanceEvent(event_name, event)
             except exception.NovaException:
                 error_callback(event_name, instance)
                 # NOTE(danms): Don't wait for any of the events. They
@@ -468,25 +542,35 @@ def wait_for_instance_event(self, instance, event_names, deadline=300,
         except self._exit_early_exc as e:
             early_events = set([objects.InstanceExternalEvent.make_key(n, t)
                                 for n, t in e.events])
-        else:
-            early_events = set([])
+
+            # If there are expected events that received early, mark them,
+            # so they won't be waited for later
+            for early_event_name in early_events:
+                if early_event_name in events:
+                    events[early_event_name].mark_as_received_early()
 
         sw = timeutils.StopWatch()
         sw.start()
-        with eventlet.timeout.Timeout(deadline):
-            for event_name, event in events.items():
-                if event_name in early_events:
-                    continue
-                else:
-                    actual_event = event.wait()
-                    if actual_event.status == 'completed':
-                        continue
-                # If we get here, we have an event that was not completed,
-                # nor skipped via exit_wait_early(). Decide whether to
-                # keep waiting by calling the error_callback() hook.
-                decision = error_callback(event_name, instance)
-                if decision is False:
-                    break
+        try:
+            with eventlet.timeout.Timeout(deadline):
+                self._wait_for_instance_events(
+                    instance, events, error_callback)
+        except eventlet.timeout.Timeout:
+            LOG.warning(
+                'Timeout waiting for %(events)s for instance with '
+                'vm_state %(vm_state)s and task_state %(task_state)s. '
+                'Event states are: %(event_states)s',
+                {
+                    'events': list(events.keys()),
+                    'vm_state': instance.vm_state,
+                    'task_state': instance.task_state,
+                    'event_states':
+                        ', '.join([str(event) for event in events.values()]),
+                },
+                instance=instance)
+
+            raise
+
         LOG.debug('Instance event wait completed in %i seconds for %s',
                   sw.elapsed(),
                   ','.join(x[0] for x in event_names),

nova/tests/unit/compute/test_virtapi.py

@@ -14,6 +14,7 @@
 
 import collections
 
+import eventlet.timeout
 import mock
 import os_traits
 from oslo_utils.fixture import uuidsentinel as uuids
@@ -187,15 +188,150 @@ def do_test():
         do_test()
 
     def test_wait_for_instance_event_timeout(self):
+        instance = mock.Mock()
+        instance.vm_state = mock.sentinel.vm_state
+        instance.task_state = mock.sentinel.task_state
+
+        mock_log = mock.Mock()
+
+        @mock.patch.object(compute_manager, 'LOG', new=mock_log)
         @mock.patch.object(self.virtapi._compute, '_event_waiter',
-                           side_effect=test.TestingException())
-        @mock.patch('eventlet.timeout.Timeout')
-        def do_test(mock_timeout, mock_waiter):
-            with self.virtapi.wait_for_instance_event('instance',
-                                                      [('foo', 'bar')]):
+                           side_effect=eventlet.timeout.Timeout())
+        def do_test(mock_waiter):
+            with self.virtapi.wait_for_instance_event(
+                    instance, [('foo', 'bar')]):
                 pass
 
-        self.assertRaises(test.TestingException, do_test)
+        self.assertRaises(eventlet.timeout.Timeout, do_test)
+        mock_log.warning.assert_called_once_with(
+            'Timeout waiting for %(events)s for instance with vm_state '
+            '%(vm_state)s and task_state %(task_state)s. '
+            'Event states are: %(event_states)s',
+            {
+                'events': ['foo-bar'],
+                'vm_state': mock.sentinel.vm_state,
+                'task_state': mock.sentinel.task_state,
+                'event_states':
+                    'foo-bar: timed out after 0.00 seconds',
+            },
+            instance=instance
+        )
+
+    def test_wait_for_instance_event_one_received_one_timed_out(self):
+        instance = mock.Mock()
+        instance.vm_state = mock.sentinel.vm_state
+        instance.task_state = mock.sentinel.task_state
+
+        mock_log = mock.Mock()
+
+        calls = []
+
+        def fake_event_waiter(*args, **kwargs):
+            calls.append((args, kwargs))
+            if len(calls) == 1:
+                event = mock.Mock(status="completed")
+                return event
+            else:
+                raise eventlet.timeout.Timeout()
+
+        @mock.patch.object(compute_manager, 'LOG', new=mock_log)
+        @mock.patch.object(self.virtapi._compute, '_event_waiter',
+                           side_effect=fake_event_waiter)
+        def do_test(mock_waiter):
+            with self.virtapi.wait_for_instance_event(
+                    instance, [('foo', 'bar'), ('missing', 'event')]):
+                pass
+
+        self.assertRaises(eventlet.timeout.Timeout, do_test)
+        mock_log.warning.assert_called_once_with(
+            'Timeout waiting for %(events)s for instance with vm_state '
+            '%(vm_state)s and task_state %(task_state)s. '
+            'Event states are: %(event_states)s',
+            {
+                'events': ['foo-bar', 'missing-event'],
+                'vm_state': mock.sentinel.vm_state,
+                'task_state': mock.sentinel.task_state,
+                'event_states':
+                    'foo-bar: received after waiting 0.00 seconds, '
+                    'missing-event: timed out after 0.00 seconds',
+            },
+            instance=instance
+        )
+
+    def test_wait_for_instance_event_multiple_events(self):
+        instance = mock.Mock()
+        instance.vm_state = mock.sentinel.vm_state
+        instance.task_state = mock.sentinel.task_state
+
+        mock_log = mock.Mock()
+
+        calls = []
+
+        def fake_event_waiter(*args, **kwargs):
+            calls.append((args, kwargs))
+            if len(calls) == 1:
+                event = mock.Mock(status="completed")
+                return event
+            else:
+                raise eventlet.timeout.Timeout()
+
+        def fake_prepare_for_instance_event(instance, name, tag):
+            m = mock.MagicMock()
+            m.instance = instance
+            m.name = name
+            m.tag = tag
+            m.event_name = '%s-%s' % (name, tag)
+            m.wait.side_effect = fake_event_waiter
+            print(name, tag)
+            if name == 'received-but-not-waited':
+                m.ready.return_value = True
+            if name == 'missing-but-not-waited':
+                m.ready.return_value = False
+            return m
+
+        self.virtapi._compute.instance_events.prepare_for_instance_event.\
+            side_effect = fake_prepare_for_instance_event
+
+        @mock.patch.object(compute_manager, 'LOG', new=mock_log)
+        def do_test():
+            with self.virtapi.wait_for_instance_event(
+                    instance,
+                    [
+                        ('received', 'event'),
+                        ('early', 'event'),
+                        ('missing', 'event'),
+                        ('received-but-not-waited', 'event'),
+                        ('missing-but-not-waited', 'event'),
+                    ]
+            ):
+                self.virtapi.exit_wait_early([('early', 'event')])
+
+        self.assertRaises(eventlet.timeout.Timeout, do_test)
+        mock_log.warning.assert_called_once_with(
+            'Timeout waiting for %(events)s for instance with vm_state '
+            '%(vm_state)s and task_state %(task_state)s. '
+            'Event states are: %(event_states)s',
+            {
+                'events':
+                    [
+                        'received-event',
+                        'early-event',
+                        'missing-event',
+                        'received-but-not-waited-event',
+                        'missing-but-not-waited-event'
+                     ],
+                'vm_state': mock.sentinel.vm_state,
+                'task_state': mock.sentinel.task_state,
+                'event_states':
+                    'received-event: received after waiting 0.00 seconds, '
+                    'early-event: received early, '
+                    'missing-event: timed out after 0.00 seconds, '
+                    'received-but-not-waited-event: received but not '
+                    'processed, '
+                    'missing-but-not-waited-event: expected but not received'
+            },
+            instance=instance
+        )
 
     def test_wait_for_instance_event_exit_early(self):
         # Wait for two events, exit early skipping one.

nova/virt/libvirt/driver.py

@@ -7488,17 +7488,9 @@ def _create_guest_with_network(
                         pause=pause, power_on=power_on,
                         post_xml_callback=post_xml_callback)
         except eventlet.timeout.Timeout:
-            # We never heard from Neutron
-            LOG.warning(
-                'Timeout waiting for %(events)s for instance with '
-                'vm_state %(vm_state)s and task_state %(task_state)s',
-                {
-                    'events': events,
-                    'vm_state': instance.vm_state,
-                    'task_state': instance.task_state,
-                },
-                instance=instance)
-
+            # We did not receive all expected events from Neutron, a warning
+            # has already been logged by wait_for_instance_event, but we need
+            # to decide if the issue is fatal.
             if CONF.vif_plugging_is_fatal:
                 # NOTE(stephenfin): don't worry, guest will be in scope since
                 # we can only hit this branch if the VIF plug timed out