From b4707d28eaf9f843dadc6613c9d4061416bdb385 Mon Sep 17 00:00:00 2001 From: Brian Lamar Date: Wed, 8 Feb 2012 01:29:05 -0500 Subject: [PATCH] Added logging to select areas of melange. The biggest change here is that now by default SQLAlchemy will not echo every query. This can still be turned on, but it is very verbose. More specific log lines should be added for debugging after this change. Change-Id: Ia51933d268412ae61cf2df8c355c0fa1b365d57f --- melange/common/auth.py | 17 ++++++++++++++--- melange/common/messaging.py | 17 +++++++++++++---- melange/db/sqlalchemy/session.py | 18 +++++++++++++++--- melange/ipam/models.py | 11 +++++++++++ melange/ipam/service.py | 13 +++++++++++++ 5 files changed, 66 insertions(+), 10 deletions(-) diff --git a/melange/common/auth.py b/melange/common/auth.py index f79caa2f..bba885f7 100644 --- a/melange/common/auth.py +++ b/melange/common/auth.py @@ -17,28 +17,36 @@ import httplib2 import json +import logging import re import urlparse -from webob import exc +import webob.exc import wsgi +LOG = logging.getLogger("melange.common.auth") + + class AuthorizationMiddleware(wsgi.Middleware): def __init__(self, application, auth_providers, **local_config): self.auth_providers = auth_providers + LOG.debug("Auth middleware providers: %s" % auth_providers) super(AuthorizationMiddleware, self).__init__(application, **local_config) def process_request(self, request): roles = request.headers.get('X_ROLE', '').split(',') + LOG.debug("Processing auth request with roles: %s" % roles) tenant_id = request.headers.get('X_TENANT', None) + LOG.debug("Processing auth request with tenant_id: %s" % tenant_id) for provider in self.auth_providers: provider.authorize(request, tenant_id, roles) @classmethod def factory(cls, global_config, **local_config): def _factory(app): + LOG.debug("Created auth middleware with config: %s" % local_config) return cls(app, [TenantBasedAuth()], **local_config) return _factory @@ -50,10 +58,13 @@ class TenantBasedAuth(object): def authorize(self, request, tenant_id, roles): if 'admin' in [role.lower() for role in roles]: + LOG.debug("Authorized admin request: %s" % request) return True match_for_tenant = self.tenant_scoped_url.match(request.path_info) if (match_for_tenant and tenant_id == match_for_tenant.group('tenant_id')): + LOG.debug("Authorized tenant '%(tenant_id)s' request: " + "%(request)s" % locals()) return True - raise exc.HTTPForbidden(_("User with tenant id %s cannot access " - "this resource") % tenant_id) + raise webob.exc.HTTPForbidden(_("User with tenant id %s cannot " + "access this resource") % tenant_id) diff --git a/melange/common/messaging.py b/melange/common/messaging.py index 3ab06de6..831e5d4a 100644 --- a/melange/common/messaging.py +++ b/melange/common/messaging.py @@ -15,12 +15,17 @@ # License for the specific language governing permissions and limitations # under the License. +import logging + import kombu.connection from melange.common import config from melange.common import utils +LOG = logging.getLogger('melange.common.messaging') + + class Queue(object): def __init__(self, name): @@ -34,14 +39,18 @@ class Queue(object): self.close() def connect(self): - self.conn = kombu.connection.BrokerConnection( - **queue_connection_options("ipv4_queue")) + options = queue_connection_options("ipv4_queue") + LOG.info("Connecting to message queue.") + LOG.debug("Message queue connect options: %(options)s" % locals()) + self.conn = kombu.connection.BrokerConnection(**options) def put(self, msg): - queue = self.conn.SimpleQueue(self.name, no_ack=True) - queue.put(msg) + queue = self.conn.SimpleQueue(self.name, no_ack=True) + LOG.debug("Putting message '%(msg)s' on queue '%(queue)s'" % locals()) + queue.put(msg) def close(self): + LOG.info("Closing connection to message queue.") self.conn.close() diff --git a/melange/db/sqlalchemy/session.py b/melange/db/sqlalchemy/session.py index ef0e6be9..179abbd5 100644 --- a/melange/db/sqlalchemy/session.py +++ b/melange/db/sqlalchemy/session.py @@ -29,6 +29,9 @@ _ENGINE = None _MAKER = None +LOG = logging.getLogger('melange.db.sqlalchemy.session') + + def configure_db(options): configure_sqlalchemy_log(options) global _ENGINE @@ -48,9 +51,18 @@ def configure_sqlalchemy_log(options): def _create_engine(options): - timeout = config.get_option(options, 'sql_idle_timeout', type='int', - default=3600) - return create_engine(options['sql_connection'], pool_recycle=timeout) + engine_args = { + "pool_recycle": config.get_option(options, + 'sql_idle_timeout', + type='int', + default=3600), + "echo": config.get_option(options, + 'sql_query_log', + type='bool', + default=False), + } + LOG.info("Creating SQLAlchemy engine with args: %s" % engine_args) + return create_engine(options['sql_connection'], **engine_args) def get_session(autocommit=True, expire_on_commit=False): diff --git a/melange/ipam/models.py b/melange/ipam/models.py index 81e80551..4051c25f 100644 --- a/melange/ipam/models.py +++ b/melange/ipam/models.py @@ -75,6 +75,7 @@ class ModelBase(object): self._convert_columns_to_proper_type() self._before_save() self['updated_at'] = utils.utcnow() + LOG.debug("Saving %s: %s" % (self.__class__.__name__, self.__dict__)) return db.db_api.save(self) def delete(self): @@ -252,6 +253,7 @@ class IpBlock(ModelBase): @classmethod def delete_all_deallocated_ips(cls): + LOG.info("Deleting all deallocated IPs") for block in db.db_api.find_all_blocks_with_deallocated_ips(): block.delete_deallocated_ips() @@ -396,17 +398,21 @@ class IpBlock(ModelBase): return network in other_network or other_network in network def find_ip(self, **kwargs): + LOG.debug("Searching for IP block %r for IP matching " + "%s" % (self.id, kwargs)) return IpAddress.find_by(ip_block_id=self.id, **kwargs) def deallocate_ip(self, address): ip_address = IpAddress.find_by(ip_block_id=self.id, address=address) if ip_address != None: + LOG.debug("Deallocating IP: %s" % ip_address) ip_address.deallocate() def delete_deallocated_ips(self): self.update(is_full=False) for ip in db.db_api.find_deallocated_ips( deallocated_by=self._deallocated_by_date(), ip_block_id=self.id): + LOG.debug("Deleting deallocated IP: %s" % ip) ip.delete() def _deallocated_by_date(self): @@ -568,15 +574,18 @@ class IpAddress(ModelBase): @classmethod def find_all_by_network(cls, network_id, **conditions): + LOG.debug("Retrieving all IPs for network %s" % network_id) return db.db_query.find_all_ips_in_network(cls, network_id=network_id, **conditions) @classmethod def find_all_allocated_ips(cls, **conditions): + LOG.debug("Retrieving all allocated IPs.") return db.db_query.find_all_allocated_ips(cls, **conditions) def delete(self): + LOG.debug("Deleting IP address: %r" % self) if self._explicitly_allowed_on_interfaces(): return self.update(marked_for_deallocation=False, deallocated_at=None, @@ -606,11 +615,13 @@ class IpAddress(ModelBase): for local_address in ip_addresses]) def deallocate(self): + LOG.debug("Marking IP address for deallocation: %r" % self) self.update(marked_for_deallocation=True, deallocated_at=utils.utcnow(), interface_id=None) def restore(self): + LOG.debug("Restored IP address: %r" % self) self.update(marked_for_deallocation=False, deallocated_at=None) def inside_globals(self, **kwargs): diff --git a/melange/ipam/service.py b/melange/ipam/service.py index 92bacc37..31c587c6 100644 --- a/melange/ipam/service.py +++ b/melange/ipam/service.py @@ -15,6 +15,7 @@ # License for the specific language governing permissions and limitations # under the License. +import logging import routes import webob.exc @@ -26,6 +27,9 @@ from melange.ipam import models from melange.ipam import views +LOG = logging.getLogger('melange.ipam.service') + + class BaseController(wsgi.Controller): exclude_attr = [] @@ -93,19 +97,24 @@ class IpBlockController(BaseController, DeleteAction, ShowAction): return models.IpBlock.find_by(**kwargs) def index(self, request, tenant_id): + LOG.info("Listing all IP blocks for tenant '%s'" % tenant_id) type_dict = utils.filter_dict(request.params, 'type') all_blocks = models.IpBlock.find_all(tenant_id=tenant_id, **type_dict) return self._paginated_response('ip_blocks', all_blocks, request) def create(self, request, tenant_id, body=None): + LOG.info("Creating an IP block for tenant '%s'" % tenant_id) params = self._extract_required_params(body, 'ip_block') block = models.IpBlock.create(tenant_id=tenant_id, **params) + LOG.debug("New IP block parameters: %s" % params) return wsgi.Result(dict(ip_block=block.data()), 201) def update(self, request, id, tenant_id, body=None): + LOG.info("Updating IP block %(id)s for %(tenant_id)s" % locals()) ip_block = self._find_block(id=id, tenant_id=tenant_id) params = self._extract_required_params(body, 'ip_block') ip_block.update(**utils.exclude(params, 'cidr', 'type')) + LOG.debug("Updated IP block %(id)s parameters: %(params)s" % locals()) return wsgi.Result(dict(ip_block=ip_block.data()), 200) @@ -403,6 +412,7 @@ class InterfacesController(BaseController, ShowAction, DeleteAction): params = self._extract_required_params(body, 'interface') params['virtual_interface_id'] = params.pop('id', None) network_params = utils.stringify_keys(params.pop('network', None)) + LOG.debug("Creating interface with parameters: %s" % params) interface = models.Interface.create_and_configure(**params) if network_params: @@ -423,6 +433,7 @@ class InterfacesController(BaseController, ShowAction, DeleteAction): def delete(self, request, **kwargs): kwargs['vif_id_on_device'] = kwargs.pop('virtual_interface_id', None) + LOG.debug("Deleting interface (kwargs=%s)" % kwargs) self._model.find_by(**kwargs).delete() @@ -459,6 +470,7 @@ class InstanceInterfacesController(BaseController): return {'instance': {'interfaces': view_data}} def delete(self, request, device_id): + LOG.debug("Deleting instance interface (device_id=%s)" % device_id) models.Interface.delete_by(device_id=device_id) @@ -468,6 +480,7 @@ class MacAddressRangesController(BaseController, ShowAction, DeleteAction): def create(self, request, body=None): params = self._extract_required_params(body, 'mac_address_range') + LOG.info("Creating MAC address range: %s" % params) mac_range = models.MacAddressRange.create(**params) return wsgi.Result(dict(mac_address_range=mac_range.data()), 201)