[Piglit] [PATCH 4/5] framework: refactor the log module

Ilia Mirkin imirkin at alum.mit.edu
Wed Aug 13 16:57:01 PDT 2014


Dylan,

Like I said, the unified diff is totally unreadable (through no fault
of your own other than the fact that you're changing a lot of stuff).
So I'm looking at the code in github. The locking seems at least a
little odd:

        with self._D_LOCK:
            # Set the length of the line just printed (minus the spaces since
            # we don't care if we leave whitespace) so that the next line will
            # print extra whitespace if necissary
            self._state['lastlength'] = len(out)

What is that protecting? The actual dict write won't be multithreaded
(due to the GIL), so I don't see what this does. (Also, 'necessary',
not 'necissary'.) There are a few other instances where you just do
one bit of state update under the lock. I'm fairly sure that's
unnecessary, but I may be wrong. It's really the read/modify/write
sequences that need to be protected.

Finally, you should probably be doing that lastlength update under the
print lock, since otherwise another print could start and read out the
old lastlength value.

Or you could simplify stuff a bit and just one one lock to rule them
all, and just always lock it at interface entry. It's going to be
ever-so-slightly less performant (a dry-run with full parallelism
would be the way to test that out), but also much simpler.

  -ilia

On Wed, Aug 13, 2014 at 7:36 PM, Dylan Baker <baker.dylan.c at gmail.com> wrote:
> From: Dylan Baker <baker.dylan.c at gmail.com>
>
> This refactors the log module away from a single class that does
> everything to having two classes. The first class LogFactory, is a state
> manager that returns BaseLog derived objects when it's get() method is
> called. However, it mainly acts as a shared state manager.
>
> The BaseLog derived classes provide three public methods; start(),
> log(), summary().
>
> This makes the interfaces much cleaner, just 3 public methods that are
> fairly obvious and clearly documented. It uses inheritance for more
> shared code, and is just generally much less complex than the previous
> implementation
>
> v2: - Fix summary line in the verbose logger to support using '\r'. This
>       works by printing the summary at the end of start() and log()
>     - add -v/--verbose option back (Ilia)
> v3: - Be more aggressive about locking
> v4: - be more granular with locking by using two locks, one for
>       printing, one for manipulating the shared data.
>     - Move some unit tests to the next patch that belong there.
>
> Signed-off-by: Dylan Baker <dylanx.c.baker at intel.com>
> ---
>  framework/core.py            |   5 +-
>  framework/exectest.py        |   7 +-
>  framework/log.py             | 311 +++++++++++++++++++++++++++++--------------
>  framework/profile.py         |  10 +-
>  framework/programs/run.py    |  32 +++--
>  framework/results.py         |   6 +-
>  framework/tests/log_tests.py | 171 ++++++++++++++++--------
>  7 files changed, 360 insertions(+), 182 deletions(-)
>
> diff --git a/framework/core.py b/framework/core.py
> index d3922a9..20f57ee 100644
> --- a/framework/core.py
> +++ b/framework/core.py
> @@ -94,13 +94,11 @@ class Options(object):
>      exclude_filter -- list of compiled regex which exclude tests that match
>      valgrind -- True if valgrind is to be used
>      dmesg -- True if dmesg checking is desired. This forces concurrency off
> -    verbose -- verbosity level.
>      env -- environment variables set for each test before run
>
>      """
>      def __init__(self, concurrent=True, execute=True, include_filter=None,
> -                 exclude_filter=None, valgrind=False, dmesg=False,
> -                 verbose=False):
> +                 exclude_filter=None, valgrind=False, dmesg=False):
>          self.concurrent = concurrent
>          self.execute = execute
>          self.filter = [re.compile(x) for x in include_filter or []]
> @@ -108,7 +106,6 @@ class Options(object):
>          self.exclude_tests = set()
>          self.valgrind = valgrind
>          self.dmesg = dmesg
> -        self.verbose = verbose
>          # env is used to set some base environment variables that are not going
>          # to change across runs, without sending them to os.environ which is
>          # fickle as easy to break
> diff --git a/framework/exectest.py b/framework/exectest.py
> index e325602..265d731 100644
> --- a/framework/exectest.py
> +++ b/framework/exectest.py
> @@ -100,8 +100,6 @@ class Test(object):
>          dmesg -- a dmesg.BaseDmesg derived class
>
>          """
> -        log_current = log.pre_log(path if self.OPTS.verbose else None)
> -
>          # Run the test
>          if self.OPTS.execute:
>              try:
> @@ -120,11 +118,10 @@ class Test(object):
>                  self.result['traceback'] = "".join(
>                      traceback.format_tb(exception[2]))
>
> -            log.log(path, self.result['result'], log_current)
> -
> +            log.log(self.result['result'])
>              json_writer.write_dict_item(path, self.result)
>          else:
> -            log.log(path, 'dry-run', log_current)
> +            log.log('dry-run')
>
>      @property
>      def command(self):
> diff --git a/framework/log.py b/framework/log.py
> index 02b3526..6b350e8 100644
> --- a/framework/log.py
> +++ b/framework/log.py
> @@ -18,136 +18,251 @@
>  # LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING
>  # FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS
>  # IN THE SOFTWARE.
> -#
> +
> +""" Module for terminal logging
> +
> +This module provides a class LogManager, which acts as a state manager
> +returning BaseLog derived instances to individual tests.
> +
> +"""
>
>  import sys
> +import abc
> +import itertools
> +import threading
>  import collections
> -from .threads import synchronized_self
>
> +__all__ = ['LogManager']
>
> -class Log(object):
> -    """ Print Progress to stdout
> +
> +class BaseLog(object):
> +    """ Abstract base class for Log objects
> +
> +    It provides two locks, _P_LOCK and _D_LOCK. The first lock is taken when a
> +    thread wants to print to the terminal, it should be released when done. The
> +    second lock is taken when a thread wants to modify the _state attribute.
>
>      Arguments:
> -    total -- The total number of tests to run.
> +    state -- the state dict from LogManager
>
>      """
> -    def __init__(self, total, verbose):
> -        self.__total = total
> -        self.__complete = 0
> -        self.__running = []
> -        self.__generator = (x for x in xrange(self.__total))
> -        self.__pad = len(str(self.__total))
> -        self.__summary_keys = set(['pass', 'fail', 'warn', 'crash', 'skip',
> -                                   'dmesg-warn', 'dmesg-fail', 'dry-run',
> -                                   'timeout'])
> -        self.__summary = collections.defaultdict(lambda: 0)
> -        self.__lastlength = 0
> -        self.__tty = sys.stdout.isatty()
> -
> -        self.__output = "[{percent}] {summary} {running}"
> -
> -        # Some automation tools (e.g, Jenkins) will buffer all output until
> -        # newline, so don't use carriage return character if the stdout is not
> -        # a TTY.
> -        if self.__tty:
> -            self.__output += "\r"
> -        else:
> -            self.__output += "\n"
> +    __metaclass__ = abc.ABCMeta
> +
> +    SUMMARY_KEYS = set([
> +        'pass', 'fail', 'warn', 'crash', 'skip', 'dmesg-warn', 'dmesg-fail',
> +        'dry-run', 'timeout'])
> +    _P_LOCK = threading.RLock()
> +    _D_LOCK = threading.RLock()
> +
> +    def __init__(self, state):
> +        self._state = state
> +        self._pad = len(str(state['total']))
> +
> +    @abc.abstractmethod
> +    def start(self, name):
> +        """ Called before test run starts
> +
> +        This method is used to print things before the test starts
> +
> +        """
>
> -        if verbose:
> -            self.__output = "{result} :: {name}\n" + self.__output
> +    @abc.abstractmethod
> +    def log(self, status):
> +        """ Print the result of the test
>
> -        self.__summary_output = "[{percent}] {summary}\n"
> +        This method is run after the test completes, and is used to log the
> +        actual result of the test
> +
> +        """
> +
> +    @abc.abstractmethod
> +    def summary(self):
> +        """ Print a final summary
> +
> +        This method is run at the end of the test run, and is used to print a
> +        final summary of the run
> +
> +        """
>
> -    def _write_output(self, output):
> -        """ write the output to stdout, ensuring any previous line is cleared """
>
> -        if self.__tty:
> -            length = len(output)
> -            if self.__lastlength > length:
> -                output = "{0}{1}{2}".format(output[:-1],
> -                                            " " * (self.__lastlength - length),
> -                                            output[-1])
> +class QuietLog(BaseLog):
> +    """ A logger providing minimal status output
> +
> +    This logger provides only a ninja like [x/y] pass: z, fail: w ... output.
> +
> +    It uses \r to print over the same line when printing to a tty. If
> +    sys.stdout is not a tty then it prints \n at the end of the line instead
> +
> +    Arguments:
> +    status -- the status to print
> +
> +    """
> +    _test_counter = itertools.count()
>
> -            self.__lastlength = length
> +    def __init__(self, *args, **kwargs):
> +        super(QuietLog, self).__init__(*args, **kwargs)
>
> -        sys.stdout.write(output)
> +        # If the output is a tty we can use '\r' (return, no linebreak) to
> +        # print over the existing line, if stdout isn't a tty that will not
> +        # work (and can break systems like jenkins), so we print a \n instead
> +        if sys.stdout.isatty():
> +            self._endcode = '\r'
> +        else:
> +            self._endcode = '\n'
>
> -        # Need to flush explicitly, otherwise it all gets buffered without a
> -        # newline.
> -        sys.stdout.flush()
> +        self.__counter = self._test_counter.next()
> +        self._state['running'].append(self.__counter)
>
> -    def _format_summary(self):
> -        """ return a summary of the statuses """
> -        return ", ".join("{0}: {1}".format(k, self.__summary[k])
> -                         for k in sorted(self.__summary))
> +    def start(self, name):
> +        pass
>
> -    def _format_running(self):
> -        """ return running tests """
> -        return "Running Test(s): {}".format(
> -            " ".join([str(x).zfill(self.__pad) for x in self.__running]))
> +    def log(self, status):
> +        with self._D_LOCK:
> +            # increment complete
> +            self._state['complete'] += 1
>
> -    def _format_percent(self):
> -        """ return the percentage of tess completed """
> -        return "{0}/{1}".format(str(self.__complete).zfill(self.__pad),
> -                                str(self.__total).zfill(self.__pad))
> +            # Add to the summary dict
> +            assert status in self.SUMMARY_KEYS
> +            self._state['summary'][status] += 1
>
> -    def __print(self, name, result):
> -        """ Do the actual printing """
> -        self._write_output(self.__output.format(
> -            percent=self._format_percent(),
> -            running=self._format_running(),
> -            summary=self._format_summary(),
> -            name=name,
> -            result=result))
> +            self._print_summary()
> +            self._state['running'].remove(self.__counter)
>
> -    @synchronized_self
> -    def log(self, name, result, value):
> -        """ Print to the screen
> +    def summary(self):
> +        self._print_summary()
>
> -        Works by moving the cursor back to the front of the line and printing
> -        over it.
> +    def _print_summary(self):
> +        """ Print the summary result
>
> -        Arguments:
> -        name -- the name of the test
> -        result -- the result of the test
> -        value -- the number of the test to remove
> +        this prints '[done/total] {status}', it is a private method hidden from
> +        the children of this class (VerboseLog)
>
>          """
> -        assert result in self.__summary_keys
> -        self.__print(name, result)
> +        with self._D_LOCK:
> +            out = '[{done}/{total}] {status} Running Test(s): {running}'.format(
> +                done=str(self._state['complete']).zfill(self._pad),
> +                total=str(self._state['total']).zfill(self._pad),
> +                status=', '.join('{0}: {1}'.format(k, v) for k, v in
> +                                 sorted(self._state['summary'].iteritems())),
> +                running=" ".join(str(x) for x in self._state['running'])
> +            )
> +
> +        with self._P_LOCK:
> +            self._print(out)
> +
> +    def _print(self, out):
> +        """ Shared print method that ensures any bad lines are overwritten """
> +        # If the new line is shorter than the old one add trailing
> +        # whitespace
> +        pad = self._state['lastlength'] - len(out)
>
> -        # Mark running complete
> -        assert value in self.__running
> -        self.__running.remove(value)
> +        with self._P_LOCK:
> +            sys.stdout.write(out)
> +            if pad > 0:
> +                sys.stdout.write(' ' * pad)
> +            sys.stdout.write(self._endcode)
> +            sys.stdout.flush()
>
> -        # increment the number of completed tests
> -        self.__complete += 1
> +        with self._D_LOCK:
> +            # Set the length of the line just printed (minus the spaces since
> +            # we don't care if we leave whitespace) so that the next line will
> +            # print extra whitespace if necissary
> +            self._state['lastlength'] = len(out)
>
> -        assert result in self.__summary_keys
> -        self.__summary[result] += 1
>
> -    @synchronized_self
> -    def pre_log(self, running=None):
> -        """ Hook to run before log()
> +class VerboseLog(QuietLog):
> +    """ A more verbose version of the QuietLog
> +
> +    This logger works like the quiet logger, except it doesn't overwrite the
> +    previous line, ever. It also prints an additional line at the start of each
> +    test, which the quite logger doesn't do.
> +
> +    """
> +    def __init__(self, *args, **kwargs):
> +        super(VerboseLog, self).__init__(*args, **kwargs)
> +        self.__name = None    # the name needs to be printed by start and log
>
> -        Returns a new number to know what processes are running, if running is
> -        set it will print a running message for the test
> +    def _print(self, out, newline=False):
> +        """ Print to the console, add a newline if necissary
>
> -        Keyword Arguments:
> -        running -- the name of a test to print is running. If Falsy then
> -                   nothing will be printed. Default: None
> +        For the verbose logger there are times that one wants both an
> +        overwritten line, and a line that is static. This method adds the
> +        ability to print a newline charcater at the end of the line.
> +
> +        This is useful for the non-status lines (running: <name>, and <status>:
> +        <name>), since these lines should be be overwritten, but the running
> +        status line should.
>
>          """
> -        if running:
> -            self.__print(running, 'running')
> +        with self._P_LOCK:
> +            super(VerboseLog, self)._print(out)
> +            if newline:
> +                sys.stdout.write('\n')
> +                sys.stdout.flush()
>
> -        x = self.__generator.next()
> -        self.__running.append(x)
> -        return x
> +    def start(self, name):
> +        """ Print the test that is being run next
>
> -    def summary(self):
> -        self._write_output(self.__summary_output.format(
> -            percent=self._format_percent(),
> -            summary=self._format_summary()))
> +        This printings a running: <testname> message before the test run
> +        starts.
> +
> +        """
> +        with self._P_LOCK:
> +            self._print('running: {}'.format(name), newline=True)
> +            self.__name = name
> +            self._print_summary()
> +
> +    def log(self, value):
> +        """ Print a message after the test finishes
> +
> +        This method prints <status>: <name>. It also does a little bit of magic
> +        before calling super() to print the status line.
> +
> +        """
> +        with self._P_LOCK:
> +            self._print('{0}: {1}'.format(value, self.__name), newline=True)
> +
> +            with self._D_LOCK:
> +                # Set lastlength to 0, this prevents printing worthless pad in
> +                # super()
> +                self._state['lastlength'] = 0
> +            super(VerboseLog, self).log(value)
> +
> +
> +class LogManager(object):
> +    """ Creates new log objects
> +
> +    Each of the log objects it creates have two accessible methods: start() and
> +    log(); neither method should return anything, and they must be thread safe.
> +    log() should accept a single argument, which is the status the test
> +    returned. start() should also take a single argument, the name of the test
> +
> +    When the LogManager is initialized it is initialized with an argument which
> +    determines which Log class it will return (they are set via the LOG_MAP
> +    dictionary, which maps string names to class callables), it will return
> +    these as long as it exists.
> +
> +    Arguments:
> +    logger -- a string name of a logger to use
> +    total -- the total number of test to run
> +
> +    """
> +    LOG_MAP = {
> +        'quiet': QuietLog,
> +        'verbose': VerboseLog,
> +    }
> +
> +    def __init__(self, logger, total):
> +        assert logger in self.LOG_MAP
> +        self._log = self.LOG_MAP[logger]
> +        self._state = {
> +            'total': total,
> +            'summary': collections.defaultdict(lambda: 0),
> +            'lastlength': 0,
> +            'complete': 0,
> +            'running': [],
> +        }
> +
> +    def get(self):
> +        """ Return a new log instance """
> +        return self._log(self._state)
> diff --git a/framework/profile.py b/framework/profile.py
> index 5428890..02b0ef0 100644
> --- a/framework/profile.py
> +++ b/framework/profile.py
> @@ -34,7 +34,7 @@ import multiprocessing.dummy
>  import importlib
>
>  from framework.dmesg import get_dmesg
> -from framework.log import Log
> +from framework.log import LogManager
>  import framework.exectest
>
>  __all__ = [
> @@ -167,7 +167,7 @@ class TestProfile(object):
>          """
>          pass
>
> -    def run(self, opts, json_writer):
> +    def run(self, opts, logger, json_writer):
>          """ Runs all tests using Thread pool
>
>          When called this method will flatten out self.tests into
> @@ -192,7 +192,7 @@ class TestProfile(object):
>          chunksize = 1
>
>          self._prepare_test_list(opts)
> -        log = Log(len(self.test_list), opts.verbose)
> +        log = LogManager(logger, len(self.test_list))
>
>          def test(pair):
>              """ Function to call test.execute from .map
> @@ -201,7 +201,7 @@ class TestProfile(object):
>
>              """
>              name, test = pair
> -            test.execute(name, log, json_writer, self.dmesg)
> +            test.execute(name, log.get(), json_writer, self.dmesg)
>
>          def run_threads(pool, testlist):
>              """ Open a pool, close it, and join it """
> @@ -228,7 +228,7 @@ class TestProfile(object):
>              run_threads(single, (x for x in self.test_list.iteritems()
>                                   if not x[1].run_concurrent))
>
> -        log.summary()
> +        log.get().summary()
>
>          self._post_run_hook()
>
> diff --git a/framework/programs/run.py b/framework/programs/run.py
> index ff75afe..fa488b5 100644
> --- a/framework/programs/run.py
> +++ b/framework/programs/run.py
> @@ -91,10 +91,20 @@ def run(input_):
>                          action="store_true",
>                          help="Capture a difference in dmesg before and "
>                               "after each test. Implies -1/--no-concurrency")
> -    parser.add_argument("-v", "--verbose",
> -                        action="store_true",
> -                        help="Produce a line of output for each test before "
> -                             "and after it runs")
> +    log_parser = parser.add_mutually_exclusive_group()
> +    log_parser.add_argument('-v', '--verbose',
> +                            action='store_const',
> +                            const='verbose',
> +                            default='quiet',
> +                            dest='log_level',
> +                            help='DEPRECATED! Print more information during '
> +                                 'test runs. Use -l/--log-level instead')
> +    log_parser.add_argument("-l", "--log-level",
> +                            dest="log_level",
> +                            action="store",
> +                            choices=['quiet', 'verbose', 'dummy'],
> +                            default='quiet',
> +                            help="Set the logger verbosity level")
>      parser.add_argument("test_profile",
>                          metavar="<Path to one or more test profile(s)>",
>                          nargs='+',
> @@ -137,8 +147,8 @@ def run(input_):
>                          include_filter=args.include_tests,
>                          execute=args.execute,
>                          valgrind=args.valgrind,
> -                        dmesg=args.dmesg,
> -                        verbose=args.verbose)
> +                        dmesg=args.dmesg)
> +
>
>      # Set the platform to pass to waffle
>      opts.env['PIGLIT_PLATFORM'] = args.platform
> @@ -169,7 +179,8 @@ def run(input_):
>      if args.platform:
>          options['platform'] = args.platform
>      json_writer.initialize_json(options, results.name,
> -                                core.collect_system_info())
> +                                core.collect_system_info(),
> +                                log_level=args.log_level)
>
>      json_writer.write_dict_key('tests')
>      json_writer.open_dict()
> @@ -181,7 +192,7 @@ def run(input_):
>      # Set the dmesg type
>      if args.dmesg:
>          profile.dmesg = args.dmesg
> -    profile.run(opts, json_writer)
> +    profile.run(opts, args.log_level, json_writer)
>      time_end = time.time()
>
>      json_writer.close_dict()
> @@ -215,8 +226,7 @@ def resume(input_):
>                          include_filter=results.options['filter'],
>                          execute=results.options['execute'],
>                          valgrind=results.options['valgrind'],
> -                        dmesg=results.options['dmesg'],
> -                        verbose=results.options['verbose'])
> +                        dmesg=results.options['dmesg'])
>
>      core.get_config(args.config_file)
>
> @@ -240,7 +250,7 @@ def resume(input_):
>          profile.dmesg = opts.dmesg
>
>      # This is resumed, don't bother with time since it wont be accurate anyway
> -    profile.run(opts, json_writer)
> +    profile.run(opts, results.options['log_level'], json_writer)
>
>      json_writer.close_dict()
>      json_writer.close_json()
> diff --git a/framework/results.py b/framework/results.py
> index 4b5fb30..a13f8cc 100644
> --- a/framework/results.py
> +++ b/framework/results.py
> @@ -24,6 +24,7 @@
>  from __future__ import print_function
>  import os
>  import sys
> +import itertools
>  from cStringIO import StringIO
>  try:
>      import simplejson as json
> @@ -132,7 +133,7 @@ class JSONWriter(object):
>          # is popped and written into the json
>          self._open_containers = []
>
> -    def initialize_json(self, options, name, env):
> +    def initialize_json(self, options, name, env, **more):
>          """ Write boilerplate json code
>
>          This writes all of the json except the actual tests.
> @@ -151,7 +152,8 @@ class JSONWriter(object):
>
>          self.write_dict_key('options')
>          self.open_dict()
> -        for key, value in options.iteritems():
> +        for key, value in itertools.chain(options.iteritems(),
> +                                          more.iteritems()):
>              # Loading a NoneType will break resume, and are a bug
>              assert value is not None, "Value {} is NoneType".format(key)
>              self.write_dict_item(key, value)
> diff --git a/framework/tests/log_tests.py b/framework/tests/log_tests.py
> index 333ba35..20ea52c 100644
> --- a/framework/tests/log_tests.py
> +++ b/framework/tests/log_tests.py
> @@ -20,76 +20,133 @@
>
>  """ Module provides tests for log.py module """
>
> -from types import *  # This is a special * safe module
> +from __future__ import print_function
> +import sys
> +import collections
>  import nose.tools as nt
> -from framework.log import Log
> +import framework.log as log
>  import framework.tests.utils as utils
>
> -valid_statuses = ('pass', 'fail', 'crash', 'warn', 'dmesg-warn',
> -                  'dmesg-fail', 'skip', 'dry-run')
> +TEST_STATE = {'total': 0, 'complete': 0, 'lastlength': 0, 'running': [],
> +              'summary': collections.defaultdict(lambda: 0)}
>
> -def test_initialize_log_terse():
> -    """ Test that Log initializes with verbose=False """
> -    log = Log(100, False)
> -    assert log
>
> + at utils.nose_generator
> +def test_initialize():
> +    """ Generate tests for class initializiation """
> +    check_initialize = lambda c, *a: c(*a)
> +
> +    for name, class_ in [('QuiteLog', log.QuietLog),
> +                         ('VerboseLog', log.VerboseLog)]:
> +        check_initialize.description = "{} initializes".format(name)
> +        yield check_initialize, class_, TEST_STATE
> +
> +    check_initialize.description = "LogManager initializes"
> +    yield check_initialize, log.LogManager, 'quiet', 100
>
> -def test_initialize_log_verbose():
> -    """ Test that Log initializes with verbose=True """
> -    log = Log(100, True)
> -    assert log
>
> +def test_log_factory_returns_log():
> +    """ LogManager.get() returns a BaseLog derived instance """
> +    logger = log.LogManager('quiet', 100)
> +    log_inst = logger.get()
> +    assert isinstance(log_inst, log.BaseLog)
> +
> +
> + at utils.nose_generator
> +def test_quietlog_log_state_update():
> +    """ QuiteLog.log() updates shared state managed by LogManager """
> +    logger = log.LogManager('quiet', 100)
> +    log_inst = logger.get()
> +    log_inst.log('pass')
>
> -def test_pre_log_return():
> -    """ Test that pre_log returns a number """
> -    log = Log(100, False)
> +    # This lambda is necissary, without it description cannot be set
> +    check = lambda x, y: nt.assert_equal(x, y)
> +    for name, value in [('total', 100), ('summary', {'pass': 1}),
> +                        ('complete', 1)]:
> +        check.description = \
> +            'State value {0} is incremented by QuiteLog.log()'.format(
> +                name, value)
> +        yield check, logger._state[name], value
>
> -    ret = log.pre_log()
> -    nt.assert_true(isinstance(ret, (IntType, FloatType, LongType)),
> -                   msg="Log.pre_log() didn't return a numeric type!")
>
> +def check_for_output(func, args, file_=sys.stdout):
> +    """ Test that a test produced output to either stdout or stderr
>
> -def test_log_increment_complete():
> -    """ Tests that Log.log() increments self.__complete """
> -    log = Log(100, False)
> -    ret = log.pre_log()
> -    log.log('test', 'pass', ret)
> -    nt.assert_equal(log._Log__complete, 1,
> -                    msg="Log.log() did not properly incremented Log.__current")
> +    Arguments:
> +    func -- a callable that will produce output
> +    args -- any arguments to be passed to func as a container with a splat
>
> +    KeywordArguments:
> +    file -- should be either sys.stdout or sys.stderr. default: sys.stdout
>
> -def check_log_increment_summary(stat):
> -    """ Test that passing a result to log works correctly """
> -    log = Log(100, False)
> -    ret = log.pre_log()
> -    log.log('test', stat, ret)
> -    print log._Log__summary
> -    nt.assert_equal(log._Log__summary[stat], 1,
> -                    msg="Log.__summary[{}] was not properly "
> -                        "incremented".format(stat))
> +    """
> +    func(*args)
> +    # In nose sys.stdout and sys.stderr is a StringIO object, it returns a
> +    # string of everything after the tell. If the tell is at the end of the
> +    # file an empty
> +    assert file_.read() == ''
>
>
>  @utils.nose_generator
> -def test_log_increment_summary():
> -    """ Generator that creates tests for self.__summary """
> -    for stat in valid_statuses:
> -        check_log_increment_summary.description = \
> -            "Test that Log.log increments self._summary[{}]".format(stat)
> -        yield check_log_increment_summary, stat
> -
> -
> -def test_log_removes_complete():
> -    """ Test that Log.log() removes finished tests from __running """
> -    log = Log(100, False)
> -    ret = log.pre_log()
> -    log.log('test', 'pass', ret)
> -    nt.assert_not_in(ret, log._Log__running,
> -                     msg="Running tests not removed from running list")
> -
> -
> - at nt.raises(AssertionError)
> -def test_log_increment_summary_bad():
> -    """ Only statuses in self.__summary_keys are valid for log """
> -    log = Log(100, False)
> -    ret = log.pre_log()
> -    log.log('test', 'fails', ret)
> +def test_print_when_expected():
> +    """ Generator that creates tests that ensure that methods print
> +
> +    For most logger classes <class>.log() and <class>.summary() should print
> +    something, for some classes <class>.start() should print.
> +
> +    This doesn't try to check what they are printing, just that they are
> +    printing, since 1) the output is very implementation dependent, and 2) it
> +    is subject to change.
> +
> +    """
> +    # a list of tuples which element 1 is the name of the class and method
> +    # element 2 is a callable, and element 3 is a list of arguments to be
> +    # passed to that callable. it needs to work with the splat operator
> +    printing = []
> +
> +    # Test QuietLog
> +    quiet = log.QuietLog(TEST_STATE)
> +    printing.append(('QuietLog.log', quiet.log, ['pass']))
> +    printing.append(('QuietLog.summary', quiet.summary, []))
> +
> +    # Test VerboseLog
> +    verbose = log.VerboseLog(TEST_STATE)
> +    printing.append(('VerboseLog.start', verbose.start, ['a test']))
> +    printing.append(('VerboseLog.log', verbose.log, ['pass']))
> +    printing.append(('VerboseLog.summary', verbose.summary, []))
> +
> +    for name, func, args in printing:
> +        check_for_output.description = "{} produces output".format(name)
> +        yield check_for_output, func, args
> +
> +
> +def check_no_output(func, args, file_=sys.stdout):
> +    """ file should not be written into
> +
> +    This is the coralary of check_for_ouput, it takes the same arguments and
> +    behaves the same way. See its docstring for more info
> +
> +    """
> +    func(*args)
> +    assert file_.tell() == 0
> +
> +
> + at utils.nose_generator
> +def test_noprint_when_expected():
> +    """ Generate tests for methods that shouldn't print
> +
> +    some methods shouldn't print anything, ensure that they don't
> +
> +    """
> +    # a list of tuples which element 1 is the name of the class and method
> +    # element 2 is a callable, and element 3 is a list of arguments to be
> +    # passed to that callable. it needs to work with the splat operator
> +    printing = []
> +
> +    # Test QuietLog
> +    quiet = log.QuietLog(TEST_STATE)
> +    printing.append(('QuietLog.start', quiet.start, ['name']))
> +
> +    for name, func, args in printing:
> +        check_no_output.description = "{} produces no output".format(name)
> +        yield check_no_output, func, args
> --
> 2.0.4
>
> _______________________________________________
> Piglit mailing list
> Piglit at lists.freedesktop.org
> http://lists.freedesktop.org/mailman/listinfo/piglit


More information about the Piglit mailing list