Delay string interpolations at logging calls

This is a general best practice which brings (slight) performance
improvements and also structured logging.

Enable the hacking check to enforce it.

Change-Id: If32753a456aba1f6cbdf008e90c41df6aeacdddd
Signed-off-by: Takashi Kajinami <kajinamit@oss.nttdata.com>
This commit is contained in:
Takashi Kajinami 2025-12-03 23:33:21 +09:00
parent 7d7927caf3
commit 7f17f50108
21 changed files with 79 additions and 89 deletions

View file

@ -246,18 +246,18 @@ class EC2Token(wsgi.Middleware):
if clouds:
for cloud in clouds:
try:
LOG.debug("Attempt authorize on %s" % cloud)
LOG.debug("Attempt authorize on %s", cloud)
return self._authorize(req, cloud)
except exception.HeatAPIException as e:
LOG.debug("Authorize failed: %s" % e.__class__)
LOG.debug("Authorize failed: %s", e.__class__)
last_failure = e
else:
for auth_uri in self._conf_get('allowed_auth_uris'):
try:
LOG.debug("Attempt authorize on %s" % auth_uri)
LOG.debug("Attempt authorize on %s", auth_uri)
return self._authorize(req, auth_uri)
except exception.HeatAPIException as e:
LOG.debug("Authorize failed: %s" % e.__class__)
LOG.debug("Authorize failed: %s", e.__class__)
last_failure = e
raise last_failure or exception.HeatAccessDeniedError()
@ -290,7 +290,7 @@ class EC2Token(wsgi.Middleware):
adapter = self._ks_adapters.get(cloud)
if not adapter:
LOG.error("Ec2Token authorization failed due to missing "
"keystone auth configuration for %s" % cloud)
"keystone auth configuration for %s", cloud)
raise exception.HeatInternalFailureError(_('Service '
'misconfigured'))

View file

@ -244,7 +244,7 @@ class StackController(object):
return req.params['TemplateBody']
elif 'TemplateUrl' in req.params:
url = req.params['TemplateUrl']
LOG.debug('TemplateUrl %s' % url)
LOG.debug('TemplateUrl %s', url)
try:
return urlfetch.get(url)
except IOError as exc:

View file

@ -66,19 +66,20 @@ class VersionNegotiationFilter(wsgi.Middleware):
minor_version = req.environ['api.minor_version']
if (major_version == 1 and minor_version == 0):
LOG.debug("Matched versioned URI. "
"Version: %(major_version)d.%(minor_version)d"
% {'major_version': major_version,
'minor_version': minor_version})
LOG.debug(
"Matched versioned URI. "
"Version: %(major_version)d.%(minor_version)d",
{'major_version': major_version,
'minor_version': minor_version})
# Strip the version from the path
req.path_info_pop()
return None
else:
LOG.debug("Unknown version in versioned URI: "
"%(major_version)d.%(minor_version)d. "
"Returning version choices."
% {'major_version': major_version,
'minor_version': minor_version})
"Returning version choices.",
{'major_version': major_version,
'minor_version': minor_version})
return self.versions_app
accept = str(req.accept)
@ -91,16 +92,16 @@ class VersionNegotiationFilter(wsgi.Middleware):
minor_version = req.environ['api.minor_version']
if (major_version == 1 and minor_version == 0):
LOG.debug("Matched versioned media type. Version: "
"%(major_version)d.%(minor_version)d"
% {'major_version': major_version,
'minor_version': minor_version})
"%(major_version)d.%(minor_version)d",
{'major_version': major_version,
'minor_version': minor_version})
return None
else:
LOG.debug("Unknown version in accept header: "
"%(major_version)d.%(minor_version)d... "
"returning version choices."
% {'major_version': major_version,
'minor_version': minor_version})
"returning version choices.",
{'major_version': major_version,
'minor_version': minor_version})
return self.versions_app
else:
if req.accept not in ('*/*', ''):

View file

@ -114,7 +114,7 @@ class InstantiationData(object):
elif self.PARAM_TEMPLATE_URL in self.data:
url = self.data[self.PARAM_TEMPLATE_URL]
LOG.debug('TemplateUrl %s' % url)
LOG.debug('TemplateUrl %s', url)
try:
template_data = urlfetch.get(url)
except IOError as ex:

View file

@ -32,7 +32,7 @@ def parse_auth_credential_to_dict(cred):
try:
_cred = json.loads(cred)
except ValueError as e:
LOG.error('Failed to parse credential with error: %s' % e)
LOG.error('Failed to parse credential with error: %s', e)
raise ValueError('Failed to parse credential, please check your '
'Stack Credential format.')
validate(_cred)

