Improve logging for agent driver

* Added debug logging for every command and for lookup call. Redundant logging
  dropped from prepare_image.
* Log more steps as INFO (currently it looks like power on, power on, done):
  1. When ramdisk is booted and ready
  2. When image writing is done
* Several small improvements

Change-Id: I70d473e446e047140a02e19f21217b48de5f74a8

ironic/drivers/modules/agent.py

@@ -26,6 +26,7 @@ from ironic.common import exception
 from ironic.common.glance_service import service_utils
 from ironic.common.i18n import _
 from ironic.common.i18n import _LE
+from ironic.common.i18n import _LI
 from ironic.common import image_service
 from ironic.common import keystone
 from ironic.common import paths
@@ -466,7 +467,8 @@ class AgentVendorInterface(agent_base_vendor.BaseAgentVendor):
         task.process_event('resume')
         node = task.node
         image_source = node.instance_info.get('image_source')
-        LOG.debug('Continuing deploy for %s', node.uuid)
+        LOG.debug('Continuing deploy for node %(node)s with image %(img)s',
+                  {'node': node.uuid, 'img': image_source})
 
         image_info = {
             'id': image_source.split('/')[-1],
@@ -482,9 +484,7 @@ class AgentVendorInterface(agent_base_vendor.BaseAgentVendor):
         }
 
         # Tell the client to download and write the image with the given args
-        res = self._client.prepare_image(node, image_info)
-        LOG.debug('prepare_image got response %(res)s for node %(node)s',
-                  {'res': res, 'node': node.uuid})
+        self._client.prepare_image(node, image_info)
 
         task.process_event('wait')
 
@@ -498,8 +498,6 @@ class AgentVendorInterface(agent_base_vendor.BaseAgentVendor):
     def reboot_to_instance(self, task, **kwargs):
         task.process_event('resume')
         node = task.node
-        LOG.debug('Preparing to reboot to instance for node %s',
-                  node.uuid)
         error = self.check_deploy_success(node)
         if error is not None:
             # TODO(jimrollenhagen) power off if using neutron dhcp to
@@ -510,7 +508,8 @@ class AgentVendorInterface(agent_base_vendor.BaseAgentVendor):
             deploy_utils.set_failed_state(task, msg)
             return
 
-        LOG.debug('Rebooting node %s to disk', node.uuid)
+        LOG.info(_LI('Image successfully written to node %s'), node.uuid)
+        LOG.debug('Rebooting node %s to instance', node.uuid)
 
         manager_utils.node_set_boot_device(task, 'disk', persistent=True)
         self.reboot_and_finish_deploy(task)

ironic/drivers/modules/agent_base_vendor.py

@@ -334,6 +334,7 @@ class BaseAgentVendor(base.VendorInterface):
         :raises: NotFound if no matching node is found.
         :raises: InvalidParameterValue with unknown payload version
         """
+        LOG.debug('Agent lookup using data %s', kwargs)
         uuid = kwargs.get('node_uuid')
         if uuid:
             node = objects.Node.get_by_uuid(context, uuid)
@@ -344,7 +345,8 @@ class BaseAgentVendor(base.VendorInterface):
 
             node = self._find_node_by_macs(context, mac_addresses)
 
-        LOG.debug('Initial lookup for node %s succeeded.', node.uuid)
+        LOG.info(_LI('Initial lookup for node %s succeeded, agent is running '
+                     'and waiting for commands'), node.uuid)
 
         return {
             'heartbeat_timeout': CONF.agent.heartbeat_timeout,
@@ -548,9 +550,13 @@ class BaseAgentVendor(base.VendorInterface):
             on encountering error while setting the boot device on the node.
         """
         node = task.node
+        LOG.debug('Configuring local boot for node %s', node.uuid)
         if not node.driver_internal_info.get(
                 'is_whole_disk_image') and root_uuid:
-            LOG.debug('Installing the bootloader on node %s', node.uuid)
+            LOG.debug('Installing the bootloader for node %(node)s on ',
+                      'partition %(part)s, EFI system partition %(efi)s',
+                      {'node': node.uuid, 'part': root_uuid,
+                       'efi': efi_system_part_uuid})
             result = self._client.install_bootloader(
                 node, root_uuid=root_uuid,
                 efi_system_part_uuid=efi_system_part_uuid)
@@ -570,5 +576,5 @@ class BaseAgentVendor(base.VendorInterface):
                     'error': e})
             self._log_and_raise_deployment_error(task, msg)
 
-        LOG.info(_LI('Bootloader successfully installed on node %s'),
+        LOG.info(_LI('Local boot successfully configured for node %s'),
                  node.uuid)

ironic/drivers/modules/agent_client.py

@@ -65,26 +65,47 @@ class AgentClient(object):
         request_params = {
             'wait': str(wait).lower()
         }
+        LOG.debug('Executing agent command %(method)s for node %(node)s',
+                  {'node': node.uuid, 'method': method})
         response = self.session.post(url,
                                      params=request_params,
                                      data=body)
 
         # TODO(russellhaering): real error handling
         try:
-            return response.json()
+            result = response.json()
         except ValueError:
             msg = _(
                 'Unable to decode response as JSON.\n'
                 'Request URL: %(url)s\nRequest body: "%(body)s"\n'
+                'Response status code: %(code)s\n'
                 'Response: "%(response)s"'
-            ) % ({'response': response.text, 'body': body, 'url': url})
+            ) % ({'response': response.text, 'body': body, 'url': url,
+                  'code': response.status_code})
             LOG.error(msg)
             raise exception.IronicException(msg)
 
+        LOG.debug('Agent command %(method)s for node %(node)s returned '
+                  'result %(res)s, error %(error)s, HTTP status code %(code)d',
+                  {'node': node.uuid, 'method': method,
+                   'res': result.get('command_result'),
+                   'error': result.get('command_error'),
+                   'code': response.status_code})
+        return result
+
     def get_commands_status(self, node):
         url = self._get_command_url(node)
-        res = self.session.get(url)
-        return res.json()['commands']
+        LOG.debug('Fetching status of agent commands for node %s', node.uuid)
+        resp = self.session.get(url)
+        result = resp.json()['commands']
+        status = '; '.join('%(cmd)s: result "%(res)s", error "%(err)s"' %
+                           {'cmd': r.get('command_name'),
+                            'res': r.get('command_result'),
+                            'err': r.get('command_error')}
+                           for r in result)
+        LOG.debug('Status of agent commands for node %(node)s: %(status)s',
+                  {'node': node.uuid, 'status': status})
+        return result
 
     def prepare_image(self, node, image_info, wait=False):
         """Call the `prepare_image` method on the node."""

ironic/tests/drivers/test_agent_client.py

@@ -24,6 +24,8 @@ from ironic.tests import base
 
 
 class MockResponse(object):
+    status_code = 200
+
     def __init__(self, text):
         assert isinstance(text, six.string_types)
         self.text = text