openstack/openstack-ansible
Code Issues Proposed changes

Add debug logging to dynamic inventory

Browse Source 
Currently debugging the dynamic inventory file can be problematic,
requiring manual intervention with a debugger to step through function
calls and inspect data structures.

This patch adds a logging facility for outputting detailed debug logs.
The output is not intended for end users, and will not be called by
Ansible runs. Rather, it is meant for running manually to aid
contributing developers.

Change-Id: Ie160c556678859abf733ef23727a9f9bff48ff8b
This commit is contained in:
Nolan Brubaker 2016-09-21 18:08:58 -04:00
parent 792dda93a6
commit 8d711ae48d
4 changed files with 121 additions and 3 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

10
doc/source/developer-docs/inventory.rst
View File

@ -111,6 +111,16 @@ disk.
This check does not do YAML syntax validation, though it will fail if there
are unparseable errors.
Writing Debug Logs
------------------
The ``--debug/-d`` parameter allows writing of a detailed log file for
debugging the inventory script's behavior. The output is written to
``inventory.log`` in the current working directory.
The ``inventory.log`` file is appended to, not overwritten.
Like ``--check``, this flag is not invoked when running from ansible.
Inspecting and Managing the Inventory
-------------------------------------

76
playbooks/inventory/dynamic_inventory.py
View File

