core/modules: debug important VM changes

core-modules/000QubesVm.py

@@ -23,6 +23,7 @@
 #
 
 import datetime
+import logging
 import lxml.etree
 import os
 import os.path
@@ -243,7 +244,6 @@ class QubesVm(object):
         return value
 
     def __init__(self, **kwargs):
-
         self._collection = None
         if 'collection' in kwargs:
             self._collection = kwargs['collection']
@@ -343,6 +343,10 @@ class QubesVm(object):
         else:
             assert self.root_img is not None, "Missing root_img for standalone VM!"
 
+        self.log = logging.getLogger('qubes.vm.{}'.format(self.qid))
+        self.log.debug('instantiated name={!r} class={}'.format(
+            self.name, self.__class__.__name__))
+
         # fire hooks
         for hook in self.hooks_init:
             hook(self)
@@ -406,6 +410,7 @@ class QubesVm(object):
             hook(self, new_netvm)
 
     def _set_netvm(self, new_netvm):
+        self.log.debug('netvm = {!r}'.format(new_netvm))
         if self.is_running() and new_netvm is not None and not new_netvm.is_running():
             raise QubesException("Cannot dynamically attach to stopped NetVM")
         if self.netvm is not None:
@@ -544,6 +549,7 @@ class QubesVm(object):
             hook(self, new_name)
 
     def set_name(self, name):
+        self.log.debug('name = {!r}'.format(name))
         if self.is_running():
             raise QubesException("Cannot change name of running VM!")
 
@@ -695,6 +701,7 @@ class QubesVm(object):
                 self._update_libvirt_domain()
             else:
                 raise
+
         return self._libvirt_domain
 
     def get_uuid(self):
@@ -1117,6 +1124,8 @@ class QubesVm(object):
         return domain_config
 
     def create_on_disk(self, verbose=False, source_template = None):
+        self.log.debug('create_on_disk(source_template={!r})'.format(
+            source_template))
         if source_template is None:
             source_template = self.template
         assert source_template is not None
@@ -1220,6 +1229,7 @@ class QubesVm(object):
         return True
 
     def remove_from_disk(self):
+        self.log.debug('remove_from_disk()')
         if dry_run:
             return
 
@@ -1368,6 +1378,7 @@ class QubesVm(object):
         return conf
 
     def pci_add(self, pci):
+        self.log.debug('pci_add(pci={!r})'.format(pci))
         if not os.path.exists('/sys/bus/pci/devices/0000:%s' % pci):
             raise QubesException("Invalid PCI device: %s" % pci)
         if self.pcidevs.count(pci):
@@ -1383,6 +1394,7 @@ class QubesVm(object):
                     "(%s), changes will be seen after VM restart" % str(e)
 
     def pci_remove(self, pci):
+        self.log.debug('pci_remove(pci={!r})'.format(pci))
         if not self.pcidevs.count(pci):
             # not attached
             return
