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

[Ilia Mirkin]

On Mon, Jul 7, 2014 at 8:17 PM, Dylan Baker <baker.dylan.c at gmail.com> wrote:
> On Monday, July 07, 2014 07:35:55 PM Ilia Mirkin wrote:
>> 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...
>
> I don't think that synchronized_self would actually work for the BaseLog
> derived methods. Unless I'm completely misunderstanding synchronized_self uses
> the repr() of self as a key for a dictionary, and the lock used is the value
> of that key. Which means that the value's are effectively instance variables,
> which works out well if you're passing a single instance to multiple threads,
> but this doesn't do that. It passes a unique instance to each thread each time
> a test is started.
>
> Or did I completely misunderstand how synchronized_self works?

I guess I meant the idea of synchronized_self, I don't remember enough
of how the impl works. But basically the log/print functions can be
called in parallel as far as I can tell, so they need to keep that in
mind when going about their business. I believe that means that they
should exclude against themselves. However you achieve that is fine
with me :)

>
>>
>> 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