diff --git a/core-modules/000QubesVm.py b/core-modules/000QubesVm.py index 7e73f77b..b50961b7 100644 --- a/core-modules/000QubesVm.py +++ b/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 diff --git a/core-modules/003QubesTemplateVm.py b/core-modules/003QubesTemplateVm.py index 138ffab4..e5c992ce 100644 --- a/core-modules/003QubesTemplateVm.py +++ b/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!" diff --git a/core-modules/005QubesNetVm.py b/core-modules/005QubesNetVm.py index f49a44ae..c721bbab 100644 --- a/core-modules/005QubesNetVm.py +++ b/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" diff --git a/core-modules/01QubesDisposableVm.py b/core-modules/01QubesDisposableVm.py index 1b501dc1..dc8020f0 100644 --- a/core-modules/01QubesDisposableVm.py +++ b/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 diff --git a/core-modules/01QubesHVm.py b/core-modules/01QubesHVm.py index a5cf565e..c688296d 100644 --- a/core-modules/01QubesHVm.py +++ b/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 diff --git a/core/qubes.py b/core/qubes.py index 7c04b11c..40c1cade 100755 --- a/core/qubes.py +++ b/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: