Improve log messages to ease debugging in user environments

Signed-off-by: Robert Breker <[email protected]>

Author: Robert Breker

src/xscontainer/api_helper.py

@@ -28,7 +28,7 @@ def decorated(*args, **kwargs):
         try:
             return func(*args, **kwargs)
         except Exception, exception:
-            log.debug("Caught exception '%s'. Retrying with new session."
+            log.error("Caught exception '%s'. Retrying with new session."
                       % (str(exception)))
             reinit_global_xapi_session()
             # Return the func undecorated
@@ -332,7 +332,9 @@ def create_vbd(session, vmref, vdiref, vbdmode, bootable):
 
 
 # ToDo: Ugly - this function may modify the file specified as filename
-def import_disk(session, sruuid, filename, fileformat, namelabel, other_config_keys={}):
+def import_disk(session, sruuid, filename, fileformat, namelabel,
+                other_config_keys={}):
+    log.info("import_disk file %s on sr %s" % (filename, sruuid))
     targetsr = session.xenapi.SR.get_by_uuid(sruuid)
     sizeinb = None
     if fileformat == "vhd":
@@ -374,6 +376,7 @@ def import_disk(session, sruuid, filename, fileformat, namelabel, other_config_k
 
 
 def export_disk(session, vdiuuid):
+    log.info("export_disk vdi %s" % (vdiuuid))
     filename = tempfile.mkstemp(suffix='.raw')[1]
     cmd = ['curl', '-k', '-o', filename,
            'https://localhost/export_raw_vdi?session_id=%s&vdi=%s&format=raw'
@@ -431,6 +434,7 @@ def get_idrsa_secret_public_keyonly(session):
 
 
 def set_idrsa_secret(session):
+    log.info("set_idrsa_secret is generating a new secret")
     (privateidrsa, publicidrsa) = util.create_idrsa()
     private_secret_ref = session.xenapi.secret.create(
         {'value': '%s' % (privateidrsa)})
@@ -472,6 +476,7 @@ def get_vm_xscontainer_username(session, vmuuid):
     username = get_value_from_vm_other_config(session, vmuuid,
                                               XSCONTAINER_USERNAME)
     if username == None:
+        # assume CoreOs's "core" by default
         username = 'core'
     return username
 

src/xscontainer/coreos.py

@@ -28,6 +28,8 @@ def remove_disks_in_vm_provisioning(session, vm_ref):
 def install_vm(session, urlvhdbz2, sruuid,
                vmname='CoreOs-%d' % (random.randint(0, 1000)),
                templatename='CoreOS'):
+    # devmode only
+    log.info("install_vm from url %s to sr %s" %(urlvhdbz2, sruuid))
     atempfile = tempfile.mkstemp(suffix='.vhd.bz2')[1]
     atempfileunpacked = atempfile.replace('.bz2', '')
     # @todo: pipe instead, so the file never actually touches Dom0
@@ -41,6 +43,7 @@ def install_vm(session, urlvhdbz2, sruuid,
     templateref = session.xenapi.VM.get_by_name_label(templatename)[0]
     vmref = session.xenapi.VM.clone(templateref, vmname)
     vmuuid = session.xenapi.VM.get_record(vmref)['uuid']
+    log.info("install_vm created vm %s" %(vmuuid))
     remove_disks_in_vm_provisioning(session, vmref)
     session.xenapi.VM.provision(vmref)
     api_helper.create_vbd(session, vmref, vdiref, 'rw', True)
@@ -49,6 +52,7 @@ def install_vm(session, urlvhdbz2, sruuid,
 
 
 def setup_network_on_lowest_pif(session, vmref):
+    # devmode only
     pifs = session.xenapi.PIF.get_all_records()
     lowest = None
     for pifref in pifs.keys():
@@ -107,6 +111,8 @@ def load_cloud_config_template(template_path=None):
         this_dir, _ = os.path.split(__file__)
         template_path = os.path.join(this_dir, "data", "cloud-config.template")
 
+    log.info("load_cloud_config_template from %s" % (template_path))
+
     fh = open(template_path)
     template_data = fh.read()
     fh.close()
@@ -126,6 +132,7 @@ def get_config_drive_default(session):
 
 
 def create_config_drive_iso(session, userdata, vmuuid):
+    log.info("create_config_drive_iso for vm %s" %(vmuuid))
     tempisodir = tempfile.mkdtemp()
     tempisofile = tempfile.mkstemp()[1]
     openstackfolder = os.path.join(tempisodir, 'openstack')
@@ -182,13 +189,16 @@ def remove_config_drive(session, vmrecord, configdisk_namelabel):
         if vbdrecord['VDI'] != api_helper.NULLREF:
             vdirecord = session.xenapi.VDI.get_record(vbdrecord['VDI'])
             if OTHER_CONFIG_CONFIG_DRIVE_KEY in vdirecord['other_config']:
+                log.info("remove_config_drive will destroy vdi %s"
+                         %(vdirecord['uuid']))
                 if vbdrecord['currently_attached']:
                     session.xenapi.VBD.unplug(vbd)
                 session.xenapi.VBD.destroy(vbd)
                 session.xenapi.VDI.destroy(vbdrecord['VDI'])
 
 
 def create_config_drive(session, vmuuid, sruuid, userdata):
+    log.info("create_config_drive for vm %s on sr %s" %(vmuuid, sruuid))
     vmref = session.xenapi.VM.get_by_uuid(vmuuid)
     vmrecord = session.xenapi.VM.get_record(vmref)
     prepare_vm_for_config_drive(session, vmref, vmuuid)
@@ -212,6 +222,7 @@ def create_config_drive(session, vmuuid, sruuid, userdata):
 
 
 def get_config_drive_configuration(session, vdiuuid):
+    log.info("get_config_drive_configuration from vdi %s" % (vdiuuid))
     filename = api_helper.export_disk(session, vdiuuid)
     tempdir = tempfile.mkdtemp()
     cmd = ['mount', '-o', 'loop', '-t', 'iso9660', filename, tempdir]

src/xscontainer/docker.py

@@ -33,18 +33,19 @@ def _interact_with_api(session, vmuuid, request_type, request,
     #protocol = headersplits[0]
     statuscode = headersplits[1]
     if statuscode[0] != '2':
+        # this did not work
         status = ' '.join(headersplits[2:])
-        failure_title = "Container enlightenment error"
+        failure_title = "Container Management Error"
         failure_body = body.strip() + " (" + statuscode + ")"
         if ":" in failure_body:
             (failure_title, failure_body) = failure_body.split(":", 1)
         if message_error:
             api_helper.send_message(session, vmuuid, failure_title,
                                     failure_body)
-        raise util.XSContainerException("Request %s led to failure %s - "
-                                        % (request, status)
-                                        + " %s: %s"
-                                          % (failure_title, failure_body))
+        message = ("Request '%s' led to status %s - %s: %s"
+                   % (request, status, failure_title, failure_body))
+        log.info(message)
+        raise util.XSContainerException(message)
     return body
 
 
@@ -143,7 +144,6 @@ def get_inspect_dict(session, vmuuid, container):
 
 def get_inspect_xml(session, vmuuid, container):
     result = {'docker_inspect': get_inspect_dict(session, vmuuid, container)}
-    log.debug(result)
     return util.converttoxml(result)
 
 

src/xscontainer/docker_monitor/__init__.py

@@ -54,8 +54,8 @@ def stop_monitoring(self, force=False):
             ssh_client.close()
 
     def _monitoring_loop(self):
-        # ToDo: not needed and not safe - doesn't survive XAPI restarts
         vmuuid = self.get_uuid()
+        log.info("monitor_loop handles VM %s" % (vmuuid))
         start_time = time.time()
         error_message = None
         docker.wipe_docker_other_config(self)
@@ -73,6 +73,8 @@ def _monitoring_loop(self):
                     # if we got past the above, it's about time to delete the
                     # error message, as all appears to be working again
                     try:
+                        log.info("monitor_loop destroys message for VM %s: %s"
+                                 % (vmuuid, error_message))
                         api_helper.destroy_message(self.get_session(),
                                                    error_message)
                     except XenAPI.Failure:
@@ -87,37 +89,40 @@ def _monitoring_loop(self):
                     try:
                         session = self.get_session()
                         cause = docker.determine_error_cause(session, vmuuid)
+                        log.info("monitor_loop creates message for VM %s: %s"
+                                 % (vmuuid, cause))
                         error_message = api_helper.send_message(
                             session,
                             self.get_uuid(),
-                            "Cannot monitor containers on VM",
+                            "Container Management cannot monitor VM",
                             cause)
                     except (XenAPI.Failure):
                         # this can happen when XAPI is not running
                         pass
-                log.info("Could not connect to VM %s, retry" % (vmuuid))
+                log.info("Could not connect to VM %s, will retry" % (vmuuid))
                 error_in_this_iteration = True
             if not error_in_this_iteration:
                 try:
                     self.__monitor_vm_events()
                 except (XenAPI.Failure, util.XSContainerException):
-                    log.exception("monitor_vm_events threw an exception, retry")
+                    log.exception("__monitor_vm_events threw an exception, "
+                                  "will retry")
             if wipe_other_config_required:
                 docker.wipe_docker_other_config(self)
             if not self._stop_monitoring_request:
                 time.sleep(MONITORRETRYSLEEPINS)
-        log.info("monitor_vm returns from handling vm %s" % (vmuuid))
+        log.info("monitor_loop returns from handling vm %s" % (vmuuid))
 
     def __monitor_vm_events(self):
         session = self.get_session()
         vmuuid = self.get_uuid()
         ssh_client = ssh_helper.prepare_ssh_client(session, vmuuid)
         try:
-            cmd = "ncat -U /var/run/docker.sock"
+            cmd = "ncat -U %s" % (docker.DOCKER_SOCKET_PATH)
+            log.info("__monitor_vm_events is running '%s' on VM '%s'"
+                     % (cmd, vmuuid ))
             stdin, stdout, _ = ssh_client.exec_command(cmd)
             stdin.write("GET /events HTTP/1.0\r\n\r\n")
-            log.debug("__monitor_vm_events at %r is running: %r"
-                      % (ssh_client.get_transport().getpeername(), cmd))
             self._ssh_client = ssh_client
             data = ""
             # set unblocking io for select.select
@@ -165,7 +170,7 @@ def __monitor_vm_events(self):
             except Exception:
                 util.log.exception("Error when closing ssh_client for %r"
                                    % ssh_client)
-        log.debug('__monitor_vm_events (%s) exited' % cmd)
+        log.info('__monitor_vm_events (%s) exited' % cmd)
 
     def handle_docker_event(self, event):
         if 'status' in event:
@@ -333,6 +338,7 @@ def monitor_host():
                 DOCKER_MONITOR = DockerMonitor(host)
             else:
                 DOCKER_MONITOR.set_host(host)
+            log.info("Monitoring host %s" %(host.get_id()))
             try:
                 # Avoid race conditions - get a current event token
                 event_from = session.xenapi.event_from(["vm"], '',  0.0)
@@ -359,8 +365,8 @@ def monitor_host():
                     log.exception("Failed when trying to logout")
         except (socket.error, XenAPI.Failure, xmlrpclib.ProtocolError):
             if session is not None:
-                log.info("Could not connect to XAPI - Is XAPI running? " +
-                         "Will retry in %d" % (XAPIRETRYSLEEPINS))
+                log.error("Could not connect to XAPI - Is XAPI running? " +
+                          "Will retry in %d" % (XAPIRETRYSLEEPINS))
             else:
                 log.exception("Recovering from XAPI failure - Is XAPI " +
                               "restarting? Will retry in %d."

src/xscontainer/docker_monitor/api.py

@@ -5,9 +5,10 @@
 from xscontainer import docker_monitor
 from xscontainer.api_helper import VM
 from xscontainer.api_helper import XenAPIClient
-
+from xscontainer.util import log
 
 def register_vm(vm_uuid, session):
+    log.info("register_vm %s" %(vm_uuid))
     client = XenAPIClient(session)
     thevm = VM(client, uuid=vm_uuid)
     thevm.update_other_config(docker_monitor.REGISTRATION_KEY,
@@ -16,6 +17,7 @@ def register_vm(vm_uuid, session):
 
 
 def deregister_vm(vm_uuid, session):
+    log.info("deregister_vm %s" %(vm_uuid))
     client = XenAPIClient(session)
     thevm = VM(client, uuid=vm_uuid)
     thevm.update_other_config(docker_monitor.REGISTRATION_KEY,
@@ -27,7 +29,7 @@ def deregister_vm(vm_uuid, session):
 def mark_monitorable_vm(vm_uuid, session):
     """ Ensure the VM has a REGISTRATION_KEY in vm:other_config. This key is
         used by XC to know whether monitoring is an option for this VM """
-
+    log.info("mark_monitorable_vm %s" %(vm_uuid))
     client = XenAPIClient(session)
     thevm = VM(client, uuid=vm_uuid)
     other_config = thevm.get_other_config()

src/xscontainer/ssh_helper.py

@@ -75,6 +75,7 @@ def missing_host_key(self, client, hostname, key):
 def prepare_ssh_client(session, vmuuid):
     username = api_helper.get_vm_xscontainer_username(session, vmuuid)
     host = api_helper.get_suitable_vm_ip(session, vmuuid)
+    log.info("prepare_ssh_client for vm %s via %s" %(vmuuid, host))
     ensure_idrsa(session)
     client = paramiko.SSHClient()
     pkey = paramiko.rsakey.RSAKey.from_private_key(
@@ -88,9 +89,10 @@ def prepare_ssh_client(session, vmuuid):
         # This exception is already improved - leave it as it is
         raise
     except paramiko.AuthenticationException, exception:
-        log.exception(exception)
-        raise AuthenticationException("Failed to authenticate with private key"
-                                      " on VM %s." % (vmuuid))
+        message = ("prepare_ssh_client failed to authenticate with private key"
+                   " on VM %s" % (vmuuid))
+        log.info(message)
+        raise AuthenticationException(message)
     except (paramiko.SSHException, socket.error), exception:
         # reraise as SshException
         raise SshException, "prepare_ssh_client: %s" % exception, (
@@ -99,7 +101,6 @@ def prepare_ssh_client(session, vmuuid):
 
 
 def execute_ssh(session, vmuuid, cmd):
-    log.info(" ".join(cmd))
     # The heavy weight is docker ps with plenty of containers.
     # Assume 283 bytes per container.
     # 300KB should be enough for 1085 containers.
@@ -110,13 +111,17 @@ def execute_ssh(session, vmuuid, cmd):
             client = prepare_ssh_client(session, vmuuid)
             if isinstance(cmd, list):
                 cmd = ' '.join(cmd)
+            log.info("execute_ssh will run '%s' on vm %s"
+                     % (cmd, vmuuid))
             _, stdout, _ = client.exec_command(cmd)
             output = stdout.read(max_read_size)
             if stdout.read(1) != "":
                 raise SshException("too much data was returned when executing"
                                 "'%s'" % (cmd))
             returncode = stdout.channel.recv_exit_status()
             if returncode != 0:
+                log.info("execute_ssh '%s' on vm %s exited with rc %d: Stdout:"
+                         " %s" % (cmd, vmuuid, returncode, stdout))
                 raise SshException("Returncode for '%s' is not 0" % cmd)
             return output
         except SshException:

src/xscontainer/util/__init__.py

@@ -24,7 +24,7 @@ def runlocal(cmd, shell=False, canfail=False):
                                shell=shell)
     stdout, stderr = process.communicate('')
     returncode = process.returncode
-    log.debug('Command %s exited with rc %d: Stdout: %s Stderr: %s' %
+    log.info('Command %s exited with rc %d: Stdout: %s Stderr: %s' %
               (cmd, returncode, stdout, stderr))
     if returncode != 0 and not canfail:
         raise(XSContainerException('Command failed'))