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 17ac0ab5..8956c4d2 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", @@ -738,7 +763,27 @@ class QubesVmCollection(dict): self.default_kernel = element.get("default_kernel") + def _check_global(self, attr, default): + qid = getattr(self, attr) + if qid is None: + return + try: + self[qid] + except KeyError: + setattr(self, attr, default) + + + def check_globals(self): + '''Ensure that all referenced qids are present in the collection''' + self._check_global('default_template_qid', None) + self._check_global('default_fw_netvm_qid', None) + self._check_global('default_netvm_qid', self.default_fw_netvm_qid) + self._check_global('updatevm_qid', self.default_netvm_qid) + self._check_global('clockvm_qid', self.default_netvm_qid) + + def load(self): + self.log.debug('load()') self.clear() try: @@ -779,6 +824,8 @@ class QubesVmCollection(dict): os.path.basename(sys.argv[0]), vm_class_name, err)) return False + self.check_globals() + # if there was no clockvm entry in qubes.xml, try to determine default: # root of default NetVM chain if tree.getroot().get("clockvm") is None: @@ -803,6 +850,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: diff --git a/tests/run.py b/tests/run.py index 091d8dd8..7c03a71d 100755 --- a/tests/run.py +++ b/tests/run.py @@ -22,6 +22,7 @@ # 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA. # +import argparse import curses import importlib import logging @@ -101,7 +102,7 @@ class QubesTestResult(unittest.TestResult): fullname[-1] = '{color[bold]}{}{color[normal]}'.format( fullname[-1], color=self.color) teststr[i] = '_'.join(fullname) - teststr = '.'.join(teststr) + teststr = '/'.join(teststr) doc_first_line = test.shortDescription() if self.descriptions and doc_first_line: @@ -145,7 +146,7 @@ class QubesTestResult(unittest.TestResult): def addFailure(self, test, err): # pylint: disable=invalid-name super(QubesTestResult, self).addFailure(test, err) - test.log.error('FAIL ({err[0]!s}: {err[1]!r})'.format(err=err)) + test.log.error('FAIL ({err[0].__name__}: {err[1]!r})'.format(err=err)) if self.showAll: self.stream.writeln('{color[red]}FAIL{color[normal]}'.format( color=self.color)) @@ -210,33 +211,108 @@ class QubesTestResult(unittest.TestResult): self.stream.writeln('%s' % err) +parser = argparse.ArgumentParser( + epilog='''When running only specific tests, write their names like in log, + in format: MODULE+"/"+CLASS+"/"+FUNCTION. MODULE should omit initial + "qubes.tests.". Example: basic/TC_00_Basic/test_000_create''') + +parser.add_argument('--failfast', '-f', + action='store_true', dest='failfast', + help='stop on the first fail, error or unexpected success') +parser.add_argument('--no-failfast', + action='store_false', dest='failfast', + help='disable --failfast') + +parser.add_argument('--verbose', '-v', + action='count', + help='increase console verbosity level') +parser.add_argument('--quiet', '-q', + action='count', + help='decrease console verbosity level') + +parser.add_argument('--loglevel', '-L', metavar='LEVEL', + action='store', choices=tuple(k + for k in sorted(logging._levelNames.keys(), + key=lambda x: logging._levelNames[x]) + if isinstance(k, basestring)), + help='logging level for file and syslog forwarding ' + '(one of: %(choices)s; default: %(default)s)') + +parser.add_argument('--logfile', '-o', metavar='FILE', + action='store', + help='if set, test run will be also logged to file') + +parser.add_argument('--syslog', + action='store_true', dest='syslog', + help='reenable logging to syslog') +parser.add_argument('--no-syslog', + action='store_false', dest='syslog', + help='disable logging to syslog') + +parser.add_argument('--kmsg', '--very-brave-or-very-stupid', + action='store_true', dest='kmsg', + help='log most important things to kernel ring-buffer') +parser.add_argument('--no-kmsg', '--i-am-smarter-than-kay-sievers', + action='store_false', dest='kmsg', + help='do not abuse kernel ring-buffer') + +parser.add_argument('names', metavar='TESTNAME', + action='store', nargs='*', + help='list of tests to run named like in description ' + '(default: run all tests)') + +parser.set_defaults( + failfast=False, + loglevel='DEBUG', + logfile=None, + syslog=True, + kmsg=False, + verbose=2, + quiet=0) + + def main(): - ha_file = logging.FileHandler( - os.path.join(os.environ['HOME'], 'qubes-tests.log')) - ha_file.setFormatter( - logging.Formatter('%(asctime)s %(name)s[%(process)d]: %(message)s')) - logging.root.addHandler(ha_file) + args = parser.parse_args() - ha_syslog = logging.handlers.SysLogHandler('/dev/log') - ha_syslog.setFormatter( - logging.Formatter('%(name)s[%(process)d]: %(message)s')) + logging.root.setLevel(args.loglevel) - try: - subprocess.check_call(('sudo', 'chmod', '666', '/dev/kmsg')) - except subprocess.CalledProcessError: - pass - else: - ha_kmsg = logging.FileHandler('/dev/kmsg', 'w') - ha_kmsg.setFormatter( + if args.logfile is not None: + ha_file = logging.FileHandler( + os.path.join(os.environ['HOME'], args.logfile)) + ha_file.setFormatter( + logging.Formatter('%(asctime)s %(name)s[%(process)d]: %(message)s')) + logging.root.addHandler(ha_file) + + if args.syslog: + ha_syslog = logging.handlers.SysLogHandler('/dev/log') + ha_syslog.setFormatter( logging.Formatter('%(name)s[%(process)d]: %(message)s')) - ha_kmsg.setLevel(logging.CRITICAL) - logging.root.addHandler(ha_kmsg) + logging.root.addHandler(ha_syslog) + + if args.kmsg: + try: + subprocess.check_call(('sudo', 'chmod', '666', '/dev/kmsg')) + except subprocess.CalledProcessError: + parser.error('could not chmod /dev/kmsg') + else: + ha_kmsg = logging.FileHandler('/dev/kmsg', 'w') + ha_kmsg.setFormatter( + logging.Formatter('%(name)s[%(process)d]: %(message)s')) + ha_kmsg.setLevel(logging.CRITICAL) + logging.root.addHandler(ha_kmsg) suite = unittest.TestSuite() loader = unittest.TestLoader() - suite.addTests(loader.loadTestsFromName('qubes.tests')) - runner = unittest.TextTestRunner(stream=sys.stdout, verbosity=2) + if args.names: + suite.addTests(loader.loadTestsFromNames( + ('qubes.tests.' + name.replace('/', '.') for name in args.names))) + else: + suite.addTests(loader.loadTestsFromName('qubes.tests')) + + runner = unittest.TextTestRunner(stream=sys.stdout, + verbosity=(args.verbose-args.quiet), + failfast=args.failfast) unittest.signals.installHandler() runner.resultclass = QubesTestResult return runner.run(suite).wasSuccessful()