Log refactoring close to new logging spec

* correct log levels
* correct log messages

partial-bug: 1419872
partial-implements-bp: unified-style-logging

Change-Id: I80c2b4c809dc52125f9f4a3beec0cd3b6c4c1213
changes/22/209922/16
Nikolay Starodubtsev 7 years ago
parent 490c63f8c9
commit 975bcc4a98
  1. 16
      murano/api/middleware/version_negotiation.py
  2. 21
      murano/api/v1/actions.py
  3. 25
      murano/api/v1/catalog.py
  4. 6
      murano/api/v1/cloudfoundry/cfapi.py
  5. 11
      murano/api/v1/deployments.py
  6. 24
      murano/api/v1/environments.py
  7. 16
      murano/api/v1/request_statistics.py
  8. 9
      murano/api/v1/services.py
  9. 33
      murano/api/v1/sessions.py
  10. 40
      murano/api/v1/template_applications.py
  11. 41
      murano/api/v1/templates.py
  12. 23
      murano/cmd/manage.py
  13. 10
      murano/common/engine.py
  14. 24
      murano/common/plugin_loader.py
  15. 19
      murano/common/policy.py
  16. 29
      murano/common/server.py
  17. 18
      murano/common/statservice.py
  18. 9
      murano/common/utils.py
  19. 14
      murano/common/wsgi.py
  20. 27
      murano/db/catalog/api.py
  21. 8
      murano/db/services/core_services.py
  22. 5
      murano/db/services/environment_templates.py
  23. 4
      murano/db/services/environments.py
  24. 14
      murano/dsl/executor.py
  25. 4
      murano/engine/environment.py
  26. 15
      murano/engine/package_loader.py
  27. 11
      murano/engine/system/agent_listener.py
  28. 7
      murano/engine/system/heat_stack.py
  29. 9
      murano/engine/system/net_explorer.py
  30. 14
      murano/tests/functional/common/utils.py
  31. 13
      murano/tests/functional/engine/manager.py
  32. 8
      murano/tests/unit/db/migration/test_migrations_base.py
  33. 18
      murano/utils.py

@ -22,6 +22,7 @@ from oslo_config import cfg
from oslo_log import log as logging
from murano.api import versions
from murano.common.i18n import _LW
from murano.common import wsgi
CONF = cfg.CONF
@ -41,11 +42,10 @@ class VersionNegotiationFilter(wsgi.Middleware):
def process_request(self, req):
"""Try to find a version first in the accept header, then the URL."""
msg = ("Determining version of request:"
" %(method)s %(path)s Accept: %(accept)s")
args = {'method': req.method, 'path': req.path, 'accept': req.accept}
LOG.debug(msg % args)
LOG.debug(("Determining version of request:{method} {path}"
"Accept: {accept}").format(method=req.method,
path=req.path,
accept=req.accept))
LOG.debug("Using url versioning")
# Remove version in url so it doesn't conflict later
req_version = self._pop_path_info(req)
@ -53,13 +53,13 @@ class VersionNegotiationFilter(wsgi.Middleware):
try:
version = self._match_version_string(req_version)
except ValueError:
LOG.debug("Unknown version. Returning version choices.")
LOG.warning(_LW("Unknown version. Returning version choices."))
return self.versions_app
req.environ['api.version'] = version
req.path_info = ''.join(('/v', str(version), req.path_info))
LOG.debug("Matched version: v%d", version)
LOG.debug('new path %s' % req.path_info)
LOG.debug("Matched version: v{version}".format(version=version))
LOG.debug('new path {path}'.format(path=req.path_info))
return None
def _match_version_string(self, subject):

@ -20,7 +20,7 @@ from murano.common import wsgi
from murano.db.services import environments as envs
from murano.db.services import sessions
from murano.db import session as db_session
from murano.common.i18n import _LI, _LE, _
from murano.common.i18n import _LE, _, _LW
from murano.services import actions
from murano.services import states
from murano.utils import verify_env
@ -43,17 +43,17 @@ class Controller(object):
env_status = envs.EnvironmentServices.get_status(environment_id)
if env_status in (states.EnvironmentStatus.DEPLOYING,
states.EnvironmentStatus.DELETING):
LOG.info(_LI('Could not open session for environment <EnvId: {0}>,'
'environment has deploying '
'status.').format(environment_id))
LOG.warning(_LW('Could not open session for environment '
'<EnvId: {id}>, environment has deploying '
'status.').format(id=environment_id))
raise exc.HTTPForbidden()
user_id = request.context.user
session = sessions.SessionServices.create(environment_id, user_id)
if not sessions.SessionServices.validate(session):
LOG.error(_LE('Session <SessionId {0}> '
'is invalid').format(session.id))
LOG.error(_LE('Session <SessionId {id}> '
'is invalid').format(id=session.id))
raise exc.HTTPForbidden()
task_id = actions.ActionServices.execute(
@ -64,7 +64,7 @@ class Controller(object):
def get_result(self, request, environment_id, task_id):
policy.check("execute_action", request.context, {})
LOG.debug('Action:GetResult <TaskId: {0}>'.format(task_id))
LOG.debug('Action:GetResult <TaskId: {id}>'.format(id=task_id))
unit = db_session.get_session()
result = actions.ActionServices.get_result(environment_id, task_id,
@ -72,10 +72,9 @@ class Controller(object):
if result is not None:
return result
msg = (_('Result for task with environment_id: {} and '
'task_id: {} was not found.')
.format(environment_id, task_id))
msg = _('Result for task with environment_id: {env_id} and task_id:'
'{task_id} was not found.').format(env_id=environment_id,
task_id=task_id)
LOG.error(msg)
raise exc.HTTPNotFound(msg)

@ -48,7 +48,7 @@ def _check_content_type(req, content_type):
try:
req.get_content_type((content_type,))
except exceptions.UnsupportedContentType:
msg = _("Content-Type must be '{0}'").format(content_type)
msg = _("Content-Type must be '{type}'").format(type=content_type)
LOG.error(msg)
raise exc.HTTPBadRequest(explanation=msg)
@ -70,10 +70,9 @@ def _get_filters(query_params):
for i in order_by[:]:
if ORDER_VALUES and i not in ORDER_VALUES:
filters['order_by'].remove(i)
LOG.warning(_LW(
"Value of 'order_by' parameter is not valid. "
"Allowed values are: {0}. Skipping it.").format(
", ".join(ORDER_VALUES)))
LOG.warning(_LW("Value of 'order_by' parameter is not valid. "
"Allowed values are: {values}. Skipping it.")
.format(values=", ".join(ORDER_VALUES)))
return filters
@ -96,9 +95,9 @@ def _validate_body(body):
' The limit is {0} Mb').format(mb_limit))
if len(body.keys()) > 2:
msg = _("'multipart/form-data' request body should contain "
"1 or 2 parts: json string and zip archive. Current body "
"consists of {0} part(s)").format(len(body.keys()))
msg = _("'multipart/form-data' request body should contain 1 or 2 "
"parts: json string and zip archive. Current body consists "
"of {amount} part(s)").format(amount=len(body.keys()))
LOG.error(msg)
raise exc.HTTPBadRequest(explanation=msg)
@ -127,12 +126,12 @@ class Controller(object):
try:
value = int(value)
except ValueError:
msg = _("limit param must be an integer")
msg = _("Limit param must be an integer")
LOG.error(msg)
raise exc.HTTPBadRequest(explanation=msg)
if value <= 0:
msg = _("limit param must be positive")
msg = _("Limit param must be positive")
LOG.error(msg)
raise exc.HTTPBadRequest(explanation=msg)
@ -207,7 +206,8 @@ class Controller(object):
try:
jsonschema.validate(package_meta, schemas.PKG_UPLOAD_SCHEMA)
except jsonschema.ValidationError as e:
msg = _("Package schema is not valid: {0}").format(e)
msg = _("Package schema is not valid: {reason}").format(
reason=e)
LOG.exception(msg)
raise exc.HTTPBadRequest(explanation=msg)
else:
@ -243,7 +243,8 @@ class Controller(object):
raise exc.HTTPConflict(msg)
return package.to_dict()
except pkg_exc.PackageLoadError as e:
msg = _("Couldn't load package from file: {0}").format(e)
msg = _("Couldn't load package from file: {reason}").format(
reason=e)
LOG.exception(msg)
raise exc.HTTPBadRequest(explanation=msg)
finally:

@ -159,7 +159,7 @@ class Controller(object):
.format(space_id=space_guid,
environment_id=environment_id))
LOG.debug('Auth: %s' % keystone.auth_ref)
LOG.debug('Keystone endpoint: {0}'.format(keystone.auth_ref))
tenant_id = keystone.project_id
ctx = context.RequestContext(user=user, tenant=tenant_id)
@ -234,9 +234,9 @@ class Controller(object):
session_id = create_session(m_cli, environment_id)
env = m_cli.environments.get(environment_id, session_id)
LOG.debug('Got environment %s' % env)
LOG.debug('Got environment {0}'.format(env))
service = self._get_service(env, service_id)
LOG.debug('Got service %s' % service)
LOG.debug('Got service {0}'.format(service))
credentials = {}
for k, v in six.iteritems(service):
if k not in filtered:

@ -18,7 +18,7 @@ from webob import exc
from murano.api.v1 import request_statistics
from murano.common.helpers import token_sanitizer
from murano.common.i18n import _LI
from murano.common.i18n import _LE
from murano.common import policy
from murano.common import utils
from murano.common import wsgi
@ -87,12 +87,13 @@ def _patch_description(description):
def verify_and_get_deployment(db_session, environment_id, deployment_id):
deployment = db_session.query(models.Task).get(deployment_id)
if not deployment:
LOG.info(_LI('Deployment with id {0} not found').format(deployment_id))
LOG.error(_LE('Deployment with id {id} not found')
.format(id=deployment_id))
raise exc.HTTPNotFound
if deployment.environment_id != environment_id:
LOG.info(_LI('Deployment with id {0} not found'
' in environment {1}').format(deployment_id,
environment_id))
LOG.error(_LE('Deployment with id {d_id} not found in environment'
'{env_id}').format(d_id=deployment_id,
env_id=environment_id))
raise exc.HTTPBadRequest
deployment.description = _patch_description(deployment.description)