View file

@ -311,8 +311,8 @@ def format_resource_properties(resource):
try:
return resource.properties[prop]
except (KeyError, ValueError):
LOG.exception("Error in fetching property %s of resource %s" %
(prop, resource.name))
LOG.exception("Error in fetching property %s of resource %s",
prop, resource.name)
return None
return dict((prop, get_property(prop))

View file

@ -67,8 +67,8 @@ class BarbicanClientPlugin(client_plugin.ClientPlugin):
raise exception.EntityNotFound(
entity="Secret",
name=secret_ref)
LOG.info('Failed to get Barbican secret from reference %s' % (
secret_ref))
LOG.info('Failed to get Barbican secret from reference %s',
secret_ref)
raise
def get_secret_payload_by_ref(self, secret_ref):

View file

@ -223,8 +223,8 @@ class KsClientWrapper(object):
project=trustor_proj_id, impersonation=True,
allow_redelegation=allow_redelegation, **role_kw)
except ks_exception.NotFound:
LOG.debug("Failed to find roles %s for user %s"
% (role_kw, trustor_user_id))
LOG.debug("Failed to find roles %s for user %s",
role_kw, trustor_user_id)
raise exception.MissingCredentialError(
required=_("roles %s") % role_kw)

View file

@ -2032,7 +2032,7 @@ class Resource(status.ResourceStatus):
while True:
count += 1
LOG.info('delete %(name)s attempt %(attempt)d' %
LOG.info('delete %(name)s attempt %(attempt)d',
{'name': str(self), 'attempt': count + 1})
if count:
delay = timeutils.retry_backoff_delay(count,

View file

@ -217,8 +217,8 @@ class TestResource(resource.Resource):
obj = getattr(self.client(name=client_name), self.entity)
obj.get(entity_id)
except Exception as exc:
LOG.debug('%s.%s(%s) %s' % (client_name, self.entity,
entity_id, str(exc)))
LOG.debug('%s.%s(%s) %s', client_name, self.entity,
entity_id, str(exc))
else:
# just sleep some more
time.sleep(1)

View file

@ -152,10 +152,8 @@ class HeatWaitCondition(resource.Resource):
if key == self.DATA:
meta = handle.metadata_get(refresh=True)
res = {k: meta[k][handle.DATA] for k in meta}
LOG.debug('%(name)s.GetAtt(%(key)s) == %(res)s'
% {'name': self.name,
'key': key,
'res': res})
LOG.debug('%(name)s.GetAtt(%(key)s) == %(res)s',
{'name': self.name, 'key': key, 'res': res})
return str(jsonutils.dumps(res))

View file

@ -153,9 +153,8 @@ class MistralExternalResource(resource.Resource):
raises ResourceUnknownState otherwise.
"""
execution = self.client().executions.get(execution_id)
LOG.debug('Mistral execution %(id)s is in state '
'%(state)s' % {'id': execution_id,
'state': execution.state})
LOG.debug('Mistral execution %(id)s is in state %(state)s',
{'id': execution_id, 'state': execution.state})
if execution.state in ('IDLE', 'RUNNING', 'PAUSED'):
return False, {}
@ -190,9 +189,9 @@ class MistralExternalResource(resource.Resource):
workflow_input=jsonutils.dumps(inputs),
description=self.properties[self.DESCRIPTION],
**action_data[self.PARAMS])
LOG.debug('Mistral execution %(id)s params set to '
'%(params)s' % {'id': execution.id,
'params': action_data[self.PARAMS]})
LOG.debug('Mistral execution %(id)s params set to %(params)s',
{'id': execution.id,
'params': action_data[self.PARAMS]})
return execution.id
def _check_action(self, action, execution_id):
@ -209,8 +208,8 @@ class MistralExternalResource(resource.Resource):
if output.get('resource_id'):
rsrc_id = output.get('resource_id')
LOG.debug('ExternalResource id set to %(rid)s from Mistral '
'execution %(eid)s output' % {'eid': execution_id,
'rid': rsrc_id})
'execution %(eid)s output',
{'eid': execution_id, 'rid': rsrc_id})
self.resource_id_set(str(rsrc_id)[:255])
return success
@ -226,9 +225,8 @@ class MistralExternalResource(resource.Resource):
for i in after_props[self.REPLACE_ON_CHANGE]:
if old_inputs.get(i) != new_inputs.get(i):
LOG.debug('Replacing ExternalResource %(id)s instead of '
'updating due to change to input "%(i)s"' %
{"id": self.resource_id,
"i": i})
'updating due to change to input "%(i)s"',
{"id": self.resource_id, "i": i})
raise resource.UpdateReplace(self)
# honor always_update if found
if self.properties[self.ALWAYS_UPDATE]:

View file

@ -480,10 +480,9 @@ class Instance(resource.Resource):
_("Unknown")))
if updates:
if instance.status != self.ACTIVE:
dmsg = ("Instance is in status %(now)s. Waiting on status"
" %(stat)s")
LOG.debug(dmsg % {"now": instance.status,
"stat": self.ACTIVE})
LOG.debug("Instance is in status %(now)s. Waiting on status"
" %(stat)s",
{"now": instance.status, "stat": self.ACTIVE})
return False
try:
return (
@ -520,17 +519,16 @@ class Instance(resource.Resource):
current_flav = str(instance.flavor['id'])
new_flav = str(new_flavor)
if new_flav != current_flav:
dmsg = "Resizing instance flavor from %(old)s to %(new)s"
LOG.debug(dmsg % {"old": current_flav, "new": new_flav})
LOG.debug("Resizing instance flavor from %(old)s to %(new)s",
{"old": current_flav, "new": new_flav})
self.client().instances.resize_instance(instance, new_flavor)
return False
return True
def _update_size(self, instance, new_size):
if new_size and instance.volume['size'] != new_size:
dmsg = "Resizing instance storage from %(old)s to %(new)s"
LOG.debug(dmsg % {"old": instance.volume['size'],
"new": new_size})
LOG.debug("Resizing instance storage from %(old)s to %(new)s",
{"old": instance.volume['size'], "new": new_size})
self.client().instances.resize_volume(instance, new_size)
return False
return True
@ -540,13 +538,12 @@ class Instance(resource.Resource):
for db in databases:
if db.get("ACTION") == self.CREATE:
db.pop("ACTION", None)
dmsg = "Adding new database %(db)s to instance"
LOG.debug(dmsg % {"db": db})
LOG.debug("Adding new database %(db)s to instance",
{"db": db})
self.client().databases.create(instance, [db])
elif db.get("ACTION") == self.DELETE:
dmsg = ("Deleting existing database %(db)s from "
"instance")
LOG.debug(dmsg % {"db": db['name']})
LOG.debug("Deleting existing database %(db)s from "
"instance", {"db": db['name']})
self.client().databases.delete(instance, db['name'])
return True
@ -558,13 +555,11 @@ class Instance(resource.Resource):
usr[self.USER_DATABASES] = dbs
if usr.get("ACTION") == self.CREATE:
usr.pop("ACTION", None)
dmsg = "Adding new user %(u)s to instance"
LOG.debug(dmsg % {"u": usr})
LOG.debug("Adding new user %(u)s to instance", {"u": usr})
self.client().users.create(instance, [usr])
elif usr.get("ACTION") == self.DELETE:
dmsg = ("Deleting existing user %(u)s from "
"instance")
LOG.debug(dmsg % {"u": usr['name']})
LOG.debug("Deleting existing user %(u)s from instance",
{"u": usr['name']})
self.client().users.delete(instance, usr['name'])
else:
newattrs = {}

View file

@ -548,7 +548,7 @@ class StackResource(resource.Resource):
def _handle_cancel(self):
stack_identity = self.nested_identifier()
if stack_identity is not None:
LOG.debug('Cancelling %s of %s' % (self.action, self))
LOG.debug('Cancelling %s of %s', self.action, self)
try:
self.rpc_client().stack_cancel_update(
self.context,

View file

@ -1297,8 +1297,8 @@ class EngineService(service.ServiceBase):
stack_identity=stack_identity, message=cancel_message)
if cancel_result is None:
LOG.debug("Successfully sent %(msg)s message "
"to remote task on engine %(eng)s" % {
'eng': engine_id, 'msg': cancel_message})
"to remote task on engine %(eng)s",
{'eng': engine_id, 'msg': cancel_message})
else:
raise exception.EventSendFailed(stack_name=current_stack.name,
engine_id=engine_id)
@ -1545,9 +1545,9 @@ class EngineService(service.ServiceBase):
stack_identity=stack_identity, message=rpc_api.THREAD_CANCEL)
if cancel_result is None:
LOG.debug("Successfully sent %(msg)s message "
"to remote task on engine %(eng)s" % {
'eng': acquire_result,
'msg': rpc_api.THREAD_CANCEL})
"to remote task on engine %(eng)s",
{'eng': acquire_result,
'msg': rpc_api.THREAD_CANCEL})
else:
raise exception.EventSendFailed(stack_name=stack.name,
engine_id=acquire_result)
@ -1945,7 +1945,7 @@ class EngineService(service.ServiceBase):
"""
def _resource_signal(stack, rsrc, details, need_check):
LOG.debug("signaling resource %s:%s" % (stack.name, rsrc.name))
LOG.debug("signaling resource %s:%s", stack.name, rsrc.name)
needs_metadata_updates = rsrc.signal(details, need_check)
if not needs_metadata_updates:

View file

@ -950,7 +950,7 @@ class Stack(collections.abc.Mapping):
dup_names = set(self.parameters) & set(resources)
if dup_names:
LOG.debug("Duplicate names %s" % dup_names)
LOG.debug("Duplicate names %s", dup_names)
raise exception.StackValidationFailed(
message=_("Duplicate names %s") % dup_names)

View file

@ -59,9 +59,8 @@ class StackLock(object):
self.stack_id,
self.engine_id)
if lock_engine_id is None:
LOG.debug("Engine %(engine)s acquired lock on stack "
"%(stack)s" % {'engine': self.engine_id,
'stack': self.stack_id})
LOG.debug("Engine %(engine)s acquired lock on stack %(stack)s",
{'engine': self.engine_id, 'stack': self.stack_id})
return
stack = stack_object.Stack.get_by_id(self.context, self.stack_id,
@ -70,8 +69,8 @@ class StackLock(object):
if (lock_engine_id == self.engine_id or
service_utils.engine_alive(self.context, lock_engine_id)):
LOG.debug("Lock on stack %(stack)s is owned by engine "
"%(engine)s" % {'stack': self.stack_id,
'engine': lock_engine_id})
"%(engine)s", {'stack': self.stack_id,
'engine': lock_engine_id})
raise exception.ActionInProgress(stack_name=stack.name,
action=stack.action)
else:
@ -118,9 +117,8 @@ class StackLock(object):
LOG.warning("Lock was already released on stack %s!",
self.stack_id)
else:
LOG.debug("Engine %(engine)s released lock on stack "
"%(stack)s" % {'engine': self.engine_id,
'stack': self.stack_id})
LOG.debug("Engine %(engine)s released lock on stack %(stack)s",
{'engine': self.engine_id, 'stack': self.stack_id})
def __enter__(self):
self.acquire()

View file

@ -89,7 +89,7 @@ class Stack(
return self._raw_template
LOG.warning('Loading a raw_template that should have been '
'eagerly loaded for stack id %s' % self.id)
'eagerly loaded for stack id %s', self.id)
self._raw_template = raw_template.RawTemplate.get_by_id(
self._context,
self['raw_template_id'])

View file

@ -74,11 +74,11 @@ class MessageProcessor(object):
try:
method = getattr(self, message.name)
except AttributeError:
LOG.error('[%s] Bad message name "%s"' % (self.name,
message.name))
LOG.error('[%s] Bad message name "%s"',
self.name, message.name)
raise
else:
LOG.info('[%s] %r' % (self.name, message.data))
LOG.info('[%s] %r', self.name, message.data)
method(message.data)
return True

View file

@ -627,16 +627,16 @@ outputs:
md = self.client.resources.metadata(stack_identifier, 'custom_lb')
actual_md = len(md['IPs'].split(','))
if actual_md != expected:
LOG.warning('check_instance_count exp:%d, meta:%s' % (expected,
md['IPs']))
LOG.warning('check_instance_count exp:%d, meta:%s',
expected, md['IPs'])
return False
stack = self.client.stacks.get(stack_identifier)
inst_list = self._stack_output(stack, 'InstanceList')
actual = len(inst_list.split(','))
if actual != expected:
LOG.warning('check_instance_count exp:%d, act:%s' % (expected,
inst_list))
LOG.warning('check_instance_count exp:%d, act:%s',
expected, inst_list)
return actual == expected
def test_scaling_meta_update(self):

View file

@ -85,7 +85,7 @@ show-source = true
# W504 line break after binary operator
# TODO(tkajinam): Check why Nnnn checks from neutron-lib are enabled
ignore = E123,W503,W504,N
enable-extensions = H203,H204,H205,H211,H212
enable-extensions = H203,H204,H205,H211,H212,H904
exclude=.*,dist,*lib/python*,*egg,build,*convergence/scenarios/*
max-complexity=23