Review and fix logging messages

Fixes levels and wording for many messages.
Also adds a couple more helpful messages.

Change-Id: Ib134d9483a29f961e4472c0c007405caa0fbc19f
Closes-Bug: #1401585

ironic_discoverd/discover.py

@@ -49,7 +49,8 @@ def discover(uuids):
         _validate(ironic, node)
         nodes.append(node)
 
-    LOG.info('Proceeding with discovery on nodes %s', [n.uuid for n in nodes])
+    LOG.info('Proceeding with discovery on node(s) %s',
+             [n.uuid for n in nodes])
     for node in nodes:
         eventlet.greenthread.spawn_n(_background_start_discover, ironic, node)
 

ironic_discoverd/firewall.py

@@ -37,8 +37,7 @@ def _iptables(*args, **kwargs):
         subprocess.check_output(cmd, **kwargs)
     except subprocess.CalledProcessError as exc:
         if ignore:
-            LOG.debug('iptables %s failed (ignoring):\n%s', args,
-                      exc.output)
+            LOG.debug('ignoring failed iptables %s:\n%s', args, exc.output)
         else:
             LOG.error('iptables %s failed:\n%s', args, exc.output)
             raise
@@ -86,7 +85,7 @@ def update_filters(ironic=None):
     with LOCK:
         macs_active = set(p.address for p in ironic.port.list(limit=0))
         to_blacklist = macs_active - node_cache.macs_on_discovery()
-        LOG.debug('Blacklisting MAC\'s %s', to_blacklist)
+        LOG.debug('Blacklisting active MAC\'s %s', to_blacklist)
 
         # Clean up a bit to account for possible troubles on previous run
         _clean_up(NEW_CHAIN)

ironic_discoverd/main.py

@@ -37,10 +37,11 @@ LOG = logging.getLogger('ironic_discoverd.main')
 @app.route('/v1/continue', methods=['POST'])
 def post_continue():
     data = request.get_json(force=True)
-    LOG.debug("Got JSON %s, going into processing thread", data)
+    LOG.debug("/v1/continue got JSON %s", data)
     try:
         res = process.process(data)
     except utils.DiscoveryFailed as exc:
+        LOG.debug('/v1/continue failed: %s', exc)
         return str(exc), exc.http_code
     else:
         return json.dumps(res), 200, {'Content-Type': 'applications/json'}
@@ -50,20 +51,21 @@ def post_continue():
 def post_discover():
     if conf.getboolean('discoverd', 'authenticate'):
         if not request.headers.get('X-Auth-Token'):
-            LOG.debug("No X-Auth-Token header, rejecting")
+            LOG.error("No X-Auth-Token header, rejecting request")
             return 'Authentication required', 401
         try:
             utils.get_keystone(token=request.headers['X-Auth-Token'])
         except exceptions.Unauthorized:
-            LOG.debug("Keystone denied access, rejecting")
+            LOG.error("Keystone denied access, rejecting request")
             return 'Access denied', 403
         # TODO(dtanstur): check for admin role
 
     data = request.get_json(force=True)
-    LOG.debug("Got JSON %s", data)
+    LOG.debug("/v1/discover got JSON %s", data)
     try:
         discover.discover(data)
     except utils.DiscoveryFailed as exc:
+        LOG.debug('/v1/discover failed: %s', exc)
         return str(exc), exc.http_code
     else:
         return "", 202
@@ -101,15 +103,15 @@ def check_ironic_available():
     attempts = conf.getint('discoverd', 'ironic_retry_attempts')
     assert attempts >= 0
     retry_period = conf.getint('discoverd', 'ironic_retry_period')
-    LOG.info('Trying to connect to Ironic')
+    LOG.debug('Trying to connect to Ironic')
     for i in range(attempts + 1):  # one attempt always required
         try:
             utils.get_client().driver.list()
         except Exception as exc:
             if i == attempts:
                 raise
