Merge "Update Instance action's updated_at when action event updated."

nova/db/sqlalchemy/api.py

@@ -5667,7 +5667,7 @@ def instance_fault_get_by_instance_uuids(context, instance_uuids,
 
 @pick_context_manager_writer
 def action_start(context, values):
-    convert_objects_related_datetimes(values, 'start_time')
+    convert_objects_related_datetimes(values, 'start_time', 'updated_at')
     action_ref = models.InstanceAction()
     action_ref.update(values)
     action_ref.save(context.session)
@@ -5676,7 +5676,8 @@ def action_start(context, values):
 
 @pick_context_manager_writer
 def action_finish(context, values):
-    convert_objects_related_datetimes(values, 'start_time', 'finish_time')
+    convert_objects_related_datetimes(values, 'start_time', 'finish_time',
+                                      'updated_at')
     query = model_query(context, models.InstanceAction).\
                         filter_by(instance_uuid=values['instance_uuid']).\
                         filter_by(request_id=values['request_id'])
@@ -5732,9 +5733,13 @@ def action_event_start(context, values):
     # according to request_id. Try to get the last created action so that
     # init_instance can continue to finish the recovery action, like:
     # powering_off, unpausing, and so on.
+    update_action = True
     if not action and not context.project_id:
         action = _action_get_last_created_by_instance_uuid(
             context, values['instance_uuid'])
+        # If we couldn't find an action by the request_id, we don't want to
+        # update this action since it likely represents an inactive action.
+        update_action = False
 
     if not action:
         raise exception.InstanceActionNotFound(
@@ -5746,9 +5751,19 @@ def action_event_start(context, values):
     event_ref = models.InstanceActionEvent()
     event_ref.update(values)
     context.session.add(event_ref)
+
+    # Update action updated_at.
+    if update_action:
+        action.update({'updated_at': values['start_time']})
+        action.save(context.session)
+
     return event_ref
 
 
+# NOTE: We need the retry_on_deadlock decorator for cases like resize where
+# a lot of events are happening at once between multiple hosts trying to
+# update the same action record in a small time window.
+@oslo_db_api.wrap_db_retry(max_retries=5, retry_on_deadlock=True)
 @pick_context_manager_writer
 def action_event_finish(context, values):
     """Finish an event on an instance action."""
@@ -5761,9 +5776,13 @@ def action_event_finish(context, values):
     # according to request_id. Try to get the last created action so that
     # init_instance can continue to finish the recovery action, like:
     # powering_off, unpausing, and so on.
+    update_action = True
     if not action and not context.project_id:
         action = _action_get_last_created_by_instance_uuid(
             context, values['instance_uuid'])
+        # If we couldn't find an action by the request_id, we don't want to
+        # update this action since it likely represents an inactive action.
+        update_action = False
 
     if not action:
         raise exception.InstanceActionNotFound(
@@ -5783,6 +5802,11 @@ def action_event_finish(context, values):
     if values['result'].lower() == 'error':
         action.update({'message': 'Error'})
 
+    # Update action updated_at.
+    if update_action:
+        action.update({'updated_at': values['finish_time']})
+        action.save(context.session)
+
     return event_ref
 
 

nova/objects/instance_action.py

@@ -55,14 +55,17 @@ class InstanceAction(base.NovaPersistentObject, base.NovaObject,
                   'user_id': context.user_id,
                   'project_id': context.project_id,
                   'action': action_name,
-                  'start_time': context.timestamp}
+                  'start_time': context.timestamp,
+                  'updated_at': context.timestamp}
         return values
 
     @staticmethod
     def pack_action_finish(context, instance_uuid):
+        utcnow = timeutils.utcnow()
         values = {'request_id': context.request_id,
                   'instance_uuid': instance_uuid,
-                  'finish_time': timeutils.utcnow()}
+                  'finish_time': utcnow,
+                  'updated_at': utcnow}
         return values
 
     @base.remotable_classmethod

nova/tests/unit/db/test_db_api.py

@@ -3776,13 +3776,15 @@ class InstanceActionTestCase(test.TestCase, ModelsObjectComparatorMixin):
 
         db.instance_create(ctxt, {'uuid': uuid})
 
+        utc_now = timeutils.utcnow()
         values = {
             'action': action,
             'instance_uuid': uuid,
             'request_id': ctxt.request_id,
             'user_id': ctxt.user_id,
             'project_id': ctxt.project_id,
-            'start_time': timeutils.utcnow(),
+            'start_time': utc_now,
+            'updated_at': utc_now,
             'message': 'action-message'
         }
         if extra is not None:
@@ -4113,6 +4115,82 @@ class InstanceActionTestCase(test.TestCase, ModelsObjectComparatorMixin):
                                              self.ctxt.request_id)
         self.assertNotEqual('Error', action['message'])
 
