Merge remote-tracking branch 'woju/master'

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 sys
-import xml.parsers.expat
+import tempfile
 import time
 import warnings
-import tempfile
+import xml.parsers.expat
-import grp
+
-import atexit
+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:

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(
+    args = parser.parse_args()
-        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)
 
-    ha_syslog = logging.handlers.SysLogHandler('/dev/log')
+    logging.root.setLevel(args.loglevel)
-    ha_syslog.setFormatter(
-        logging.Formatter('%(name)s[%(process)d]: %(message)s'))
 
-    try:
+    if args.logfile is not None:
-        subprocess.check_call(('sudo', 'chmod', '666', '/dev/kmsg'))
+        ha_file = logging.FileHandler(
-    except subprocess.CalledProcessError:
+            os.path.join(os.environ['HOME'], args.logfile))
-        pass
+        ha_file.setFormatter(
-    else:
+            logging.Formatter('%(asctime)s %(name)s[%(process)d]: %(message)s'))
-        ha_kmsg = logging.FileHandler('/dev/kmsg', 'w')
+        logging.root.addHandler(ha_file)
-        ha_kmsg.setFormatter(
+
+    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_syslog)
-        logging.root.addHandler(ha_kmsg)
+
+    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()