Refactor: use lazy logging

As described in pep282 [1], the variable part of a log message
should be passed in via parameter.  In this case the parameters
are evaluated only when they need to be.

This patch fixes (unifies) this for DIB.

A check using pylint was added that this kind of passing parameters to
the logging subsystem is enforced in future.  As a blueprint a similar
(stripped-down) approach from cinder [2] was used.

[1] https://www.python.org/dev/peps/pep-0282/
[2] https://github.com/openstack/cinder/blob/master/tox.ini

Change-Id: I2d7bcc863e4e9583d82d204438b3c781ac99824e
Signed-off-by: Andreas Florath <andreas@florath.net>
This commit is contained in:
Andreas Florath 2017-05-28 05:19:05 +00:00 committed by Ian Wienand
parent 543dc1baa6
commit f314df12c3
15 changed files with 86 additions and 87 deletions

View File

@ -133,7 +133,7 @@ class BlockDevice(object):
logger.debug("Creating BlockDevice object")
self.params = params
logger.debug("Params [%s]" % self.params)
logger.debug("Params [%s]", self.params)
self.state_dir = os.path.join(
self.params['build-dir'], "states/block-device")
@ -153,7 +153,7 @@ class BlockDevice(object):
pass
def write_state(self, state):
logger.debug("Write state [%s]" % self.state_json_file_name)
logger.debug("Write state [%s]", self.state_json_file_name)
with open(self.state_json_file_name, "w") as fd:
json.dump(state, fd)
@ -171,16 +171,16 @@ class BlockDevice(object):
"""
with open(self.params['config'], "rt") as config_fd:
self.config = yaml.safe_load(config_fd)
logger.debug("Config before merge [%s]" % self.config)
logger.debug("Config before merge [%s]", self.config)
self.config = config_tree_to_graph(self.config)
logger.debug("Config before merge [%s]" % self.config)
logger.debug("Config before merge [%s]", self.config)
self._merge_into_config()
logger.debug("Final config [%s]" % self.config)
logger.debug("Final config [%s]", self.config)
# Write the final config
with open(self.config_json_file_name, "wt") as fd:
json.dump(self.config, fd)
logger.info("Wrote final block device config to [%s]"
% self.config_json_file_name)
logger.info("Wrote final block device config to [%s]",
self.config_json_file_name)
def _config_get_mount(self, path):
for entry in self.config:
@ -214,17 +214,17 @@ class BlockDevice(object):
Arguments:
:param symbol: the symbol to get
"""
logger.info("Getting value for [%s]" % symbol)
logger.info("Getting value for [%s]", symbol)
if symbol == "root-label":
root_mount = self._config_get_mount("/")
root_fs = self._config_get_mkfs(root_mount['base'])
logger.debug("root-label [%s]" % root_fs['label'])
logger.debug("root-label [%s]", root_fs['label'])
print("%s" % root_fs['label'])
return 0
if symbol == "root-fstype":
root_mount = self._config_get_mount("/")
root_fs = self._config_get_mkfs(root_mount['base'])
logger.debug("root-fstype [%s]" % root_fs['type'])
logger.debug("root-fstype [%s]", root_fs['type'])
print("%s" % root_fs['type'])
return 0
if symbol == 'mount-points':
@ -246,7 +246,7 @@ class BlockDevice(object):
print("%s" % self.state['blockdev']['image0']['image'])
return 0
logger.error("Invalid symbol [%s] for getval" % symbol)
logger.error("Invalid symbol [%s] for getval", symbol)
return 1
def cmd_writefstab(self):
@ -257,7 +257,7 @@ class BlockDevice(object):
with open(tmp_fstab, "wt") as fstab_fd:
# This gives the order in which this must be mounted
for mp in self.state['mount_order']:
logger.debug("Writing fstab entry for [%s]" % mp)
logger.debug("Writing fstab entry for [%s]", mp)
fs_base = self.state['mount'][mp]['base']
fs_name = self.state['mount'][mp]['name']
fs_val = self.state['filesys'][fs_base]
@ -290,7 +290,7 @@ class BlockDevice(object):
"""Creates the block device"""
logger.info("create() called")
logger.debug("Using config [%s]" % self.config)
logger.debug("Using config [%s]", self.config)
self.state = {}
rollback = []
@ -335,7 +335,7 @@ class BlockDevice(object):
for node in reverse_order:
node.cleanup(self.state)
logger.info("Removing temporary dir [%s]" % self.state_dir)
logger.info("Removing temporary dir [%s]", self.state_dir)
shutil.rmtree(self.state_dir)
return 0
@ -350,7 +350,7 @@ class BlockDevice(object):
for node in reverse_order:
node.delete(self.state)
logger.info("Removing temporary dir [%s]" % self.state_dir)
logger.info("Removing temporary dir [%s]", self.state_dir)
shutil.rmtree(self.state_dir)
return 0

