Log which instance event was timed out

Nova compute logs what external events it waits for and logs if timeout
happens but it is not easy to figure out which even are timed out if
nova waits for multiple events, i.e.: there are multiple ports to be
plugged.

This patch moves the warning log into wait_for_instance_event itself and
extends the log with the name of the event nova waited for when the
timeout happens.

Change-Id: I91c42af8226dc8607d86c52413924351ba0586ac

Author: Balazs Gibizer

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

@@ -7268,17 +7268,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