@@ -1415,6 +1427,10 @@ class QubesVm(object):
             When ignore_stderr=True, stderr is connected to /dev/null.
             """
 
+        self.log.debug(
+            'run(command={!r}, user={!r}, passio={!r}, wait={!r})'.format(
+                command, user, passio, wait))
+
         if user is None:
             user = self.default_user
         null = None
@@ -1492,6 +1508,7 @@ class QubesVm(object):
                         passio_popen=passio_popen, user=user, wait=True)
 
     def attach_network(self, verbose = False, wait = True, netvm = None):
+        self.log.debug('attach_network(netvm={!r})'.format(netvm))
         if dry_run:
             return
 
@@ -1514,6 +1531,7 @@ class QubesVm(object):
                 self._format_net_dev(self.ip, self.mac, self.netvm.name))
 
     def detach_network(self, verbose = False, netvm = None):
+        self.log.debug('detach_network(netvm={!r})'.format(netvm))
         if dry_run:
             return
 
@@ -1530,6 +1548,7 @@ class QubesVm(object):
             self.mac, self.netvm.name))
 
     def wait_for_session(self, notify_function = None):
+        self.log.debug('wait_for_session()')
         #self.run('echo $$ >> /tmp/qubes-session-waiter; [ ! -f /tmp/qubes-session-env ] && exec sleep 365d', ignore_stderr=True, gui=False, wait=True)
 
         # Note : User root is redefined to SYSTEM in the Windows agent code
@@ -1538,6 +1557,9 @@ class QubesVm(object):
 
     def start_guid(self, verbose = True, notify_function = None,
             extra_guid_args=None, before_qrexec=False):
+        self.log.debug(
+            'start_guid(extra_guid_args={!r}, before_qrexec={!r})'.format(
+                extra_guid_args, before_qrexec))
         if verbose:
             print >> sys.stderr, "--> Starting Qubes GUId..."
 
@@ -1571,6 +1593,7 @@ class QubesVm(object):
         self.wait_for_session(notify_function)
 
     def start_qrexec_daemon(self, verbose = False, notify_function = None):
+        self.log.debug('start_qrexec_daemon()')
         if verbose:
             print >> sys.stderr, "--> Starting the qrexec daemon..."
         qrexec_args = [str(self.xid), self.name, self.default_user]
@@ -1584,6 +1607,7 @@ class QubesVm(object):
             raise OSError ("Cannot execute qrexec-daemon!")
 
     def start_qubesdb(self):
+        self.log.debug('start_qubesdb()')
         retcode = subprocess.call ([
             system_path["qubesdb_daemon_path"],
             str(self.xid),
@@ -1594,6 +1618,9 @@ class QubesVm(object):
 
     def start(self, verbose = False, preparing_dvm = False, start_guid = True,
             notify_function = None, mem_required = None):
+        self.log.debug('start('
+            'preparing_dvm={!r}, start_guid={!r}, mem_required={!r})'.format(
+                preparing_dvm, start_guid, mem_required))
         if dry_run:
             return
 
@@ -1647,6 +1674,7 @@ class QubesVm(object):
         self.start_qubesdb()
 
         xid = self.xid
+        self.log.debug('xid={}'.format(xid))
 
         if preparing_dvm:
             self.services['qubes-dvm'] = True
@@ -1709,6 +1737,7 @@ class QubesVm(object):
                 pass
 
     def shutdown(self, force=False, xid = None):
+        self.log.debug('shutdown()')
         if dry_run:
             return
 
@@ -1718,6 +1747,7 @@ class QubesVm(object):
         self.libvirt_domain.shutdown()
 
     def force_shutdown(self, xid = None):
+        self.log.debug('force_shutdown()')
         if dry_run:
             return
 
@@ -1727,6 +1757,7 @@ class QubesVm(object):
         self.libvirt_domain.destroy()
 
     def suspend(self):
+        self.log.debug('suspend()')
         if dry_run:
             return
 
@@ -1741,6 +1772,7 @@ class QubesVm(object):
             self.pause()
 
     def resume(self):
+        self.log.debug('resume()')
         if dry_run:
             return
 
@@ -1750,6 +1782,7 @@ class QubesVm(object):
             self.unpause()
 
     def pause(self):
+        self.log.debug('pause()')
         if dry_run:
             return
 
@@ -1759,6 +1792,7 @@ class QubesVm(object):
         self.libvirt_domain.suspend()
 
     def unpause(self):
+        self.log.debug('unpause()')
         if dry_run:
             return
 

core-modules/003QubesTemplateVm.py

@@ -81,6 +81,7 @@ class QubesTemplateVm(QubesVm):
         self.commit_changes(verbose=verbose)
 
     def commit_changes (self, verbose = False):
+        self.log.debug('commit_changes()')
 
         if not vmm.offline_mode:
             assert not self.is_running(), "Attempt to commit changes on running Template VM!"

core-modules/005QubesNetVm.py

@@ -73,6 +73,9 @@ class QubesNetVm(QubesVm):
 
         self.__external_ip_allowed_xids = set()
 
+        self.log.debug('network={} netmask={} gateway={} secondary_dns={}'.format(
+            self.network, self.netmask, self.gateway, self.secondary_dns))
+
     @property
     def type(self):
         return "NetVM"

core-modules/01QubesDisposableVm.py

@@ -118,6 +118,7 @@ class QubesDisposableVm(QubesVm):
         return attrs
 
     def start(self, verbose = False, **kwargs):
+        self.log.debug('start()')
         if dry_run:
             return
 

core-modules/01QubesHVm.py

@@ -195,6 +195,8 @@ class QubesHVm(QubesVm):
         self._drive = drv_type + ":" + value
 
     def create_on_disk(self, verbose, source_template = None):
+        self.log.debug('create_on_disk(source_template={!r})'.format(
+            source_template))
         if dry_run:
             return
 

core/qubes.py

@@ -23,16 +23,19 @@
 
 from __future__ import absolute_import
 
-import sys
+import atexit
+import grp
+import logging
 import os
 import os.path
-import lxml.etree
-import xml.parsers.expat
+import sys
+import tempfile
 import time
 import warnings
-import tempfile
-import grp
-import atexit
+import xml.parsers.expat
+
+import lxml.etree
+
 if os.name == 'posix':
     import fcntl
 elif os.name == 'nt':
@@ -295,9 +298,17 @@ class QubesVmCollection(dict):
         self.clockvm_qid = None
         self.qubes_store_file = None
 
+        self.log = logging.getLogger('qubes.qvmc.{:x}'.format(id(self)))
+        self.log.debug('instantiated store_filename={!r}'.format(
+            self.qubes_store_filename))
+
     def __repr__(self):
         return '<{} {!r}>'.format(self.__class__.__name__, list(sorted(self.keys())))
 
+    def clear(self):
+        self.log.debug('clear()')
+        super(QubesVmCollection, self).clear()
+
     def values(self):
         for qid in self.keys():
             yield self[qid]
@@ -313,12 +324,15 @@ class QubesVmCollection(dict):
     keys = __iter__
 
     def __setitem__(self, key, value):
+        self.log.debug('[{!r}] = {!r}'.format(key, value))
         if key not in self:
             return super(QubesVmCollection, self).__setitem__(key, value)
         else:
             assert False, "Attempt to add VM with qid that already exists in the collection!"
 
     def add_new_vm(self, vm_type, **kwargs):
+        self.log.debug('add_new_vm(vm_type={}, **kwargs={!r})'.format(
+            vm_type, kwargs))
         if vm_type not in QubesVmClasses.keys():
             raise ValueError("Unknown VM type: %s" % vm_type)
 
@@ -428,6 +442,7 @@ class QubesVmCollection(dict):
                               netvm = self.get_default_fw_netvm())
 
     def set_default_template(self, vm):
+        self.log.debug('set_default_template({!r})'.format(vm))
         if vm is None:
             self.default_template_qid = None
         else:
@@ -441,6 +456,7 @@ class QubesVmCollection(dict):
             return self[self.default_template_qid]
 
     def set_default_netvm(self, vm):
+        self.log.debug('set_default_netvm({!r})'.format(vm))
         if vm is None:
             self.default_netvm_qid = None
         else:
@@ -454,6 +470,7 @@ class QubesVmCollection(dict):
             return self[self.default_netvm_qid]
 
     def set_default_kernel(self, kernel):
+        self.log.debug('set_default_kernel({!r})'.format(kernel))
         assert os.path.exists(
                 os.path.join(system_path["qubes_kernels_base_dir"], kernel)), \
             "Kerel {0} not installed!".format(kernel)
@@ -463,6 +480,7 @@ class QubesVmCollection(dict):
         return self.default_kernel
 
     def set_default_fw_netvm(self, vm):
+        self.log.debug('set_default_fw_netvm({!r})'.format(vm))
         if vm is None:
             self.default_fw_netvm_qid = None
         else:
@@ -476,6 +494,7 @@ class QubesVmCollection(dict):
             return self[self.default_fw_netvm_qid]
 
     def set_updatevm_vm(self, vm):
+        self.log.debug('set_updatevm_vm({!r})'.format(vm))
         if vm is None:
             self.updatevm_qid = None
         else:
@@ -488,6 +507,7 @@ class QubesVmCollection(dict):
             return self[self.updatevm_qid]
 
     def set_clockvm_vm(self, vm):
+        self.log.debug('set_clockvm({!r})'.format(vm))
         if vm is None:
             self.clockvm_qid = None
         else:
@@ -576,6 +596,7 @@ class QubesVmCollection(dict):
         return True
 
     def create_empty_storage(self):
+        self.log.debug('create_empty_storage()')
         self.qubes_store_file = open (self.qubes_store_filename, 'w')
         self.clear()
         self.save()
@@ -584,6 +605,7 @@ class QubesVmCollection(dict):
         # save() would rename the file over qubes.xml, _then_ release lock,
         # so we need to ensure that the file for which we've got the lock is
         # still the right file
+        self.log.debug('lock_db_for_reading()')
         while True:
             self.qubes_store_file = open (self.qubes_store_filename, 'r')
             if os.name == 'posix':
@@ -601,6 +623,7 @@ class QubesVmCollection(dict):
         # save() would rename the file over qubes.xml, _then_ release lock,
         # so we need to ensure that the file for which we've got the lock is
         # still the right file
+        self.log.debug('lock_db_for_writing()')
         while True:
             self.qubes_store_file = open (self.qubes_store_filename, 'r+')
             if os.name == 'posix':
@@ -617,9 +640,11 @@ class QubesVmCollection(dict):
     def unlock_db(self):
         # intentionally do not call explicit unlock to not unlock the file
         # before all buffers are flushed
+        self.log.debug('unlock_db()')
         self.qubes_store_file.close()
 
     def save(self):
+        self.log.debug('save()')
         root = lxml.etree.Element(
             "QubesVmCollection",
 
@@ -754,6 +779,7 @@ class QubesVmCollection(dict):
 
 
     def load(self):
+        self.log.debug('load()')
         self.clear()
 
         try:
@@ -819,6 +845,8 @@ class QubesVmCollection(dict):
         return True
 
     def pop(self, qid):
+        self.log.debug('pop({})'.format(qid))
+
         if self.default_netvm_qid == qid:
             self.default_netvm_qid = None
         if self.default_fw_netvm_qid == qid: