Add a hacking rule for string interpolation at logging

From [1], string interpolation should be delayed to be handled by
the logging code, rather than being done at the point of the logging
call. Add a hacking rule, [M331], to delay the string interpolation.

[1] https://docs.openstack.org/oslo.i18n/latest/user/guidelines.html#adding-variables-to-log-messages
Change-Id: Ibf0ac960ae84e935979f93f3a0dec8d774aade78
Closes-Bug: #1705634
This commit is contained in:
Sharat Sharma 2017-07-21 14:31:21 +05:30
parent 281668a000
commit b38dceec50
32 changed files with 293 additions and 149 deletions

View File

@ -16,3 +16,4 @@ Mistral Specific Commandments
- [M328] Python 3: do not use dict.iteritems. - [M328] Python 3: do not use dict.iteritems.
- [M329] Python 3: do not use dict.iterkeys. - [M329] Python 3: do not use dict.iterkeys.
- [M330] Python 3: do not use dict.itervalues. - [M330] Python 3: do not use dict.itervalues.
- [M331] String interpolation should be delayed at logging calls.

View File

@ -43,8 +43,10 @@ def get_mapping():
path = CONF.openstack_actions_mapping_path path = CONF.openstack_actions_mapping_path
mapping_file_path = pkg.resource_filename(package, path) mapping_file_path = pkg.resource_filename(package, path)
LOG.info("Processing OpenStack action mapping from file: %s", LOG.info(
mapping_file_path) "Processing OpenStack action mapping from file: %s",
mapping_file_path
)
with open(mapping_file_path) as fh: with open(mapping_file_path) as fh:
mapping = json.load(fh) mapping = json.load(fh)
@ -140,8 +142,10 @@ class OpenStackActionGenerator(action_generator.ActionGenerator):
try: try:
client_method = class_.get_fake_client_method() client_method = class_.get_fake_client_method()
except Exception: except Exception:
LOG.exception("Failed to create action: %s.%s" % LOG.exception(
(cls.action_namespace, action_name)) "Failed to create action: %s.%s",
cls.action_namespace, action_name
)
continue continue
arg_list = i_u.get_arg_list_as_str(client_method) arg_list = i_u.get_arg_list_as_str(client_method)

View File

@ -78,7 +78,7 @@ class NovaAction(base.OpenStackAction):
return novaclient.Client return novaclient.Client
def _create_client(self, context): def _create_client(self, context):
LOG.debug("Nova action security context: %s" % context) LOG.debug("Nova action security context: %s", context)
return novaclient.Client(2, **self.get_session_and_auth(context)) return novaclient.Client(2, **self.get_session_and_auth(context))
@ -96,7 +96,7 @@ class GlanceAction(base.OpenStackAction):
def _create_client(self, context): def _create_client(self, context):
LOG.debug("Glance action security context: %s" % context) LOG.debug("Glance action security context: %s", context)
glance_endpoint = self.get_service_endpoint() glance_endpoint = self.get_service_endpoint()
@ -121,7 +121,7 @@ class KeystoneAction(base.OpenStackAction):
def _create_client(self, context): def _create_client(self, context):
LOG.debug("Keystone action security context: %s" % context) LOG.debug("Keystone action security context: %s", context)
kwargs = self.get_session_and_auth(context) kwargs = self.get_session_and_auth(context)
@ -157,7 +157,7 @@ class CeilometerAction(base.OpenStackAction):
def _create_client(self, context): def _create_client(self, context):
LOG.debug("Ceilometer action security context: %s" % context) LOG.debug("Ceilometer action security context: %s", context)
ceilometer_endpoint = self.get_service_endpoint() ceilometer_endpoint = self.get_service_endpoint()
@ -188,7 +188,7 @@ class HeatAction(base.OpenStackAction):
def _create_client(self, context): def _create_client(self, context):
LOG.debug("Heat action security context: %s" % context) LOG.debug("Heat action security context: %s", context)
heat_endpoint = self.get_service_endpoint() heat_endpoint = self.get_service_endpoint()
@ -220,7 +220,7 @@ class NeutronAction(base.OpenStackAction):
def _create_client(self, context): def _create_client(self, context):
LOG.debug("Neutron action security context: %s" % context) LOG.debug("Neutron action security context: %s", context)
neutron_endpoint = self.get_service_endpoint() neutron_endpoint = self.get_service_endpoint()
@ -242,7 +242,7 @@ class CinderAction(base.OpenStackAction):
def _create_client(self, context): def _create_client(self, context):
LOG.debug("Cinder action security context: %s" % context) LOG.debug("Cinder action security context: %s", context)
cinder_endpoint = self.get_service_endpoint() cinder_endpoint = self.get_service_endpoint()
@ -282,7 +282,7 @@ class MistralAction(base.OpenStackAction):
def _create_client(self, context): def _create_client(self, context):
LOG.debug("Mistral action security context: %s" % context) LOG.debug("Mistral action security context: %s", context)
session_and_auth = self.get_session_and_auth(context) session_and_auth = self.get_session_and_auth(context)
return self._get_client_class()( return self._get_client_class()(
@ -304,7 +304,7 @@ class TroveAction(base.OpenStackAction):
def _create_client(self, context): def _create_client(self, context):
LOG.debug("Trove action security context: %s" % context) LOG.debug("Trove action security context: %s", context)
trove_endpoint = self.get_service_endpoint() trove_endpoint = self.get_service_endpoint()
@ -341,7 +341,7 @@ class IronicAction(base.OpenStackAction):
def _create_client(self, context): def _create_client(self, context):
LOG.debug("Ironic action security context: %s" % context) LOG.debug("Ironic action security context: %s", context)
ironic_endpoint = self.get_service_endpoint() ironic_endpoint = self.get_service_endpoint()
@ -376,7 +376,7 @@ class BaremetalIntrospectionAction(base.OpenStackAction):
return cls._get_client_class()(session=sess) return cls._get_client_class()(session=sess)
except Exception as e: except Exception as e:
LOG.warning("There was an error trying to create the " LOG.warning("There was an error trying to create the "
"ironic-inspector client using a session: %s" % str(e)) "ironic-inspector client using a session: %s", str(e))
# If it's not possible to establish a keystone session, attempt to # If it's not possible to establish a keystone session, attempt to
# create a client without it. This should fall back to where the # create a client without it. This should fall back to where the
# ironic-inspector client tries to get it's own version on the # ironic-inspector client tries to get it's own version on the
@ -389,7 +389,7 @@ class BaremetalIntrospectionAction(base.OpenStackAction):
def _create_client(self, context): def _create_client(self, context):
LOG.debug( LOG.debug(
"Baremetal introspection action security context: %s" % context) "Baremetal introspection action security context: %s", context)
inspector_endpoint = keystone_utils.get_endpoint_for_project( inspector_endpoint = keystone_utils.get_endpoint_for_project(
service_type='baremetal-introspection' service_type='baremetal-introspection'
@ -410,7 +410,7 @@ class SwiftAction(base.OpenStackAction):
def _create_client(self, context): def _create_client(self, context):
LOG.debug("Swift action security context: %s" % context) LOG.debug("Swift action security context: %s", context)
swift_endpoint = keystone_utils.get_endpoint_for_project('swift') swift_endpoint = keystone_utils.get_endpoint_for_project('swift')
@ -433,7 +433,7 @@ class ZaqarAction(base.OpenStackAction):
def _create_client(self, context): def _create_client(self, context):
LOG.debug("Zaqar action security context: %s" % context) LOG.debug("Zaqar action security context: %s", context)
zaqar_endpoint = keystone_utils.get_endpoint_for_project( zaqar_endpoint = keystone_utils.get_endpoint_for_project(
service_type='messaging') service_type='messaging')
@ -538,7 +538,7 @@ class BarbicanAction(base.OpenStackAction):
def _create_client(self, context): def _create_client(self, context):
LOG.debug("Barbican action security context: %s" % context) LOG.debug("Barbican action security context: %s", context)
barbican_endpoint = keystone_utils.get_endpoint_for_project('barbican') barbican_endpoint = keystone_utils.get_endpoint_for_project('barbican')
keystone_endpoint = keystone_utils.get_keystone_endpoint_v2() keystone_endpoint = keystone_utils.get_keystone_endpoint_v2()
@ -644,7 +644,7 @@ class DesignateAction(base.OpenStackAction):
def _create_client(self, context): def _create_client(self, context):
LOG.debug("Designate action security context: %s" % context) LOG.debug("Designate action security context: %s", context)
designate_endpoint = self.get_service_endpoint() designate_endpoint = self.get_service_endpoint()
@ -680,7 +680,7 @@ class MagnumAction(base.OpenStackAction):
def _create_client(self, context): def _create_client(self, context):
LOG.debug("Magnum action security context: %s" % context) LOG.debug("Magnum action security context: %s", context)
keystone_endpoint = keystone_utils.get_keystone_endpoint_v2() keystone_endpoint = keystone_utils.get_keystone_endpoint_v2()
auth_url = keystone_endpoint.url auth_url = keystone_endpoint.url
@ -709,7 +709,7 @@ class MuranoAction(base.OpenStackAction):
def _create_client(self, context): def _create_client(self, context):
LOG.debug("Murano action security context: %s" % context) LOG.debug("Murano action security context: %s", context)
keystone_endpoint = keystone_utils.get_keystone_endpoint_v2() keystone_endpoint = keystone_utils.get_keystone_endpoint_v2()
murano_endpoint = self.get_service_endpoint() murano_endpoint = self.get_service_endpoint()
@ -737,7 +737,7 @@ class TackerAction(base.OpenStackAction):
def _create_client(self, context): def _create_client(self, context):
LOG.debug("Tacker action security context: %s" % context) LOG.debug("Tacker action security context: %s", context)
keystone_endpoint = keystone_utils.get_keystone_endpoint_v2() keystone_endpoint = keystone_utils.get_keystone_endpoint_v2()
tacker_endpoint = self.get_service_endpoint() tacker_endpoint = self.get_service_endpoint()
@ -765,7 +765,7 @@ class SenlinAction(base.OpenStackAction):
def _create_client(self, context): def _create_client(self, context):
LOG.debug("Senlin action security context: %s" % context) LOG.debug("Senlin action security context: %s", context)
keystone_endpoint = keystone_utils.get_keystone_endpoint_v2() keystone_endpoint = keystone_utils.get_keystone_endpoint_v2()
senlin_endpoint = self.get_service_endpoint() senlin_endpoint = self.get_service_endpoint()
@ -793,7 +793,7 @@ class AodhAction(base.OpenStackAction):
def _create_client(self, context): def _create_client(self, context):
LOG.debug("Aodh action security context: %s" % context) LOG.debug("Aodh action security context: %s", context)
aodh_endpoint = self.get_service_endpoint() aodh_endpoint = self.get_service_endpoint()
@ -824,7 +824,7 @@ class GnocchiAction(base.OpenStackAction):
def _create_client(self, context): def _create_client(self, context):
LOG.debug("Gnocchi action security context: %s" % context) LOG.debug("Gnocchi action security context: %s", context)
gnocchi_endpoint = self.get_service_endpoint() gnocchi_endpoint = self.get_service_endpoint()

View File

@ -45,7 +45,7 @@ class EchoAction(actions.Action):
self.output = output self.output = output
def run(self, context): def run(self, context):
LOG.info('Running echo action [output=%s]' % self.output) LOG.info('Running echo action [output=%s]', self.output)
return self.output return self.output
@ -158,11 +158,12 @@ class HTTPAction(actions.Action):
self.verify = verify self.verify = verify
def run(self, context): def run(self, context):
LOG.info("Running HTTP action " LOG.info(
"Running HTTP action "
"[url=%s, method=%s, params=%s, body=%s, headers=%s," "[url=%s, method=%s, params=%s, body=%s, headers=%s,"
" cookies=%s, auth=%s, timeout=%s, allow_redirects=%s," " cookies=%s, auth=%s, timeout=%s, allow_redirects=%s,"
" proxies=%s, verify=%s]" % " proxies=%s, verify=%s]",
(self.url, self.url,
self.method, self.method,
self.params, self.params,
self.body, self.body,
@ -172,7 +173,8 @@ class HTTPAction(actions.Action):
self.timeout, self.timeout,
self.allow_redirects, self.allow_redirects,
self.proxies, self.proxies,
self.verify)) self.verify
)
try: try:
resp = requests.request( resp = requests.request(
@ -192,7 +194,9 @@ class HTTPAction(actions.Action):
raise exc.ActionException("Failed to send HTTP request: %s" % e) raise exc.ActionException("Failed to send HTTP request: %s" % e)
LOG.info( LOG.info(
"HTTP action response:\n%s\n%s" % (resp.status_code, resp.content) "HTTP action response:\n%s\n%s",
resp.status_code,
resp.content
) )
# TODO(akuznetsova): Need to refactor Mistral serialiser and # TODO(akuznetsova): Need to refactor Mistral serialiser and
@ -295,10 +299,15 @@ class SendEmailAction(actions.Action):
self.password = smtp_password self.password = smtp_password
def run(self, context): def run(self, context):
LOG.info("Sending email message " LOG.info(
"[from=%s, to=%s, subject=%s, using smtp=%s, body=%s...]" % "Sending email message "
(self.sender, self.to, self.subject, "[from=%s, to=%s, subject=%s, using smtp=%s, body=%s...]",
self.smtp_server, self.body[:128])) self.sender,
self.to,
self.subject,
self.smtp_server,
self.body[:128]
)
message = text.MIMEText(self.body, _charset='utf-8') message = text.MIMEText(self.body, _charset='utf-8')
message['Subject'] = header.Header(self.subject, 'utf-8') message['Subject'] = header.Header(self.subject, 'utf-8')
@ -325,10 +334,15 @@ class SendEmailAction(actions.Action):
def test(self, context): def test(self, context):
# Just logging the operation since this action is not supposed # Just logging the operation since this action is not supposed
# to return a result. # to return a result.
LOG.info("Sending email message " LOG.info(
"[from=%s, to=%s, subject=%s, using smtp=%s, body=%s...]" % "Sending email message "
(self.sender, self.to, self.subject, "[from=%s, to=%s, subject=%s, using smtp=%s, body=%s...]",
self.smtp_server, self.body[:128])) self.sender,
self.to,
self.subject,
self.smtp_server,
self.body[:128]
)
class SSHAction(actions.Action): class SSHAction(actions.Action):
@ -466,7 +480,7 @@ class SleepAction(actions.Action):
self._seconds = 0 self._seconds = 0
def run(self, context): def run(self, context):
LOG.info('Running sleep action [seconds=%s]' % self._seconds) LOG.info('Running sleep action [seconds=%s]', self._seconds)
time.sleep(self._seconds) time.sleep(self._seconds)
@ -488,8 +502,10 @@ class TestDictAction(actions.Action):
def run(self, context): def run(self, context):
LOG.info( LOG.info(
'Running test_dict action [size=%s, key_prefix=%s, val=%s]' % 'Running test_dict action [size=%s, key_prefix=%s, val=%s]',
(self.size, self.key_prefix, self.val) self.size,
self.key_prefix,
self.val
) )
res = {} res = {}

View File

@ -136,7 +136,10 @@ class ActionExecutionsController(rest.RestController):
""" """
acl.enforce('action_executions:create', context.ctx()) acl.enforce('action_executions:create', context.ctx())
LOG.info("Create action_execution [action_execution=%s]", action_ex) LOG.info(
"Create action_execution [action_execution=%s]",
action_ex
)
name = action_ex.name name = action_ex.name
description = action_ex.description or None description = action_ex.description or None
@ -172,8 +175,9 @@ class ActionExecutionsController(rest.RestController):
acl.enforce('action_executions:update', context.ctx()) acl.enforce('action_executions:update', context.ctx())
LOG.info( LOG.info(
"Update action_execution [id=%s, action_execution=%s]" "Update action_execution [id=%s, action_execution=%s]",
% (id, action_ex) id,
action_ex
) )
output = action_ex.output output = action_ex.output
@ -274,9 +278,15 @@ class ActionExecutionsController(rest.RestController):
description=description description=description
) )
LOG.info("Fetch action_executions. marker=%s, limit=%s, " LOG.info(
"Fetch action_executions. marker=%s, limit=%s, "
"sort_keys=%s, sort_dirs=%s, filters=%s", "sort_keys=%s, sort_dirs=%s, filters=%s",
marker, limit, sort_keys, sort_dirs, filters) marker,
limit,
sort_keys,
sort_dirs,
filters
)
return _get_action_executions( return _get_action_executions(
marker=marker, marker=marker,
@ -397,9 +407,15 @@ class TasksActionExecutionController(rest.RestController):
description=description description=description
) )
LOG.info("Fetch action_executions. marker=%s, limit=%s, " LOG.info(
"Fetch action_executions. marker=%s, limit=%s, "
"sort_keys=%s, sort_dirs=%s, filters=%s", "sort_keys=%s, sort_dirs=%s, filters=%s",
marker, limit, sort_keys, sort_dirs, filters) marker,
limit,
sort_keys,
sort_dirs,
filters
)
return _get_action_executions( return _get_action_executions(
marker=marker, marker=marker,

View File

@ -39,7 +39,7 @@ class CronTriggersController(rest.RestController):
""" """
acl.enforce('cron_triggers:get', context.ctx()) acl.enforce('cron_triggers:get', context.ctx())
LOG.info('Fetch cron trigger [name=%s]' % name) LOG.info('Fetch cron trigger [name=%s]', name)
db_model = db_api.get_cron_trigger(name) db_model = db_api.get_cron_trigger(name)
@ -58,7 +58,7 @@ class CronTriggersController(rest.RestController):
""" """
acl.enforce('cron_triggers:create', context.ctx()) acl.enforce('cron_triggers:create', context.ctx())
LOG.info('Create cron trigger: %s' % cron_trigger) LOG.info('Create cron trigger: %s', cron_trigger)
values = cron_trigger.to_dict() values = cron_trigger.to_dict()
@ -84,7 +84,7 @@ class CronTriggersController(rest.RestController):
""" """
acl.enforce('cron_triggers:delete', context.ctx()) acl.enforce('cron_triggers:delete', context.ctx())
LOG.info("Delete cron trigger [name=%s]" % name) LOG.info("Delete cron trigger [name=%s]", name)
triggers.delete_cron_trigger(name) triggers.delete_cron_trigger(name)

View File

@ -108,7 +108,7 @@ class EnvironmentController(rest.RestController):
""" """
acl.enforce('environments:get', context.ctx()) acl.enforce('environments:get', context.ctx())
LOG.info("Fetch environment [name=%s]" % name) LOG.info("Fetch environment [name=%s]", name)
db_model = db_api.get_environment(name) db_model = db_api.get_environment(name)
@ -127,7 +127,7 @@ class EnvironmentController(rest.RestController):
""" """
acl.enforce('environments:create', context.ctx()) acl.enforce('environments:create', context.ctx())
LOG.info("Create environment [env=%s]" % env) LOG.info("Create environment [env=%s]", env)
self._validate_environment( self._validate_environment(
json.loads(wsme_pecan.pecan.request.body.decode()), json.loads(wsme_pecan.pecan.request.body.decode()),
@ -152,7 +152,7 @@ class EnvironmentController(rest.RestController):
'Name of the environment is not provided.' 'Name of the environment is not provided.'
) )
LOG.info("Update environment [name=%s, env=%s]" % (env.name, env)) LOG.info("Update environment [name=%s, env=%s]", env.name, env)
definition = json.loads(wsme_pecan.pecan.request.body.decode()) definition = json.loads(wsme_pecan.pecan.request.body.decode())
definition.pop('name') definition.pop('name')
@ -175,7 +175,7 @@ class EnvironmentController(rest.RestController):
""" """
acl.enforce('environments:delete', context.ctx()) acl.enforce('environments:delete', context.ctx())
LOG.info("Delete environment [name=%s]" % name) LOG.info("Delete environment [name=%s]", name)
db_api.delete_environment(name) db_api.delete_environment(name)

View File

@ -96,7 +96,7 @@ class ExecutionsController(rest.RestController):
""" """
acl.enforce('executions:update', context.ctx()) acl.enforce('executions:update', context.ctx())
LOG.info('Update execution [id=%s, execution=%s]' % (id, wf_ex)) LOG.info('Update execution [id=%s, execution=%s]', id, wf_ex)
with db_api.transaction(): with db_api.transaction():
db_api.ensure_workflow_execution_exists(id) db_api.ensure_workflow_execution_exists(id)

View File

@ -142,7 +142,7 @@ class TasksController(rest.RestController):
:param id: UUID of task to retrieve :param id: UUID of task to retrieve
""" """
acl.enforce('tasks:get', context.ctx()) acl.enforce('tasks:get', context.ctx())
LOG.info("Fetch task [id=%s]" % id) LOG.info("Fetch task [id=%s]", id)
with db_api.transaction(): with db_api.transaction():
task_ex = db_api.get_task_execution(id) task_ex = db_api.get_task_execution(id)
@ -248,7 +248,7 @@ class TasksController(rest.RestController):
""" """
acl.enforce('tasks:update', context.ctx()) acl.enforce('tasks:update', context.ctx())
LOG.info("Update task execution [id=%s, task=%s]" % (id, task)) LOG.info("Update task execution [id=%s, task=%s]", id, task)
with db_api.transaction(): with db_api.transaction():
task_ex = db_api.get_task_execution(id) task_ex = db_api.get_task_execution(id)

View File

@ -51,7 +51,7 @@ class WorkbooksController(rest.RestController, hooks.HookController):
""" """
acl.enforce('workbooks:get', context.ctx()) acl.enforce('workbooks:get', context.ctx())
LOG.info("Fetch workbook [name=%s]" % name) LOG.info("Fetch workbook [name=%s]", name)
db_model = db_api.get_workbook(name) db_model = db_api.get_workbook(name)
@ -65,7 +65,7 @@ class WorkbooksController(rest.RestController, hooks.HookController):
definition = pecan.request.text definition = pecan.request.text
LOG.info("Update workbook [definition=%s]" % definition) LOG.info("Update workbook [definition=%s]", definition)
wb_db = workbooks.update_workbook_v2(definition) wb_db = workbooks.update_workbook_v2(definition)
@ -79,7 +79,7 @@ class WorkbooksController(rest.RestController, hooks.HookController):
definition = pecan.request.text definition = pecan.request.text
LOG.info("Create workbook [definition=%s]" % definition) LOG.info("Create workbook [definition=%s]", definition)
wb_db = workbooks.create_workbook_v2(definition) wb_db = workbooks.create_workbook_v2(definition)
@ -96,7 +96,7 @@ class WorkbooksController(rest.RestController, hooks.HookController):
""" """
acl.enforce('workbooks:delete', context.ctx()) acl.enforce('workbooks:delete', context.ctx())
LOG.info("Delete workbook [name=%s]" % name) LOG.info("Delete workbook [name=%s]", name)
db_api.delete_workbook(name) db_api.delete_workbook(name)

View File

@ -79,7 +79,7 @@ class KeycloakAuthHandler(auth.AuthHandler):
resp.raise_for_status() resp.raise_for_status()
LOG.debug( LOG.debug(
"HTTP response from OIDC provider: %s" % "HTTP response from OIDC provider: %s",
pprint.pformat(resp.json()) pprint.pformat(resp.json())
) )

View File

@ -92,9 +92,11 @@ class EngineServer(service_base.MistralService):
LOG.info( LOG.info(
"Received RPC request 'start_workflow'[workflow_identifier=%s, " "Received RPC request 'start_workflow'[workflow_identifier=%s, "
"workflow_input=%s, description=%s, params=%s]" % "workflow_input=%s, description=%s, params=%s]",
(workflow_identifier, utils.cut(workflow_input), workflow_identifier,
description, params) utils.cut(workflow_input),
description,
params
) )
return self.engine.start_workflow( return self.engine.start_workflow(
@ -117,8 +119,11 @@ class EngineServer(service_base.MistralService):
""" """
LOG.info( LOG.info(
"Received RPC request 'start_action'[name=%s, input=%s, " "Received RPC request 'start_action'[name=%s, input=%s, "
"description=%s, params=%s]" "description=%s, params=%s]",
% (action_name, utils.cut(action_input), description, params) action_name,
utils.cut(action_input),
description,
params
) )
return self.engine.start_action( return self.engine.start_action(
@ -139,7 +144,9 @@ class EngineServer(service_base.MistralService):
""" """
LOG.info( LOG.info(
"Received RPC request 'on_action_complete'[action_ex_id=%s, " "Received RPC request 'on_action_complete'[action_ex_id=%s, "
"result=%s]" % (action_ex_id, result.cut_repr()) "result=%s]",
action_ex_id,
result.cut_repr()
) )
return self.engine.on_action_complete(action_ex_id, result, wf_action) return self.engine.on_action_complete(action_ex_id, result, wf_action)
@ -152,7 +159,7 @@ class EngineServer(service_base.MistralService):
:return: Workflow execution. :return: Workflow execution.
""" """
LOG.info( LOG.info(
"Received RPC request 'pause_workflow'[execution_id=%s]" % "Received RPC request 'pause_workflow'[execution_id=%s]",
execution_id execution_id
) )
@ -168,7 +175,7 @@ class EngineServer(service_base.MistralService):
:return: Workflow execution. :return: Workflow execution.
""" """
LOG.info( LOG.info(
"Received RPC request 'rerun_workflow'[task_ex_id=%s]" % "Received RPC request 'rerun_workflow'[task_ex_id=%s]",
task_ex_id task_ex_id
) )
@ -183,7 +190,8 @@ class EngineServer(service_base.MistralService):
:return: Workflow execution. :return: Workflow execution.
""" """
LOG.info( LOG.info(
"Received RPC request 'resume_workflow'[wf_ex_id=%s]" % wf_ex_id "Received RPC request 'resume_workflow'[wf_ex_id=%s]",
wf_ex_id
) )
return self.engine.resume_workflow(wf_ex_id, env) return self.engine.resume_workflow(wf_ex_id, env)
@ -205,8 +213,10 @@ class EngineServer(service_base.MistralService):
""" """
LOG.info( LOG.info(
"Received RPC request 'stop_workflow'[execution_id=%s," "Received RPC request 'stop_workflow'[execution_id=%s,"
" state=%s, message=%s]" % " state=%s, message=%s]",
(execution_id, state, message) execution_id,
state,
message
) )
return self.engine.stop_workflow(execution_id, state, message) return self.engine.stop_workflow(execution_id, state, message)
@ -218,7 +228,7 @@ class EngineServer(service_base.MistralService):
:return: Workflow execution. :return: Workflow execution.
""" """
LOG.info( LOG.info(
"Received RPC request 'rollback_workflow'[execution_id=%s]" % "Received RPC request 'rollback_workflow'[execution_id=%s]",
execution_id execution_id
) )

View File

@ -284,8 +284,10 @@ class RegularTask(Task):
self._create_task_execution() self._create_task_execution()
LOG.debug( LOG.debug(
'Starting task [workflow=%s, task=%s, init_state=%s]' % 'Starting task [workflow=%s, task=%s, init_state=%s]',
(self.wf_ex.name, self.task_spec.get_name(), self.task_ex.state) self.wf_ex.name,
self.task_spec.get_name(),
self.task_ex.state
) )
self._before_task_start() self._before_task_start()

View File

@ -220,8 +220,10 @@ class Workflow(object):
except Exception as e: except Exception as e:
LOG.warning( LOG.warning(
'Failed to get final context for workflow execution. ' 'Failed to get final context for workflow execution. '
'[wf_ex_id: %s, wf_name: %s, error: %s]' % '[wf_ex_id: %s, wf_name: %s, error: %s]',
(self.wf_ex.id, self.wf_ex.name, str(e)) self.wf_ex.id,
self.wf_ex.name,
str(e)
) )
return final_context return final_context

View File

@ -74,13 +74,12 @@ class ExecutorServer(service_base.MistralService):
LOG.info( LOG.info(
"Received RPC request 'run_action'[action_ex_id=%s, " "Received RPC request 'run_action'[action_ex_id=%s, "
"action_cls_str=%s, action_cls_attrs=%s, params=%s]" % ( "action_cls_str=%s, action_cls_attrs=%s, params=%s]",
action_ex_id, action_ex_id,
action_cls_str, action_cls_str,
action_cls_attrs, action_cls_attrs,
utils.cut(params) utils.cut(params)
) )
)
redelivered = rpc_ctx.redelivered or False redelivered = rpc_ctx.redelivered or False

View File

@ -78,8 +78,12 @@ def _evaluate_item(item, context):
try: try:
return evaluate(item, context) return evaluate(item, context)
except AttributeError as e: except AttributeError as e:
LOG.debug("Expression %s is not evaluated, [context=%s]: %s" LOG.debug(
% (item, context, e)) "Expression %s is not evaluated, [context=%s]: %s",
item,
context,
e
)
return item return item
else: else:
return evaluate_recursively(item, context) return evaluate_recursively(item, context)

View File

@ -114,8 +114,10 @@ class InlineJinjaEvaluator(Evaluator):
@classmethod @classmethod
def evaluate(cls, expression, data_context): def evaluate(cls, expression, data_context):
LOG.debug( LOG.debug(
"Start to evaluate Jinja expression. [expression='%s', context=%s]" "Start to evaluate Jinja expression. "
% (expression, data_context) "[expression='%s', context=%s]",
expression,
data_context
) )
patterns = cls.find_expression_pattern.findall(expression) patterns = cls.find_expression_pattern.findall(expression)
@ -127,8 +129,9 @@ class InlineJinjaEvaluator(Evaluator):
result = cls._env.from_string(expression).render(**ctx) result = cls._env.from_string(expression).render(**ctx)
LOG.debug( LOG.debug(
"Finished evaluation. [expression='%s', result: %s]" % "Finished evaluation. [expression='%s', result: %s]",
(expression, result) expression,
result
) )
return result return result

View File

@ -84,8 +84,10 @@ class InlineYAQLEvaluator(YAQLEvaluator):
@classmethod @classmethod
def evaluate(cls, expression, data_context): def evaluate(cls, expression, data_context):
LOG.debug( LOG.debug(
"Start to evaluate YAQL expression. [expression='%s', context=%s]" "Start to evaluate YAQL expression. "
% (expression, data_context) "[expression='%s', context=%s]",
expression,
data_context
) )
result = expression result = expression
@ -102,8 +104,9 @@ class InlineYAQLEvaluator(YAQLEvaluator):
result = result.replace(expr, str(evaluated)) result = result.replace(expr, str(evaluated))
LOG.debug( LOG.debug(
"Finished evaluation. [expression='%s', result: %s]" % "Finished evaluation. [expression='%s', result: %s]",
(expression, result) expression,
result
) )
return result return result

View File

@ -34,6 +34,9 @@ assert_equal_end_with_none_re = re.compile(
r"(.)*assertEqual\((\w|\.|\'|\"|\[|\])+, None\)") r"(.)*assertEqual\((\w|\.|\'|\"|\[|\])+, None\)")
assert_equal_start_with_none_re = re.compile( assert_equal_start_with_none_re = re.compile(
r"(.)*assertEqual\(None, (\w|\.|\'|\"|\[|\])+\)") r"(.)*assertEqual\(None, (\w|\.|\'|\"|\[|\])+\)")
log_string_interpolation = re.compile(r".*LOG\.(?:error|warn|warning|info"
r"|critical|exception|debug)"
r"\([^,]*%[^,]*[,)]")
def assert_equal_none(logical_line): def assert_equal_none(logical_line):
@ -122,6 +125,27 @@ def check_python3_no_itervalues(logical_line):
yield(0, msg) yield(0, msg)
def check_delayed_string_interpolation(logical_line, filename, noqa):
"""M331: String interpolation should be delayed at logging calls.
M331: LOG.debug('Example: %s' % 'bad')
Okay: LOG.debug('Example: %s', 'good')
"""
msg = ("M331 String interpolation should be delayed to be "
"handled by the logging code, rather than being done "
"at the point of the logging call. "
"Use ',' instead of '%'.")
if noqa:
return
if 'mistral/tests/' in filename:
return
if log_string_interpolation.match(logical_line):
yield(logical_line.index('%'), msg)
class BaseASTChecker(ast.NodeVisitor): class BaseASTChecker(ast.NodeVisitor):
"""Provides a simple framework for writing AST-based checks. """Provides a simple framework for writing AST-based checks.
@ -291,3 +315,4 @@ def factory(register):
register(check_python3_no_iterkeys) register(check_python3_no_iterkeys)
register(check_python3_no_itervalues) register(check_python3_no_itervalues)
register(check_python3_xrange) register(check_python3_xrange)
register(check_delayed_string_interpolation)

View File

@ -75,7 +75,7 @@ class KombuRPCListener(ConsumerMixin):
try: try:
message.ack() message.ack()
except Exception as e: except Exception as e:
LOG.exception("Failed to acknowledge AMQP message: %s" % e) LOG.exception("Failed to acknowledge AMQP message: %s", e)
else: else:
LOG.debug("AMQP message acknowledged.") LOG.debug("AMQP message acknowledged.")
@ -103,7 +103,8 @@ class KombuRPCListener(ConsumerMixin):
def on_connection_error(self, exc, interval): def on_connection_error(self, exc, interval):
self.connection = six.next(self._connections) self.connection = six.next(self._connections)
LOG.debug("Broker connection failed: %s" % exc) LOG.debug("Broker connection failed: %s", exc)
LOG.debug("Sleeping for %s seconds, then retrying connection" % LOG.debug(
"Sleeping for %s seconds, then retrying connection",
interval interval
) )

View File

@ -120,10 +120,11 @@ class KombuRPCServer(rpc_base.RPCServer, kombu_base.Base):
self._running.set() self._running.set()
self._stopped.clear() self._stopped.clear()
LOG.info("Connected to AMQP at %s:%s" % ( LOG.info(
"Connected to AMQP at %s:%s",
host.hostname, host.hostname,
host.port host.port
)) )
while self.is_running: while self.is_running:
try: try:
@ -134,18 +135,20 @@ class KombuRPCServer(rpc_base.RPCServer, kombu_base.Base):
self.stop() self.stop()
LOG.info("Server with id='{0}' stopped.".format( LOG.info("Server with id='{0}' stopped.".format(
self.server_id)) self.server_id)
)
return return
except (socket.error, amqp.exceptions.ConnectionForced) as e: except (socket.error, amqp.exceptions.ConnectionForced) as e:
LOG.debug("Broker connection failed: %s" % e) LOG.debug("Broker connection failed: %s", e)
_retry_connection = True _retry_connection = True
finally: finally:
self._stopped.set() self._stopped.set()
if _retry_connection: if _retry_connection:
LOG.debug( LOG.debug(
"Sleeping for %s seconds, than retrying connection" % "Sleeping for %s seconds, than retrying "
"connection",
self._sleep_time self._sleep_time
) )
@ -168,7 +171,7 @@ class KombuRPCServer(rpc_base.RPCServer, kombu_base.Base):
try: try:
self._worker.shutdown(wait=True) self._worker.shutdown(wait=True)
except AttributeError as e: except AttributeError as e:
LOG.warning("Cannot stop worker in graceful way: %s" % e) LOG.warning("Cannot stop worker in graceful way: %s", e)
def _get_rpc_method(self, method_name): def _get_rpc_method(self, method_name):
for endpoint in self.endpoints: for endpoint in self.endpoints:
@ -209,7 +212,7 @@ class KombuRPCServer(rpc_base.RPCServer, kombu_base.Base):
"Got exception while consuming message. Exception would be " "Got exception while consuming message. Exception would be "
"send back to the caller." "send back to the caller."
) )
LOG.debug("Exceptions: %s" % str(e)) LOG.debug("Exceptions: %s", str(e))
# Wrap exception into another exception for compability with oslo. # Wrap exception into another exception for compability with oslo.
self.publish_message( self.publish_message(
@ -222,8 +225,7 @@ class KombuRPCServer(rpc_base.RPCServer, kombu_base.Base):
message.ack() message.ack()
def _on_message(self, request, message): def _on_message(self, request, message):
LOG.debug('Received message %s', LOG.debug('Received message %s', request)
request)
is_async = request.get('async', False) is_async = request.get('async', False)
rpc_ctx = request.get('rpc_ctx') rpc_ctx = request.get('rpc_ctx')

View File

@ -65,11 +65,11 @@ def register_action_class(name, action_class_str, attributes,
} }
try: try:
LOG.debug("Registering action in DB: %s" % name) LOG.debug("Registering action in DB: %s", name)
db_api.create_action_definition(values) db_api.create_action_definition(values)
except exc.DBDuplicateEntryError: except exc.DBDuplicateEntryError:
LOG.debug("Action %s already exists in DB." % name) LOG.debug("Action %s already exists in DB.", name)
def _clear_system_action_db(): def _clear_system_action_db():

View File

@ -36,7 +36,7 @@ class MistralPeriodicTasks(periodic_task.PeriodicTasks):
@periodic_task.periodic_task(spacing=1, run_immediately=True) @periodic_task.periodic_task(spacing=1, run_immediately=True)
def process_cron_triggers_v2(self, ctx): def process_cron_triggers_v2(self, ctx):
for trigger in triggers.get_next_cron_triggers(): for trigger in triggers.get_next_cron_triggers():
LOG.debug("Processing cron trigger: %s" % trigger) LOG.debug("Processing cron trigger: %s", trigger)
try: try:
# Setup admin context before schedule triggers. # Setup admin context before schedule triggers.
@ -45,7 +45,7 @@ class MistralPeriodicTasks(periodic_task.PeriodicTasks):
) )
auth_ctx.set_ctx(ctx) auth_ctx.set_ctx(ctx)
LOG.debug("Cron trigger security context: %s" % ctx) LOG.debug("Cron trigger security context: %s", ctx)
# Try to advance the cron trigger next_execution_time and # Try to advance the cron trigger next_execution_time and
# remaining_executions if relevant. # remaining_executions if relevant.
@ -55,7 +55,8 @@ class MistralPeriodicTasks(periodic_task.PeriodicTasks):
if modified: if modified:
LOG.debug( LOG.debug(
"Starting workflow '%s' by cron trigger '%s'", "Starting workflow '%s' by cron trigger '%s'",
trigger.workflow.name, trigger.name trigger.workflow.name,
trigger.name
) )
rpc.get_engine_client().start_workflow( rpc.get_engine_client().start_workflow(
@ -68,7 +69,8 @@ class MistralPeriodicTasks(periodic_task.PeriodicTasks):
except Exception: except Exception:
# Log and continue to next cron trigger. # Log and continue to next cron trigger.
LOG.exception( LOG.exception(
"Failed to process cron trigger %s" % str(trigger) "Failed to process cron trigger %s",
str(trigger)
) )
finally: finally:
auth_ctx.set_ctx(None) auth_ctx.set_ctx(None)

View File

@ -98,7 +98,7 @@ def delete_trust(trust_id):
try: try:
keystone_client.trusts.delete(trust_id) keystone_client.trusts.delete(trust_id)
except Exception as e: except Exception as e:
LOG.warning("Failed to delete trust [id=%s]: %s" % (trust_id, e)) LOG.warning("Failed to delete trust [id=%s]: %s", trust_id, e)
def add_trust_id(secure_object_values): def add_trust_id(secure_object_values):

View File

@ -131,6 +131,59 @@ class BaseLoggingCheckTest(base.BaseTest):
self.assertEqual(0, len(list(checks.check_python3_no_itervalues( self.assertEqual(0, len(list(checks.check_python3_no_itervalues(
"six.itervalues(ob))")))) "six.itervalues(ob))"))))
def test_check_delayed_string_interpolation(self):
checker = checks.check_delayed_string_interpolation
code = """
msg_w = _LW('Test string (%s)')
msg_i = _LI('Test string (%s)')
value = 'test'
LOG.error(_LE("Test string (%s)") % value)
LOG.warning(msg_w % 'test%string')
LOG.info(msg_i %
"test%string%info")
LOG.critical(
_LC('Test string (%s)') % value,
instance=instance)
LOG.exception(_LE(" 'Test quotation %s' \"Test\"") % 'test')
LOG.debug(' "Test quotation %s" \'Test\'' % "test")
LOG.debug('Tesing %(test)s' %
{'test': ','.join(
['%s=%s' % (name, value)
for name, value in test.items()])})
"""
expected_errors = [(5, 34, 'M331'), (6, 18, 'M331'), (7, 15, 'M331'),
(10, 28, 'M331'), (12, 49, 'M331'),
(13, 40, 'M331'), (14, 28, 'M331')]
self._assert_has_errors(code, checker, expected_errors=expected_errors)
self._assert_has_no_errors(
code, checker, filename='mistral/tests/unit/hacking/test_checks.py'
)
code = """
msg_w = _LW('Test string (%s)')
msg_i = _LI('Test string (%s)')
value = 'test'
LOG.error(_LE("Test string (%s)"), value)
LOG.error(_LE("Test string (%s)") % value) # noqa
LOG.warn(_LW('Test string (%s)'),
value)
LOG.info(msg_i,
"test%string%info")
LOG.critical(
_LC('Test string (%s)'), value,
instance=instance)
LOG.exception(_LE(" 'Test quotation %s' \"Test\""), 'test')
LOG.debug(' "Test quotation %s" \'Test\'', "test")
LOG.debug('Tesing %(test)s',
{'test': ','.join(
['%s=%s' % (name, value)
for name, value in test.items()])})
"""
self._assert_has_no_errors(code, checker)
class TestLoggingWithWarn(BaseLoggingCheckTest): class TestLoggingWithWarn(BaseLoggingCheckTest):

View File

@ -43,7 +43,7 @@ def wrap_wsme_controller_exception(func):
except (exc.MistralException, exc.MistralError) as e: except (exc.MistralException, exc.MistralError) as e:
pecan.response.translatable_error = e pecan.response.translatable_error = e
LOG.error('Error during API call: %s' % str(e)) LOG.error('Error during API call: %s', str(e))
raise wsme_exc.ClientSideError( raise wsme_exc.ClientSideError(
msg=six.text_type(e), msg=six.text_type(e),
@ -64,7 +64,7 @@ def wrap_pecan_controller_exception(func):
try: try:
return func(*args, **kwargs) return func(*args, **kwargs)
except (exc.MistralException, exc.MistralError) as e: except (exc.MistralException, exc.MistralError) as e:
LOG.error('Error during API call: %s' % str(e)) LOG.error('Error during API call: %s', str(e))
return webob.Response( return webob.Response(
status=e.http_code, status=e.http_code,

View File

@ -55,7 +55,7 @@ def _connect(host, username, password=None, pkey=None, proxy=None):
if isinstance(pkey, six.string_types): if isinstance(pkey, six.string_types):
pkey = _to_paramiko_private_key(pkey, password) pkey = _to_paramiko_private_key(pkey, password)
LOG.debug('Creating SSH connection to %s' % host) LOG.debug('Creating SSH connection to %s', host)
ssh_client = paramiko.SSHClient() ssh_client = paramiko.SSHClient()
ssh_client.set_missing_host_key_policy(paramiko.AutoAddPolicy()) ssh_client.set_missing_host_key_policy(paramiko.AutoAddPolicy())
@ -108,14 +108,14 @@ def execute_command_via_gateway(cmd, host, username, private_key_filename,
proxy = None proxy = None
if proxy_command: if proxy_command:
LOG.debug('Creating proxy using command: %s' % proxy_command) LOG.debug('Creating proxy using command: %s', proxy_command)
proxy = paramiko.ProxyCommand(proxy_command) proxy = paramiko.ProxyCommand(proxy_command)
_proxy_ssh_client = paramiko.SSHClient() _proxy_ssh_client = paramiko.SSHClient()
_proxy_ssh_client.set_missing_host_key_policy(paramiko.AutoAddPolicy()) _proxy_ssh_client.set_missing_host_key_policy(paramiko.AutoAddPolicy())
LOG.debug('Connecting to proxy gateway at: %s' % gateway_host) LOG.debug('Connecting to proxy gateway at: %s', gateway_host)
if not gateway_username: if not gateway_username:
gateway_username = username gateway_username = username
@ -153,6 +153,6 @@ def execute_command(cmd, host, username, password=None,
raise_when_error=True): raise_when_error=True):
ssh_client = _connect(host, username, password, private_key_filename) ssh_client = _connect(host, username, password, private_key_filename)
LOG.debug("Executing command %s" % cmd) LOG.debug("Executing command %s", cmd)
return _execute_command(ssh_client, cmd, get_stderr, raise_when_error) return _execute_command(ssh_client, cmd, get_stderr, raise_when_error)

View File

@ -148,7 +148,7 @@ class WorkflowController(object):
for t_e in task_execs for t_e in task_execs
] ]
LOG.debug("Commands to rerun workflow tasks: %s" % cmds) LOG.debug("Commands to rerun workflow tasks: %s", cmds)
return cmds return cmds

View File

@ -194,7 +194,8 @@ def publish_variables(task_ex, task_spec):
if task_ex.name in expr_ctx: if task_ex.name in expr_ctx:
LOG.warning( LOG.warning(
'Shadowing context variable with task name while publishing: %s' % 'Shadowing context variable with task name while '
'publishing: %s',
task_ex.name task_ex.name
) )

View File

@ -148,7 +148,7 @@ class DirectWorkflowController(base.WorkflowController):
cmds.append(cmd) cmds.append(cmd)
LOG.debug("Found commands: %s" % cmds) LOG.debug("Found commands: %s", cmds)
return cmds return cmds

View File

@ -46,9 +46,11 @@ class ActionExecutionTestsV2(base.TestCase):
try: try:
cls.client.delete_obj('action_executions', action_ex) cls.client.delete_obj('action_executions', action_ex)
except Exception as e: except Exception as e:
LOG.exception('Exception raised when deleting ' LOG.exception(
'action_executions %s, error message: %s.' 'Exception raised when deleting '
% (action_ex, six.text_type(e))) 'action_executions %s, error message: %s.',
action_ex, six.text_type(e)
)
cls.client.action_executions = [] cls.client.action_executions = []

View File

@ -100,7 +100,7 @@ class SSHActionsTestsV2(base.TestCaseAdvanced):
def _wait_until_server_up(cls, server_ip, timeout=120, delay=2): def _wait_until_server_up(cls, server_ip, timeout=120, delay=2):
seconds_remain = timeout seconds_remain = timeout
LOG.info("Waiting server SSH [IP=%s]..." % server_ip) LOG.info("Waiting server SSH [IP=%s]...", server_ip)
while seconds_remain > 0: while seconds_remain > 0:
try: try:
@ -123,7 +123,7 @@ class SSHActionsTestsV2(base.TestCaseAdvanced):
def _wait_until_server_active(cls, server_id, timeout=60, delay=2): def _wait_until_server_active(cls, server_id, timeout=60, delay=2):
seconds_remain = timeout seconds_remain = timeout
LOG.info("Waiting server [id=%s]..." % server_id) LOG.info("Waiting server [id=%s]...", server_id)
while seconds_remain > 0: while seconds_remain > 0:
server_info = cls.mgr.servers_client.show_server(server_id) server_info = cls.mgr.servers_client.show_server(server_id)
@ -141,7 +141,7 @@ class SSHActionsTestsV2(base.TestCaseAdvanced):
def _wait_until_server_delete(cls, server_id, timeout=60, delay=2): def _wait_until_server_delete(cls, server_id, timeout=60, delay=2):
seconds_remain = timeout seconds_remain = timeout
LOG.info("Deleting server [id=%s]..." % server_id) LOG.info("Deleting server [id=%s]...", server_id)
while seconds_remain > 0: while seconds_remain > 0:
try: try:
@ -181,9 +181,7 @@ class SSHActionsTestsV2(base.TestCaseAdvanced):
overwrite=True overwrite=True
) )
LOG.info( LOG.info("Private key saved to %s", cls.key_dir + cls.key_name)
"Private key saved to %s" % cls.key_dir + cls.key_name
)
# Create keypair in nova. # Create keypair in nova.
cls.mgr.keypairs_client.create_keypair( cls.mgr.keypairs_client.create_keypair(