@ -44,7 +44,8 @@ class Controller(object):
@request_statistics.stats_count(API_NAME, 'Index')
def index(self, request):
all_tenants = request.GET.get('all_tenants', 'false').lower() == 'true'
LOG.debug('Environments:List <all_tenants: {0}>'.format(all_tenants))
LOG.debug('Environments:List <all_tenants: {tenants}>'.format(
tenants=all_tenants))
if all_tenants:
policy.check('list_environments_all_tenants', request.context)
@ -61,7 +62,7 @@ class Controller(object):
@request_statistics.stats_count(API_NAME, 'Create')
def create(self, request, body):
LOG.debug(u'Environments:Create <Body {0}>'.format(body))
LOG.debug('Environments:Create <Body {body}>'.format(body=body))
policy.check('create_environment', request.context)
if not body.get('name'):
@ -84,8 +85,8 @@ class Controller(object):
LOG.exception(msg)
raise exc.HTTPConflict(explanation=msg)
else:
msg = _('Environment name must contain only alphanumeric '
'or "_-." characters, must start with alpha')
msg = _('Environment name must contain only alphanumericor "_-." '
'characters, must start with alpha')
LOG.exception(msg)
raise exc.HTTPClientError(explanation=msg)
@ -94,7 +95,7 @@ class Controller(object):
@request_statistics.stats_count(API_NAME, 'Show')
@verify_env
def show(self, request, environment_id):
LOG.debug('Environments:Show <Id: {0}>'.format(environment_id))
LOG.debug('Environments:Show <Id: {id}>'.format(id=environment_id))
target = {"environment_id": environment_id}
policy.check('show_environment', request.context, target)
@ -119,21 +120,20 @@ class Controller(object):
@request_statistics.stats_count(API_NAME, 'Update')
@verify_env
def update(self, request, environment_id, body):
LOG.debug('Environments:Update <Id: {0}, '
'Body: {1}>'.format(environment_id, body))
LOG.debug('Environments:Update <Id: {id}, '
'Body: {body}>'.format(id=environment_id, body=body))
target = {"environment_id": environment_id}
policy.check('update_environment', request.context, target)
session = db_session.get_session()
environment = session.query(models.Environment).get(environment_id)
LOG.debug('ENV NAME: {0}>'.format(body['name']))
if VALID_NAME_REGEX.match(str(body['name'])):
try:
environment.update(body)
environment.save(session)
except db_exc.DBDuplicateEntry:
msg = _('Environment with specified name already exists')
LOG.exception(msg)
LOG.error(msg)
raise exc.HTTPConflict(explanation=msg)
else:
msg = _('Environment name must contain only alphanumeric '
@ -149,10 +149,12 @@ class Controller(object):
policy.check('delete_environment', request.context, target)
if request.GET.get('abandon', '').lower() == 'true':
check_env(request, environment_id)
LOG.debug('Environments:Abandon <Id: {0}>'.format(environment_id))
LOG.debug('Environments:Abandon <Id: {id}>'
.format(id=environment_id))
envs.EnvironmentServices.remove(environment_id)
else:
LOG.debug('Environments:Delete <Id: {0}>'.format(environment_id))
LOG.debug('Environments:Delete <Id: {id}>'
.format(id=environment_id))
sessions_controller = sessions.Controller()
session = sessions_controller.configure(request, environment_id)
session_id = session['id']

@ -63,10 +63,8 @@ def stats_count(api, method):
except Exception:
te = time.time()
tenant = args[1].context.tenant
LOG.exception(
_LE('API {0} method {1} raised an exception').format(
api, method)
)
LOG.exception(_LE('API {api} method {method} raised an '
'exception').format(api=api, method=method))
update_error_count(api, method, te - te, tenant)
raise
return wrap
@ -75,17 +73,15 @@ def stats_count(api, method):
def update_count(api, method, ex_time, tenant=None):
LOG.debug("Updating count stats for %s, %s on object %s" % (api,
method,
v1.stats))
LOG.debug("Updating count stats for {api}, {method} on object {object}"
.format(api=api, method=method, object=v1.stats))
v1.stats.add_api_request(tenant, ex_time)
v1.stats.request_count += 1
def update_error_count(api, method, ex_time, tenant=None):
LOG.debug("Updating count stats for %s, %s on object %s" % (api,
method,
v1.stats))
LOG.debug("Updating count stats for {api}, {method} on object "
"{object}".format(api=api, method=method, object=v1.stats))
v1.stats.add_api_error(tenant, ex_time)
v1.stats.error_count += 1
v1.stats.request_count += 1

@ -48,8 +48,8 @@ class Controller(object):
@utils.verify_env
@normalize_path
def get(self, request, environment_id, path):
LOG.debug('Services:Get <EnvId: {0}, '
'Path: {1}>'.format(environment_id, path))
LOG.debug('Services:Get <EnvId: {env_id}, '
'Path: {path}>'.format(env_id=environment_id, path=path))
session_id = None
if hasattr(request, 'context') and request.context.session:
@ -74,8 +74,9 @@ class Controller(object):
LOG.error(msg)
raise exc.HTTPBadRequest(msg)
secure_data = token_sanitizer.TokenSanitizer().sanitize(body)
LOG.debug('Services:Post <EnvId: {0}, Path: {2}, '
'Body: {1}>'.format(environment_id, secure_data, path))
LOG.debug('Services:Post <EnvId: {env_id}, Path: {path}, '
'Body: {body}>'.format(env_id=environment_id,
body=secure_data, path=path))
post_data = core_services.CoreServices.post_data
session_id = request.context.session

@ -34,7 +34,8 @@ class Controller(object):
@request_statistics.stats_count(API_NAME, 'Create')
def configure(self, request, environment_id):
LOG.debug('Session:Configure <EnvId: {0}>'.format(environment_id))
LOG.debug('Session:Configure <EnvId: {env_id}>'
.format(env_id=environment_id))
check_env(request, environment_id)
@ -42,8 +43,9 @@ class Controller(object):
env_status = envs.EnvironmentServices.get_status(environment_id)
if env_status in (states.EnvironmentStatus.DEPLOYING,
states.EnvironmentStatus.DELETING):
msg = _('Could not open session for environment <EnvId: {0}>,'
'environment has deploying status.').format(environment_id)
msg = _('Could not open session for environment <EnvId: '
'{env_id}>, environment has deploying status.').format(
env_id=environment_id)
LOG.error(msg)
raise exc.HTTPForbidden(explanation=msg)
@ -54,7 +56,7 @@ class Controller(object):
@request_statistics.stats_count(API_NAME, 'Index')
def show(self, request, environment_id, session_id):
LOG.debug('Session:Show <SessionId: {0}>'.format(session_id))
LOG.debug('Session:Show <SessionId: {id}>'.format(id=session_id))
unit = db_session.get_session()
session = unit.query(models.Session).get(session_id)
@ -62,9 +64,11 @@ class Controller(object):
check_session(request, environment_id, session, session_id)
user_id = request.context.user
msg = _('User <UserId {0}> is not authorized to access session'
'<SessionId {1}>.').format(user_id, session_id)
if session.user_id != user_id:
msg = _('User <UserId {usr_id}> is not authorized to access'
'session <SessionId {s_id}>.').format(usr_id=user_id,
s_id=session_id)
LOG.error(msg)
raise exc.HTTPUnauthorized(explanation=msg)
@ -79,7 +83,7 @@ class Controller(object):
@request_statistics.stats_count(API_NAME, 'Delete')
def delete(self, request, environment_id, session_id):
LOG.debug('Session:Delete <SessionId: {0}>'.format(session_id))
LOG.debug('Session:Delete <SessionId: {s_id}>'.format(s_id=session_id))
unit = db_session.get_session()
session = unit.query(models.Session).get(session_id)
@ -88,14 +92,15 @@ class Controller(object):
user_id = request.context.user
if session.user_id != user_id:
msg = _('User <UserId {0}> is not authorized to access session'
'<SessionId {1}>.').format(user_id, session_id)
msg = _('User <UserId {usr_id}> is not authorized to access '
'session <SessionId {s_id}>.').format(usr_id=user_id,
s_id=session_id)
LOG.error(msg)
raise exc.HTTPUnauthorized(explanation=msg)
if session.state == states.SessionState.DEPLOYING:
msg = _('Session <SessionId: {0}> is in deploying state and '
'could not be deleted').format(session_id)
msg = _('Session <SessionId: {s_id}> is in deploying state '
'and could not be deleted').format(s_id=session_id)
LOG.error(msg)
raise exc.HTTPForbidden(explanation=msg)
@ -106,7 +111,7 @@ class Controller(object):
@request_statistics.stats_count(API_NAME, 'Deploy')
def deploy(self, request, environment_id, session_id):
LOG.debug('Session:Deploy <SessionId: {0}>'.format(session_id))
LOG.debug('Session:Deploy <SessionId: {s_id}>'.format(s_id=session_id))
unit = db_session.get_session()
session = unit.query(models.Session).get(session_id)
@ -121,8 +126,8 @@ class Controller(object):
raise exc.HTTPForbidden(explanation=msg)
if session.state != states.SessionState.OPENED:
msg = _('Session <SessionId {0}> is already deployed or '
'deployment is in progress').format(session_id)
msg = _('Session <SessionId {s_id}> is already deployed or '
'deployment is in progress').format(s_id=session_id)
LOG.error(msg)
raise exc.HTTPForbidden(explanation=msg)

@ -58,14 +58,15 @@ class Controller(object):
contains the services
:param path: The operation path
"""
LOG.debug('Applications:Get <EnvTemplateId: {0}, '
'Path: {1}>'.format(env_template_id, path))
LOG.debug('Applications:Get <EnvTemplateId: {templ_id}, '
'Path: {path}>'.format(templ_id=env_template_id, path=path))
try:
get_data = core_services.CoreServices.get_template_data
result = get_data(env_template_id, path)
except (KeyError, ValueError, AttributeError):
msg = 'The environment template does not exist' + env_template_id
msg = _('The environment template {templ_id} does not '
'exist').format(templ_id=env_template_id)
LOG.exception(msg)
raise exc.HTTPNotFound(msg)
return result
@ -81,14 +82,15 @@ class Controller(object):
:param path: The path include the service id
:return: the service description.
"""
LOG.debug('Applications:Get <EnvTemplateId: {0}, '
'Path: {1}>'.format(env_template_id, path))
LOG.debug('Applications:Get <EnvTemplateId: {templ_id}, '
'Path: {path}>'.format(templ_id=env_template_id, path=path))
try:
get_data = core_services.CoreServices.get_template_data
result = get_data(env_template_id, path)
except (KeyError, ValueError, AttributeError):
msg = 'The template does not exist' + env_template_id
msg = _('The template does not exist {templ_id}').format(
templ_id=env_template_id)
LOG.exception(msg)
raise exc.HTTPNotFound(msg)
return result
@ -106,14 +108,17 @@ class Controller(object):
:return: the service description.
"""
secure_data = token_sanitizer.TokenSanitizer().sanitize(body)
LOG.debug('Applications:Post <EnvTempId: {0}, Path: {2}, '
'Body: {1}>'.format(env_template_id, secure_data, path))
LOG.debug('Applications:Post <EnvTempId: {env_id}, Path: {path}, '
'Body: {body}>'.format(env_id=env_template_id,
body=secure_data,
path=path))
post_data = core_services.CoreServices.post_application_data
try:
result = post_data(env_template_id, body, path)
except (KeyError, ValueError):
msg = 'The template does not exist ' + env_template_id
msg = _('The template does not exist {templ_id}').format(
templ_id=env_template_id)
LOG.exception(msg)
raise exc.HTTPNotFound(msg)
return result
@ -131,8 +136,10 @@ class Controller(object):
:param body: the information about the service
:return: the service description updated.
"""
LOG.debug('Applications:Put <EnvTempId: {0}, Path: {2}, '
'Body: {1}>'.format(env_template_id, body, path))
LOG.debug('Applications:Put <EnvTempId: {templ_id}, Path: {path}, '
'Body: {body}>'.format(templ_id=env_template_id,
body=body,
path=path))
put_data = core_services.CoreServices.put_data
session_id = request.context.session
@ -140,7 +147,8 @@ class Controller(object):
try:
result = put_data(env_template_id, session_id, body, path)
except (KeyError, ValueError):
msg = 'The template does not exist' + env_template_id
msg = _('The template does not exist {templ_id}').format(
templ_id=env_template_id)
LOG.exception(msg)
raise exc.HTTPNotFound(msg)
return result
@ -155,13 +163,15 @@ class Controller(object):
the service belongs to.
:param path: The path contains the service id
"""
LOG.debug('Applications:Put <EnvTempId: {0}, '
'Path: {1}>'.format(env_template_id, path))
LOG.debug('Applications:Put <EnvTempId: {templ_id}, '
'Path: {path}>'.format(templ_id=env_template_id,
path=path))
delete_data = core_services.CoreServices.delete_env_template_data
try:
delete_data(env_template_id, path)
except (KeyError, ValueError):
msg = 'The template does not exist' + env_template_id
msg = _('The template does not exist {templ_id}').format(
templ_id=env_template_id)
LOG.exception(msg)
raise exc.HTTPNotFound(msg)

@ -18,7 +18,7 @@ from webob import exc
from murano.api.v1 import environments as envs_api
from murano.api.v1 import request_statistics
from murano.common.i18n import _
from murano.common.i18n import _, _LE
from murano.common import policy
from murano.common import utils
from murano.common import wsgi
@ -58,14 +58,15 @@ class Controller(object):
:param body: the env template description
:return: the description of the created template.
"""
LOG.debug('EnvTemplates:Create <Body {0}>'.format(body))
LOG.debug('EnvTemplates:Create <Body {body}>'.format(body=body))
policy.check('create_env_template', request.context)
try:
LOG.debug('ENV TEMP NAME: {0}>'.format(body['name']))
LOG.debug('ENV TEMP NAME: {templ_name}>'.format(
templ_name=body['name']))
if not envs_api.VALID_NAME_REGEX.match(str(body['name'])):
msg = _('Environment Template must contain only alphanumeric '
'or "_-." characters, must start with alpha')
LOG.exception(msg)
LOG.error(msg)
raise exc.HTTPBadRequest(msg)
except Exception:
msg = _('Env template body is incorrect')
@ -92,7 +93,8 @@ class Controller(object):
:param env_template_id: the env template ID.
:return: the description of the env template.
"""
LOG.debug('Templates:Show <Id: {0}>'.format(env_template_id))
LOG.debug('Templates:Show <Id: {templ_id}>'.format(
templ_id=env_template_id))
target = {"env_template_id": env_template_id}
policy.check('show_env_template', request.context, target)
@ -114,14 +116,15 @@ class Controller(object):
:param body: the description to be updated
:return: the updated template description.
"""
LOG.debug('Templates:Update <Id: {0}, '
'Body: {1}>'.format(env_template_id, body))
LOG.debug('Templates:Update <Id: {templ_id}, '
'Body: {body}>'.format(templ_id=env_template_id, body=body))
target = {"env_template_id": env_template_id}
policy.check('update_env_template', request.context, target)
self._validate_request(request, env_template_id)
try:
LOG.debug('ENV TEMP NAME: {0}>'.format(body['name']))
LOG.debug('ENV TEMP NAME: {temp_name}>'.format(
temp_name=body['name']))
if not envs_api.VALID_NAME_REGEX.match(str(body['name'])):
msg = _('Env Template must contain only alphanumeric '
'or "_-." characters, must start with alpha')
@ -141,7 +144,8 @@ class Controller(object):
:param request: the operation request.
:param env_template_id: the template ID.
"""
LOG.debug('EnvTemplates:Delete <Id: {0}>'.format(env_template_id))
LOG.debug('EnvTemplates:Delete <Id: {templ_id}>'.format(
templ_id=env_template_id))
target = {"env_template_id": env_template_id}
policy.check('delete_env_template', request.context, target)
self._validate_request(request, env_template_id)
@ -169,8 +173,8 @@ class Controller(object):
:param body: the environment name
:return: session_id and environment_id
"""
LOG.debug('Templates:Create environment <Id: {0}>'.
format(env_template_id))
LOG.debug('Templates:Create environment <Id: {templ_id}>'.
format(templ_id=env_template_id))
target = {"env_template_id": env_template_id}
policy.check('create_environment', request.context, target)
@ -184,7 +188,8 @@ class Controller(object):
'or "_-." characters, must start with alpha')
LOG.error(msg)
raise exc.HTTPBadRequest(explanation=msg)
LOG.debug('ENVIRONMENT NAME: {0}>'.format(body['name']))
LOG.debug('ENVIRONMENT NAME: {env_name}>'.format(
env_name=body['name']))
try:
environment = envs.EnvironmentServices.create(
@ -214,15 +219,15 @@ class Controller(object):
def _validate_request(self, request, env_template_id):
env_template_exists = env_temps.EnvTemplateServices.env_template_exist
if not env_template_exists(env_template_id):
mng = _('EnvTemplate <TempId {0}> is not found').format(
env_template_id)
LOG.exception(mng)
raise exc.HTTPNotFound(explanation=mng)
msg = _('EnvTemplate <TempId {temp_id}> is not found').format(
temp_id=env_template_id)
LOG.exception(msg)
raise exc.HTTPNotFound(explanation=msg)
get_env_template = env_temps.EnvTemplateServices.get_env_template
env_template = get_env_template(env_template_id)
if env_template.tenant_id != request.context.tenant:
LOG.exception(_('User is not authorized to access '
'this tenant resources.'))
LOG.exception(_LE('User is not authorized to access this tenant '
'resources.'))
raise exc.HTTPUnauthorized

@ -41,23 +41,23 @@ class AdminContext(object):
def _do_import_package(_dir, categories, update=False):
LOG.info(_LI("Going to import Murano package from {0}").format(_dir))
LOG.debug("Going to import Murano package from {source}".format(
source=_dir))
pkg = load_utils.load_from_dir(_dir)
LOG.info(_LI("Checking for existing"))
LOG.debug("Checking for existing packages")
existing = db_catalog_api.package_search(
{'fqn': pkg.full_name},
AdminContext())
if existing:
existing_pkg = existing[0]
if update:
LOG.info(_LI(
"Deleting existing package {0}").format(existing_pkg.id))
LOG.debug('Deleting existing package {exst_pkg_id}').format(
exst_pkg_id=existing_pkg.id)
db_catalog_api.package_delete(existing_pkg.id, AdminContext())
else:
LOG.error(_LE("Package '{0}' exists ({1}). Use --update.").format(
pkg.full_name,
existing_pkg.id))
LOG.error(_LE("Package '{name}' exists ({pkg_id}). Use --update.")
.format(name=pkg.full_name, pkg_id=existing_pkg.id))
return
package = {
@ -83,7 +83,8 @@ def _do_import_package(_dir, categories, update=False):
# it is a required field in the DB, that's why we pass an empty string
result = db_catalog_api.package_upload(package, '')
LOG.info(_LI("Finished import of package {0}").format(result.id))
LOG.info(_LI("Finished import of package {res_id}").format(
res_id=result.id))
# TODO(ruhe): proper error handling
@ -155,14 +156,16 @@ def main():
version=version.version_string,
default_config_files=default_config_files)
except RuntimeError as e:
LOG.error(_LE("failed to initialize murano-manage: %s") % e)
LOG.error(_LE("failed to initialize murano-manage: {error}").format(
error=e))
sys.exit("ERROR: %s" % e)
try:
CONF.command.func()
except Exception as e:
tb = traceback.format_exc()
err_msg = _LE("murano-manage command failed: {0}\n{1}").format(e, tb)
err_msg = _LE("murano-manage command failed: {error}\n"
"{traceback}").format(error=e, traceback=tb)
LOG.error(err_msg)
sys.exit(err_msg)

@ -153,7 +153,7 @@ class TaskExecutor(object):
try:
self._delete_trust()
except Exception:
LOG.warn(_LW('Cannot delete trust'), exc_info=True)
LOG.warning(_LW('Cannot delete trust'), exc_info=True)
return result
@ -174,20 +174,20 @@ class TaskExecutor(object):
return self.exception_result(e, obj, '<validate>')
try:
LOG.info(_LI('Invoking pre-cleanup hooks'))
LOG.debug('Invoking pre-cleanup hooks')
self.environment.start()
executor.cleanup(self._model)
except Exception as e:
return self.exception_result(e, obj, '<GC>')
finally:
LOG.info(_LI('Invoking post-cleanup hooks'))
LOG.debug('Invoking post-cleanup hooks')
self.environment.finish()
self._model['ObjectsCopy'] = copy.deepcopy(self._model.get('Objects'))
action_result = None
if self.action:
try:
LOG.info(_LI('Invoking pre-execution hooks'))
LOG.debug('Invoking pre-execution hooks')
self.environment.start()
try:
action_result = self._invoke(executor)
@ -199,7 +199,7 @@ class TaskExecutor(object):
except Exception as e:
return self.exception_result(e, obj, self.action['method'])
finally:
LOG.info(_LI('Invoking post-execution hooks'))
LOG.debug('Invoking post-execution hooks')
self.environment.finish()
try:

@ -50,7 +50,8 @@ class PluginLoader(object):
dist_name = str(extension.entry_point.dist)
name = extension.entry_point.name
if not NAME_RE.match(name):
LOG.warning(_LW("Entry-point 'name' %s is invalid") % name)
LOG.warning(_LW("Entry-point 'name' {name} is invalid").format(
name=name))
return
name = "%s.%s" % (self.namespace, name)
name_map.setdefault(name, []).append(dist_name)
@ -64,19 +65,21 @@ class PluginLoader(object):
try:
package.classes[name] = initialize_plugin(plugin)
except Exception:
LOG.exception(_LE("Unable to initialize plugin for %s") % name)
LOG.exception(_LE("Unable to initialize plugin for {name}").format(
name=name))
return
LOG.info(_LI("Loaded class '%(class_name)s' from '%(dist)s'")
% dict(class_name=name, dist=dist_name))
LOG.info(_LI("Loaded class {class_name} from {dist}").format(
class_name=name, dist=dist_name))
def cleanup_duplicates(self, name_map):
for class_name, package_names in six.iteritems(name_map):
if len(package_names) >= 2:
LOG.warning(_LW("Class is defined in multiple packages!"))
for package_name in package_names:
LOG.warning(_LW("Disabling class '%(class_name)s' in "
"'%(dist)s' due to conflict") %
dict(class_name=class_name, dist=package_name))
LOG.warning(_LW("Disabling class {class_name} in {dist} "
"due to conflict").format(
class_name=class_name,
dist=package_name))
self.packages[package_name].classes.pop(class_name)
@staticmethod
@ -89,9 +92,8 @@ class PluginLoader(object):
@staticmethod
def _on_load_failure(manager, ep, exc):
LOG.warning(_LW("Error loading entry-point '%(ep)s' "
"from package '%(dist)s': %(err)s")
% dict(ep=ep.name, dist=ep.dist, err=exc))
LOG.warning(_LW("Error loading entry-point {ep} from package {dist}: "
"{err}").format(ep=ep.name, dist=ep.dist, err=exc))
def register_in_loader(self, package_loader):
for package in six.itervalues(self.packages):
@ -103,7 +105,7 @@ def initialize_plugin(plugin):
if hasattr(plugin, "init_plugin"):
initializer = getattr(plugin, "init_plugin")
if inspect.ismethod(initializer) and initializer.__self__ is plugin:
LOG.debug("Initializing plugin class %s" % plugin)
LOG.debug("Initializing plugin class {name}".format(name=plugin))
initializer()
return plugin

@ -19,8 +19,6 @@ from oslo_log import log as logging
from oslo_policy import policy
from webob import exc as exceptions
from murano.common.i18n import _
LOG = logging.getLogger(__name__)
CONF = cfg.CONF
@ -44,8 +42,9 @@ def set_rules(data, default_rule=None, overwrite=True):
if default_rule:
_ENFORCER.default_rule = default_rule
msg = "Loading rules %s, default: %s, overwrite: %s"
LOG.debug(msg, data, default_rule, overwrite)
LOG.debug("Loading rules {rules}, default: {def_rule}, overwrite: "
"{overwrite}".format(rules=data, def_rule=default_rule,
overwrite=overwrite))
if isinstance(data, dict):
rules = policy.Rules.from_dict(data, default_rule)
@ -77,13 +76,13 @@ def check(rule, ctxt, target={}, do_raise=True, exc=exceptions.HTTPForbidden):
extra = {'policy': {'rule': rule, 'target': target}}
if result:
LOG.info(_("Policy check succeeded for rule "
"'%(rule)s' on target %(target)s"),
{'rule': rule, 'target': repr(target)}, extra=extra)
LOG.debug("Policy check succeeded for rule {rule} on target "
"{target}".format(rule=rule, target=repr(target),
extra=extra))
else:
LOG.info(_("Policy check failed for rule "
"'%(rule)s' on target: %(target)s"),
{'rule': rule, 'target': repr(target)}, extra=extra)
LOG.debug("Policy check failed for rule {rule} on target: "
"{target}".format(rule=rule, target=repr(target),
extra=extra))
def check_is_admin(context):

@ -27,7 +27,7 @@ from murano.db import models
from murano.db.services import environments
from murano.db.services import instances
from murano.db import session
from murano.common.i18n import _, _LI, _LW
from murano.common.i18n import _LI, _LW
from murano.services import states
CONF = cfg.CONF
@ -43,7 +43,7 @@ class ResultEndpoint(object):
def process_result(context, result, environment_id):
secure_result = token_sanitizer.TokenSanitizer().sanitize(result)
LOG.debug('Got result from orchestration '
'engine:\n{0}'.format(secure_result))
'engine:\n{result}'.format(result=secure_result))
model = result['model']
action_result = result.get('action', {})
@ -114,13 +114,18 @@ class ResultEndpoint(object):
objects = model['Objects']
if objects:
services = objects.get('services')
message = _LI('EnvId: {0} TenantId: {1} Status: {2} Apps: {3}').format(
environment.id,
environment.tenant_id,
_('Failed') if num_errors + num_warnings > 0 else _('Successful'),
', '.join(map(lambda a: a['?']['type'], services))
)
LOG.info(message)
if num_errors + num_warnings > 0:
LOG.warning(_LW('EnvId: {env_id} TenantId: {tenant_id} Status: '
'Failed Apps: {services}')
.format(env_id=environment.id,
tenant_id=environment.tenant_id,
services=services))
else:
LOG.info(_LI('EnvId: {env_id} TenantId: {tenant_id} Status: '
'Successful Apps: {services}')
.format(env_id=environment.id,
tenant_id=environment.tenant_id,
services=services))
def notification_endpoint_wrapper(priority='info'):
@ -143,7 +148,7 @@ def notification_endpoint_wrapper(priority='info'):
@notification_endpoint_wrapper()
def track_instance(payload):
LOG.debug('Got track instance request from orchestration '
'engine:\n{0}'.format(payload))
'engine:\n{payload}'.format(payload=payload))
instance_id = payload['instance']
instance_type = payload.get('instance_type', 0)
environment_id = payload['environment']
@ -159,7 +164,7 @@ def track_instance(payload):
@notification_endpoint_wrapper()
def untrack_instance(payload):
LOG.debug('Got untrack instance request from orchestration '
'engine:\n{0}'.format(payload))
'engine:\n{payload}'.format(payload=payload))
instance_id = payload['instance']
environment_id = payload['environment']
instances.InstanceStatsServices.destroy_instance(
@ -169,7 +174,7 @@ def untrack_instance(payload):
@notification_endpoint_wrapper()
def report_notification(report):
LOG.debug('Got report from orchestration '
'engine:\n{0}'.format(report))
'engine:\n{report}'.format(report=report))
report['entity_id'] = report['id']
del report['id']

@ -57,13 +57,13 @@ class StatsCollectingService(service.Service):
def update_stats(self):
LOG.debug("Updating statistic information.")
LOG.debug("Stats object: %s" % v1.stats)
LOG.debug("Stats: Requests:%s Errors: %s Ave.Res.Time %2.4f\n"
"Per tenant: %s" %
(v1.stats.request_count,
v1.stats.error_count,
v1.stats.average_time,
v1.stats.requests_per_tenant))
LOG.debug("Stats object: {stats}".format(stats=v1.stats))
LOG.debug("Stats: Requests:{amount} Errors: {error}"
"Ave.Res.Time {time:2.4f}\n Per tenant: {req_count}".format(
amount=v1.stats.request_count,
error=v1.stats.error_count,
time=v1.stats.average_time,
req_count=v1.stats.requests_per_tenant))
try:
stats = self._stats_db.get_stats_by_host(self._hostname)
if stats is None:
@ -93,5 +93,5 @@ class StatsCollectingService(service.Service):
stats.cpu_percent = psutil.cpu_percent()
self._stats_db.update(self._hostname, stats)
except Exception as e:
LOG.exception(_LE("Failed to get statistics object "
"form a database. %s"), e)
LOG.exception(_LE("Failed to get statistics object from a "
"database. {error_code}").format(error_code=e))

