[Piglit] [PATCH 4/5] framework: refactor the log module
Ilia Mirkin
imirkin at alum.mit.edu
Tue Aug 19 14:45:43 PDT 2014
On Tue, Aug 19, 2014 at 5:21 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.
> v5: - simplify the locking. This may have a performance impact, but
> makes the code much simpler. It should be possible to make the
> locking finer grained later
>
> Signed-off-by: Dylan Baker <dylanx.c.baker at intel.com>
> ---
>
> Ilia,
>
> If it wasn't already obvious I haven't had to do a lot of work with
> locks and threaded applications in the past. I'm definitely learning to
> swim by not drowning here. Thanks for your patience with this series.
No problem. Locking is probably one of the most complicated subjects
out there :) I'm again looking at the final output in your
log-refactor branch, not this patch specifically, although it should
be ~the same.
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)
with self._LOCK:
... use pad ...
So let's say you have (hopefully the ascii art works out... my
make-fonts-not-retarded-in-gmail plugin appears to have stopped
working for email composition)
thread 1 thread 2
_print
_print
pad = ...
acquire lock
pad = ...
use pad
self._state['lastlength'] = ...
release lock
acquire lock
use pad
Then that would be unfortunate, right? I think that the retrieval of
self._state['lastlength'] needs to move inside of the lock. That said,
it appears that _print is only ever called with the lock already
taken, in which case it shouldn't bother with the lock at all. In
general, having recursive locks is a sign of laziness, but I think it
can be forgiven here. But for _print, perhaps you can just assert that
the lock has already been taken.
Otherwise this (series) LGTM. Perhaps a little over-locked, but... not
unreasonably so.
Out of curiousity, what is the dry-run time with this patch on
tests/gpu.py (for example)? That should give a good idea as to the
overhead of the locking... perhaps compare it to using
dummy_threading.RLock.
>
> framework/core.py | 5 +-
> framework/exectest.py | 7 +-
> framework/log.py | 306 +++++++++++++++++++++++++++++--------------
> framework/profile.py | 10 +-
> framework/programs/run.py | 32 +++--
> framework/results.py | 6 +-
> framework/tests/log_tests.py | 171 ++++++++++++++++--------
> 7 files changed, 355 insertions(+), 182 deletions(-)
>
> diff --git a/framework/core.py b/framework/core.py
> index d5f1fcc..f949775 100644
> --- a/framework/core.py
> +++ b/framework/core.py
> @@ -89,13 +89,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 []]
> @@ -103,7 +101,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..0599272 100644
> --- a/framework/log.py
> +++ b/framework/log.py
> @@ -18,136 +18,246 @@
> # 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 a lock, which should be used to lock whever the shared state is
> + modified, or when printing to the screen (or both).
>
> 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'])
> + _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._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._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'])
> + )
> +
> + 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._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
> + # 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._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._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._LOCK:
> + self._print('{0}: {1}'.format(value, self.__name), newline=True)
> +
> + # Set lastlength to 0, this prevents printing needless padding 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
>
More information about the Piglit
mailing list