@ -19,6 +19,7 @@ import argparse
import copy
import datetime
import json
import logging
import netaddr
import os
import Queue
@ -28,6 +29,8 @@ import tarfile
import uuid
import yaml
logger = logging.getLogger('osa-inventory')
USED_IPS = set()
INVENTORY_SKEL = {
'_meta': {
@ -146,6 +149,15 @@ def args(arg_list):
action='store_true',
)
parser.add_argument(
'-d',
'--debug',
help=('Output debug messages to log file. '
'File is appended to, not overwritten'),
action='store_true',
default=False,
)
return vars(parser.parse_args(arg_list))
@ -192,6 +204,7 @@ def _parse_belongs_to(key, belongs_to, inventory):
"""
for item in belongs_to:
if key not in inventory[item]['children']:
logger.debug("Adding %s to %s", key, item)
append_if(array=inventory[item]['children'], item=key)
@ -236,12 +249,16 @@ def _build_container_hosts(container_affinity, container_hosts, type_and_name,
cuuid = '%s' % uuid.uuid4()
cuuid = cuuid.split('-')[0]
container_host_name = '%s-%s' % (type_and_name, cuuid)
logger.debug("Generated container name %s",
container_host_name)
hostvars_options = hostvars[container_host_name] = {}
if container_host_type not in inventory:
inventory[container_host_type] = {
"hosts": [],
}
logger.debug("Adding container %s to %s",
container_host_name, container_host_type)
append_if(
array=inventory[container_host_type]["hosts"],
item=container_host_name
@ -283,6 +300,8 @@ def _append_container_types(inventory, host_type):
if 'container_name' in hdata:
if hdata['container_name'].startswith(host_type):
if 'physical_host' not in hdata:
logger.debug("Set physical host for %s to %s",
_host, host_type)
hdata['physical_host'] = host_type
@ -299,6 +318,7 @@ def _append_to_host_groups(inventory, container_type, assignment, host_type,
"""
physical_group_type = '%s_all' % container_type.split('_')[0]
if physical_group_type not in inventory:
logger.debug("Added %s group to inventory", physical_group_type)
inventory[physical_group_type] = {'hosts': []}
iph = inventory[physical_group_type]['hosts']
@ -321,15 +341,23 @@ def _append_to_host_groups(inventory, container_type, assignment, host_type,
hdata['physical_host'] = host_type
if container.startswith('%s-' % type_and_name):
logger.debug("Added host %s to %s hosts",
container, assignment)
append_if(array=iah, item=container)
elif is_metal is True:
if component == assignment:
logger.debug("Added is_metal host %s to %s hosts",
container, assignment)
append_if(array=iah, item=container)
if container.startswith('%s-' % type_and_name):
logger.debug("Added host %s to %s hosts",
container, physical_group_type)
append_if(array=iph, item=container)
elif is_metal is True:
if container.startswith(host_type):
logger.debug("Added is_metal host %s to %s hosts",
container, physical_group_type)
append_if(array=iph, item=container)
# Append any options in config to the host_vars of a container
@ -352,6 +380,7 @@ def _append_to_host_groups(inventory, container_type, assignment, host_type,
)
if limit is None or (component and limit in component):
logger.debug("Set options for %s", hname)
hdata[_keys] = options
@ -389,6 +418,7 @@ def _add_container_hosts(assignment, config, container_name, container_type,
# This section will ensure that we are not it by the following bug:
# https://bugzilla.mindrot.org/show_bug.cgi?id=2239
type_and_name = '%s_%s' % (host_type, container_name)
logger.debug("Generated container name %s", type_and_name)
max_hostname_len = 52
if len(type_and_name) > max_hostname_len:
raise SystemExit(
@ -409,6 +439,7 @@ def _add_container_hosts(assignment, config, container_name, container_type,
physical_host['container_types'] = container_host_type
# Add all of the containers into the inventory
logger.debug("Building containers for host %s", container_name)
_build_container_hosts(
container_affinity,
container_hosts,
@ -445,9 +476,11 @@ def user_defined_setup(config, inventory):
for key, value in config.iteritems():
if key.endswith('hosts'):
if key not in inventory:
logger.debug("Key %s was added to inventory", key)
inventory[key] = {'hosts': []}
if value is None:
logger.debug("Key %s had no value", key)
return
for _key, _value in value.iteritems():
@ -461,6 +494,7 @@ def user_defined_setup(config, inventory):
'is_metal': True,
'physical_host_group': key
})
logger.debug("Hostvars info updated for %s", key)
# If the entry is missing the properties key add it.
properties = hvs[_key].get('properties')
@ -474,6 +508,8 @@ def user_defined_setup(config, inventory):
hvs[_key][_k] = _v
USED_IPS.add(_value['ip'])
logger.debug("Attempting to add host %s to group %s",
_key, key)
append_if(array=inventory[key]['hosts'], item=_key)
@ -488,6 +524,7 @@ def skel_setup(environment, inventory):
continue
for _key, _value in value.iteritems():
if _key not in inventory:
logger.debug("Key %s added to inventory", _key)
inventory[_key] = {}
if _key.endswith('container'):
if 'hosts' not in inventory[_key]:
@ -495,12 +532,15 @@ def skel_setup(environment, inventory):
else:
if 'children' not in inventory[_key]:
inventory[_key]['children'] = []
# TODO(nrb): This line is duplicated above;
# is that necessary?
if 'hosts' not in inventory[_key]:
inventory[_key]['hosts'] = []
if 'belongs_to' in _value:
for assignment in _value['belongs_to']:
if assignment not in inventory:
logger.debug("Created group %s", assignment)
inventory[assignment] = {}
if 'children' not in inventory[assignment]:
inventory[assignment]['children'] = []
@ -702,7 +742,9 @@ def container_skel_load(container_skel, inventory, config):
:param inventory: ``dict`` Living dictionary of inventory
:param config: ``dict`` User defined information
"""
logger.debug("Loading container skeleton")
if 'lxc_hosts' not in inventory.keys():
logger.debug("Created lxc_hosts group.")
inventory['lxc_hosts'] = {'hosts': []}
for key, value in container_skel.iteritems():
contains_in = value.get('contains', False)
@ -809,6 +851,7 @@ def _set_used_ips(user_defined_config, inventory):
)
USED_IPS.update([str(i) for i in ip_range])
else:
logger.debug("IP %s set as used", split_ip[0])
USED_IPS.add(split_ip[0])
# Find all used IP addresses and ensure that they are not used again
@ -817,6 +860,7 @@ def _set_used_ips(user_defined_config, inventory):
for network_entry in networks.values():
address = network_entry.get('address')
if address:
logger.debug("IP %s set as used", address)
USED_IPS.add(address)
@ -850,6 +894,8 @@ def _ensure_inventory_uptodate(inventory, container_skel):
for host in hosts:
container = host_vars[host]
if 'properties' in type_vars:
logger.debug("Copied propeties for %s from skeleton",
container)
container['properties'] = type_vars['properties']
@ -874,10 +920,12 @@ def _parse_global_variables(user_cidr, inventory, user_defined_config):
inventory['all']['vars'].update(
user_defined_config['global_overrides']
)
logger.debug("Applied global_overrides")
# Remove global overrides that were deleted from inventory, too
for key in inventory['all']['vars'].keys():
if key not in user_defined_config['global_overrides']:
logger.debug("Deleting key %s from inventory", key)
del inventory['all']['vars'][key]
@ -890,6 +938,8 @@ def append_if(array, item):
"""
if item not in array:
array.append(item)
# TODO(nrb): Would be nice to change this to return true/false
# for logging purposes.
return array
@ -926,6 +976,7 @@ def _extra_config(user_defined_config, base_dir):
user_defined_config,
yaml.safe_load(f.read()) or {}
)
logger.debug("Merged overrides from file %s", name)
def _check_same_ip_to_multiple_host(config):
@ -946,6 +997,7 @@ def _check_same_ip_to_multiple_host(config):
if ips_to_hostnames_mapping[ip] != hostname:
info = (ip, ips_to_hostnames_mapping[ip], hostname)
raise MultipleHostsWithOneIPError(*info)
logger.debug("No hosts with duplicated IPs found")
def _check_multiple_ips_to_host(config):
@ -967,12 +1019,14 @@ def _check_multiple_ips_to_host(config):
if not current_ip == new_ip:
raise MultipleIpForHostError(hostname, current_ip,
new_ip)
logger.debug("No hosts with multiple IPs found.")
return True
def _check_lxc_hosts(config):
if 'lxc_hosts' in config.keys():
raise LxcHostsDefined()
logger.debug("lxc_hosts group not defined")
def _check_config_settings(cidr_networks, config, container_skel):
@ -1022,6 +1076,8 @@ def _check_config_settings(cidr_networks, config, container_skel):
not p_net.get('is_container_address')):
raise ProviderNetworkMisconfiguration(q_name)
logger.debug("Provider network information OK")
# look for same ip address assigned to different hosts
_check_same_ip_to_multiple_host(config)
@ -1042,7 +1098,7 @@ def load_environment(config_path, environment):
if os.path.isdir(env_plugins):
_extra_config(user_defined_config=environment, base_dir=env_plugins)
logger.debug("Loaded environment from %s", config_path)
return environment
@ -1072,6 +1128,7 @@ def load_user_configuration(config_path):
'No openstack_user_config files are available in either \n%s'
'\nor \n%s/conf.d directory' % (config_path, config_path)
)
logger.debug("User configuration loaded from: %s", user_config_file)
return user_defined_config
@ -1085,6 +1142,7 @@ def make_backup(config_path, inventory_file_path):
basename = os.path.basename(inventory_file_path)
backup_name = get_backup_name(basename)
tar.add(inventory_file_path, arcname=backup_name)
logger.debug("Backup written to %s", inventory_backup_file)
def get_backup_name(basename):
@ -1097,16 +1155,25 @@ def get_inventory(config_path, inventory_file_path):
if os.path.isfile(inventory_file_path):
with open(inventory_file_path, 'rb') as f:
dynamic_inventory = json.loads(f.read())
logger.debug("Loaded existing inventory from %s",
inventory_file_path)
make_backup(config_path, inventory_file_path)
else:
dynamic_inventory = copy.deepcopy(INVENTORY_SKEL)
logger.debug("No existing inventory, created fresh skeleton.")
return dynamic_inventory
def main(all_args):
"""Run the main application."""
if all_args.get('debug'):
log_fmt = "%(lineno)d - %(funcName)s: %(message)s"
logging.basicConfig(format=log_fmt, filename='inventory.log')
logger.setLevel(logging.DEBUG)
logger.info("Beginning new inventory run")
# Get the path to the user configuration files
config_path = find_config_path(
user_config_path=all_args.get('config')
@ -1151,10 +1218,12 @@ def main(all_args):
_set_used_ips(user_defined_config, dynamic_inventory)
user_defined_setup(user_defined_config, dynamic_inventory)
skel_setup(environment, dynamic_inventory)
logger.debug("Loading physical skel.")
skel_load(
environment.get('physical_skel'),
dynamic_inventory
)
logger.debug("Loading component skel")
skel_load(
environment.get('component_skel'),
dynamic_inventory
@ -1202,9 +1271,14 @@ def main(all_args):
)
)
if logger.isEnabledFor(logging.DEBUG):
num_hosts = len(dynamic_inventory['_meta']['hostvars'])
logger.debug("%d hosts found." % num_hosts)
# Save new dynamic inventory
with open(dynamic_inventory_file, 'wb') as f:
f.write(dynamic_inventory_json)
logger.info("Inventory written")
return dynamic_inventory_json

6
releasenotes/notes/inventory-debug-flag-ead0ae2a2a1d7b90.yaml Normal file
View File

@ -0,0 +1,6 @@
---
features:
- A new debug flag has been added to ``dynamic_inventory.py``. This
should make it easier to understand what's happening with the inventory
script, and provide a way to gather output for more detailed bug reports.
See the developer docs for more details.

32
tests/test_inventory.py
View File

@ -39,10 +39,13 @@ def cleanup():
os.remove(f_file)
def get_inventory(clean=True):
def get_inventory(clean=True, extra_args=None):
"Return the inventory mapping in a dict."
args = {'config': TARGET_DIR}
if extra_args:
args.update(extra_args)
try:
inventory_string = di.main({'config': TARGET_DIR})
inventory_string = di.main(args)
inventory = json.loads(inventory_string)
return inventory
finally:
@ -1064,6 +1067,31 @@ class TestNetworkEntry(unittest.TestCase):
self.assertEqual(entry['interface'], 'eth1')
class TestDebugLogging(unittest.TestCase):
@mock.patch('dynamic_inventory.logging')
@mock.patch('dynamic_inventory.logger')
def test_logging_enabled(self, mock_logger, mock_logging):
# Shadow the real value so tests don't complain about it
mock_logging.DEBUG = 10
get_inventory(extra_args={"debug": True})
self.assertTrue(mock_logging.basicConfig.called)
self.assertTrue(mock_logger.info.called)
self.assertTrue(mock_logger.debug.called)
@mock.patch('dynamic_inventory.logging')
@mock.patch('dynamic_inventory.logger')
def test_logging_disabled(self, mock_logger, mock_logging):
get_inventory(extra_args={"debug": False})
self.assertFalse(mock_logging.basicConfig.called)
# Even though logging is disabled, we still call these
# all over the place; they just choose not to do anything.
self.assertTrue(mock_logger.info.called)
self.assertTrue(mock_logger.debug.called)
class TestLxcHosts(TestConfigCheckBase):
def test_lxc_hosts_group_present(self):