framework: refactor the log module

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

The use of a non-recursive lock mandates that the majority of the code
be in un-locked protected methods, while the public method takes the
lock, otherwise inheritance is nearly impossible.

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
v6: - Lock one additional command
v7: - fix bug in Test. Test did not call log.start() so verbose log
      would print <status>: None
    - replace RLock with Lock. This requires a little bit of refactoring
      to make it work, since the lock cannot be called recursively
v8: - remove trailing whitespace

Signed-off-by: Dylan Baker <dylanx.c.baker@intel.com>
Reviewed-by: Ilia Mirkin <imirkin@alum.mit.edu>

1 files changed, 223 insertions, 103 deletions

diff --git a/framework/log.py b/framework/log.py
index 02b352693..c06de65b2 100644
--- a/framework/log.py
+++ b/framework/log.py
@@ -18,136 +18,256 @@
 # 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.Lock()
 
-        if verbose:
-            self.__output = "{result} :: {name}\n" + self.__output
+    def __init__(self, state):
+        self._state = state
+        self._pad = len(str(state['total']))
 
-        self.__summary_output = "[{percent}] {summary}\n"
+    @abc.abstractmethod
+    def start(self, name):
+        """ Called before test run starts
 
-    def _write_output(self, output):
-        """ write the output to stdout, ensuring any previous line is cleared """
+        This method is used to print things before the test starts
 
-        if self.__tty:
-            length = len(output)
-            if self.__lastlength > length:
-                output = "{0}{1}{2}".format(output[:-1],
-                                            " " * (self.__lastlength - length),
-                                            output[-1])
+        """
 
-            self.__lastlength = length
+    @abc.abstractmethod
+    def log(self, status):
+        """ Print the result of the test
 
-        sys.stdout.write(output)
+        This method is run after the test completes, and is used to log the
+        actual result of the test
 
-        # Need to flush explicitly, otherwise it all gets buffered without a
-        # newline.
-        sys.stdout.flush()
+        """
+
+    @abc.abstractmethod
+    def summary(self):
+        """ Print a final summary
 
-    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 _format_running(self):
-        """ return running tests """
-        return "Running Test(s): {}".format(
-            " ".join([str(x).zfill(self.__pad) for x in self.__running]))
-
-    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))
-
-    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))
-
-    @synchronized_self
-    def log(self, name, result, value):
-        """ Print to the screen
-
-        Works by moving the cursor back to the front of the line and printing
-        over it.
-
-        Arguments:
-        name -- the name of the test
-        result -- the result of the test
-        value -- the number of the test to remove
+        This method is run at the end of the test run, and is used to print a
+        final summary of the run
 
         """
-        assert result in self.__summary_keys
-        self.__print(name, result)
 
-        # Mark running complete
-        assert value in self.__running
-        self.__running.remove(value)
 
-        # increment the number of completed tests
-        self.__complete += 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()
+
+    def __init__(self, *args, **kwargs):
+        super(QuietLog, self).__init__(*args, **kwargs)
 
-        assert result in self.__summary_keys
-        self.__summary[result] += 1
+        # 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'
+
+        self.__counter = self._test_counter.next()
+        self._state['running'].append(self.__counter)
 
-    @synchronized_self
-    def pre_log(self, running=None):
-        """ Hook to run before log()
+    def start(self, name):
+        pass
 
-        Returns a new number to know what processes are running, if running is
-        set it will print a running message for the test
+    def _log(self, status):
+        """ non-locked helper for logging
 
-        Keyword Arguments:
-        running -- the name of a test to print is running. If Falsy then
-                   nothing will be printed. Default: None
+        To allow for code sharing with a subclass using a non-recursive lock we
+        need to share this code in a an unlocked form.
 
         """
-        if running:
-            self.__print(running, 'running')
+        # 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)
 
-        x = self.__generator.next()
-        self.__running.append(x)
-        return x
+    def log(self, status):
+        with self._LOCK:
+            self._log(status)
 
     def summary(self):
-        self._write_output(self.__summary_output.format(
-            percent=self._format_percent(),
-            summary=self._format_summary()))
+        with self._LOCK:
+            self._print_summary()
+
+    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 self._LOCK.locked()
+
+        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 """
+        assert self._LOCK.locked()
+
+        # 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()
+
+        # 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)
+
+
+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
+
+    def _print(self, out, newline=False):
+        """ Print to the console, add a newline if necissary
+
+        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.
+
+        """
+        super(VerboseLog, self)._print(out)
+        if newline:
+            sys.stdout.write('\n')
+            sys.stdout.flush()
+
+    def start(self, name):
+        """ Print the test that is being run next
+
+        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.
+
+        """
+        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)