View File

@ -101,7 +101,7 @@ class BlockDeviceCmd(object):
"DIB_BLOCK_DEVICE_PARAMS_YAML or --params not set")
else:
param_file = self.args.params
logger.info("params [%s]" % param_file)
logger.info("params [%s]", param_file)
try:
with open(param_file) as f:
self.params = yaml.safe_load(f)

View File

@ -160,7 +160,7 @@ def create_graph(config, default_config):
# this should have been checked by generate_config
assert len(config_entry) == 1
logger.debug("Config entry [%s]" % config_entry)
logger.debug("Config entry [%s]", config_entry)
cfg_obj_name = list(config_entry.keys())[0]
cfg_obj_val = config_entry[cfg_obj_name]

View File

@ -34,14 +34,14 @@ class LocalLoopNode(NodeBase):
"""
def __init__(self, config, default_config):
logger.debug("Creating LocalLoop object; config [%s] "
"default_config [%s]" % (config, default_config))
"default_config [%s]", config, default_config)
super(LocalLoopNode, self).__init__(config['name'])
if 'size' in config:
self.size = parse_abs_size_spec(config['size'])
logger.debug("Image size [%s]" % self.size)
logger.debug("Image size [%s]", self.size)
else:
self.size = parse_abs_size_spec(default_config['image-size'])
logger.debug("Using default image size [%s]" % self.size)
logger.debug("Using default image size [%s]", self.size)
if 'directory' in config:
self.image_dir = config['directory']
else:
@ -54,14 +54,14 @@ class LocalLoopNode(NodeBase):
@staticmethod
def image_create(filename, size):
logger.info("Create image file [%s]" % filename)
logger.info("Create image file [%s]", filename)
with open(filename, "w") as fd:
fd.seek(size - 1)
fd.write("\0")
@staticmethod
def _image_delete(filename):
logger.info("Remove image file [%s]" % filename)
logger.info("Remove image file [%s]", filename)
os.remove(filename)
@staticmethod
@ -74,7 +74,7 @@ class LocalLoopNode(NodeBase):
if rval == 0:
# [:-1]: Cut of the newline
block_device = subp.stdout.read()[:-1].decode("utf-8")
logger.info("New block device [%s]" % block_device)
logger.info("New block device [%s]", block_device)
return block_device
else:
logger.error("losetup failed")
@ -91,18 +91,18 @@ class LocalLoopNode(NodeBase):
loopdev])
rval = subp.wait()
if rval == 0:
logger.info("Successfully detached [%s]" % loopdev)
logger.info("Successfully detached [%s]", loopdev)
return 0
else:
logger.error("loopdev detach failed")
# Do not raise an error - maybe other cleanup methods
# can at least do some more work.
logger.debug("Gave up trying to detach [%s]" % loopdev)
logger.debug("Gave up trying to detach [%s]", loopdev)
return rval
def create(self, result, rollback):
logger.debug("[%s] Creating loop on [%s] with size [%d]" %
(self.name, self.filename, self.size))
logger.debug("[%s] Creating loop on [%s] with size [%d]",
self.name, self.filename, self.size)
rollback.append(lambda: self._image_delete(self.filename))
self.image_create(self.filename, self.size)
@ -115,8 +115,8 @@ class LocalLoopNode(NodeBase):
result['blockdev'][self.name] = {"device": block_device,
"image": self.filename}
logger.debug("Created loop name [%s] device [%s] image [%s]"
% (self.name, block_device, self.filename))
logger.debug("Created loop name [%s] device [%s] image [%s]",
self.name, block_device, self.filename)
return
def umount(self, state):

View File

@ -190,8 +190,8 @@ class MBR(object):
head = (lba // MBR.sectors_per_track) % MBR.heads_per_cylinder
sector = (lba % MBR.sectors_per_track) + 1
logger.debug("Convert LBA to CHS [%d] -> [%d, %d, %d]"
% (lba, cylinder, head, sector))
logger.debug("Convert LBA to CHS [%d] -> [%d, %d, %d]",
lba, cylinder, head, sector)
return cylinder, head, sector
def encode_chs(self, cylinders, heads, sectors):
@ -212,8 +212,8 @@ class MBR(object):
es = es | hc # pass them into the top two bits of the sector
logger.debug("Encode CHS to disk format [%d %d %d] "
"-> [%02x %02x %02x]" % (cylinders, heads, sectors,
eh, es, ec))
"-> [%02x %02x %02x]", cylinders, heads, sectors,
eh, es, ec)
return eh, es, ec
def write_mbr(self):
@ -246,8 +246,8 @@ class MBR(object):
and also the EBR use the same format.
"""
logger.info("Write partition entry blockno [%d] entry [%d] "
"start [%d] length [%d]" % (blockno, entry,
lba_start, lba_length))
"start [%d] length [%d]", blockno, entry,
lba_start, lba_length)
self.image_fd.seek(
blockno * MBR.bytes_per_sector +
@ -290,9 +290,9 @@ class MBR(object):
lba_abs_partition_end \
= self.align(lba_partition_abs_start + lba_partition_length)
logger.info("Partition absolute [%d] relative [%d] "
"length [%d] absolute end [%d]"
% (lba_partition_abs_start, lba_partition_rel_start,
lba_partition_length, lba_abs_partition_end))
"length [%d] absolute end [%d]",
lba_partition_abs_start, lba_partition_rel_start,
lba_partition_length, lba_abs_partition_end)
return lba_partition_abs_start, lba_partition_length, \
lba_abs_partition_end
@ -305,14 +305,14 @@ class MBR(object):
self.align(lba_partition_abs_start), lba_partition_length)
self.partition_abs_next_free = lba_abs_partition_end
logger.debug("Next free [%d]" % self.partition_abs_next_free)
logger.debug("Next free [%d]", self.partition_abs_next_free)
self.primary_partitions_created += 1
self.partition_number += 1
return self.partition_number
def add_extended_partition(self, bootflag, size, ptype):
lba_ebr_abs = self.partition_abs_next_free
logger.info("EBR block absolute [%d]" % lba_ebr_abs)
logger.info("EBR block absolute [%d]", lba_ebr_abs)
_, lba_partition_length, lba_abs_partition_end \
= self.compute_partition_lbas(lba_ebr_abs + 1, size)
@ -332,7 +332,7 @@ class MBR(object):
self.write_mbr_signature(lba_ebr_abs)
self.partition_abs_next_free = lba_abs_partition_end
logger.debug("Next free [%d]" % self.partition_abs_next_free)
logger.debug("Next free [%d]", self.partition_abs_next_free)
self.disk_block_last_ref = lba_ebr_abs
self.extended_partitions_created += 1
self.partition_number += 1
@ -341,8 +341,8 @@ class MBR(object):
def add_partition(self, primaryflag, bootflag, size, ptype):
"""Adds a partition with the given type and size"""
logger.debug("Add new partition primary [%s] boot [%s] "
"size [%d] type [%x]" %
(primaryflag, bootflag, size, ptype))
"size [%d] type [%x]",
primaryflag, bootflag, size, ptype)
# primaries must be created before extended
if primaryflag and self.extended_partitions_created > 0:

View File

@ -33,7 +33,7 @@ logger = logging.getLogger(__name__)
class Partitioning(PluginBase):
def __init__(self, config, default_config):
logger.debug("Creating Partitioning object; config [%s]" % config)
logger.debug("Creating Partitioning object; config [%s]", config)
super(Partitioning, self).__init__()
# Because using multiple partitions of one base is done
@ -91,13 +91,13 @@ class Partitioning(PluginBase):
def _all_part_devices_exist(self, expected_part_devices):
for part_device in expected_part_devices:
logger.debug("Checking if partition device [%s] exists" %
logger.debug("Checking if partition device [%s] exists",
part_device)
if not os.path.exists(part_device):
logger.info("Partition device [%s] does not exists"
% part_device)
logger.info("Partition device [%s] does not exists",
part_device)
return False
logger.debug("Partition already exists [%s]" % part_device)
logger.debug("Partition already exists [%s]", part_device)
return True
def _notify_os_of_partition_changes(self, device_path, partition_devices):
@ -112,7 +112,7 @@ class Partitioning(PluginBase):
exec_sudo(["partprobe", device_path])
exec_sudo(["udevadm", "settle"])
except CalledProcessError as e:
logger.info("Ignoring settling failure: %s" % e)
logger.info("Ignoring settling failure: %s", e)
pass
if self._all_part_devices_exist(partition_devices):
@ -133,8 +133,8 @@ class Partitioning(PluginBase):
# created are calling back into this.
image_path = result['blockdev'][self.base]['image']
device_path = result['blockdev'][self.base]['device']
logger.info("Creating partition on [%s] [%s]" %
(self.base, image_path))
logger.info("Creating partition on [%s] [%s]",
self.base, image_path)
# This is a bit of a hack. Each of the partitions is actually
# in the graph, so for every partition we get a create() call
@ -158,14 +158,14 @@ class Partitioning(PluginBase):
part_size = part_cfg.get_size()
part_free = part_impl.free()
part_type = part_cfg.get_type()
logger.debug("Not partitioned space [%d]" % part_free)
logger.debug("Not partitioned space [%d]", part_free)
part_size = parse_rel_size_spec(part_size,
part_free)[1]
part_no \
= part_impl.add_partition(part_primary, part_bootflag,
part_size, part_type)
logger.debug("Create partition [%s] [%d]" %
(part_name, part_no))
logger.debug("Create partition [%s] [%d]",
part_name, part_no)
partition_device_name = device_path + "p%d" % part_no
result['blockdev'][part_name] \
= {'device': partition_device_name}

View File

@ -44,7 +44,7 @@ file_system_max_label_length = {
class FilesystemNode(NodeBase):
def __init__(self, config):
logger.debug("Create filesystem object; config [%s]" % config)
logger.debug("Create filesystem object; config [%s]", config)
super(FilesystemNode, self).__init__(config['name'])
# Parameter check (mandatory)
@ -85,8 +85,8 @@ class FilesystemNode(NodeBase):
'max': file_system_max_label_length[self.type]}))
else:
logger.warning("Length of label [%s] cannot be checked for "
"filesystem [%s]: unknown max length" %
(self.label, self.type))
"filesystem [%s]: unknown max length",
self.label, self.type)
logger.warning("Continue - but this might lead to an error")
if self.opts is not None:
@ -95,7 +95,7 @@ class FilesystemNode(NodeBase):
if self.uuid is None:
self.uuid = str(uuid.uuid4())
logger.debug("Filesystem created [%s]" % self)
logger.debug("Filesystem created [%s]", self)
def get_edges(self):
edge_from = [self.base]
@ -103,7 +103,7 @@ class FilesystemNode(NodeBase):
return (edge_from, edge_to)
def create(self, result, rollback):
logger.info("create called; result [%s]" % result)
logger.info("create called; result [%s]", result)
cmd = ["mkfs"]
@ -117,8 +117,8 @@ class FilesystemNode(NodeBase):
elif self.type == 'xfs':
cmd.extend(['-m', "uuid=%s" % self.uuid])
else:
logger.warning("UUID will not be written for fs type [%s]"
% self.type)
logger.warning("UUID will not be written for fs type [%s]",
self.type)
if self.type in ('ext2', 'ext3', 'ext4', 'xfs'):
cmd.append('-q')
@ -128,7 +128,7 @@ class FilesystemNode(NodeBase):
device = result['blockdev'][self.base]['device']
cmd.append(device)
logger.debug("Creating fs command [%s]" % (cmd))
logger.debug("Creating fs command [%s]", cmd)
exec_sudo(cmd)
if 'filesys' not in result:

View File

@ -45,7 +45,7 @@ class MountPointNode(NodeBase):
raise BlockDeviceSetupException(
"MountPoint config needs [%s]" % pname)
setattr(self, pname, config[pname])
logger.debug("MountPoint created [%s]" % self)
logger.debug("MountPoint created [%s]", self)
def get_node(self):
global mount_points
@ -53,7 +53,7 @@ class MountPointNode(NodeBase):
raise BlockDeviceSetupException(
"Mount point [%s] specified more than once"
% self.mount_point)
logger.debug("Insert node [%s]" % self)
logger.debug("Insert node [%s]", self)
mount_points[self.mount_point] = self
return self
@ -77,9 +77,9 @@ class MountPointNode(NodeBase):
global mount_points
global sorted_mount_points
if sorted_mount_points is None:
logger.debug("Mount points [%s]" % mount_points)
logger.debug("Mount points [%s]", mount_points)
sorted_mount_points = sort_mount_points(mount_points.keys())
logger.info("Sorted mount points [%s]" % (sorted_mount_points))
logger.info("Sorted mount points [%s]", sorted_mount_points)
# Look for the occurance in the list
mpi = sorted_mount_points.index(self.mount_point)
@ -92,8 +92,8 @@ class MountPointNode(NodeBase):
return (edge_from, edge_to)
def create(self, result, rollback):
logger.debug("mount called [%s]" % self.mount_point)
logger.debug("result [%s]" % result)
logger.debug("mount called [%s]", self.mount_point)
logger.debug("result [%s]", result)
rel_mp = self.mount_point if self.mount_point[0] != '/' \
else self.mount_point[1:]
mount_point = os.path.join(self.mount_base, rel_mp)
@ -101,7 +101,7 @@ class MountPointNode(NodeBase):
# Need to sudo this because of permissions in the new
# file system tree.
exec_sudo(['mkdir', '-p', mount_point])
logger.info("Mounting [%s] to [%s]" % (self.name, mount_point))
logger.info("Mounting [%s] to [%s]", self.name, mount_point)
exec_sudo(["mount", result['filesys'][self.base]['device'],
mount_point])
@ -115,7 +115,7 @@ class MountPointNode(NodeBase):
result['mount_order'].append(self.mount_point)
def umount(self, state):
logger.info("Called for [%s]" % self.name)
logger.info("Called for [%s]", self.name)
exec_sudo(["umount", state['mount'][self.mount_point]['path']])
def delete(self, state):

View File

@ -35,8 +35,8 @@ class FstabNode(NodeBase):
return (edge_from, edge_to)
def create(self, result, rollback):
logger.debug("fstab create called [%s]" % self.name)
logger.debug("result [%s]" % result)
logger.debug("fstab create called [%s]", self.name)
logger.debug("result [%s]", result)
if 'fstab' not in result:
result['fstab'] = {}

View File

@ -104,7 +104,7 @@ def exec_sudo(cmd):
sudo_cmd = ["sudo"]
sudo_cmd.extend(cmd)
try:
logger.info("Calling [%s]" % " ".join(sudo_cmd))
logger.info("Calling [%s]", " ".join(sudo_cmd))
except TypeError:
# Popen actually doesn't care, but we've managed to get mixed
# str and bytes in argument lists which causes errors logging
@ -117,7 +117,7 @@ def exec_sudo(cmd):
stderr=subprocess.STDOUT)
for line in iter(proc.stdout.readline, b""):
logger.debug("exec_sudo: %s" % line.rstrip())
logger.debug("exec_sudo: %s", line.rstrip())
proc.wait()
if proc.returncode != 0:
@ -126,7 +126,7 @@ def exec_sudo(cmd):
def sort_mount_points(mount_points):
logger.debug("sort_mount_points called [%s]" % mount_points)
logger.debug("sort_mount_points called [%s]", mount_points)
def insert_sorted(mp, sorted_mount_points):
if len(sorted_mount_points) == 0:
@ -141,5 +141,5 @@ def sort_mount_points(mount_points):
sorted_mount_points = []
for mp in mount_points:
insert_sorted(mp, sorted_mount_points)
logger.debug("sort_mount_points result [%s]" % sorted_mount_points)
logger.debug("sort_mount_points result [%s]", sorted_mount_points)
return sorted_mount_points

