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

[Ilia Mirkin]

On Sun, Jul 6, 2014 at 3:13 AM, Dylan Baker <baker.dylan.c at gmail.com> wrote:
> 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)
>
> Signed-off-by: Dylan Baker <baker.dylan.c at gmail.com>
> ---

[...]

> +class QuietLog(BaseLog):
> +    """ A logger providing minimal status output
>
> -    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))
> +    This logger provides only a ninja like [x/y] pass: z, fail: w ... output.
>
> -    def _format_running(self):
> -        """ return running tests """
> -        return "Running Test(s): {}".format(
> -            " ".join([str(x).zfill(self.__pad) for x in self.__running]))
> +    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
>
> -    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))
> +    Arguments:
> +    status -- the status to print
>
> -    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))
> +    """
> +    _test_counter = itertools.count()
> +
> +    def __init__(self, *args, **kwargs):
> +        super(QuietLog, self).__init__(*args, **kwargs)
>
> -    @synchronized_self
> -    def log(self, name, result, value):
> -        """ Print to the screen
> +        # 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'
>
> -        Works by moving the cursor back to the front of the line and printing
> -        over it.
> +        self.__counter = self._test_counter.next()
> +        self._state['running'].append(self.__counter)
> +
> +    def start(self, name):
> +        pass
> +
> +    def log(self, status):
> +        # increment complete
> +        self._state['complete'] += 1
> +
> +        # Add to the summary dict
> +        assert status in self.SUMMARY_KEYS
> +        self._state['summary'][status] += 1
> +
> +        self._print_summary()
> +        self._state['running'].remove(self.__counter)
> +
> +    def summary(self):
> +        self._print_summary()
>
> -        Arguments:
> -        name -- the name of the test
> -        result -- the result of the test
> -        value -- the number of the test to remove
> +    def _print_summary(self):
> +        """ Print the summary result
> +
> +        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)
> +        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 """
> +        with self._LOCK:
> +            # If the new line is shorter than the old one add trailing
> +            # whitespace
> +            pad = self._state['lastlength'] - len(out)
> +
> +            sys.stdout.write(out)
> +            if pad > 0:
> +                sys.stdout.write(' ' * pad)
> +            sys.stdout.write(self._endcode)
> +            sys.stdout.flush()
>
> -        # Mark running complete
> -        assert value in self.__running
> -        self.__running.remove(value)
> +        # 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)

This should be done under the lock, no? And also the += 1's...

>
> -        # increment the number of completed tests
> -        self.__complete += 1
>
> -        assert result in self.__summary_keys
> -        self.__summary[result] += 1

[...]

> +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': [],
> +        }  # XXX Does access to this dict need locking?

Can two threads call print at the same time? I think they can, so the
answer is "yes", since while no 2 threads run at the same time due to
the GIL, they may get interrupted at arbitrary points. What was wrong
with the @synchronized_self stuff -- just stick that on the log()
method...

With that fixed (which is also my comment above), patches 1-4
Reviewed-by: Ilia Mirkin <imirkin at alum.mit.edu>

(nothing wrong with patch 5, just haven't looked at it yet)

  -ilia