Logging audit for trove/guestagent module

Adjust logging to conform to logging standards. Found
and fixed a pattern of not logging exception information.
Cleaned up some messages that were unclear.

Also addressed a pattern of having exception's using
LOG.error to log the exception (rather than using
LOG.exception).

Change-Id: Idab510051321f4f9ed096c9972322530028ad2e6
Partial-Bug: #1324206
This commit is contained in:
Amrith Kumar 2014-07-17 10:45:27 -04:00
parent 5f98abb9df
commit b668e85cb6
6 changed files with 74 additions and 60 deletions

View File

@ -27,6 +27,7 @@ from trove.openstack.common import rpc
from trove.openstack.common import log as logging
from trove.openstack.common.rpc import proxy
from trove.openstack.common.rpc import common
from trove.openstack.common.gettextutils import _
CONF = cfg.CONF
LOG = logging.getLogger(__name__)
@ -45,34 +46,34 @@ class API(proxy.RpcProxy):
RPC_API_VERSION)
def _call(self, method_name, timeout_sec, **kwargs):
LOG.debug("Calling %s with timeout %s" % (method_name, timeout_sec))
LOG.debug("Calling %s with timeout %s." % (method_name, timeout_sec))
try:
result = self.call(self.context,
self.make_msg(method_name, **kwargs),
timeout=timeout_sec)
LOG.debug("Result is %s" % result)
LOG.debug("Result is %s." % result)
return result
except common.RemoteError as r:
LOG.error(r)
LOG.exception(_("Error calling %s") % method_name)
raise exception.GuestError(original_message=r.value)
except Exception as e:
LOG.error(e)
LOG.exception(_("Error calling %s") % method_name)
raise exception.GuestError(original_message=str(e))
except Timeout:
raise exception.GuestTimeout()
def _cast(self, method_name, **kwargs):
LOG.debug("Casting %s" % method_name)
LOG.debug("Casting %s." % method_name)
try:
self.cast(self.context, self.make_msg(method_name, **kwargs),
topic=kwargs.get('topic'),
version=kwargs.get('version'))
except common.RemoteError as r:
LOG.error(r)
LOG.exception(_("Error calling %s") % method_name)
raise exception.GuestError(original_message=r.value)
except Exception as e:
LOG.error(e)
LOG.exception(_("Error calling %s") % method_name)
raise exception.GuestError(original_message=str(e))
def _cast_with_consumer(self, method_name, **kwargs):
@ -81,10 +82,10 @@ class API(proxy.RpcProxy):
conn = rpc.create_connection(new=True)
conn.create_consumer(self._get_routing_key(), None, fanout=False)
except common.RemoteError as r:
LOG.error(r)
LOG.exception(_("Error calling %s") % method_name)
raise exception.GuestError(original_message=r.value)
except Exception as e:
LOG.error(e)
LOG.exception(_("Error calling %s") % method_name)
raise exception.GuestError(original_message=str(e))
finally:
if conn:
@ -117,31 +118,31 @@ class API(proxy.RpcProxy):
"""Make an asynchronous call to change the passwords of one or more
users.
"""
LOG.debug("Changing passwords for users on Instance %s", self.id)
LOG.debug("Changing passwords for users on Instance %s.", self.id)
self._cast("change_passwords", users=users)
def update_attributes(self, username, hostname, user_attrs):
"""Update user attributes."""
LOG.debug("Changing user attributes on Instance %s", self.id)
LOG.debug("Changing user attributes on Instance %s.", self.id)
self._cast("update_attributes", username=username, hostname=hostname,
user_attrs=user_attrs)
def create_user(self, users):
"""Make an asynchronous call to create a new database user"""
LOG.debug("Creating Users for Instance %s", self.id)
LOG.debug("Creating Users for Instance %s.", self.id)
self._cast("create_user", users=users)
def get_user(self, username, hostname):
"""Make an asynchronous call to get a single database user."""
LOG.debug("Getting a user on Instance %s", self.id)
LOG.debug("User name is %s" % username)
LOG.debug("Getting a user on Instance %s.", self.id)
LOG.debug("User name is %s." % username)
return self._call("get_user", AGENT_LOW_TIMEOUT,
username=username, hostname=hostname)
def list_access(self, username, hostname):
"""Show all the databases to which a user has more than USAGE."""
LOG.debug("Showing user grants on Instance %s", self.id)
LOG.debug("User name is %s" % username)
LOG.debug("Showing user grants on Instance %s.", self.id)
LOG.debug("User name is %s." % username)
return self._call("list_access", AGENT_LOW_TIMEOUT,
username=username, hostname=hostname)
@ -159,13 +160,13 @@ class API(proxy.RpcProxy):
def list_users(self, limit=None, marker=None, include_marker=False):
"""Make an asynchronous call to list database users."""
LOG.debug("Listing Users for Instance %s", self.id)
LOG.debug("Listing Users for Instance %s.", self.id)
return self._call("list_users", AGENT_LOW_TIMEOUT, limit=limit,
marker=marker, include_marker=include_marker)
def delete_user(self, user):
"""Make an asynchronous call to delete an existing database user."""
LOG.debug("Deleting user %(user)s for Instance %(instance_id)s" %
LOG.debug("Deleting user %(user)s for Instance %(instance_id)s." %
{'user': user, 'instance_id': self.id})
self._cast("delete_user", user=user)
@ -173,12 +174,12 @@ class API(proxy.RpcProxy):
"""Make an asynchronous call to create a new database
within the specified container
"""
LOG.debug("Creating databases for Instance %s", self.id)
LOG.debug("Creating databases for Instance %s.", self.id)
self._cast("create_database", databases=databases)
def list_databases(self, limit=None, marker=None, include_marker=False):
"""Make an asynchronous call to list databases."""
LOG.debug("Listing databases for Instance %s", self.id)
LOG.debug("Listing databases for Instance %s.", self.id)
return self._call("list_databases", AGENT_LOW_TIMEOUT, limit=limit,
marker=marker, include_marker=include_marker)
@ -187,39 +188,39 @@ class API(proxy.RpcProxy):
within the specified container
"""
LOG.debug("Deleting database %(database)s for "
"Instance %(instance_id)s" % {'database': database,
'instance_id': self.id})
"Instance %(instance_id)s." % {'database': database,
'instance_id': self.id})
self._cast("delete_database", database=database)
def enable_root(self):
"""Make a synchronous call to enable the root user for
access from anywhere
"""
LOG.debug("Enable root user for Instance %s", self.id)
LOG.debug("Enable root user for Instance %s.", self.id)
return self._call("enable_root", AGENT_HIGH_TIMEOUT)
def disable_root(self):
"""Make a synchronous call to disable the root user for
access from anywhere
"""
LOG.debug("Disable root user for Instance %s", self.id)
LOG.debug("Disable root user for Instance %s.", self.id)
return self._call("disable_root", AGENT_LOW_TIMEOUT)
def is_root_enabled(self):
"""Make a synchronous call to check if root access is
available for the container
"""
LOG.debug("Check root access for Instance %s", self.id)
LOG.debug("Check root access for Instance %s.", self.id)
return self._call("is_root_enabled", AGENT_LOW_TIMEOUT)
def get_hwinfo(self):
"""Make a synchronous call to get hardware info for the container"""
LOG.debug("Check hwinfo on Instance %s", self.id)
LOG.debug("Check hwinfo on Instance %s.", self.id)
return self._call("get_hwinfo", AGENT_LOW_TIMEOUT)
def get_diagnostics(self):
"""Make a synchronous call to get diagnostics for the container"""
LOG.debug("Check diagnostics on Instance %s", self.id)
LOG.debug("Check diagnostics on Instance %s.", self.id)
return self._call("get_diagnostics", AGENT_LOW_TIMEOUT)
def prepare(self, memory_mb, packages, databases, users,
@ -229,7 +230,7 @@ class API(proxy.RpcProxy):
"""Make an asynchronous call to prepare the guest
as a database container optionally includes a backup id for restores
"""
LOG.debug("Sending the call to prepare the Guest")
LOG.debug("Sending the call to prepare the Guest.")
packages = packages.split()
self._cast_with_consumer(
"prepare", packages=packages, databases=databases,
@ -267,7 +268,7 @@ class API(proxy.RpcProxy):
def upgrade(self, instance_version, location, metadata=None):
"""Make an asynchronous call to self upgrade the guest agent."""
LOG.debug("Sending an upgrade call to nova-guest")
LOG.debug("Sending an upgrade call to nova-guest.")
self._cast("upgrade",
instance_version=instance_version,
location=location,
@ -275,7 +276,7 @@ class API(proxy.RpcProxy):
def get_volume_info(self):
"""Make a synchronous call to get volume info for the container."""
LOG.debug("Check Volume Info on Instance %s", self.id)
LOG.debug("Check Volume Info on Instance %s.", self.id)
# self._check_for_hearbeat()
return self._call("get_filesystem_stats", AGENT_LOW_TIMEOUT,
fs_path=None)
@ -287,57 +288,57 @@ class API(proxy.RpcProxy):
def create_backup(self, backup_info):
"""Make async call to create a full backup of this instance."""
LOG.debug("Create Backup %(backup_id)s "
"for Instance %(instance_id)s" %
"for Instance %(instance_id)s." %
{'backup_id': backup_info['id'], 'instance_id': self.id})
self._cast("create_backup", backup_info=backup_info)
def mount_volume(self, device_path=None, mount_point=None):
"""Mount the volume."""
LOG.debug("Mount volume %(mount)s on instance %(id)s" % {
LOG.debug("Mount volume %(mount)s on instance %(id)s." % {
'mount': mount_point, 'id': self.id})
self._call("mount_volume", AGENT_LOW_TIMEOUT,
device_path=device_path, mount_point=mount_point)
def unmount_volume(self, device_path=None, mount_point=None):
"""Unmount the volume."""
LOG.debug("Unmount volume %(device)s on instance %(id)s" % {
LOG.debug("Unmount volume %(device)s on instance %(id)s." % {
'device': device_path, 'id': self.id})
self._call("unmount_volume", AGENT_LOW_TIMEOUT,
device_path=device_path, mount_point=mount_point)
def resize_fs(self, device_path=None, mount_point=None):
"""Resize the filesystem."""
LOG.debug("Resize device %(device)s on instance %(id)s" % {
LOG.debug("Resize device %(device)s on instance %(id)s." % {
'device': device_path, 'id': self.id})
self._call("resize_fs", AGENT_HIGH_TIMEOUT, device_path=device_path,
mount_point=mount_point)
def update_overrides(self, overrides, remove=False):
"""Update the overrides."""
LOG.debug("Updating overrides on Instance %s", self.id)
LOG.debug("Updating overrides values %s" % overrides)
LOG.debug("Updating overrides on Instance %s.", self.id)
LOG.debug("Updating overrides values %s." % overrides)
self._cast("update_overrides", overrides=overrides, remove=remove)
def apply_overrides(self, overrides):
LOG.debug("Applying overrides on Instance %s", self.id)
LOG.debug("Applying overrides values %s" % overrides)
LOG.debug("Applying overrides on Instance %s.", self.id)
LOG.debug("Applying overrides values %s." % overrides)
self._cast("apply_overrides", overrides=overrides)
def get_replication_snapshot(self, master_config=None):
LOG.debug("Retrieving replication snapshot from instance %s", self.id)
LOG.debug("Retrieving replication snapshot from instance %s.", self.id)
self._call("get_replication_snapshot", AGENT_HIGH_TIMEOUT,
master_config=master_config)
def attach_replication_slave(self, snapshot, slave_config=None):
LOG.debug("Configuring instance %s to replicate from %s",
LOG.debug("Configuring instance %s to replicate from %s.",
self.id, snapshot.get('master').get('id'))
self._cast("attach_replication_slave", snapshot=snapshot,
slave_config=slave_config)
def detach_replication_slave(self):
LOG.debug("Detaching slave %s from its master", self.id)
LOG.debug("Detaching slave %s from its master.", self.id)
self._call("detach_replication_slave", AGENT_LOW_TIMEOUT)
def demote_replication_master(self):
LOG.debug("Demoting instance %s to non-master", self.id)
LOG.debug("Demoting instance %s to non-master.", self.id)
self._call("demote_replication_master", AGENT_LOW_TIMEOUT)

View File

@ -28,6 +28,7 @@ import os
from trove.openstack.common import log
from itertools import chain
from trove.common import cfg
from trove.openstack.common.gettextutils import _
LOG = log.getLogger(__name__)
@ -69,7 +70,7 @@ def get_filesystem_volume_stats(fs_path):
try:
stats = os.statvfs(fs_path)
except OSError:
LOG.exception("Error getting volume stats.")
LOG.exception(_("Error getting volume stats."))
raise RuntimeError("Filesystem not found (%s)" % fs_path)
total = stats.f_blocks * stats.f_bsize

View File

@ -21,6 +21,7 @@ from trove.common import utils
from trove.db import get_db_api
from trove.db import models as dbmodels
from trove.openstack.common import log as logging
from trove.openstack.common.gettextutils import _
LOG = logging.getLogger(__name__)
@ -81,8 +82,8 @@ class AgentHeartBeat(dbmodels.DatabaseModelBase):
try:
return cls.find_by(instance_id=instance_id)
except exception.NotFound as e:
LOG.error(e.message)
except exception.NotFound:
LOG.exception(_("Error finding instance %s") % instance_id)
raise exception.ModelNotFoundError(instance_id=instance_id)
@staticmethod

View File

@ -114,7 +114,8 @@ class RedhatPackagerMixin(BasePackagerMixin):
utils.execute("rpm", "-e", "--nodeps", package_name,
run_as_root=True, root_helper="sudo")
except ProcessExecutionError:
LOG.error(_("Error removing conflict %s") % package_name)
LOG.exception(_("Error removing conflict %(package)s") %
package_name)
def _install(self, packages, time_out):
"""Attempts to install packages.
@ -164,6 +165,7 @@ class RedhatPackagerMixin(BasePackagerMixin):
"""
cmd = "sudo yum --color=never -y remove %s" % package_name
LOG.debug("Running package remove command: %s" % cmd)
output_expects = ['\[sudo\] password for .*:',
'No Packages marked for removal',
'Removed:']
@ -210,8 +212,9 @@ class RedhatPackagerMixin(BasePackagerMixin):
if matches:
line = matches.group()
return line
msg = _("version() saw unexpected output from rpm!")
LOG.error(msg)
LOG.error(_("Unexpected output from rpm command. (%(output)s)") %
{'output': std_out})
def pkg_remove(self, package_name, time_out):
"""Removes a package."""
@ -233,7 +236,7 @@ class DebianPackagerMixin(BasePackagerMixin):
utils.execute("dpkg", "--configure", "-a", run_as_root=True,
root_helper="sudo")
except ProcessExecutionError:
LOG.error(_("Error fixing dpkg"))
LOG.exception(_("Error fixing dpkg"))
def _fix_package_selections(self, packages, config_opts):
"""
@ -320,6 +323,7 @@ class DebianPackagerMixin(BasePackagerMixin):
"'sudo dpkg --configure -a'"),
"Unable to lock the administration directory",
"Removing %s*" % package_name]
LOG.debug("Running remove package command %s" % cmd)
i, match = self.pexpect_run(cmd, output_expects, time_out)
if i == 0:
raise PkgPermissionError("Invalid permissions.")
@ -339,7 +343,7 @@ class DebianPackagerMixin(BasePackagerMixin):
utils.execute("apt-get", "update", run_as_root=True,
root_helper="sudo")
except ProcessExecutionError:
LOG.error(_("Error updating the apt sources"))
LOG.exception(_("Error updating the apt sources"))
result = self._install(packages, time_out)
if result != OK:

