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
This commit is contained in:
Brian Lamar 2012-02-08 01:29:05 -05:00
parent a5b116b6fb
commit b4707d28ea
5 changed files with 66 additions and 10 deletions

View File

@ -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)

View File

@ -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()

View File

@ -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):

View File

@ -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):

View File

@ -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)