@ -20,7 +20,7 @@ import eventlet
import jsonschema
from oslo_log import log as logging
from murano.common.i18n import _, _LI
from murano.common.i18n import _, _LE
LOG = logging.getLogger(__name__)
@ -238,10 +238,9 @@ def retry(ExceptionToCheck, tries=4, delay=3, backoff=2):
try:
return f(*args, **kwargs)
except ExceptionToCheck as e:
LOG.exception(e)
LOG.info(_LI("Retrying in {0} seconds...").format(mdelay))
LOG.exception(_LE("An exception occured {exc}. Retrying in"
"{time} seconds").format(exc=e,
time=mdelay))
eventlet.sleep(mdelay)
if not forever:

@ -41,7 +41,7 @@ import webob.exc
from murano.api.v1 import schemas
from murano.common import exceptions
from murano.common.i18n import _
from murano.common.i18n import _, _LE, _LW
from murano.common import xmlutils
wsgi_opts = [
@ -711,8 +711,8 @@ class RequestDeserializer(object):
try:
content_type = request.get_content_type()
except exceptions.UnsupportedContentType as e:
msg = "Unrecognized Content-Type provided in request: {0}"
LOG.debug(unicode(msg).format(str(e)))
LOG.error(_LE("Unrecognized Content-Type provided in request: "
"{error}").format(error=str(e)))
raise
if content_type is None:
@ -856,7 +856,8 @@ class JSONPatchDeserializer(TextDeserializer):
try:
jsonschema.validate(property_to_update, schemas.PKG_UPDATE_SCHEMA)
except jsonschema.ValidationError as e:
LOG.exception(e)
LOG.error(_LE("Schema validation error occured: {error}")
.format(error=e))
raise webob.exc.HTTPBadRequest(explanation=e.message)
def _decode_json_pointer(self, pointer):
@ -986,10 +987,11 @@ class FormDataDeserializer(TextDeserializer):
def _from_json(self, datastring):
value = datastring
try:
LOG.debug("Trying deserialize '{0}' to json".format(datastring))
LOG.debug("Trying deserialize '{data}' to json".format(
data=datastring))
value = jsonutils.loads(datastring)
except ValueError:
LOG.debug("Unable deserialize to json, using raw text")
LOG.warning(_LW("Unable deserialize to json, using raw text"))
return value
def default(self, request):

@ -42,8 +42,7 @@ def _package_get(package_id, session):
# UUID before trying to treat it as one
package = session.query(models.Package).get(package_id)
if not package:
msg = _("Package id '{0}' not found").\
format(package_id)
msg = _("Package id '{pkg_id}' not found").format(pkg_id=package_id)
LOG.error(msg)
raise exc.HTTPNotFound(explanation=msg)
@ -54,13 +53,15 @@ def _authorize_package(package, context, allow_public=False):
if package.owner_id != context.tenant:
if not allow_public:
msg = _("Package '{0}' is not owned by "
"tenant '{1}'").format(package.id, context.tenant)
msg = _("Package '{pkg_id}' is not owned by tenant "
"'{tenant}'").format(pkg_id=package.id,
tenant=context.tenant)
LOG.error(msg)
raise exc.HTTPForbidden(explanation=msg)
if not package.is_public:
msg = _("Package '{0}' is not public and not owned by "
"tenant '{1}' ").format(package.id, context.tenant)
msg = _("Package '{pkg_id}' is not public and not owned by "
"tenant '{tenant}' ").format(pkg_id=package.id,
tenant=context.tenant)
LOG.error(msg)
raise exc.HTTPForbidden(explanation=msg)
@ -164,9 +165,9 @@ def _do_add(package, change):
try: