Adjusted audit logging for taskmanager module

The taskmanager module audit log messages are unclear, some debug
messages are supposed to be info and vice versa.

Changed logging of various messages to conform to standard.

Change-Id: Idaa46b67096c1fbbacdf730c06c823aaf3e1e255
Partial-Bug: #1324206
This commit is contained in:
Simon Chang 2014-07-18 09:54:32 -04:00
parent accce2ced3
commit b5fc1a5519
2 changed files with 97 additions and 85 deletions

View File

@ -134,7 +134,7 @@ class API(proxy.RpcProxy):
overrides=overrides))
def update_overrides(self, instance_id, overrides=None):
LOG.debug("Making async call to update configuration overrides for "
LOG.debug("Making async call to update datastore configurations for "
"instance %s" % instance_id)
self.cast(self.context,
@ -143,7 +143,7 @@ class API(proxy.RpcProxy):
overrides=overrides))
def unassign_configuration(self, instance_id, flavor, configuration_id):
LOG.debug("Making async call to unassign configuration for "
LOG.debug("Making async call to remove datastore configurations for "
"instance %s" % instance_id)
self.cast(self.context,

178
trove/taskmanager/models.py Normal file → Executable file
View File

@ -167,7 +167,7 @@ class FreshInstanceTasks(FreshInstance, NotifyMixin, ConfigurationMixin):
backup_id, availability_zone, root_password, nics,
overrides):
LOG.debug("begin create_instance for id: %s" % self.id)
LOG.info(_("Creating instance %s.") % self.id)
security_groups = None
# If security group support is enabled and heat based instance
@ -259,16 +259,17 @@ class FreshInstanceTasks(FreshInstance, NotifyMixin, ConfigurationMixin):
utils.poll_until(self._service_is_active,
sleep_time=USAGE_SLEEP_TIME,
time_out=usage_timeout)
LOG.info(_("Created instance %s successfully.") % self.id)
self.send_usage_event('create', instance_size=flavor['ram'])
except PollTimeOut:
LOG.error(_("Timeout for service changing to active. "
"No usage create-event sent."))
LOG.error(_("Failed to create instance %s. "
"Timeout waiting for instance to become active. "
"No usage create-event was sent.") % self.id)
self.update_statuses_on_time_out()
except Exception:
LOG.exception(_("Error during create-event call."))
LOG.debug("end create_instance for id: %s" % self.id)
LOG.exception(_("Failed to send usage create-event for "
"instance %s.") % self.id)
def report_root_enabled(self):
mysql_models.RootHistory.create(self.context, self.id, 'root')
@ -328,7 +329,7 @@ class FreshInstanceTasks(FreshInstance, NotifyMixin, ConfigurationMixin):
def _create_server_volume(self, flavor_id, image_id, security_groups,
datastore_manager, volume_size,
availability_zone, nics):
LOG.debug("begin _create_server_volume for id: %s" % self.id)
LOG.debug("Begin _create_server_volume for id: %s" % self.id)
try:
files = {"/etc/guest_info": ("[DEFAULT]\n--guest_id="
"%s\n--datastore_manager=%s\n"
@ -361,14 +362,14 @@ class FreshInstanceTasks(FreshInstance, NotifyMixin, ConfigurationMixin):
except Exception as e:
msg = _("Error creating server and volume for "
"instance %s") % self.id
LOG.debug("end _create_server_volume for id: %s" % self.id)
LOG.debug("End _create_server_volume for id: %s" % self.id)
err = inst_models.InstanceTasks.BUILDING_ERROR_SERVER
self._log_and_raise(e, msg, err)
device_path = self.device_path
mount_point = CONF.get(datastore_manager).mount_point
volume_info = {'device_path': device_path, 'mount_point': mount_point}
LOG.debug("end _create_server_volume for id: %s" % self.id)
LOG.debug("End _create_server_volume for id: %s" % self.id)
return volume_info
def _build_sg_rules_mapping(self, rule_ports):
@ -384,7 +385,7 @@ class FreshInstanceTasks(FreshInstance, NotifyMixin, ConfigurationMixin):
def _create_server_volume_heat(self, flavor, image_id,
datastore_manager,
volume_size, availability_zone, nics):
LOG.debug("begin _create_server_volume_heat for id: %s" % self.id)
LOG.debug("Begin _create_server_volume_heat for id: %s" % self.id)
try:
client = create_heat_client(self.context)
tcp_rules_mapping_list = self._build_sg_rules_mapping(CONF.get(
@ -403,8 +404,7 @@ class FreshInstanceTasks(FreshInstance, NotifyMixin, ConfigurationMixin):
try:
heat_template = heat_template_unicode.encode('utf-8')
except UnicodeEncodeError:
LOG.error(_("heat template ascii encode issue"))
raise TroveError("heat template ascii encode issue")
raise TroveError("Failed to utf-8 encode Heat template.")
parameters = {"Flavor": flavor["name"],
"VolumeSize": volume_size,
@ -425,23 +425,23 @@ class FreshInstanceTasks(FreshInstance, NotifyMixin, ConfigurationMixin):
sleep_time=USAGE_SLEEP_TIME,
time_out=HEAT_TIME_OUT)
except PollTimeOut:
LOG.error(_("Timeout during stack status tracing"))
raise TroveError("Timeout occurred in tracking stack status")
raise TroveError("Failed to obtain Heat stack status. "
"Timeout occurred.")
stack = client.stacks.get(stack_name)
if ((stack.action, stack.stack_status)
not in HEAT_STACK_SUCCESSFUL_STATUSES):
raise TroveError("Heat Stack Create Failed.")
raise TroveError("Failed to create Heat stack.")
resource = client.resources.get(stack.id, 'BaseInstance')
if resource.resource_status != HEAT_RESOURCE_SUCCESSFUL_STATE:
raise TroveError("Heat Resource Provisioning Failed.")
raise TroveError("Failed to provision Heat base instance.")
instance_id = resource.physical_resource_id
if self.volume_support:
resource = client.resources.get(stack.id, 'DataVolume')
if resource.resource_status != HEAT_RESOURCE_SUCCESSFUL_STATE:
raise TroveError("Heat Resource Provisioning Failed.")
raise TroveError("Failed to provision Heat data volume.")
volume_id = resource.physical_resource_id
self.update_db(compute_instance_id=instance_id,
volume_id=volume_id)
@ -464,8 +464,8 @@ class FreshInstanceTasks(FreshInstance, NotifyMixin, ConfigurationMixin):
except (TroveError, heat_exceptions.HTTPNotFound,
heat_exceptions.HTTPException) as e:
msg = "Error during creating stack for instance %s" % self.id
LOG.debug(msg)
msg = _("Error occurred during Heat stack creation for "
"instance %s.") % self.id
err = inst_models.InstanceTasks.BUILDING_ERROR_SERVER
self._log_and_raise(e, msg, err)
@ -473,14 +473,14 @@ class FreshInstanceTasks(FreshInstance, NotifyMixin, ConfigurationMixin):
mount_point = CONF.get(datastore_manager).mount_point
volume_info = {'device_path': device_path, 'mount_point': mount_point}
LOG.debug("end _create_server_volume_heat for id: %s" % self.id)
LOG.debug("End _create_server_volume_heat for id: %s" % self.id)
return volume_info
def _create_server_volume_individually(self, flavor_id, image_id,
security_groups, datastore_manager,
volume_size,
availability_zone, nics):
LOG.debug("begin _create_server_volume_individually for id: %s" %
LOG.debug("Begin _create_server_volume_individually for id: %s" %
self.id)
server = None
volume_info = self._build_volume_info(datastore_manager,
@ -495,10 +495,10 @@ class FreshInstanceTasks(FreshInstance, NotifyMixin, ConfigurationMixin):
# Save server ID.
self.update_db(compute_instance_id=server_id)
except Exception as e:
msg = _("Error creating server for instance %s") % self.id
msg = _("Failed to create server for instance %s") % self.id
err = inst_models.InstanceTasks.BUILDING_ERROR_SERVER
self._log_and_raise(e, msg, err)
LOG.debug("end _create_server_volume_individually for id: %s" %
LOG.debug("End _create_server_volume_individually for id: %s" %
self.id)
return volume_info
@ -513,7 +513,7 @@ class FreshInstanceTasks(FreshInstance, NotifyMixin, ConfigurationMixin):
volume_info = self._create_volume(
volume_size, datastore_manager)
except Exception as e:
msg = _("Error provisioning volume for instance: %s") % self.id
msg = _("Failed to create volume for instance %s") % self.id
err = inst_models.InstanceTasks.BUILDING_ERROR_VOLUME
self._log_and_raise(e, msg, err)
else:
@ -535,8 +535,7 @@ class FreshInstanceTasks(FreshInstance, NotifyMixin, ConfigurationMixin):
raise TroveError(message=message)
def _create_volume(self, volume_size, datastore_manager):
LOG.info("Entering create_volume")
LOG.debug("begin _create_volume for id: %s" % self.id)
LOG.debug("Begin _create_volume for id: %s" % self.id)
volume_client = create_cinder_client(self.context)
volume_desc = ("datastore volume for %s" % self.id)
volume_ref = volume_client.volumes.create(
@ -555,7 +554,7 @@ class FreshInstanceTasks(FreshInstance, NotifyMixin, ConfigurationMixin):
v_ref = volume_client.volumes.get(volume_ref.id)
if v_ref.status in ['error']:
raise VolumeCreationFailure()
LOG.debug("end _create_volume for id: %s" % self.id)
LOG.debug("End _create_volume for id: %s" % self.id)
return self._build_volume(v_ref, datastore_manager)
def _build_volume(self, v_ref, datastore_manager):
@ -609,7 +608,7 @@ class FreshInstanceTasks(FreshInstance, NotifyMixin, ConfigurationMixin):
availability_zone=availability_zone, nics=nics,
config_drive=config_drive)
LOG.debug("Created new compute instance %(server_id)s "
"for id: %(id)s" %
"for instance %(id)s" %
{'server_id': server.id, 'id': self.id})
return server
@ -617,7 +616,6 @@ class FreshInstanceTasks(FreshInstance, NotifyMixin, ConfigurationMixin):
packages, databases, users, backup_info=None,
config_contents=None, root_password=None,
overrides=None):
LOG.info(_("Entering guest_prepare"))
# Now wait for the response from the create to do additional work
self.guest.prepare(flavor_ram, packages, databases, users,
device_path=volume_info['device_path'],
@ -641,8 +639,7 @@ class FreshInstanceTasks(FreshInstance, NotifyMixin, ConfigurationMixin):
return self.nova_client.servers.get(c_id)
def ip_is_available(server):
LOG.info(_("Polling for ip addresses: $%s ") %
server.addresses)
LOG.debug("Polling for ip addresses: $%s " % server.addresses)
if server.addresses != {}:
return True
elif (server.addresses == {} and
@ -650,9 +647,9 @@ class FreshInstanceTasks(FreshInstance, NotifyMixin, ConfigurationMixin):
return False
elif (server.addresses == {} and
server.status == InstanceStatus.ERROR):
LOG.error(_("Instance IP not available, "
"instance (%(instance)s): "
"server had status (%(status)s).") %
LOG.error(_("Failed to create DNS entry for instance "
"%(instance)s. Server status was "
"%(status)s).") %
{'instance': self.id, 'status': server.status})
raise TroveError(status=server.status)
@ -661,10 +658,11 @@ class FreshInstanceTasks(FreshInstance, NotifyMixin, ConfigurationMixin):
server = self.nova_client.servers.get(
self.db_info.compute_instance_id)
self.db_info.addresses = server.addresses
LOG.info(_("Creating dns entry..."))
LOG.debug(_("Creating dns entry..."))
ip = self.dns_ip_address
if not ip:
raise TroveError('Error creating DNS. No IP available.')
raise TroveError("Failed to create DNS entry for instance %s. "
"No IP available." % self.id)
dns_client.create_instance_entry(self.id, ip)
else:
LOG.debug("%(gt)s: DNS not enabled for instance: %(id)s" %
@ -681,14 +679,15 @@ class FreshInstanceTasks(FreshInstance, NotifyMixin, ConfigurationMixin):
def _create_rules(self, s_group, ports, protocol):
err = inst_models.InstanceTasks.BUILDING_ERROR_SEC_GROUP
err_msg = _("Error creating security group rules."
" Invalid port format. "
err_msg = _("Failed to create security group rules for instance "
"%(instance_id)s: Invalid port format - "
"FromPort = %(from)s, ToPort = %(to)s")
def set_error_and_raise(port_or_range):
from_port, to_port = port_or_range
self.update_db(task_status=err)
msg = err_msg % {'from': from_port, 'to': to_port}
msg = err_msg % {'instance_id': self.id, 'from': from_port,
'to': to_port}
raise MalformedSecurityGroupRuleError(message=msg)
for port_or_range in set(ports):
@ -730,7 +729,7 @@ class BuiltInstanceTasks(BuiltInstance, NotifyMixin, ConfigurationMixin):
"""
def _delete_resources(self, deleted_at):
LOG.debug("begin _delete_resources for id: %s" % self.id)
LOG.debug("Begin _delete_resources for instance %s" % self.id)
server_id = self.db_info.compute_instance_id
old_server = self.nova_client.servers.get(server_id)
try:
@ -754,14 +753,14 @@ class BuiltInstanceTasks(BuiltInstance, NotifyMixin, ConfigurationMixin):
LOG.exception(_("Error during dns entry of instance %(id)s: "
"%(ex)s") % {'id': self.db_info.id, 'ex': ex})
# Poll until the server is gone.
# Poll until the server is gone.
def server_is_finished():
try:
server = self.nova_client.servers.get(server_id)
if not self.server_status_matches(['SHUTDOWN', 'ACTIVE'],
server=server):
LOG.error(_("Server %(server_id)s got into ERROR status "
"during delete of instance %(instance_id)s!") %
LOG.error(_("Server %(server_id)s entered ERROR status "
"when deleting instance %(instance_id)s!") %
{'server_id': server.id, 'instance_id': self.id})
return False
except nova_exceptions.NotFound:
@ -771,12 +770,14 @@ class BuiltInstanceTasks(BuiltInstance, NotifyMixin, ConfigurationMixin):
utils.poll_until(server_is_finished, sleep_time=2,
time_out=CONF.server_delete_time_out)
except PollTimeOut:
LOG.exception(_("Timout during nova server delete of server: %s") %
server_id)
LOG.exception(_("Failed to delete instance %(instance_id)s: "
"Timeout deleting compute server %(server_id)s") %
{'instance_id': self.id, 'server_id': server_id})
self.send_usage_event('delete',
deleted_at=timeutils.isotime(deleted_at),
server=old_server)
LOG.debug("end _delete_resources for id: %s" % self.id)
LOG.debug("End _delete_resources for instance %s" % self.id)
def server_status_matches(self, expected_status, server=None):
if not server:
@ -785,29 +786,37 @@ class BuiltInstanceTasks(BuiltInstance, NotifyMixin, ConfigurationMixin):
status.upper() for status in expected_status)
def resize_volume(self, new_size):
LOG.debug("begin resize_volume for instance: %s" % self.id)
LOG.info(_("Resizing volume for instance %(instance_id)s from "
"%(old_size)s GB to %(new_size)s GB.") %
{'instance_id': self.id, 'old_size': self.volume_size,
'new_size': new_size})
action = ResizeVolumeAction(self, self.volume_size, new_size)
action.execute()
LOG.debug("end resize_volume for instance: %s" % self.id)
LOG.info(_("Resized volume for instance %s successfully.") % self.id)
def resize_flavor(self, old_flavor, new_flavor):
LOG.info(_("Resizing instance %(instance_id)s from flavor "
"%(old_flavor)s to %(new_flavor)s.") %
{'instance_id': self.id, 'old_flavor': old_flavor['id'],
'new_flavor': new_flavor['id']})
action = ResizeAction(self, old_flavor, new_flavor)
action.execute()
LOG.info(_("Resized instance %s successfully.") % self.id)
def migrate(self, host):
LOG.debug("Calling migrate with host(%s)..." % host)
LOG.info(_("Initiating migration to host %s.") % host)
action = MigrateAction(self, host)
action.execute()
def create_backup(self, backup_info):
LOG.debug("Calling create_backup %s " % self.id)
LOG.info(_("Initiating backup for instance %s.") % self.id)
self.guest.create_backup(backup_info)
def reboot(self):
try:
LOG.debug("Instance %s calling stop_db..." % self.id)
LOG.debug("Stopping datastore on instance %s." % self.id)
self.guest.stop_db()
LOG.debug("Rebooting instance %s" % self.id)
LOG.info(_("Rebooting instance %s.") % self.id)
self.server.reboot()
# Poll nova until instance is active
@ -825,29 +834,27 @@ class BuiltInstanceTasks(BuiltInstance, NotifyMixin, ConfigurationMixin):
# Set the status to PAUSED. The guest agent will reset the status
# when the reboot completes and MySQL is running.
self.set_datastore_status_to_paused()
LOG.debug("Successfully rebooted instance %s" % self.id)
LOG.info(_("Rebooted instance %s successfully.") % self.id)
except Exception as e:
LOG.error(_("Failed to reboot instance %(id)s: %(e)s") %
{'id': self.id, 'e': str(e)})
finally:
LOG.debug("Rebooting FINALLY %s" % self.id)
LOG.debug("Rebooting FINALLY %s" % self.id)
self.reset_task_status()
def restart(self):
LOG.debug("Restarting datastore on instance %s " % self.id)
LOG.info(_("Initiating datastore restart on instance %s.") % self.id)
try:
self.guest.restart()
LOG.debug("Restarting datastore successful %s " % self.id)
except GuestError:
LOG.error(_("Failure to restart datastore for instance %s.") %
self.id)
LOG.error(_("Failed to initiate datastore restart on instance "
"%s.") % self.id)
finally:
LOG.debug("Restarting complete on instance %s " % self.id)
self.reset_task_status()
def update_overrides(self, overrides, remove=False):
LOG.debug("Updating configuration overrides on instance %s"
% self.id)
LOG.info(_("Initiating datastore configurations update on instance "
"%s.") % self.id)
LOG.debug("overrides: %s" % overrides)
LOG.debug("self.ds_version: %s" % self.ds_version.__dict__)
# todo(cp16net) How do we know what datastore type we have?
@ -867,19 +874,19 @@ class BuiltInstanceTasks(BuiltInstance, NotifyMixin, ConfigurationMixin):
self.guest.update_overrides(config_overrides.config_contents,
remove=remove)
self.guest.apply_overrides(overrides)
LOG.debug("Configuration overrides update successful.")
except GuestError:
LOG.error(_("Failed to update configuration overrides."))
LOG.error(_("Failed to initiate datastore configurations update "
"on instance %s.") % self.id)
def unassign_configuration(self, flavor, configuration_id):
LOG.debug("Unassigning the configuration from the instance %s"
% self.id)
LOG.debug("Unassigning the configuration id %s"
% self.configuration.id)
LOG.info(_("Initiating configuration group %(config_id)s removal from "
"instance %(instance_id)s.")
% {'config_id': configuration_id,
'instance_id': self.id})
def _find_item(items, item_name):
LOG.debug("items: %s" % items)
LOG.debug("item_name: %s" % item_name)
LOG.debug("Searching for %(item_name)s in %(items)s" %
{'item_name': item_name, 'items': items})
# find the item in the list
for i in items:
if i[0] == item_name:
@ -969,25 +976,26 @@ class BackupTasks(object):
cont, prefix = cls._parse_manifest(manifest)
if all([cont, prefix]):
# This is a manifest file, first delete all segments.
LOG.info(_("Deleting files with prefix: %(cont)s/%(prefix)s") %
{'cont': cont, 'prefix': prefix})
LOG.debug("Deleting files with prefix: %(cont)s/%(prefix)s" %
{'cont': cont, 'prefix': prefix})
# list files from container/prefix specified by manifest
headers, segments = client.get_container(cont, prefix=prefix)
LOG.debug(headers)
for segment in segments:
name = segment.get('name')
if name:
LOG.info(_("Deleting file: %(cont)s/%(name)s") %
{'cont': cont, 'name': name})
LOG.debug("Deleting file: %(cont)s/%(name)s" %
{'cont': cont, 'name': name})
client.delete_object(cont, name)
# Delete the manifest file
LOG.info(_("Deleting file: %(cont)s/%(filename)s") %
{'cont': cont, 'filename': filename})
LOG.debug("Deleting file: %(cont)s/%(filename)s" %
{'cont': cont, 'filename': filename})
client.delete_object(container, filename)
@classmethod
def delete_backup(cls, context, backup_id):
#delete backup from swift
LOG.info(_("Deleting backup %s.") % backup_id)
backup = bkup_models.Backup.get_by_id(context, backup_id)
try:
filename = backup.filename
@ -1000,13 +1008,15 @@ class BackupTasks(object):
# Backup already deleted in swift
backup.delete()
else:
LOG.exception(_("Exception deleting from swift. "
LOG.exception(_("Error occurred when deleting from swift. "
"Details: %s") % e)
backup.state = bkup_models.BackupState.DELETE_FAILED
backup.save()
raise TroveError("Failed to delete swift objects")
raise TroveError("Failed to delete swift object for backup %s."
% backup_id)
else:
backup.delete()
LOG.info(_("Deleted backup %s successfully.") % backup_id)
class ResizeVolumeAction(object):
@ -1193,7 +1203,7 @@ class ResizeVolumeAction(object):
raise
def _resize_active_volume(self):
LOG.debug("begin _resize_active_volume for id: %(id)s" % {
LOG.debug("Begin _resize_active_volume for id: %(id)s" % {
'id': self.instance.id})
self._stop_db()
self._unmount_volume(recover_func=self._recover_restart)
@ -1205,7 +1215,7 @@ class ResizeVolumeAction(object):
self._resize_fs(recover_func=self._fail)
self._mount_volume(recover_func=self._fail)
self.instance.restart()
LOG.debug("end _resize_active_volume for id: %(id)s" % {
LOG.debug("End _resize_active_volume for id: %(id)s" % {
'id': self.instance.id})
def execute(self):
@ -1232,9 +1242,11 @@ class ResizeVolumeAction(object):
volume_size=volume.size)
else:
self.instance.reset_task_status()
msg = _("Volume resize failed for instance %(id)s. The instance "
"must be in state %(state)s not %(inst_state)s.") % {
msg = _("Failed to resize instance %(id)s volume for server "
"%(server_id)s. The instance must be in state %(state)s "
"not %(inst_state)s.") % {
'id': self.instance.id,
'server_id': self.instance.server.id,
'state': InstanceStatus.ACTIVE,
'inst_state': self.instance.server.status}
raise TroveError(msg)
@ -1334,7 +1346,7 @@ class ResizeActionBase(object):
def _perform_nova_action(self):
"""Calls Nova to resize or migrate an instance, and confirms."""
LOG.debug("begin resize method _perform_nova_action instance: %s" %
LOG.debug("Begin resize method _perform_nova_action instance: %s" %
self.instance.id)
need_to_revert = False
try:
@ -1372,7 +1384,7 @@ class ResizeActionBase(object):
LOG.debug("Recording success")
self._record_action_success()
LOG.debug("end resize method _perform_nova_action instance: %s" %
LOG.debug("End resize method _perform_nova_action instance: %s" %
self.instance.id)
def _wait_for_nova_action(self):