Record instance actions and events

Record when an action is initiated on an instance, and the underlying
events related to completing that action.

Actions will typically occur at the API level and should match what a
user intended to do with an instance.  Events will typically track what
happens behind the scenes and may include things that would be unclear
for a user if exposed, but should be beneficial to an admin/deployer.

Adds a new wrapper to the compute manager.  The wrapper will record when
an event begins and finishes from the point of view of the compute
manager.  It will also record errors if they occur.

Blueprint instance-actions

Change-Id: I801f3e796d091e146413f84c2ccfab95ad2e1af4

15 files changed, 579 insertions, 42 deletions

diff --git a/nova/compute/api.py b/nova/compute/api.py
index a9d0a1bdd..64ca20148 100644
--- a/nova/compute/api.py
+++ b/nova/compute/api.py
@@ -31,6 +31,7 @@ import uuid
 
 from nova import availability_zones
 from nova import block_device
+from nova.compute import instance_actions
 from nova.compute import instance_types
 from nova.compute import power_state
 from nova.compute import rpcapi as compute_rpcapi
@@ -190,6 +191,11 @@ class API(base.Base):
 
         return instance_ref
 
+    def _record_action_start(self, context, instance, action):
+        act = compute_utils.pack_action_start(context, instance['uuid'],
+                                              action)
+        self.db.action_start(context, act)
+
     def _check_injected_file_quota(self, context, injected_files):
         """Enforce quota limits on injected files.
 
@@ -624,6 +630,10 @@ class API(base.Base):
                         block_device_mapping, auto_disk_config,
                         reservation_id, scheduler_hints)
 
+        for instance in instances:
+            self._record_action_start(context, instance,
+                                      instance_actions.CREATE)
+
         self.scheduler_rpcapi.run_instance(context,
                 request_spec=request_spec,
                 admin_password=admin_password, injected_files=injected_files,
@@ -1030,6 +1040,10 @@ class API(base.Base):
                         context.elevated(), instance['host'])
                 if self.servicegroup_api.service_is_up(service):
                     is_up = True
+
+                    self._record_action_start(context, instance,
+                                              instance_actions.DELETE)
+
                     cb(context, instance, bdms)
             except exception.ComputeHostNotFound:
                 pass
@@ -1173,6 +1187,8 @@ class API(base.Base):
         num_instances, quota_reservations = self._check_num_instances_quota(
                 context, instance_type, 1, 1)
 
+        self._record_action_start(context, instance, instance_actions.RESTORE)
+
         try:
             if instance['host']:
                 instance = self.update(context, instance,
@@ -1214,6 +1230,8 @@ class API(base.Base):
                     expected_task_state=None,
                     progress=0)
 
+        self._record_action_start(context, instance, instance_actions.STOP)
+
         self.compute_rpcapi.stop_instance(context, instance, cast=do_cast)
 
     @wrap_check_policy
@@ -1227,6 +1245,7 @@ class API(base.Base):
                                task_state=task_states.POWERING_ON,
                                expected_task_state=None)
 
+        self._record_action_start(context, instance, instance_actions.START)
         # TODO(yamahata): injected_files isn't supported right now.
         #                 It is used only for osapi. not for ec2 api.
         #                 availability_zone isn't used by run_instance.
@@ -1637,6 +1656,8 @@ class API(base.Base):
         block_info = self._get_block_device_info(elevated,
                                                         instance['uuid'])
 
+        self._record_action_start(context, instance, instance_actions.REBOOT)
+
         self.compute_rpcapi.reboot_instance(context, instance=instance,
                                             block_device_info=block_info,
                                             reboot_type=reboot_type)
@@ -1727,6 +1748,8 @@ class API(base.Base):
         bdms = self.db.block_device_mapping_get_all_by_instance(context,
                 instance['uuid'])
 
+        self._record_action_start(context, instance, instance_actions.REBUILD)
+
         self.compute_rpcapi.rebuild_instance(context, instance=instance,
                 new_pass=admin_password, injected_files=files_to_inject,
                 image_ref=image_href, orig_image_ref=orig_image_ref,
@@ -1757,6 +1780,9 @@ class API(base.Base):
             QUOTAS.commit(context, reservations)
             reservations = []
 
+        self._record_action_start(context, instance,
+                                  instance_actions.REVERT_RESIZE)
+
         self.compute_rpcapi.revert_resize(context,
                 instance=instance, migration=migration_ref,
                 host=migration_ref['dest_compute'], reservations=reservations)
@@ -1786,6 +1812,9 @@ class API(base.Base):
             QUOTAS.commit(context, reservations)
             reservations = []
 
+        self._record_action_start(context, instance,
+                                  instance_actions.CONFIRM_RESIZE)
+
         self.compute_rpcapi.confirm_resize(context,
                 instance=instance, migration=migration_ref,
                 host=migration_ref['source_compute'],
@@ -1961,6 +1990,9 @@ class API(base.Base):
             "filter_properties": filter_properties,
             "reservations": reservations,
         }
+
+        self._record_action_start(context, instance, instance_actions.RESIZE)
+
         self.scheduler_rpcapi.prep_resize(context, **args)
 
     @wrap_check_policy
@@ -1987,6 +2019,9 @@ class API(base.Base):
                     vm_state=vm_states.ACTIVE,
                     task_state=task_states.PAUSING,
                     expected_task_state=None)
+
+        self._record_action_start(context, instance, instance_actions.PAUSE)
+
         self.compute_rpcapi.pause_instance(context, instance=instance)
 
     @wrap_check_policy
@@ -1999,6 +2034,9 @@ class API(base.Base):
                     vm_state=vm_states.PAUSED,
                     task_state=task_states.UNPAUSING,
                     expected_task_state=None)
+
+        self._record_action_start(context, instance, instance_actions.UNPAUSE)
+
         self.compute_rpcapi.unpause_instance(context, instance=instance)
 
     @wrap_check_policy
@@ -2020,6 +2058,9 @@ class API(base.Base):
                     vm_state=vm_states.ACTIVE,
                     task_state=task_states.SUSPENDING,
                     expected_task_state=None)
+
+        self._record_action_start(context, instance, instance_actions.SUSPEND)
+
         self.compute_rpcapi.suspend_instance(context, instance=instance)
 
     @wrap_check_policy
@@ -2032,6 +2073,9 @@ class API(base.Base):
                     vm_state=vm_states.SUSPENDED,
                     task_state=task_states.RESUMING,
                     expected_task_state=None)
+
+        self._record_action_start(context, instance, instance_actions.RESUME)
+
         self.compute_rpcapi.resume_instance(context, instance=instance)
 
     @wrap_check_policy
@@ -2045,6 +2089,8 @@ class API(base.Base):
                     task_state=task_states.RESCUING,
                     expected_task_state=None)
 
+        self._record_action_start(context, instance, instance_actions.RESCUE)
+
         self.compute_rpcapi.rescue_instance(context, instance=instance,
                 rescue_password=rescue_password)
 
@@ -2058,6 +2104,9 @@ class API(base.Base):
                     vm_state=vm_states.RESCUED,
                     task_state=task_states.UNRESCUING,
                     expected_task_state=None)
+
+        self._record_action_start(context, instance, instance_actions.UNRESCUE)
+
         self.compute_rpcapi.unrescue_instance(context, instance=instance)
 
     @wrap_check_policy
@@ -2070,6 +2119,9 @@ class API(base.Base):
                     task_state=task_states.UPDATING_PASSWORD,
                     expected_task_state=None)
 
+        self._record_action_start(context, instance,
+                                  instance_actions.CHANGE_PASSWORD)
+
         self.compute_rpcapi.set_admin_password(context,
                                                instance=instance,
                                                new_pass=password)
diff --git a/nova/compute/instance_actions.py b/nova/compute/instance_actions.py
new file mode 100644
index 000000000..cbb517387
--- /dev/null
+++ b/nova/compute/instance_actions.py
@@ -0,0 +1,44 @@
+# vim: tabstop=4 shiftwidth=4 softtabstop=4
+
+# Copyright 2013 OpenStack LLC.
+# All Rights Reserved.
+#
+#    Licensed under the Apache License, Version 2.0 (the "License"); you may
+#    not use this file except in compliance with the License. You may obtain
+#    a copy of the License at
+#
+#         http://www.apache.org/licenses/LICENSE-2.0
+#
+#    Unless required by applicable law or agreed to in writing, software
+#    distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+#    WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+#    License for the specific language governing permissions and limitations
+#    under the License.
+
+"""Possible actions on an instance.
+
+Actions should probably match a user intention at the API level.  Because they
+can be user visible that should help to avoid confusion.  For that reason they
+tend to maintain the casing sent to the API.
+
+Maintaining a list of actions here should protect against inconsistencies when
+they are used.
+"""
+
+CREATE = 'create'
+DELETE = 'delete'
+RESTORE = 'restore'
+STOP = 'stop'
+START = 'start'
+REBOOT = 'reboot'
+REBUILD = 'rebuild'
+REVERT_RESIZE = 'revertResize'
+CONFIRM_RESIZE = 'confirmResize'
+RESIZE = 'resize'
+PAUSE = 'pause'
+UNPAUSE = 'unpause'
+SUSPEND = 'suspend'
+RESUME = 'resume'
+RESCUE = 'rescue'
+UNRESCUE = 'unrescue'
+CHANGE_PASSWORD = 'changePassword'
diff --git a/nova/compute/manager.py b/nova/compute/manager.py
index 0ad5c1dc8..0295ac19a 100644
--- a/nova/compute/manager.py
+++ b/nova/compute/manager.py
@@ -233,6 +233,29 @@ def wrap_instance_fault(function):
     return decorated_function
 
 
+def wrap_instance_event(function):
+    """Wraps a method to log the event taken on the instance, and result.
+
+    This decorator wraps a method to log the start and result of an event, as
+    part of an action taken on an instance.
+    """
+
+    @functools.wraps(function)
+    def decorated_function(self, context, *args, **kwargs):
+        wrapped_func = utils.get_wrapped_function(function)
+        keyed_args = utils.getcallargs(wrapped_func, context, *args,
+                                       **kwargs)
+        instance_uuid = keyed_args['instance']['uuid']
+
+        event_name = 'compute_{0}'.format(function.func_name)
+        with compute_utils.EventReporter(context, self.conductor_api,
+                                         event_name, instance_uuid):
+
+            function(self, context, *args, **kwargs)
+
+    return decorated_function
+
+
 def _get_image_meta(context, image_ref):
     image_service, image_id = glance.get_remote_image_service(context,
                                                               image_ref)
@@ -1036,6 +1059,7 @@ class ComputeManager(manager.SchedulerDependentManager):
 
     @exception.wrap_exception(notifier=notifier, publisher_id=publisher_id())
     @reverts_task_state
+    @wrap_instance_event
     @wrap_instance_fault
     def run_instance(self, context, instance, request_spec=None,
                      filter_properties=None, requested_networks=None,
@@ -1142,6 +1166,7 @@ class ComputeManager(manager.SchedulerDependentManager):
                 system_metadata=system_meta)
 
     @exception.wrap_exception(notifier=notifier, publisher_id=publisher_id())
+    @wrap_instance_event
     @wrap_instance_fault
     def terminate_instance(self, context, instance, bdms=None):
         """Terminate an instance on this host."""
@@ -1174,6 +1199,7 @@ class ComputeManager(manager.SchedulerDependentManager):
     # can't use that name in grizzly.
     @exception.wrap_exception(notifier=notifier, publisher_id=publisher_id())
     @reverts_task_state
+    @wrap_instance_event
     @wrap_instance_fault
     def stop_instance(self, context, instance):
         """Stopping an instance on this host."""
@@ -1193,6 +1219,7 @@ class ComputeManager(manager.SchedulerDependentManager):
     # can't use that name in grizzly.
     @exception.wrap_exception(notifier=notifier, publisher_id=publisher_id())
     @reverts_task_state
+    @wrap_instance_event
     @wrap_instance_fault
     def start_instance(self, context, instance):
         """Starting an instance on this host."""
@@ -1209,6 +1236,7 @@ class ComputeManager(manager.SchedulerDependentManager):
 
     @exception.wrap_exception(notifier=notifier, publisher_id=publisher_id())
     @reverts_task_state
+    @wrap_instance_event
     @wrap_instance_fault
     def soft_delete_instance(self, context, instance):
         """Soft delete an instance on this host."""
@@ -1230,6 +1258,7 @@ class ComputeManager(manager.SchedulerDependentManager):
 
     @exception.wrap_exception(notifier=notifier, publisher_id=publisher_id())
     @reverts_task_state
+    @wrap_instance_event
     @wrap_instance_fault
     def restore_instance(self, context, instance):
         """Restore a soft-deleted instance on this host."""
@@ -1272,6 +1301,7 @@ class ComputeManager(manager.SchedulerDependentManager):
 
     @exception.wrap_exception(notifier=notifier, publisher_id=publisher_id())
     @reverts_task_state
+    @wrap_instance_event
     @wrap_instance_fault
     def rebuild_instance(self, context, instance, orig_image_ref, image_ref,
                          injected_files, new_pass, orig_sys_metadata=None,
@@ -1417,6 +1447,7 @@ class ComputeManager(manager.SchedulerDependentManager):
 
     @exception.wrap_exception(notifier=notifier, publisher_id=publisher_id())
     @reverts_task_state
+    @wrap_instance_event
     @wrap_instance_fault
     def reboot_instance(self, context, instance,
                         block_device_info=None,
@@ -1573,6 +1604,7 @@ class ComputeManager(manager.SchedulerDependentManager):
 
     @exception.wrap_exception(notifier=notifier, publisher_id=publisher_id())
     @reverts_task_state
+    @wrap_instance_event
     @wrap_instance_fault
     def set_admin_password(self, context, instance, new_pass=None):
         """Set the root/admin password for an instance on this host.
@@ -1673,6 +1705,7 @@ class ComputeManager(manager.SchedulerDependentManager):
 
     @exception.wrap_exception(notifier=notifier, publisher_id=publisher_id())
     @reverts_task_state
+    @wrap_instance_event
     @wrap_instance_fault
     def rescue_instance(self, context, instance, rescue_password=None):
         """
@@ -1710,6 +1743,7 @@ class ComputeManager(manager.SchedulerDependentManager):
 
     @exception.wrap_exception(notifier=notifier, publisher_id=publisher_id())
     @reverts_task_state
+    @wrap_instance_event
     @wrap_instance_fault
     def unrescue_instance(self, context, instance):
         """Rescue an instance on this host."""
@@ -1740,6 +1774,7 @@ class ComputeManager(manager.SchedulerDependentManager):
         self.driver.change_instance_metadata(context, instance, diff)
 
     @exception.wrap_exception(notifier=notifier, publisher_id=publisher_id())
+    @wrap_instance_event
     @wrap_instance_fault
     def confirm_resize(self, context, instance, reservations=None,
                        migration=None, migration_id=None):
@@ -1771,6 +1806,7 @@ class ComputeManager(manager.SchedulerDependentManager):
 
     @exception.wrap_exception(notifier=notifier, publisher_id=publisher_id())
     @reverts_task_state
+    @wrap_instance_event
     @wrap_instance_fault
     def revert_resize(self, context, instance, migration=None,
                       migration_id=None, reservations=None):
@@ -1815,6 +1851,7 @@ class ComputeManager(manager.SchedulerDependentManager):
 
     @exception.wrap_exception(notifier=notifier, publisher_id=publisher_id())
     @reverts_task_state
+    @wrap_instance_event
     @wrap_instance_fault
     def finish_revert_resize(self, context, instance, reservations=None,
                              migration=None, migration_id=None):
@@ -1923,6 +1960,7 @@ class ComputeManager(manager.SchedulerDependentManager):
 
     @exception.wrap_exception(notifier=notifier, publisher_id=publisher_id())
     @reverts_task_state
+    @wrap_instance_event
     @wrap_instance_fault
     def prep_resize(self, context, image, instance, instance_type,
                     reservations=None, request_spec=None,
@@ -2000,6 +2038,7 @@ class ComputeManager(manager.SchedulerDependentManager):
 
     @exception.wrap_exception(notifier=notifier, publisher_id=publisher_id())
     @reverts_task_state
+    @wrap_instance_event
     @wrap_instance_fault
     def resize_instance(self, context, instance, image,
                         reservations=None, migration=None, migration_id=None,
@@ -2133,6 +2172,7 @@ class ComputeManager(manager.SchedulerDependentManager):
 
     @exception.wrap_exception(notifier=notifier, publisher_id=publisher_id())
     @reverts_task_state
+    @wrap_instance_event
     @wrap_instance_fault
     def finish_resize(self, context, disk_info, image, instance,
                       reservations=None, migration=None, migration_id=None):
@@ -2203,6 +2243,7 @@ class ComputeManager(manager.SchedulerDependentManager):
 
     @exception.wrap_exception(notifier=notifier, publisher_id=publisher_id())
     @reverts_task_state
+    @wrap_instance_event
     @wrap_instance_fault
     def pause_instance(self, context, instance):
         """Pause an instance on this host."""
@@ -2220,6 +2261,7 @@ class ComputeManager(manager.SchedulerDependentManager):
 
     @exception.wrap_exception(notifier=notifier, publisher_id=publisher_id())
     @reverts_task_state
+    @wrap_instance_event
     @wrap_instance_fault
     def unpause_instance(self, context, instance):
         """Unpause a paused instance on this host."""
@@ -2268,6 +2310,7 @@ class ComputeManager(manager.SchedulerDependentManager):
 
     @exception.wrap_exception(notifier=notifier, publisher_id=publisher_id())
     @reverts_task_state
+    @wrap_instance_event
     @wrap_instance_fault
     def suspend_instance(self, context, instance):
         """Suspend the given instance."""
@@ -2287,6 +2330,7 @@ class ComputeManager(manager.SchedulerDependentManager):
 
     @exception.wrap_exception(notifier=notifier, publisher_id=publisher_id())
     @reverts_task_state
+    @wrap_instance_event
     @wrap_instance_fault
     def resume_instance(self, context, instance):
         """Resume the given suspended instance."""
diff --git a/nova/compute/utils.py b/nova/compute/utils.py
index 8d363fa1c..0e161327f 100644
--- a/nova/compute/utils.py
+++ b/nova/compute/utils.py
@@ -28,6 +28,7 @@ from nova import notifications
 from nova.openstack.common import cfg
 from nova.openstack.common import log
 from nova.openstack.common.notifier import api as notifier_api
+from nova.openstack.common import timeutils
 from nova import utils
 from nova.virt import driver
 
@@ -64,6 +65,46 @@ def add_instance_fault_from_exc(context, conductor,
     conductor.instance_fault_create(context, values)
 
 
+def pack_action_start(context, instance_uuid, action_name):
+    values = {'action': action_name,
+              'instance_uuid': instance_uuid,
+              'request_id': context.request_id,
+              'user_id': context.user_id,
+              'start_time': context.timestamp}
+    return values
+
+
+def pack_action_finish(context, instance_uuid):
+    values = {'instance_uuid': instance_uuid,
+              'request_id': context.request_id,
+              'finish_time': timeutils.utcnow()}
+    return values
+
+
+def pack_action_event_start(context, instance_uuid, event_name):
+    values = {'event': event_name,
+              'instance_uuid': instance_uuid,
+              'request_id': context.request_id,
+              'start_time': timeutils.utcnow()}
+    return values
+
+
+def pack_action_event_finish(context, instance_uuid, event_name, exc_val=None,
+                             exc_tb=None):
+    values = {'event': event_name,
+              'instance_uuid': instance_uuid,
+              'request_id': context.request_id,
+              'finish_time': timeutils.utcnow()}
+    if exc_tb is None:
+        values['result'] = 'Success'
+    else:
+        values['result'] = 'Error'
+        values['message'] = str(exc_val)
+        values['traceback'] = ''.join(traceback.format_tb(exc_tb))
+
+    return values
+
+
 def get_device_name_for_instance(context, instance, bdms, device):
     """Validates (or generates) a device name for instance.
 
@@ -249,3 +290,28 @@ def usage_volume_info(vol_usage):
                 vol_usage['curr_write_bytes'])
 
     return usage_info
+
+
+class EventReporter(object):
+    """Context manager to report instance action events."""
+
+    def __init__(self, context, conductor, event_name, *instance_uuids):
+        self.context = context
+        self.conductor = conductor
+        self.event_name = event_name
+        self.instance_uuids = instance_uuids
+
+    def __enter__(self):
+        for uuid in self.instance_uuids:
+            event = pack_action_event_start(self.context, uuid,
+                                            self.event_name)
+            self.conductor.action_event_start(self.context, event)
+
+        return self
+
+    def __exit__(self, exc_type, exc_val, exc_tb):
+        for uuid in self.instance_uuids:
+            event = pack_action_event_finish(self.context, uuid,
+                                             self.event_name, exc_val, exc_tb)
+            self.conductor.action_event_finish(self.context, event)
+        return False
diff --git a/nova/conductor/rpcapi.py b/nova/conductor/rpcapi.py
index 248a4e211..ebf41ec57 100644
--- a/nova/conductor/rpcapi.py
+++ b/nova/conductor/rpcapi.py
@@ -300,11 +300,13 @@ class ConductorAPI(nova.openstack.common.rpc.proxy.RpcProxy):
         return self.call(context, msg, version='1.36')
 
     def action_event_start(self, context, values):
-        msg = self.make_msg('action_event_start', values=values)
+        values_p = jsonutils.to_primitive(values)
+        msg = self.make_msg('action_event_start', values=values_p)
         return self.call(context, msg, version='1.25')
 
     def action_event_finish(self, context, values):
-        msg = self.make_msg('action_event_finish', values=values)
+        values_p = jsonutils.to_primitive(values)
+        msg = self.make_msg('action_event_finish', values=values_p)
         return self.call(context, msg, version='1.25')
 
     def instance_info_cache_update(self, context, instance, values):
diff --git a/nova/db/sqlalchemy/api.py b/nova/db/sqlalchemy/api.py
index ad7e4f21f..0ba9ea445 100644
--- a/nova/db/sqlalchemy/api.py
+++ b/nova/db/sqlalchemy/api.py
@@ -4589,6 +4589,7 @@ def instance_fault_get_by_instance_uuids(context, instance_uuids):
 
 
 def action_start(context, values):
+    convert_datetimes(values, 'start_time')
     action_ref = models.InstanceAction()
     action_ref.update(values)
     action_ref.save()
@@ -4596,6 +4597,7 @@ def action_start(context, values):
 
 
 def action_finish(context, values):
+    convert_datetimes(values, 'start_time', 'finish_time')
     session = get_session()
     with session.begin():
         action_ref = model_query(context, models.InstanceAction,
@@ -4643,6 +4645,7 @@ def _action_get_by_request_id(context, instance_uuid, request_id,
 
 def action_event_start(context, values):
     """Start an event on an instance action."""
+    convert_datetimes(values, 'start_time')
     session = get_session()
     with session.begin():
         action = _action_get_by_request_id(context, values['instance_uuid'],
@@ -4663,6 +4666,7 @@ def action_event_start(context, values):
 
 def action_event_finish(context, values):
     """Finish an event on an instance action."""
+    convert_datetimes(values, 'start_time', 'finish_time')
     session = get_session()
     with session.begin():
         action = _action_get_by_request_id(context, values['instance_uuid'],
diff --git a/nova/db/sqlalchemy/models.py b/nova/db/sqlalchemy/models.py
index fd8348678..e91988a95 100644
--- a/nova/db/sqlalchemy/models.py
+++ b/nova/db/sqlalchemy/models.py
@@ -1005,7 +1005,11 @@ class InstanceFault(BASE, NovaBase):
 
 
 class InstanceAction(BASE, NovaBase):
-    """Track client actions on an instance."""
+    """Track client actions on an instance.
+
+    The intention is that there will only be one of these per user request.  A
+    lookup by (instance_uuid, request_id) should always return a single result.
+    """
     __tablename__ = 'instance_actions'
     id = Column(Integer, primary_key=True, nullable=False, autoincrement=True)
     action = Column(String(255))
diff --git a/nova/scheduler/manager.py b/nova/scheduler/manager.py
index e6bf1a293..a129a1b6d 100644
--- a/nova/scheduler/manager.py
+++ b/nova/scheduler/manager.py
@@ -104,22 +104,26 @@ class SchedulerManager(manager.Manager):
         """Tries to call schedule_run_instance on the driver.
         Sets instance vm_state to ERROR on exceptions
         """
-        try:
-            return self.driver.schedule_run_instance(context,
-                    request_spec, admin_password, injected_files,
-                    requested_networks, is_first_time, filter_properties)
-        except exception.NoValidHost as ex:
-            # don't re-raise
-            self._set_vm_state_and_notify('run_instance',
-                                         {'vm_state': vm_states.ERROR,
-                                          'task_state': None},
-                                          context, ex, request_spec)
-        except Exception as ex:
-            with excutils.save_and_reraise_exception():
+        instance_uuids = request_spec['instance_uuids']
+        with compute_utils.EventReporter(context, conductor_api.LocalAPI(),
+                                         'schedule', *instance_uuids):
+            try:
+                return self.driver.schedule_run_instance(context,
+                        request_spec, admin_password, injected_files,
+                        requested_networks, is_first_time, filter_properties)
+
+            except exception.NoValidHost as ex:
+                # don't re-raise
                 self._set_vm_state_and_notify('run_instance',
-                                             {'vm_state': vm_states.ERROR,
+                                              {'vm_state': vm_states.ERROR,
                                               'task_state': None},
-                                             context, ex, request_spec)
+                                              context, ex, request_spec)
+            except Exception as ex:
+                with excutils.save_and_reraise_exception():
+                    self._set_vm_state_and_notify('run_instance',
+                                                  {'vm_state': vm_states.ERROR,
+                                                  'task_state': None},
+                                                  context, ex, request_spec)
 
     def prep_resize(self, context, image, request_spec, filter_properties,
                     instance, instance_type, reservations):
@@ -127,32 +131,35 @@ class SchedulerManager(manager.Manager):
         Sets instance vm_state to ACTIVE on NoHostFound
         Sets vm_state to ERROR on other exceptions
         """
-        try:
-            kwargs = {
-                'context': context,
-                'image': image,
-                'request_spec': request_spec,
-                'filter_properties': filter_properties,
-                'instance': instance,
-                'instance_type': instance_type,
-                'reservations': reservations,
-            }
-            return self.driver.schedule_prep_resize(**kwargs)
-        except exception.NoValidHost as ex:
-            self._set_vm_state_and_notify('prep_resize',
-                                         {'vm_state': vm_states.ACTIVE,
-                                          'task_state': None},
-                                         context, ex, request_spec)
-            if reservations:
-                QUOTAS.rollback(context, reservations)
-        except Exception as ex:
-            with excutils.save_and_reraise_exception():
+        instance_uuid = instance['uuid']
+        with compute_utils.EventReporter(context, conductor_api.LocalAPI(),
+                                         'schedule', instance_uuid):
+            try:
+                kwargs = {
+                    'context': context,
+                    'image': image,
+                    'request_spec': request_spec,
+                    'filter_properties': filter_properties,
+                    'instance': instance,
+                    'instance_type': instance_type,
+                    'reservations': reservations,
+                }
+                return self.driver.schedule_prep_resize(**kwargs)
+            except exception.NoValidHost as ex:
                 self._set_vm_state_and_notify('prep_resize',
-                                             {'vm_state': vm_states.ERROR,
+                                             {'vm_state': vm_states.ACTIVE,
                                               'task_state': None},
                                              context, ex, request_spec)
                 if reservations:
                     QUOTAS.rollback(context, reservations)
+            except Exception as ex:
+                with excutils.save_and_reraise_exception():
+                    self._set_vm_state_and_notify('prep_resize',
+                                                 {'vm_state': vm_states.ERROR,
+                                                  'task_state': None},
+                                                 context, ex, request_spec)
+                    if reservations:
+                        QUOTAS.rollback(context, reservations)
 
     def _set_vm_state_and_notify(self, method, updates, context, ex,
                                  request_spec):
diff --git a/nova/tests/compute/test_compute.py b/nova/tests/compute/test_compute.py
index b5a8b91a2..9985ab351 100644
--- a/nova/tests/compute/test_compute.py
+++ b/nova/tests/compute/test_compute.py
@@ -38,6 +38,7 @@ from nova.compute import rpcapi as compute_rpcapi
 from nova.compute import task_states
 from nova.compute import utils as compute_utils
 from nova.compute import vm_states
+from nova.conductor import manager as conductor_manager
 from nova import context
 from nova import db
 from nova import exception
@@ -59,6 +60,7 @@ from nova import quota
 from nova import test
 from nova.tests.compute import fake_resource_tracker
 from nova.tests.db import fakes as db_fakes
+from nova.tests import fake_instance_actions
 from nova.tests import fake_network
 from nova.tests.image import fake as fake_image
 from nova.tests import matchers
@@ -143,6 +145,7 @@ class BaseTestCase(test.TestCase):
         fake_rpcapi = FakeSchedulerAPI()
         self.stubs.Set(self.compute, 'scheduler_rpcapi', fake_rpcapi)
         fake_network.set_stub_network_methods(self.stubs)
+        fake_instance_actions.stub_out_action_events(self.stubs)
 
         def fake_get_nw_info(cls, ctxt, instance, *args, **kwargs):
             self.assertTrue(ctxt.is_admin)
@@ -287,6 +290,64 @@ class ComputeTestCase(BaseTestCase):
 
         self.assertFalse(called['fault_added'])
 
+    def test_wrap_instance_event(self):
+        inst = {"uuid": "fake_uuid"}
+
+        called = {'started': False,
+                  'finished': False}
+
+        def did_it_update_start(self2, context, values):
+            called['started'] = True
+
+        def did_it_update_finish(self2, context, values):
+            called['finished'] = True
+
+        self.stubs.Set(conductor_manager.ConductorManager,
+                       'action_event_start', did_it_update_start)
+
+        self.stubs.Set(conductor_manager.ConductorManager,
+                       'action_event_finish', did_it_update_finish)
+
+        @compute_manager.wrap_instance_event
+        def fake_event(self, context, instance):
+            pass
+
+        fake_event(self.compute, self.context, instance=inst)
+
+        self.assertTrue(called['started'])
+        self.assertTrue(called['finished'])
+
+    def test_wrap_instance_event_log_exception(self):
+        inst = {"uuid": "fake_uuid"}
+
+        called = {'started': False,
+                  'finished': False,
+                  'message': ''}
+
+        def did_it_update_start(self2, context, values):
+            called['started'] = True
+
+        def did_it_update_finish(self2, context, values):
+            called['finished'] = True
+            called['message'] = values['message']
+
+        self.stubs.Set(conductor_manager.ConductorManager,
+                       'action_event_start', did_it_update_start)
+
+        self.stubs.Set(conductor_manager.ConductorManager,
+                       'action_event_finish', did_it_update_finish)
+
+        @compute_manager.wrap_instance_event
+        def fake_event(self2, context, instance):
+            raise exception.NovaException()
+
+        self.assertRaises(exception.NovaException, fake_event,
+                          self.compute, self.context, instance=inst)
+
+        self.assertTrue(called['started'])
+        self.assertTrue(called['finished'])
+        self.assertEqual('An unknown exception occurred.', called['message'])
+
     def test_create_instance_with_img_ref_associates_config_drive(self):
         # Make sure create associates a config drive.
 
diff --git a/nova/tests/compute/test_compute_utils.py b/nova/tests/compute/test_compute_utils.py
index 4372039e0..970fb0b80 100644
--- a/nova/tests/compute/test_compute_utils.py
+++ b/nova/tests/compute/test_compute_utils.py
@@ -32,6 +32,7 @@ from nova.openstack.common import log as logging
 from nova.openstack.common.notifier import api as notifier_api
 from nova.openstack.common.notifier import test_notifier
 from nova import test
+from nova.tests import fake_instance_actions
 from nova.tests import fake_network
 import nova.tests.image.fake
 
@@ -236,6 +237,7 @@ class UsageInfoTestCase(test.TestCase):
         self.stubs.Set(nova.tests.image.fake._FakeImageService,
                        'show', fake_show)
         fake_network.set_stub_network_methods(self.stubs)
+        fake_instance_actions.stub_out_action_events(self.stubs)
 
     def _create_instance(self, params={}):
         """Create a test instance."""
diff --git a/nova/tests/fake_instance_actions.py b/nova/tests/fake_instance_actions.py
new file mode 100644
index 000000000..1667ac62d
--- /dev/null
+++ b/nova/tests/fake_instance_actions.py
@@ -0,0 +1,30 @@
+# vim: tabstop=4 shiftwidth=4 softtabstop=4
+#
+#    Copyright 2013 OpenStack LLC
+#
+#    Licensed under the Apache License, Version 2.0 (the "License"); you may
+#    not use this file except in compliance with the License. You may obtain
+#    a copy of the License at
+#
+#         http://www.apache.org/licenses/LICENSE-2.0
+#
+#    Unless required by applicable law or agreed to in writing, software
+#    distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+#    WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+#    License for the specific language governing permissions and limitations
+#    under the License.
+
+from nova import db
+
+
+def fake_action_event_start(*args):
+    pass
+
+
+def fake_action_event_finish(*args):
+    pass
+
+
+def stub_out_action_events(stubs):
+    stubs.Set(db, 'action_event_start', fake_action_event_start)
+    stubs.Set(db, 'action_event_finish', fake_action_event_finish)
diff --git a/nova/tests/scheduler/test_scheduler.py b/nova/tests/scheduler/test_scheduler.py
index 142d8ea0e..14be14a1a 100644
--- a/nova/tests/scheduler/test_scheduler.py
+++ b/nova/tests/scheduler/test_scheduler.py
@@ -37,6 +37,7 @@ from nova.scheduler import driver
 from nova.scheduler import manager
 from nova import servicegroup
 from nova import test
+from nova.tests import fake_instance_actions
 from nova.tests import matchers
 from nova.tests.scheduler import fakes
 
@@ -57,6 +58,7 @@ class SchedulerManagerTestCase(test.TestCase):
         self.topic = 'fake_topic'
         self.fake_args = (1, 2, 3)
         self.fake_kwargs = {'cat': 'meow', 'dog': 'woof'}
+        fake_instance_actions.stub_out_action_events(self.stubs)
 
     def test_1_correct_init(self):
         # Correct scheduler driver
@@ -179,8 +181,8 @@ class SchedulerManagerTestCase(test.TestCase):
         self.mox.StubOutWithMock(compute_utils, 'add_instance_fault_from_exc')
         self.mox.StubOutWithMock(db, 'instance_update_and_get_original')
 
-        request_spec = {'instance_properties':
-                {'uuid': fake_instance_uuid}}
+        request_spec = {'instance_properties': inst,
+                        'instance_uuids': [fake_instance_uuid]}
 
         self.manager.driver.schedule_run_instance(self.context,
                 request_spec, None, None, None, None, {}).AndRaise(
@@ -199,6 +201,7 @@ class SchedulerManagerTestCase(test.TestCase):
 
     def test_prep_resize_no_valid_host_back_in_active_state(self):
         fake_instance_uuid = 'fake-instance-id'
+        fake_instance = {'uuid': fake_instance_uuid}
         inst = {"vm_state": "", "task_state": ""}
 
         self._mox_schedule_method_helper('schedule_prep_resize')
@@ -214,7 +217,7 @@ class SchedulerManagerTestCase(test.TestCase):
                 'image': 'fake_image',
                 'request_spec': request_spec,
                 'filter_properties': 'fake_props',
-                'instance': 'fake_instance',
+                'instance': fake_instance,
                 'instance_type': 'fake_type',
                 'reservations': list('fake_res'),
         }
@@ -233,6 +236,7 @@ class SchedulerManagerTestCase(test.TestCase):
 
     def test_prep_resize_exception_host_in_error_state_and_raise(self):
         fake_instance_uuid = 'fake-instance-id'
+        fake_instance = {'uuid': fake_instance_uuid}
 
         self._mox_schedule_method_helper('schedule_prep_resize')
 
@@ -246,7 +250,7 @@ class SchedulerManagerTestCase(test.TestCase):
                 'image': 'fake_image',
                 'request_spec': request_spec,
                 'filter_properties': 'fake_props',
-                'instance': 'fake_instance',
+                'instance': fake_instance,
                 'instance_type': 'fake_type',
                 'reservations': list('fake_res'),
         }
diff --git a/nova/tests/test_db_api.py b/nova/tests/test_db_api.py
index 684f9fded..4bec55030 100644
--- a/nova/tests/test_db_api.py
+++ b/nova/tests/test_db_api.py
@@ -721,6 +721,34 @@ class DbApiTestCase(test.TestCase):
         self.assertEqual(start_time, events[0]['start_time'])
         self.assertEqual(finish_time, events[0]['finish_time'])
 
+    def test_instance_action_and_event_start_string_time(self):
+        """Create an instance action and event with a string start_time."""
+        ctxt = context.get_admin_context()
+        uuid = str(stdlib_uuid.uuid4())
+
+        start_time = timeutils.utcnow()
+        start_time_str = timeutils.strtime(start_time)
+        action_values = {'action': 'run_instance',
+                         'instance_uuid': uuid,
+                         'request_id': ctxt.request_id,
+                         'user_id': ctxt.user_id,
+                         'project_id': ctxt.project_id,
+                         'start_time': start_time_str}
+        action = db.action_start(ctxt, action_values)
+
+        event_values = {'event': 'schedule',
+                        'instance_uuid': uuid,
+                        'request_id': ctxt.request_id,
+                        'start_time': start_time_str}
+        db.action_event_start(ctxt, event_values)
+
+        # Retrieve the event to ensure it was successfully added
+        events = db.action_events_get(ctxt, action['id'])
+        self.assertEqual(1, len(events))
+        self.assertEqual('schedule', events[0]['event'])
+        # db api still returns models with datetime, not str, values
+        self.assertEqual(start_time, events[0]['start_time'])
+
     def test_instance_action_event_get_by_id(self):
         """Get a specific instance action event."""
         ctxt1 = context.get_admin_context()
diff --git a/nova/tests/test_utils.py b/nova/tests/test_utils.py
index 84d56cadf..ddbb185a6 100644
--- a/nova/tests/test_utils.py
+++ b/nova/tests/test_utils.py
@@ -16,6 +16,7 @@
 
 import __builtin__
 import datetime
+import functools
 import hashlib
 import os
 import os.path
@@ -789,3 +790,137 @@ class MetadataToDictTestCase(test.TestCase):
 
     def test_metadata_to_dict_empty(self):
         self.assertEqual(utils.metadata_to_dict([]), {})
+
+
+class WrappedCodeTestCase(test.TestCase):
+    """Test the get_wrapped_function utility method."""
+
+    def _wrapper(self, function):
+        @functools.wraps(function)
+        def decorated_function(self, *args, **kwargs):
+            function(self, *args, **kwargs)
+        return decorated_function
+
+    def test_single_wrapped(self):
+        @self._wrapper
+        def wrapped(self, instance, red=None, blue=None):
+            pass
+
+        func = utils.get_wrapped_function(wrapped)
+        func_code = func.func_code
+        self.assertEqual(4, len(func_code.co_varnames))
+        self.assertTrue('self' in func_code.co_varnames)
+        self.assertTrue('instance' in func_code.co_varnames)
+        self.assertTrue('red' in func_code.co_varnames)
+        self.assertTrue('blue' in func_code.co_varnames)
+
+    def test_double_wrapped(self):
+        @self._wrapper
+        @self._wrapper
+        def wrapped(self, instance, red=None, blue=None):
+            pass
+
+        func = utils.get_wrapped_function(wrapped)
+        func_code = func.func_code
+        self.assertEqual(4, len(func_code.co_varnames))
+        self.assertTrue('self' in func_code.co_varnames)
+        self.assertTrue('instance' in func_code.co_varnames)
+        self.assertTrue('red' in func_code.co_varnames)
+        self.assertTrue('blue' in func_code.co_varnames)
+
+    def test_triple_wrapped(self):
+        @self._wrapper
+        @self._wrapper
+        @self._wrapper
+        def wrapped(self, instance, red=None, blue=None):
+            pass
+
+        func = utils.get_wrapped_function(wrapped)
+        func_code = func.func_code
+        self.assertEqual(4, len(func_code.co_varnames))
+        self.assertTrue('self' in func_code.co_varnames)
+        self.assertTrue('instance' in func_code.co_varnames)
+        self.assertTrue('red' in func_code.co_varnames)
+        self.assertTrue('blue' in func_code.co_varnames)
+
+
+class GetCallArgsTestCase(test.TestCase):
+    def _test_func(self, instance, red=None, blue=None):
+        pass
+
+    def test_all_kwargs(self):
+        args = ()
+        kwargs = {'instance': {'uuid': 1}, 'red': 3, 'blue': 4}
+        callargs = utils.getcallargs(self._test_func, *args, **kwargs)
+        #implicit self counts as an arg
+        self.assertEqual(4, len(callargs))
+        self.assertTrue('instance' in callargs)
+        self.assertEqual({'uuid': 1}, callargs['instance'])
+        self.assertTrue('red' in callargs)
+        self.assertEqual(3, callargs['red'])
+        self.assertTrue('blue' in callargs)
+        self.assertEqual(4, callargs['blue'])
+
+    def test_all_args(self):
+        args = ({'uuid': 1}, 3, 4)
+        kwargs = {}
+        callargs = utils.getcallargs(self._test_func, *args, **kwargs)
+        #implicit self counts as an arg
+        self.assertEqual(4, len(callargs))
+        self.assertTrue('instance' in callargs)
+        self.assertEqual({'uuid': 1}, callargs['instance'])
+        self.assertTrue('red' in callargs)
+        self.assertEqual(3, callargs['red'])
+        self.assertTrue('blue' in callargs)
+        self.assertEqual(4, callargs['blue'])
+
+    def test_mixed_args(self):
+        args = ({'uuid': 1}, 3)
+        kwargs = {'blue': 4}
+        callargs = utils.getcallargs(self._test_func, *args, **kwargs)
+        #implicit self counts as an arg
+        self.assertEqual(4, len(callargs))
+        self.assertTrue('instance' in callargs)
+        self.assertEqual({'uuid': 1}, callargs['instance'])
+        self.assertTrue('red' in callargs)
+        self.assertEqual(3, callargs['red'])
+        self.assertTrue('blue' in callargs)
+        self.assertEqual(4, callargs['blue'])
+
+    def test_partial_kwargs(self):
+        args = ()
+        kwargs = {'instance': {'uuid': 1}, 'red': 3}
+        callargs = utils.getcallargs(self._test_func, *args, **kwargs)
+        #implicit self counts as an arg
+        self.assertEqual(4, len(callargs))
+        self.assertTrue('instance' in callargs)
+        self.assertEqual({'uuid': 1}, callargs['instance'])
+        self.assertTrue('red' in callargs)
+        self.assertEqual(3, callargs['red'])
+        self.assertTrue('blue' in callargs)
+        self.assertEqual(None, callargs['blue'])
+
+    def test_partial_args(self):
+        args = ({'uuid': 1}, 3)
+        kwargs = {}
+        callargs = utils.getcallargs(self._test_func, *args, **kwargs)
+        #implicit self counts as an arg
+        self.assertEqual(4, len(callargs))
+        self.assertTrue('instance' in callargs)
+        self.assertEqual({'uuid': 1}, callargs['instance'])
+        self.assertTrue('red' in callargs)
+        self.assertEqual(3, callargs['red'])
+        self.assertTrue('blue' in callargs)
+        self.assertEqual(None, callargs['blue'])
+
+    def test_partial_mixed_args(self):
+        args = (3,)
+        kwargs = {'instance': {'uuid': 1}}
+        callargs = utils.getcallargs(self._test_func, *args, **kwargs)
+        self.assertEqual(4, len(callargs))
+        self.assertTrue('instance' in callargs)
+        self.assertEqual({'uuid': 1}, callargs['instance'])
+        self.assertTrue('red' in callargs)
+        self.assertEqual(3, callargs['red'])
+        self.assertTrue('blue' in callargs)
+        self.assertEqual(None, callargs['blue'])
diff --git a/nova/utils.py b/nova/utils.py
index 83bf55583..21b670e8b 100644
--- a/nova/utils.py
+++ b/nova/utils.py
@@ -1293,3 +1293,57 @@ def metadata_to_dict(metadata):
     for item in metadata:
         result[item['key']] = item['value']
     return result
+
+
+def get_wrapped_function(function):
+    """Get the method at the bottom of a stack of decorators."""
+    if not hasattr(function, 'func_closure') or not function.func_closure:
+        return function
+
+    def _get_wrapped_function(function):
+        if not hasattr(function, 'func_closure') or not function.func_closure:
+            return None
+
+        for closure in function.func_closure:
+            func = closure.cell_contents
+
+            deeper_func = _get_wrapped_function(func)
+            if deeper_func:
+                return deeper_func
+            elif hasattr(closure.cell_contents, '__call__'):
+                return closure.cell_contents
+
+    return _get_wrapped_function(function)
+
+
+def getcallargs(function, *args, **kwargs):
+    """This is a simplified inspect.getcallargs (2.7+).
+
+    It should be replaced when python >= 2.7 is standard.
+    """
+    keyed_args = {}
+    argnames, varargs, keywords, defaults = inspect.getargspec(function)
+
+    keyed_args.update(kwargs)
+
+    #NOTE(alaski) the implicit 'self' or 'cls' argument shows up in
+    # argnames but not in args or kwargs.  Uses 'in' rather than '==' because
+    # some tests use 'self2'.
+    if 'self' in argnames[0] or 'cls' == argnames[0]:
+        # The function may not actually be a method or have im_self.
+        # Typically seen when it's stubbed with mox.
+        if inspect.ismethod(function) and hasattr(function, 'im_self'):
+            keyed_args[argnames[0]] = function.im_self
+        else:
+            keyed_args[argnames[0]] = None
+
+    remaining_argnames = filter(lambda x: x not in keyed_args, argnames)
+    keyed_args.update(dict(zip(remaining_argnames, args)))
+
+    if defaults:
+        num_defaults = len(defaults)
+        for argname, value in zip(argnames[-num_defaults:], defaults):
+            if argname not in keyed_args:
+                keyed_args[argname] = value
+
+    return keyed_args