View File

@ -164,8 +164,8 @@ def _expand_element_dependencies(user_elements, all_elements):
logger.error(
"The following elements are already provided by another element")
for element in conflicts:
logger.error("%s : already provided by %s" %
(element, provided_by[element]))
logger.error("%s : already provided by %s",
element, provided_by[element])
raise AlreadyProvidedException()
if "operating-system" not in provided:
@ -200,7 +200,7 @@ def _find_all_elements(paths=None):
else:
paths = list(reversed(paths.split(':')))
logger.debug("ELEMENTS_PATH is: %s" % ":".join(paths))
logger.debug("ELEMENTS_PATH is: %s", ":".join(paths))
for path in paths:
if not os.path.isdir(path):

View File

@ -64,8 +64,8 @@ class TestBlockDevice(testtools.TestCase):
logging.info("test_create_default_config called")
builddir = self.useFixture(fixtures.TempDir()).path
imagedir = self.useFixture(fixtures.TempDir()).path
logging.info("builddir [%s]" % builddir)
logging.info("imagedir [%s]" % imagedir)
logging.info("builddir [%s]", builddir)
logging.info("imagedir [%s]", imagedir)
logging.info("Calling BlockDevice constructor")
bd = self.useFixture(BlockDeviceFixture(
@ -75,12 +75,12 @@ class TestBlockDevice(testtools.TestCase):
bd.cmd_create()
logging.info("Check result")
logging.info("State [%s]" % bd.state)
logging.info("State [%s]", bd.state)
self.assertTrue('device' in bd.state['image0'])
lb_dev = bd.state['image0']['device']
# partprobe loopback so we can get partition info
args = ['sudo', 'partprobe', lb_dev]
logging.info("Call: %s" % args)
logging.info("Call: %s", args)
subprocess.check_call(args)
bd.cmd_cleanup()
self._assert_loopbacks_cleaned(bd)

View File

@ -27,7 +27,7 @@ data_dir = os.path.abspath(
def _populate_element(element_dir, element_name, element_deps=[], provides=[]):
logger.debug("Populate %s <%s>" % (element_name, element_dir))
logger.debug("Populate %s <%s>", element_name, element_dir)
element_home = os.path.join(element_dir, element_name)
os.mkdir(element_home)
deps_path = os.path.join(element_home, 'element-deps')

View File

@ -2,6 +2,5 @@
persistent=no
[MESSAGES CONTROL]
disable=all
enable=bad-indentation
enable=bad-indentation, logging-not-lazy

View File

@ -1,5 +1,5 @@
[tox]
envlist = py35,py27,pep8
envlist = py35,py27,pep8,pylint
minversion = 1.6
skipsdist = True