View File

@ -13,13 +13,10 @@
# License for the specific language governing permissions and limitations
# under the License.
from trove.openstack.common import log as logging
import routes
from trove.common import wsgi
LOG = logging.getLogger(__name__)
class Controller(wsgi.Controller):
"""Base controller class."""

View File

@ -54,15 +54,22 @@ class VolumeDevice(object):
"""
try:
num_tries = CONF.num_tries
LOG.debug("Checking if %s exists." % self.device_path)
utils.execute('sudo', 'blockdev', '--getsize64', self.device_path,
attempts=num_tries)
except ProcessExecutionError:
LOG.exception(_("Error getting device status"))
raise GuestError(_("InvalidDevicePath(path=%s)") %
self.device_path)
def _check_format(self):
"""Checks that an unmounted volume is formatted."""
child = pexpect.spawn("sudo dumpe2fs %s" % self.device_path)
cmd = "sudo dumpe2fs %s" % self.device_path
LOG.debug("Checking whether %s is formated: %s." %
(self.device_path, cmd))
child = pexpect.spawn(cmd)
try:
i = child.expect(['has_journal', 'Wrong magic number'])
if i == 0:
@ -83,6 +90,8 @@ class VolumeDevice(object):
cmd = "sudo mkfs -t %s %s %s" % (volume_fstype,
format_options, self.device_path)
volume_format_timeout = CONF.volume_format_timeout
LOG.debug("Formatting %s. Executing: %s.",
(self.device_path, cmd))
child = pexpect.spawn(cmd, timeout=volume_format_timeout)
# child.expect("(y,n)")
# child.sendline('y')
@ -96,6 +105,8 @@ class VolumeDevice(object):
def mount(self, mount_point, write_to_fstab=True):
"""Mounts, and writes to fstab."""
LOG.debug("Will mount %s at %s." % (self.device_path, mount_point))
mount_point = VolumeMountPoint(self.device_path, mount_point)
mount_point.mount()
if write_to_fstab:
@ -111,8 +122,8 @@ class VolumeDevice(object):
run_as_root=True, root_helper="sudo")
utils.execute("resize2fs", self.device_path,
run_as_root=True, root_helper="sudo")
except ProcessExecutionError as err:
LOG.error(err)
except ProcessExecutionError:
LOG.exception(_("Error resizing file system."))
raise GuestError(_("Error resizing the filesystem: %s") %
self.device_path)
@ -127,9 +138,8 @@ class VolumeDevice(object):
mount_points = self.mount_points(device_path)
for mnt in mount_points:
LOG.info(_("Device %(device)s is already mounted in "
"%(mount_point)s") %
"%(mount_point)s. Unmounting now.") %
{'device': device_path, 'mount_point': mnt})
LOG.info(_("Unmounting %s") % mnt)
self.unmount(mnt)
def mount_points(self, device_path):
@ -139,8 +149,8 @@ class VolumeDevice(object):
stdout, stderr = utils.execute(cmd, shell=True)
return stdout.strip().split('\n')
except ProcessExecutionError as err:
LOG.error(err)
except ProcessExecutionError:
LOG.exception(_("Error retrieving mount points"))
raise GuestError(_("Could not obtain a list of mount points for "
"device: %s") % device_path)