+    def test_instance_action_updated_with_event_start_and_finish_action(self):
+        uuid = uuidsentinel.uuid1
+        action = db.action_start(self.ctxt, self._create_action_values(uuid))
+        updated_create = action['updated_at']
+        self.assertIsNotNone(updated_create)
+        event_values = self._create_event_values(uuid)
+
+        # event start action
+        time_start = timeutils.utcnow() + datetime.timedelta(seconds=5)
+        event_values['start_time'] = time_start
+        db.action_event_start(self.ctxt, event_values)
+        action = db.action_get_by_request_id(self.ctxt, uuid,
+                                             self.ctxt.request_id)
+        updated_event_start = action['updated_at']
+        self.assertEqual(time_start.isoformat(),
+                         updated_event_start.isoformat())
+        self.assertTrue(updated_event_start > updated_create)
+
+        # event finish action
+        time_finish = timeutils.utcnow() + datetime.timedelta(seconds=10)
+        event_values = {
+            'finish_time': time_finish,
+            'result': 'Success'
+        }
+        event_values = self._create_event_values(uuid, extra=event_values)
+        db.action_event_finish(self.ctxt, event_values)
+        action = db.action_get_by_request_id(self.ctxt, uuid,
+                                             self.ctxt.request_id)
+        updated_event_finish = action['updated_at']
+        self.assertEqual(time_finish.isoformat(),
+                         updated_event_finish.isoformat())
+        self.assertTrue(updated_event_finish > updated_event_start)
+
+    def test_instance_action_not_updated_with_unknown_event_request(self):
+        """Tests that we don't update the action.updated_at field when
+        starting or finishing an action event if we couldn't find the
+        action by the request_id.
+        """
+        # Create a valid action - this represents an active user request.
+        uuid = uuidsentinel.uuid1
+        action = db.action_start(self.ctxt, self._create_action_values(uuid))
+        updated_create = action['updated_at']
+        self.assertIsNotNone(updated_create)
+        event_values = self._create_event_values(uuid)
+
+        # Now start an event on an unknown request ID and admin context where
+        # project_id won't be set.
+        time_start = timeutils.utcnow() + datetime.timedelta(seconds=5)
+        event_values['start_time'] = time_start
+        random_request_id = 'req-%s' % uuidsentinel.request_id
+        event_values['request_id'] = random_request_id
+        admin_context = context.get_admin_context()
+        event_ref = db.action_event_start(admin_context, event_values)
+        # The event would be created on the existing action.
+        self.assertEqual(action['id'], event_ref['action_id'])
+        # And the action.update_at should be the same as before the event was
+        # started.
+        action = db.action_get_by_request_id(self.ctxt, uuid,
+                                             self.ctxt.request_id)
+        self.assertEqual(updated_create, action['updated_at'])
+
+        # Now finish the event on the unknown request ID and admin context.
+        time_finish = timeutils.utcnow() + datetime.timedelta(seconds=10)
+        event_values = {
+            'finish_time': time_finish,
+            'request_id': random_request_id,
+            'result': 'Success'
+        }
+        event_values = self._create_event_values(uuid, extra=event_values)
+        db.action_event_finish(admin_context, event_values)
+        # And the action.update_at should be the same as before the event was
+        # finished.
+        action = db.action_get_by_request_id(self.ctxt, uuid,
+                                             self.ctxt.request_id)
+        self.assertEqual(updated_create, action['updated_at'])
+
 
 class InstanceFaultTestCase(test.TestCase, ModelsObjectComparatorMixin):
     def setUp(self):

nova/tests/unit/objects/test_instance_action.py

@@ -148,11 +148,13 @@ class _TestInstanceActionObject(object):
             'instance_uuid': uuids.instance,
             'action': 'fake-action',
             'start_time': self.context.timestamp,
+            'updated_at': self.context.timestamp,
         }
         expected_packed_action_finish = {
             'request_id': self.context.request_id,
             'instance_uuid': uuids.instance,
             'finish_time': NOW,
+            'updated_at': NOW,
         }
         mock_start.return_value = fake_action
         mock_finish.return_value = fake_action