-            LOG.error('Unable to connect to Ironic or Keystone, retrying %d '
-                      'times more: %s', attempts - i, exc)
+            LOG.warning('Unable to connect to Ironic or Keystone, retrying %d '
+                        'times more: %s', attempts - i, exc)
         else:
             break
         eventlet.greenthread.sleep(retry_period)
@@ -126,6 +128,8 @@ def main():
     logging.getLogger('urllib3.connectionpool').setLevel(logging.WARNING)
     logging.getLogger('requests.packages.urllib3.connectionpool').setLevel(
         logging.WARNING)
+    logging.getLogger('ironicclient.common.http').setLevel(
+        logging.INFO if debug else logging.ERROR)
 
     if not conf.getboolean('discoverd', 'authenticate'):
         LOG.warning('Starting unauthenticated, please check configuration')
@@ -136,8 +140,11 @@ def main():
 
     period = conf.getint('discoverd', 'firewall_update_period')
     eventlet.greenthread.spawn_n(periodic_update, period)
-    period = conf.getint('discoverd', 'clean_up_period')
-    eventlet.greenthread.spawn_n(periodic_clean_up, period)
+    if conf.getint('discoverd', 'timeout') > 0:
+        period = conf.getint('discoverd', 'clean_up_period')
+        eventlet.greenthread.spawn_n(periodic_clean_up, period)
+    else:
+        LOG.warning('Timeout is disabled in configuration')
 
     app.run(debug=debug,
             host=conf.get('discoverd', 'listen_address'),

ironic_discoverd/node_cache.py

@@ -88,7 +88,10 @@ def add_node(uuid, **attributes):
                 db.executemany("insert into attributes(name, value, uuid) "
                                "values(?, ?, ?)",
                                [(name, v, uuid) for v in value])
-            except sqlite3.IntegrityError:
+            except sqlite3.IntegrityError as exc:
+                LOG.error('Database integrity error %s, some or all of '
+                          '%s\'s %s seem to be on discovery already',
+                          exc, name, value)
                 raise utils.DiscoveryFailed(
                     'Some or all of %(name)s\'s %(value)s are already '
                     'on discovery' %
@@ -122,12 +125,13 @@ def pop_node(**attributes):
     db = _db()
     for (name, value) in sorted(attributes.items()):
         if not value:
-            LOG.warning('Empty value for attribute %s', name)
+            LOG.debug('Empty value for attribute %s', name)
             continue
         if not isinstance(value, list):
             value = [value]
 
-        LOG.debug('Trying to use %s %s for discovery' % (name, value))
+        LOG.debug('Trying to use %s of value %s for node look up'
+                  % (name, value))
         rows = db.execute('select distinct uuid from attributes where ' +
                           ' OR '.join('name=? AND value=?' for _ in value),
                           sum(([name, v] for v in value), [])).fetchall()
@@ -166,7 +170,6 @@ def clean_up():
     """
     timeout = conf.getint('discoverd', 'timeout')
     if timeout <= 0:
-        LOG.debug('Timeout is disabled')
         return []
 
     threshold = time.time() - timeout

ironic_discoverd/process.py

@@ -97,7 +97,9 @@ def _process_node(ironic, node, node_info, cached_node):
     for mac, patches in port_patches.items():
         utils.retry_on_conflict(ironic.port.update, ports[mac].uuid, patches)
 
-    LOG.info('Node %s was updated with data from discovery process', node.uuid)
+    LOG.debug('Node %s was updated with data from discovery process, '
+              'patches %s, port patches %s',
+              node.uuid, node_patches, port_patches)
 
     firewall.update_filters(ironic)
 
@@ -145,3 +147,5 @@ def _finish_discovery(ironic, node):
     patch = [{'op': 'add', 'path': '/extra/newly_discovered', 'value': 'true'},
              {'op': 'remove', 'path': '/extra/on_discovery'}]
     utils.retry_on_conflict(ironic.node.update, node.uuid, patch)
+
+    LOG.info('Discovery finished successfully for node %s', node.uuid)