diff --git a/devstack/plugin.sh b/devstack/plugin.sh index f4991a3..606af5b 100644 --- a/devstack/plugin.sh +++ b/devstack/plugin.sh @@ -194,6 +194,7 @@ function configure_inspector { mkdir_chown_stack "$IRONIC_INSPECTOR_RAMDISK_LOGDIR" inspector_iniset processing ramdisk_logs_dir "$IRONIC_INSPECTOR_RAMDISK_LOGDIR" inspector_iniset processing always_store_ramdisk_logs "$IRONIC_INSPECTOR_ALWAYS_STORE_RAMDISK_LOGS" + inspector_iniset processing log_bmc_address False } function configure_inspector_swift { diff --git a/example.conf b/example.conf index 9bbd4df..ef78b96 100644 --- a/example.conf +++ b/example.conf @@ -84,47 +84,62 @@ # The name of a logging configuration file. This file is appended to # any existing logging configuration files. For details about logging # configuration files, see the Python logging module documentation. -# (string value) +# Note that when logging configuration files are used then all logging +# configuration is set in the configuration file and other logging +# configuration options are ignored (for example, log_format). (string +# value) # Deprecated group/name - [DEFAULT]/log_config #log_config_append = # DEPRECATED. A logging.Formatter log message format string which may # use any of the available logging.LogRecord attributes. This option # is deprecated. Please use logging_context_format_string and -# logging_default_format_string instead. (string value) +# logging_default_format_string instead. This option is ignored if +# log_config_append is set. (string value) #log_format = # Format string for %%(asctime)s in log records. Default: %(default)s -# . (string value) +# . This option is ignored if log_config_append is set. (string value) #log_date_format = %Y-%m-%d %H:%M:%S # (Optional) Name of log file to output to. If no default is set, -# logging will go to stdout. (string value) +# logging will go to stdout. This option is ignored if +# log_config_append is set. (string value) # Deprecated group/name - [DEFAULT]/logfile #log_file = # (Optional) The base directory used for relative --log-file paths. -# (string value) +# This option is ignored if log_config_append is set. (string value) # Deprecated group/name - [DEFAULT]/logdir #log_dir = +# (Optional) Uses logging handler designed to watch file system. When +# log file is moved or removed this handler will open a new log file +# with specified path instantaneously. It makes sense only if log-file +# option is specified and Linux platform is used. This option is +# ignored if log_config_append is set. (boolean value) +#watch_log_file = false + # Use syslog for logging. Existing syslog format is DEPRECATED and -# will be changed later to honor RFC5424. (boolean value) +# will be changed later to honor RFC5424. This option is ignored if +# log_config_append is set. (boolean value) #use_syslog = false # (Optional) Enables or disables syslog rfc5424 format for logging. If # enabled, prefixes the MSG part of the syslog message with APP-NAME # (RFC5424). The format without the APP-NAME is deprecated in Kilo, -# and will be removed in Mitaka, along with this option. (boolean -# value) +# and will be removed in Mitaka, along with this option. This option +# is ignored if log_config_append is set. (boolean value) # This option is deprecated for removal. # Its value may be silently ignored in the future. #use_syslog_rfc_format = true -# Syslog facility to receive log lines. (string value) +# Syslog facility to receive log lines. This option is ignored if +# log_config_append is set. (string value) #syslog_log_facility = LOG_USER -# Log output to standard error. (boolean value) +# Log output to standard error. This option is ignored if +# log_config_append is set. (boolean value) #use_stderr = true # Format string to use for log messages with context. (string value) @@ -141,7 +156,8 @@ # value) #logging_exception_prefix = %(asctime)s.%(msecs)03d %(process)d ERROR %(name)s %(instance)s -# List of logger=LEVEL pairs. (list value) +# List of logger=LEVEL pairs. This option is ignored if +# log_config_append is set. (list value) #default_log_levels = amqp=WARN,amqplib=WARN,boto=WARN,qpid=WARN,sqlalchemy=WARN,suds=INFO,oslo.messaging=INFO,iso8601=WARN,requests.packages.urllib3.connectionpool=WARN,urllib3.connectionpool=WARN,websocket=WARN,requests.packages.urllib3.util.retry=WARN,urllib3.util.retry=WARN,keystonemiddleware=WARN,routes.middleware=WARN,stevedore=WARN,taskflow=WARN # Enables or disables publication of error events. (boolean value) @@ -155,6 +171,10 @@ # (string value) #instance_uuid_format = "[instance: %(uuid)s] " +# Format string for user_identity field of the +# logging_context_format_string (string value) +#logging_user_identity_format = %(user)s %(tenant)s %(domain)s %(user_domain)s %(project_domain)s + # Enables or disables fatal status of deprecations. (boolean value) #fatal_deprecations = false @@ -535,6 +555,14 @@ # Service tenant name. (string value) #admin_tenant_name = admin +# Authentication type to load (unknown value) +# Deprecated group/name - [DEFAULT]/auth_plugin +#auth_type = + +# Config Section from which to load plugin specific options (unknown +# value) +#auth_section = + [processing] @@ -615,6 +643,10 @@ # local_gb is calculated on the ramdisk side. (boolean value) #disk_partitioning_spacing = true +# Whether to log node BMC address with every message during +# processing. (boolean value) +#log_bmc_address = true + [swift] diff --git a/ironic_inspector/conf.py b/ironic_inspector/conf.py index ce218c0..fb490ae 100644 --- a/ironic_inspector/conf.py +++ b/ironic_inspector/conf.py @@ -178,6 +178,10 @@ PROCESSING_OPTS = [ 'partitioning. Only has effect when used with the IPA ' 'as a ramdisk, for older ramdisk local_gb is ' 'calculated on the ramdisk side.'), + cfg.BoolOpt('log_bmc_address', + default=True, + help='Whether to log node BMC address with every message ' + 'during processing.'), ] diff --git a/ironic_inspector/introspect.py b/ironic_inspector/introspect.py index 37edb5f..1660151 100644 --- a/ironic_inspector/introspect.py +++ b/ironic_inspector/introspect.py @@ -20,7 +20,6 @@ import time from eventlet import semaphore from ironicclient import exceptions from oslo_config import cfg -from oslo_log import log from ironic_inspector.common.i18n import _, _LI, _LW from ironic_inspector import firewall @@ -30,7 +29,7 @@ from ironic_inspector import utils CONF = cfg.CONF -LOG = log.getLogger("ironic_inspector.introspect") +LOG = utils.getProcessingLogger(__name__) PASSWORD_ACCEPTED_CHARS = set(string.ascii_letters + string.digits) PASSWORD_MAX_LENGTH = 20 # IPMI v2.0 @@ -47,20 +46,19 @@ def _validate_ipmi_credentials(node, new_ipmi_credentials): if not new_username: new_username = node.driver_info.get('ipmi_username') if not new_username: - raise utils.Error(_('Setting IPMI credentials requested for node %s,' - ' but neither new user name nor' - ' driver_info[ipmi_username] are provided') - % node.uuid) + raise utils.Error(_('Setting IPMI credentials requested, but neither ' + 'new user name nor driver_info[ipmi_username] ' + 'are provided'), + node_info=node) wrong_chars = {c for c in new_password if c not in PASSWORD_ACCEPTED_CHARS} if wrong_chars: raise utils.Error(_('Forbidden characters encountered in new IPMI ' - 'password for node %(node)s: "%(chars)s"; ' - 'use only letters and numbers') % - {'node': node.uuid, 'chars': ''.join(wrong_chars)}) + 'password: "%s"; use only letters and numbers') + % ''.join(wrong_chars), node_info=node) if not 0 < len(new_password) <= PASSWORD_MAX_LENGTH: raise utils.Error(_('IPMI password length should be > 0 and <= %d') - % PASSWORD_MAX_LENGTH) + % PASSWORD_MAX_LENGTH, node_info=node) return new_username, new_password @@ -91,10 +89,9 @@ def introspect(uuid, new_ipmi_credentials=None, token=None): else: validation = ironic.node.validate(node.uuid) if not validation.power['result']: - msg = _('Failed validation of power interface for node %(node)s, ' - 'reason: %(reason)s') - raise utils.Error(msg % {'node': node.uuid, - 'reason': validation.power['reason']}) + msg = _('Failed validation of power interface, reason: %s') + raise utils.Error(msg % validation.power['reason'], + node_info=node) node_info = node_cache.add_node(node.uuid, bmc_address=utils.get_ipmi_address(node), @@ -105,10 +102,11 @@ def introspect(uuid, new_ipmi_credentials=None, token=None): try: _background_introspect(ironic, node_info) except utils.Error as exc: + # Logging has already happened in Error.__init__ node_info.finished(error=str(exc)) except Exception as exc: msg = _('Unexpected exception in background introspection thread') - LOG.exception(msg) + LOG.exception(msg, node_info=node_info) node_info.finished(error=msg) utils.spawn_n(_handle_exceptions) @@ -141,42 +139,38 @@ def _background_introspect_locked(ironic, node_info): macs = list(node_info.ports()) if macs: node_info.add_attribute(node_cache.MACS_ATTRIBUTE, macs) - LOG.info(_LI('Whitelisting MAC\'s %(macs)s for node %(node)s on the' - ' firewall') % - {'macs': macs, 'node': node_info.uuid}) + LOG.info(_LI('Whitelisting MAC\'s %s on the firewall'), macs, + node_info=node_info) firewall.update_filters(ironic) attrs = node_info.attributes if CONF.processing.node_not_found_hook is None and not attrs: raise utils.Error( - _('No lookup attributes were found for node %s, inspector won\'t ' - 'be able to find it after introspection. Consider creating ' - 'ironic ports or providing an IPMI address.') % node_info.uuid) + _('No lookup attributes were found, inspector won\'t ' + 'be able to find it after introspection, consider creating ' + 'ironic ports or providing an IPMI address'), + node_info=node_info) - LOG.info(_LI('The following attributes will be used for looking up ' - 'node %(uuid)s: %(attrs)s'), - {'attrs': attrs, 'uuid': node_info.uuid}) + LOG.info(_LI('The following attributes will be used for look up: %s'), + attrs, node_info=node_info) if not node_info.options.get('new_ipmi_credentials'): try: ironic.node.set_boot_device(node_info.uuid, 'pxe', persistent=False) except Exception as exc: - LOG.warning(_LW('Failed to set boot device to PXE for' - ' node %(node)s: %(exc)s') % - {'node': node_info.uuid, 'exc': exc}) + LOG.warning(_LW('Failed to set boot device to PXE: %s'), + exc, node_info=node_info) try: ironic.node.set_power_state(node_info.uuid, 'reboot') except Exception as exc: - raise utils.Error(_('Failed to power on node %(node)s,' - ' check it\'s power ' - 'management configuration:\n%(exc)s') - % {'node': node_info.uuid, 'exc': exc}) - LOG.info(_LI('Introspection started successfully for node %s'), - node_info.uuid) + raise utils.Error(_('Failed to power on the node, check it\'s ' + 'power management configuration: %s'), + exc, node_info=node_info) + LOG.info(_LI('Introspection started successfully'), + node_info=node_info) else: - LOG.info(_LI('Introspection environment is ready for node %(node)s, ' - 'manual power on is required within %(timeout)d seconds') % - {'node': node_info.uuid, - 'timeout': CONF.timeout}) + LOG.info(_LI('Introspection environment is ready, manual power on is ' + 'required within %d seconds'), CONF.timeout, + node_info=node_info) diff --git a/ironic_inspector/main.py b/ironic_inspector/main.py index ecd57cd..df2dae8 100644 --- a/ironic_inspector/main.py +++ b/ironic_inspector/main.py @@ -42,7 +42,7 @@ CONF = cfg.CONF app = flask.Flask(__name__) -LOG = log.getLogger('ironic_inspector.main') +LOG = utils.getProcessingLogger(__name__) MINIMUM_API_VERSION = (1, 0) CURRENT_API_VERSION = (1, 2) @@ -172,7 +172,8 @@ def api_continue(): logged_data = {k: (v if k not in _LOGGING_EXCLUDED_KEYS else '') for k, v in data.items()} - LOG.debug("Received data from the ramdisk: %s", logged_data) + LOG.debug("Received data from the ramdisk: %s", logged_data, + data=data) return flask.jsonify(process.process(data)) diff --git a/ironic_inspector/node_cache.py b/ironic_inspector/node_cache.py index 63ed59c..9f46cd5 100644 --- a/ironic_inspector/node_cache.py +++ b/ironic_inspector/node_cache.py @@ -21,7 +21,6 @@ from ironicclient import exceptions from oslo_concurrency import lockutils from oslo_config import cfg from oslo_db import exception as db_exc -from oslo_log import log from oslo_utils import excutils from sqlalchemy import text @@ -32,7 +31,7 @@ from ironic_inspector import utils CONF = cfg.CONF -LOG = log.getLogger("ironic_inspector.node_cache") +LOG = utils.getProcessingLogger(__name__) MACS_ATTRIBUTE = 'mac' @@ -96,13 +95,13 @@ class NodeInfo(object): if self._locked: return True - LOG.debug('Attempting to acquire lock on node %s', self.uuid) + LOG.debug('Attempting to acquire lock', node_info=self) if self._lock.acquire(blocking): self._locked = True - LOG.debug('Successfully acquired lock on node %s', self.uuid) + LOG.debug('Successfully acquired lock', node_info=self) return True else: - LOG.debug('Unable to acquire lock on node %s', self.uuid) + LOG.debug('Unable to acquire lock', node_info=self) return False def release_lock(self): @@ -111,7 +110,7 @@ class NodeInfo(object): Does nothing if lock was not acquired using this NodeInfo object. """ if self._locked: - LOG.debug('Successfully released lock on node %s', self.uuid) + LOG.debug('Successfully released lock', node_info=self) self._lock.release() self._locked = False @@ -192,10 +191,11 @@ class NodeInfo(object): session) except db_exc.DBDuplicateEntry as exc: LOG.error(_LE('Database integrity error %s during ' - 'adding attributes'), exc) + 'adding attributes'), exc, node_info=self) raise utils.Error(_( 'Some or all of %(name)s\'s %(value)s are already ' - 'on introspection') % {'name': name, 'value': value}) + 'on introspection') % {'name': name, 'value': value}, + node_info=self) # Invalidate attributes so they're loaded on next usage self._attributes = None @@ -229,9 +229,8 @@ class NodeInfo(object): if mac not in self.ports(): self._create_port(mac) else: - LOG.warning( - _LW('Port %(mac)s already exists for node %(uuid)s, ' - 'skipping'), {'mac': mac, 'uuid': self.uuid}) + LOG.warning(_LW('Port %s already exists, skipping'), + mac, node_info=self) def ports(self): """Get Ironic port objects associated with the cached node record. @@ -249,9 +248,8 @@ class NodeInfo(object): try: port = self.ironic.port.create(node_uuid=self.uuid, address=mac) except exceptions.Conflict: - LOG.warning( - _LW('Port %(mac)s already exists for node %(uuid)s, ' - 'skipping'), {'mac': mac, 'uuid': self.uuid}) + LOG.warning(_LW('Port %s already exists, skipping'), + mac, node_info=self) # NOTE(dtantsur): we didn't get port object back, so we have to # reload ports on next access self._ports = None @@ -266,8 +264,7 @@ class NodeInfo(object): :param patches: JSON patches to apply :raises: ironicclient exceptions """ - LOG.debug('Updating node %(uuid)s with patches %(patches)s', - {'uuid': self.uuid, 'patches': patches}) + LOG.debug('Updating node with patches %s', patches, node_info=self) self._node = self.ironic.node.update(self.uuid, patches) def patch_port(self, port, patches): @@ -280,9 +277,9 @@ class NodeInfo(object): if isinstance(port, str): port = ports[port] - LOG.debug('Updating port %(mac)s of node %(uuid)s with patches ' - '%(patches)s', - {'mac': port.address, 'uuid': self.uuid, 'patches': patches}) + LOG.debug('Updating port %(mac)s with patches %(patches)s', + {'mac': port.address, 'patches': patches}, + node_info=self) new_port = self.ironic.port.update(port.uuid, patches) ports[port.address] = new_port diff --git a/ironic_inspector/plugins/extra_hardware.py b/ironic_inspector/plugins/extra_hardware.py index fa5dd2f..e9fa6d9 100644 --- a/ironic_inspector/plugins/extra_hardware.py +++ b/ironic_inspector/plugins/extra_hardware.py @@ -21,15 +21,15 @@ is stored in the 'inspector' container. import json from oslo_config import cfg -from oslo_log import log from ironic_inspector.common.i18n import _LW from ironic_inspector.common import swift from ironic_inspector.plugins import base +from ironic_inspector import utils CONF = cfg.CONF -LOG = log.getLogger('ironic_inspector.plugins.extra_hardware') +LOG = utils.getProcessingLogger(__name__) EDEPLOY_ITEM_SIZE = 4 @@ -52,7 +52,8 @@ class ExtraHardwareHook(base.ProcessingHook): """ if 'data' not in introspection_data: LOG.warning(_LW('No extra hardware information was received from ' - 'the ramdisk')) + 'the ramdisk'), + node_info=node_info, data=introspection_data) return data = introspection_data['data'] @@ -65,16 +66,19 @@ class ExtraHardwareHook(base.ProcessingHook): # by rules. if self._is_edeploy_data(data): LOG.debug('Extra hardware data is in eDeploy format, ' - 'converting to usable format.') + 'converting to usable format', + node_info=node_info, data=introspection_data) introspection_data['extra'] = self._convert_edeploy_data(data) else: LOG.warning(_LW('Extra hardware data was not in a recognised ' 'format (eDeploy), and will not be forwarded to ' - 'introspection rules.')) + 'introspection rules'), + node_info=node_info, data=introspection_data) LOG.debug('Deleting \"data\" key from introspection data as it is ' 'assumed unusable by introspection rules. Raw data is ' - 'stored in swift.') + 'stored in swift', + node_info=node_info, data=introspection_data) del introspection_data['data'] node_info.patch([{'op': 'add', 'path': '/extra/hardware_swift_object', diff --git a/ironic_inspector/plugins/raid_device.py b/ironic_inspector/plugins/raid_device.py index c36f6d2..027fadd 100644 --- a/ironic_inspector/plugins/raid_device.py +++ b/ironic_inspector/plugins/raid_device.py @@ -13,13 +13,12 @@ """Gather root device hint from recognized block devices.""" -from oslo_log import log - from ironic_inspector.common.i18n import _LI, _LW from ironic_inspector.plugins import base +from ironic_inspector import utils -LOG = log.getLogger(__name__) +LOG = utils.getProcessingLogger(__name__) class RaidDeviceDetection(base.ProcessingHook): @@ -55,19 +54,22 @@ class RaidDeviceDetection(base.ProcessingHook): """Adds fake local_gb value if it's missing from introspection_data.""" if not introspection_data.get('local_gb'): LOG.info(_LI('No volume is found on the node. Adding a fake ' - 'value for "local_gb"')) + 'value for "local_gb"'), + data=introspection_data) introspection_data['local_gb'] = 1 def before_update(self, introspection_data, node_info, **kwargs): current_devices = self._get_serials(introspection_data) if not current_devices: - LOG.warning(_LW('No block device was received from ramdisk')) + LOG.warning(_LW('No block device was received from ramdisk'), + node_info=node_info, data=introspection_data) return node = node_info.node() if 'root_device' in node.properties: - LOG.info(_LI('Root device is already known for the node')) + LOG.info(_LI('Root device is already known for the node'), + node_info=node_info, data=introspection_data) return if 'block_devices' in node.extra: @@ -78,10 +80,12 @@ class RaidDeviceDetection(base.ProcessingHook): if len(new_devices) > 1: LOG.warning(_LW('Root device cannot be identified because ' - 'multiple new devices were found')) + 'multiple new devices were found'), + node_info=node_info, data=introspection_data) return elif len(new_devices) == 0: - LOG.warning(_LW('No new devices were found')) + LOG.warning(_LW('No new devices were found'), + node_info=node_info, data=introspection_data) return node_info.patch([ diff --git a/ironic_inspector/plugins/rules.py b/ironic_inspector/plugins/rules.py index 4c29368..8cc93ae 100644 --- a/ironic_inspector/plugins/rules.py +++ b/ironic_inspector/plugins/rules.py @@ -16,13 +16,12 @@ import operator import netaddr -from oslo_log import log from ironic_inspector.plugins import base from ironic_inspector import utils -LOG = log.getLogger(__name__) +LOG = utils.getProcessingLogger(__name__) def coerce(value, expected): @@ -84,7 +83,7 @@ class FailAction(base.RuleActionPlugin): REQUIRED_PARAMS = {'message'} def apply(self, node_info, params, **kwargs): - raise utils.Error(params['message']) + raise utils.Error(params['message'], node_info=node_info) class SetAttributeAction(base.RuleActionPlugin): @@ -99,9 +98,8 @@ class SetAttributeAction(base.RuleActionPlugin): try: node_info.get_by_path(params['path']) except KeyError: - LOG.debug('Field %(path)s was not set on node %(node)s, ' - 'no need for rollback', - {'path': params['path'], 'node': node_info.uuid}) + LOG.debug('Field %s was not set, no need for rollback', + params['path'], node_info=node_info) return node_info.patch([{'op': 'remove', 'path': params['path']}]) diff --git a/ironic_inspector/plugins/standard.py b/ironic_inspector/plugins/standard.py index 7bd0426..9be4a01 100644 --- a/ironic_inspector/plugins/standard.py +++ b/ironic_inspector/plugins/standard.py @@ -19,7 +19,6 @@ import os import sys from oslo_config import cfg -from oslo_log import log from oslo_utils import units from ironic_inspector.common.i18n import _, _LC, _LI, _LW @@ -30,7 +29,7 @@ from ironic_inspector import utils CONF = cfg.CONF -LOG = log.getLogger('ironic_inspector.plugins.standard') +LOG = utils.getProcessingLogger('ironic_inspector.plugins.standard') KNOWN_ROOT_DEVICE_HINTS = ('model', 'vendor', 'serial', 'wwn', 'hctl', 'size') @@ -47,21 +46,22 @@ class RootDiskSelectionHook(base.ProcessingHook): """Detect root disk from root device hints and IPA inventory.""" hints = node_info.node().properties.get('root_device') if not hints: - LOG.debug('Root device hints are not provided for node %s', - node_info.uuid) + LOG.debug('Root device hints are not provided', + node_info=node_info, data=introspection_data) return inventory = introspection_data.get('inventory') if not inventory: LOG.error(_LW('Root device selection require ironic-python-agent ' - 'as an inspection ramdisk')) + 'as an inspection ramdisk'), + node_info=node_info, data=introspection_data) # TODO(dtantsur): make it a real error in Mitaka cycle return disks = inventory.get('disks', []) if not disks: - raise utils.Error(_('No disks found on a node %s') % - node_info.uuid) + raise utils.Error(_('No disks found'), + node_info=node_info, data=introspection_data) for disk in disks: properties = disk.copy() @@ -72,22 +72,21 @@ class RootDiskSelectionHook(base.ProcessingHook): actual = properties.get(name) if actual != value: LOG.debug('Disk %(disk)s does not satisfy hint ' - '%(name)s=%(value)s for node %(node)s, ' - 'actual value is %(actual)s', - {'disk': disk.get('name'), - 'name': name, 'value': value, - 'node': node_info.uuid, 'actual': actual}) + '%(name)s=%(value)s, actual value is %(actual)s', + {'disk': disk.get('name'), 'name': name, + 'value': value, 'actual': actual}, + node_info=node_info, data=introspection_data) break else: LOG.debug('Disk %(disk)s of size %(size)s satisfies ' - 'root device hints for node %(node)s', - {'disk': disk.get('name'), 'node': node_info.uuid, - 'size': disk['size']}) + 'root device hints', + {'disk': disk.get('name'), 'size': disk['size']}, + node_info=node_info, data=introspection_data) introspection_data['root_disk'] = disk return - raise utils.Error(_('No disks satisfied root device hints for node %s') - % node_info.uuid) + raise utils.Error(_('No disks satisfied root device hints'), + node_info=node_info, data=introspection_data) class SchedulerHook(base.ProcessingHook): @@ -107,11 +106,12 @@ class SchedulerHook(base.ProcessingHook): if missing: raise utils.Error( _('The following required parameters are missing: %s') % - missing) + missing, node_info=node_info, data=introspection_data) LOG.info(_LI('Discovered data: CPUs: %(cpus)s %(cpu_arch)s, ' 'memory %(memory_mb)s MiB, disk %(local_gb)s GiB'), - {key: introspection_data.get(key) for key in self.KEYS}) + {key: introspection_data.get(key) for key in self.KEYS}, + node_info=node_info, data=introspection_data) overwrite = CONF.processing.overwrite_existing properties = {key: str(introspection_data[key]) @@ -140,28 +140,23 @@ class ValidateInterfacesHook(base.ProcessingHook): def before_processing(self, introspection_data, **kwargs): """Validate information about network interfaces.""" - bmc_address = introspection_data.get('ipmi_address') if not introspection_data.get('interfaces'): - raise utils.Error(_('No interfaces supplied by the ramdisk')) + raise utils.Error(_('No interfaces supplied by the ramdisk'), + data=introspection_data) valid_interfaces = { n: iface for n, iface in introspection_data['interfaces'].items() if utils.is_valid_mac(iface.get('mac')) } - pxe_mac = introspection_data.get('boot_interface') + pxe_mac = utils.get_pxe_mac(introspection_data) if CONF.processing.add_ports == 'pxe' and not pxe_mac: LOG.warning(_LW('No boot interface provided in the introspection ' - 'data, will add all ports with IP addresses')) + 'data, will add all ports with IP addresses'), + data=introspection_data) if CONF.processing.add_ports == 'pxe' and pxe_mac: - LOG.info(_LI('PXE boot interface was %s'), pxe_mac) - if '-' in pxe_mac: - # pxelinux format: 01-aa-bb-cc-dd-ee-ff - pxe_mac = pxe_mac.split('-', 1)[1] - pxe_mac = pxe_mac.replace('-', ':').lower() - valid_interfaces = { n: iface for n, iface in valid_interfaces.items() if iface['mac'].lower() == pxe_mac @@ -173,20 +168,19 @@ class ValidateInterfacesHook(base.ProcessingHook): } if not valid_interfaces: - raise utils.Error(_('No valid interfaces found for node with ' - 'BMC %(ipmi_address)s, got %(interfaces)s') % - {'ipmi_address': bmc_address, - 'interfaces': introspection_data['interfaces']}) + raise utils.Error(_('No valid interfaces found in %s') % + introspection_data['interfaces'], + data=introspection_data) elif valid_interfaces != introspection_data['interfaces']: invalid = {n: iface for n, iface in introspection_data['interfaces'].items() if n not in valid_interfaces} LOG.warning(_LW( 'The following interfaces were invalid or not eligible in ' - 'introspection data for node with BMC %(ipmi_address)s and ' - 'were excluded: %(invalid)s'), - {'invalid': invalid, 'ipmi_address': bmc_address}) - LOG.info(_LI('Eligible interfaces are %s'), valid_interfaces) + 'introspection data and were excluded: %s'), invalid, + data=introspection_data) + LOG.info(_LI('Eligible interfaces are %s'), valid_interfaces, + data=introspection_data) introspection_data['all_interfaces'] = introspection_data['interfaces'] introspection_data['interfaces'] = valid_interfaces @@ -209,12 +203,11 @@ class ValidateInterfacesHook(base.ProcessingHook): for port in list(node_info.ports().values()): if port.address not in expected_macs: LOG.info(_LI("Deleting port %(port)s as its MAC %(mac)s is " - "not in expected MAC list %(expected)s for node " - "%(node)s"), + "not in expected MAC list %(expected)s"), {'port': port.uuid, 'mac': port.address, - 'expected': list(sorted(expected_macs)), - 'node': node_info.uuid}) + 'expected': list(sorted(expected_macs))}, + node_info=node_info, data=introspection_data) node_info.delete_port(port) @@ -231,17 +224,20 @@ class RamdiskErrorHook(base.ProcessingHook): if logs: self._store_logs(logs, introspection_data) else: - LOG.debug('No logs received from the ramdisk') + LOG.debug('No logs received from the ramdisk', + data=introspection_data) if error: - raise utils.Error(_('Ramdisk reported error: %s') % error) + raise utils.Error(_('Ramdisk reported error: %s') % error, + data=introspection_data) def _store_logs(self, logs, introspection_data): if not CONF.processing.ramdisk_logs_dir: LOG.warning( _LW('Failed to store logs received from the ramdisk ' 'because ramdisk_logs_dir configuration option ' - 'is not set')) + 'is not set'), + data=introspection_data) return if not os.path.exists(CONF.processing.ramdisk_logs_dir): @@ -253,4 +249,5 @@ class RamdiskErrorHook(base.ProcessingHook): with open(os.path.join(CONF.processing.ramdisk_logs_dir, file_name), 'wb') as fp: fp.write(base64.b64decode(logs)) - LOG.info(_LI('Ramdisk logs stored in file %s'), file_name) + LOG.info(_LI('Ramdisk logs stored in file %s'), file_name, + data=introspection_data) diff --git a/ironic_inspector/process.py b/ironic_inspector/process.py index 4d5b2eb..1447a0d 100644 --- a/ironic_inspector/process.py +++ b/ironic_inspector/process.py @@ -16,7 +16,6 @@ import eventlet from ironicclient import exceptions from oslo_config import cfg -from oslo_log import log from ironic_inspector.common.i18n import _, _LE, _LI, _LW from ironic_inspector.common import swift @@ -28,7 +27,7 @@ from ironic_inspector import utils CONF = cfg.CONF -LOG = log.getLogger("ironic_inspector.process") +LOG = utils.getProcessingLogger(__name__) _CREDENTIALS_WAIT_RETRIES = 10 _CREDENTIALS_WAIT_PERIOD = 3 @@ -74,13 +73,15 @@ def process(introspection_data): except utils.Error as exc: LOG.error(_LE('Hook %(hook)s failed, delaying error report ' 'until node look up: %(error)s'), - {'hook': hook_ext.name, 'error': exc}) + {'hook': hook_ext.name, 'error': exc}, + data=introspection_data) failures.append('Preprocessing hook %(hook)s: %(error)s' % {'hook': hook_ext.name, 'error': exc}) except Exception as exc: LOG.exception(_LE('Hook %(hook)s failed, delaying error report ' 'until node look up: %(error)s'), - {'hook': hook_ext.name, 'error': exc}) + {'hook': hook_ext.name, 'error': exc}, + data=introspection_data) failures.append(_('Unexpected exception %(exc_class)s during ' 'preprocessing in hook %(hook)s: %(error)s') % {'hook': hook_ext.name, @@ -93,28 +94,23 @@ def process(introspection_data): # node_not_found hook node_info.acquire_lock() - if failures and node_info: + if failures or node_info is None: msg = _('The following failures happened during running ' - 'pre-processing hooks for node %(uuid)s:\n%(failures)s') % { - 'uuid': node_info.uuid, - 'failures': '\n'.join(failures) - } - node_info.finished(error='\n'.join(failures)) - raise utils.Error(msg) - elif not node_info: - msg = _('The following failures happened during running ' - 'pre-processing hooks for unknown node:\n%(failures)s') % { - 'failures': '\n'.join(failures) - } - raise utils.Error(msg) + 'pre-processing hooks:\n%s') % '\n'.join(failures) + if node_info is not None: + node_info.finished(error='\n'.join(failures)) + raise utils.Error(msg, node_info=node_info, data=introspection_data) + + LOG.info(_LI('Matching node is %s'), node_info.uuid, + node_info=node_info, data=introspection_data) try: node = node_info.node() except exceptions.NotFound: - msg = (_('Node UUID %s was found in cache, but is not found in Ironic') - % node_info.uuid) + msg = _('Node was found in cache, but is not found in Ironic') node_info.finished(error=msg) - raise utils.Error(msg, code=404) + raise utils.Error(msg, code=404, node_info=node_info, + data=introspection_data) try: return _process_node(node, introspection_data, node_info) @@ -127,7 +123,7 @@ def process(introspection_data): '%(error)s') % {'exc_class': exc.__class__.__name__, 'error': exc} node_info.finished(error=msg) - raise utils.Error(msg) + raise utils.Error(msg, node_info=node_info, data=introspection_data) def _run_post_hooks(node_info, introspection_data): @@ -160,16 +156,17 @@ def _process_node(node, introspection_data, node_info): if CONF.processing.store_data == 'swift': swift_object_name = swift.store_introspection_data(introspection_data, node_info.uuid) - LOG.info(_LI('Introspection data for node %(node)s was stored in ' - 'Swift in object %(obj)s'), - {'node': node_info.uuid, 'obj': swift_object_name}) + LOG.info(_LI('Introspection data was stored in Swift in object %s'), + swift_object_name, + node_info=node_info, data=introspection_data) if CONF.processing.store_data_location: node_info.patch([{'op': 'add', 'path': '/extra/%s' % CONF.processing.store_data_location, 'value': swift_object_name}]) else: - LOG.debug('Swift support is disabled, introspection data for node %s ' - 'won\'t be stored', node_info.uuid) + LOG.debug('Swift support is disabled, introspection data ' + 'won\'t be stored', + node_info=node_info, data=introspection_data) ironic = utils.get_client() firewall.update_filters(ironic) @@ -189,7 +186,7 @@ def _process_node(node, introspection_data, node_info): resp['ipmi_username'] = new_username resp['ipmi_password'] = new_password else: - utils.spawn_n(_finish, ironic, node_info) + utils.spawn_n(_finish, ironic, node_info, introspection_data) return resp @@ -212,22 +209,22 @@ def _finish_set_ipmi_credentials(ironic, node, node_info, introspection_data, # We don't care about boot device, obviously. ironic.node.get_boot_device(node_info.uuid) except Exception as exc: - LOG.info(_LI('Waiting for credentials update on node %(node)s,' - ' attempt %(attempt)d current error is %(exc)s') % - {'node': node_info.uuid, - 'attempt': attempt, 'exc': exc}) + LOG.info(_LI('Waiting for credentials update, attempt %(attempt)d ' + 'current error is %(exc)s') % + {'attempt': attempt, 'exc': exc}, + node_info=node_info, data=introspection_data) eventlet.greenthread.sleep(_CREDENTIALS_WAIT_PERIOD) else: - _finish(ironic, node_info) + _finish(ironic, node_info, introspection_data) return msg = (_('Failed to validate updated IPMI credentials for node ' '%s, node might require maintenance') % node_info.uuid) node_info.finished(error=msg) - raise utils.Error(msg) + raise utils.Error(msg, node_info=node_info, data=introspection_data) -def _finish(ironic, node_info): +def _finish(ironic, node_info, introspection_data): LOG.debug('Forcing power off of node %s', node_info.uuid) try: ironic.node.set_power_state(node_info.uuid, 'off') @@ -236,8 +233,8 @@ def _finish(ironic, node_info): 'management configuration: %(exc)s') % {'node': node_info.uuid, 'exc': exc}) node_info.finished(error=msg) - raise utils.Error(msg) + raise utils.Error(msg, node_info=node_info, data=introspection_data) node_info.finished() - LOG.info(_LI('Introspection finished successfully for node %s'), - node_info.uuid) + LOG.info(_LI('Introspection finished successfully'), + node_info=node_info, data=introspection_data) diff --git a/ironic_inspector/rules.py b/ironic_inspector/rules.py index 5621822..5b7341e 100644 --- a/ironic_inspector/rules.py +++ b/ironic_inspector/rules.py @@ -17,7 +17,6 @@ import jsonpath_rw as jsonpath import jsonschema from oslo_db import exception as db_exc -from oslo_log import log from oslo_utils import timeutils from oslo_utils import uuidutils from sqlalchemy import orm @@ -28,7 +27,7 @@ from ironic_inspector.plugins import base as plugins_base from ironic_inspector import utils -LOG = log.getLogger(__name__) +LOG = utils.getProcessingLogger(__name__) _CONDITIONS_SCHEMA = None _ACTIONS_SCHEMA = None @@ -128,8 +127,8 @@ class IntrospectionRule(object): :param data: introspection data :returns: True if conditions match, otherwise False """ - LOG.debug('Checking rule "%(descr)s" on node %(uuid)s', - {'descr': self.description, 'uuid': node_info.uuid}) + LOG.debug('Checking rule "%s"', self.description, + node_info=node_info, data=data) ext_mgr = plugins_base.rule_conditions_manager() for cond in self._conditions: field_values = jsonpath.parse(cond.field).find(data) @@ -138,16 +137,15 @@ class IntrospectionRule(object): if not field_values: if cond_ext.ALLOW_NONE: - LOG.debug('Field with JSON path %(path)s was not found in ' - 'data for node %(uuid)s', - {'path': cond.field, 'uuid': node_info.uuid}) + LOG.debug('Field with JSON path %s was not found in data', + cond.field, node_info=node_info, data=data) field_values = [None] else: LOG.info(_LI('Field with JSON path %(path)s was not found ' - 'in data for node %(uuid)s, rule "%(rule)s" ' - 'will not be applied'), - {'path': cond.field, 'uuid': node_info.uuid, - 'rule': self.description}) + 'in data, rule "%(rule)s" will not ' + 'be applied'), + {'path': cond.field, 'rule': self.description}, + node_info=node_info, data=data) return False for value in field_values: @@ -158,46 +156,45 @@ class IntrospectionRule(object): break if not result: - LOG.info(_LI('Rule "%(rule)s" will not be applied to node ' - '%(uuid)s: condition %(field)s %(op)s %(params)s ' - 'failed'), - {'rule': self.description, 'uuid': node_info.uuid, - 'field': cond.field, 'op': cond.op, - 'params': cond.params}) + LOG.info(_LI('Rule "%(rule)s" will not be applied: condition ' + '%(field)s %(op)s %(params)s failed'), + {'rule': self.description, 'field': cond.field, + 'op': cond.op, 'params': cond.params}, + node_info=node_info, data=data) return False - LOG.info(_LI('Rule "%(rule)s" will be applied to node %(uuid)s'), - {'rule': self.description, 'uuid': node_info.uuid}) + LOG.info(_LI('Rule "%s" will be applied'), self.description, + node_info=node_info, data=data) return True - def apply_actions(self, node_info, rollback=False): + def apply_actions(self, node_info, rollback=False, data=None): """Run actions on a node. :param node_info: NodeInfo instance :param rollback: if True, rollback actions are executed + :param data: introspection data (only used for logging) """ if rollback: method = 'rollback' else: method = 'apply' - LOG.debug('Running %(what)s actions for rule "%(rule)s" ' - 'on node %(node)s', - {'what': method, 'rule': self.description, - 'node': node_info.uuid}) + LOG.debug('Running %(what)s actions for rule "%(rule)s"', + {'what': method, 'rule': self.description}, + node_info=node_info, data=data) ext_mgr = plugins_base.rule_actions_manager() for act in self._actions: - LOG.debug('Running %(what)s action `%(action)s %(params)s` for ' - 'node %(node)s', + LOG.debug('Running %(what)s action `%(action)s %(params)s`', {'action': act.action, 'params': act.params, - 'node': node_info.uuid, 'what': method}) + 'what': method}, + node_info=node_info, data=data) ext = ext_mgr[act.action].obj getattr(ext, method)(node_info, act.params) - LOG.debug('Successfully applied %(what)s to node %(node)s', - {'what': 'rollback actions' if rollback else 'actions', - 'node': node_info.uuid}) + LOG.debug('Successfully applied %s', + 'rollback actions' if rollback else 'actions', + node_info=node_info, data=data) def create(conditions_json, actions_json, uuid=None, @@ -349,11 +346,12 @@ def apply(node_info, data): """Apply rules to a node.""" rules = get_all() if not rules: - LOG.debug('No custom introspection rules to apply to node %s', - node_info.uuid) + LOG.debug('No custom introspection rules to apply', + node_info=node_info, data=data) return - LOG.debug('Applying custom introspection rules to node %s', node_info.uuid) + LOG.debug('Applying custom introspection rules', + node_info=node_info, data=data) to_rollback = [] to_apply = [] @@ -364,18 +362,19 @@ def apply(node_info, data): to_rollback.append(rule) if to_rollback: - LOG.debug('Running rollback actions on node %s', node_info.uuid) + LOG.debug('Running rollback actions', node_info=node_info, data=data) for rule in to_rollback: rule.apply_actions(node_info, rollback=True) else: - LOG.debug('No rollback actions to apply on node %s', node_info.uuid) + LOG.debug('No rollback actions to apply', + node_info=node_info, data=data) if to_apply: - LOG.debug('Running actions on node %s', node_info.uuid) + LOG.debug('Running actions', node_info=node_info, data=data) for rule in to_apply: rule.apply_actions(node_info, rollback=False) else: - LOG.debug('No actions to apply on node %s', node_info.uuid) + LOG.debug('No actions to apply', node_info=node_info, data=data) - LOG.info(_LI('Successfully applied custom introspection rules to node %s'), - node_info.uuid) + LOG.info(_LI('Successfully applied custom introspection rules'), + node_info=node_info, data=data) diff --git a/ironic_inspector/test/test_introspect.py b/ironic_inspector/test/test_introspect.py index cef08c6..dcbcba4 100644 --- a/ironic_inspector/test/test_introspect.py +++ b/ironic_inspector/test/test_introspect.py @@ -213,7 +213,7 @@ class TestIntrospect(BaseTest): self.assertRaisesRegexp( utils.Error, - 'Failed validation of power interface for node', + 'Failed validation of power interface', introspect.introspect, self.uuid) cli.node.validate.assert_called_once_with(self.uuid) @@ -229,7 +229,7 @@ class TestIntrospect(BaseTest): cli.node.get.return_value = self.node self.assertRaisesRegexp( - utils.Error, 'Invalid provision state "active"', + utils.Error, 'Invalid provision state for introspection: "active"', introspect.introspect, self.uuid) self.assertEqual(0, self.node_info.ports.call_count) diff --git a/ironic_inspector/test/test_utils.py b/ironic_inspector/test/test_utils.py index 37d85d2..7315fa6 100644 --- a/ironic_inspector/test/test_utils.py +++ b/ironic_inspector/test/test_utils.py @@ -158,7 +158,8 @@ class TestGetIpmiAddress(base.BaseTest): @mock.patch('socket.gethostbyname') def test_bad_hostname_errors(self, mock_socket): node = mock.Mock(spec=['driver_info', 'uuid'], - driver_info={'ipmi_address': 'meow'}) + driver_info={'ipmi_address': 'meow'}, + uuid='uuid1') mock_socket.side_effect = socket.gaierror('Boom') self.assertRaises(utils.Error, utils.get_ipmi_address, node) @@ -212,3 +213,66 @@ class TestSpawnN(unittest.TestCase): greenpool.spawn_n.assert_called_with(func, "goodbye") mock_green_pool.assert_called_once_with(CONF.max_concurrency) + + +class TestProcessingLogger(base.BaseTest): + def test_prefix_no_info(self): + self.assertEqual('[unidentified node]', + utils.processing_logger_prefix()) + + def test_prefix_only_uuid(self): + node_info = mock.Mock(uuid='NNN') + self.assertEqual('[node: NNN]', + utils.processing_logger_prefix(node_info=node_info)) + + def test_prefix_only_bmc(self): + data = {'inventory': {'bmc_address': '1.2.3.4'}} + self.assertEqual('[node: BMC 1.2.3.4]', + utils.processing_logger_prefix(data=data)) + + def test_prefix_only_mac(self): + data = {'boot_interface': '01-aa-bb-cc-dd-ee-ff'} + self.assertEqual('[node: MAC aa:bb:cc:dd:ee:ff]', + utils.processing_logger_prefix(data=data)) + + def test_prefix_everything(self): + node_info = mock.Mock(uuid='NNN') + data = {'boot_interface': '01-aa-bb-cc-dd-ee-ff', + 'inventory': {'bmc_address': '1.2.3.4'}} + self.assertEqual('[node: NNN MAC aa:bb:cc:dd:ee:ff BMC 1.2.3.4]', + utils.processing_logger_prefix(node_info=node_info, + data=data)) + + def test_adapter_no_bmc(self): + CONF.set_override('log_bmc_address', False, 'processing') + node_info = mock.Mock(uuid='NNN') + data = {'boot_interface': '01-aa-bb-cc-dd-ee-ff', + 'inventory': {'bmc_address': '1.2.3.4'}} + logger = utils.getProcessingLogger(__name__) + msg, _kwargs = logger.process('foo', {'node_info': node_info, + 'data': data}) + self.assertEqual( + '[node: NNN MAC aa:bb:cc:dd:ee:ff] foo', + msg) + + def test_adapter_with_bmc(self): + node_info = mock.Mock(uuid='NNN') + data = {'boot_interface': '01-aa-bb-cc-dd-ee-ff', + 'inventory': {'bmc_address': '1.2.3.4'}} + logger = utils.getProcessingLogger(__name__) + msg, _kwargs = logger.process('foo', {'node_info': node_info, + 'data': data}) + self.assertEqual( + '[node: NNN MAC aa:bb:cc:dd:ee:ff BMC 1.2.3.4] foo', + msg) + + def test_adapter_empty_data(self): + logger = utils.getProcessingLogger(__name__) + msg, _kwargs = logger.process('foo', {'node_info': None, + 'data': None}) + self.assertEqual('[unidentified node] foo', msg) + + def test_adapter_no_data(self): + logger = utils.getProcessingLogger(__name__) + msg, _kwargs = logger.process('foo', {}) + self.assertEqual('foo', msg) diff --git a/ironic_inspector/utils.py b/ironic_inspector/utils.py index f2b9ed5..3f7d547 100644 --- a/ironic_inspector/utils.py +++ b/ironic_inspector/utils.py @@ -11,6 +11,7 @@ # See the License for the specific language governing permissions and # limitations under the License. +import logging as pylog import re import socket @@ -23,6 +24,7 @@ from oslo_log import log import six from ironic_inspector.common.i18n import _, _LE +from ironic_inspector import conf # noqa CONF = cfg.CONF @@ -30,21 +32,107 @@ CONF = cfg.CONF VALID_STATES = {'enroll', 'manageable', 'inspecting', 'inspectfail'} SET_CREDENTIALS_VALID_STATES = {'enroll'} - -LOG = log.getLogger('ironic_inspector.utils') - GREEN_POOL = None # 1.6 is a Kilo API version, which has all we need and is pretty well tested DEFAULT_IRONIC_API_VERSION = '1.6' +def get_ipmi_address(node): + ipmi_fields = ['ipmi_address'] + CONF.ipmi_address_fields + # NOTE(sambetts): IPMI Address is useless to us if bridging is enabled so + # just ignore it and return None + if node.driver_info.get("ipmi_bridging", "no") != "no": + return + for name in ipmi_fields: + value = node.driver_info.get(name) + if value: + try: + ip = socket.gethostbyname(value) + return ip + except socket.gaierror: + msg = ('Failed to resolve the hostname (%s) for node %s') + raise Error(msg % (value, node.uuid), node_info=node) + + +def get_ipmi_address_from_data(introspection_data): + try: + return introspection_data['inventory']['bmc_address'] + except KeyError: + return introspection_data.get('ipmi_address') + + +def get_pxe_mac(introspection_data): + pxe_mac = introspection_data.get('boot_interface') + if pxe_mac and '-' in pxe_mac: + # pxelinux format: 01-aa-bb-cc-dd-ee-ff + pxe_mac = pxe_mac.split('-', 1)[1] + pxe_mac = pxe_mac.replace('-', ':').lower() + return pxe_mac + + +def processing_logger_prefix(data=None, node_info=None): + """Calculate prefix for logging. + + Tries to use: + * node UUID, + * node PXE MAC, + * node BMC address + + :param data: introspection data + :param node_info: NodeInfo or ironic node object + :return: logging prefix as a string + """ + # TODO(dtantsur): try to get MAC and BMC address for node_info as well + parts = [] + data = data or {} + + if node_info is not None: + parts.append(node_info.uuid) + + pxe_mac = get_pxe_mac(data) + if pxe_mac: + parts.append('MAC %s' % pxe_mac) + + if CONF.processing.log_bmc_address: + bmc_address = get_ipmi_address_from_data(data) if data else None + if bmc_address: + parts.append('BMC %s' % bmc_address) + + if parts: + return _('[node: %s]') % ' '.join(parts) + else: + return _('[unidentified node]') + + +class ProcessingLoggerAdapter(log.KeywordArgumentAdapter): + def process(self, msg, kwargs): + if 'data' not in kwargs and 'node_info' not in kwargs: + return super(ProcessingLoggerAdapter, self).process(msg, kwargs) + + data = kwargs.get('data', {}) + node_info = kwargs.get('node_info') + prefix = processing_logger_prefix(data, node_info) + + msg, kwargs = super(ProcessingLoggerAdapter, self).process(msg, kwargs) + return ('%s %s' % (prefix, msg)), kwargs + + +def getProcessingLogger(name): + # We can't use getLogger from oslo_log, as it's an adapter itself + logger = pylog.getLogger(name) + return ProcessingLoggerAdapter(logger, {}) + + +LOG = getProcessingLogger(__name__) + + class Error(Exception): """Inspector exception.""" - def __init__(self, msg, code=400): + def __init__(self, msg, code=400, **kwargs): super(Error, self).__init__(msg) - LOG.error(msg) + LOG.error(msg, **kwargs) self.http_code = code @@ -155,35 +243,19 @@ def get_auth_strategy(): return CONF.auth_strategy -def get_ipmi_address(node): - ipmi_fields = ['ipmi_address'] + CONF.ipmi_address_fields - # NOTE(sambetts): IPMI Address is useless to us if bridging is enabled so - # just ignore it and return None - if node.driver_info.get("ipmi_bridging", "no") != "no": - return - for name in ipmi_fields: - value = node.driver_info.get(name) - if value: - try: - ip = socket.gethostbyname(value) - return ip - except socket.gaierror: - msg = ('Failed to resolve the hostname (%s) for node %s') - raise Error(msg % (value, node.uuid)) - - def check_provision_state(node, with_credentials=False): state = node.provision_state.lower() if with_credentials and state not in SET_CREDENTIALS_VALID_STATES: - msg = _('Invalid provision state "%(state)s" for setting IPMI ' - 'credentials on node %(node)s, valid states are %(valid)s') - raise Error(msg % {'node': node.uuid, 'state': state, - 'valid': list(SET_CREDENTIALS_VALID_STATES)}) + msg = _('Invalid provision state for setting IPMI credentials: ' + '"%(state)s", valid states are %(valid)s') + raise Error(msg % {'state': state, + 'valid': list(SET_CREDENTIALS_VALID_STATES)}, + node_info=node) elif not with_credentials and state not in VALID_STATES: - msg = _('Invalid provision state "%(state)s" for introspection of ' - 'node %(node)s, valid states are "%(valid)s"') - raise Error(msg % {'node': node.uuid, 'state': state, - 'valid': list(VALID_STATES)}) + msg = _('Invalid provision state for introspection: ' + '"%(state)s", valid states are "%(valid)s"') + raise Error(msg % {'state': state, 'valid': list(VALID_STATES)}, + node_info=node) def capabilities_to_dict(caps): diff --git a/releasenotes/notes/processing-logging-e2d27bbac95a7213.yaml b/releasenotes/notes/processing-logging-e2d27bbac95a7213.yaml new file mode 100644 index 0000000..c594605 --- /dev/null +++ b/releasenotes/notes/processing-logging-e2d27bbac95a7213.yaml @@ -0,0 +1,6 @@ +--- +other: + - Logging during processing is now more consistent in terms of how it + identifies the node. Now we try to prefix the log message with node UUID, + BMC address and PXE MAC address (if available). Logging BMC addresses can + be disabled via new "log_bmc_address" option in the "processing" section.