clean up NRWT logging/metering, be less verbose
authordpranke@chromium.org <dpranke@chromium.org@268f45cc-cd09-0410-ab3c-d52691b4dbfc>
Sat, 24 Mar 2012 21:22:41 +0000 (21:22 +0000)
committerdpranke@chromium.org <dpranke@chromium.org@268f45cc-cd09-0410-ab3c-d52691b4dbfc>
Sat, 24 Mar 2012 21:22:41 +0000 (21:22 +0000)
https://bugs.webkit.org/show_bug.cgi?id=73846

Reviewed by Ojan Vafai.

This patch totally rewrites the metered_stream module and
changes the way it and the printing module now interact with the
logging subsystem.

The printing module becomes a dumb layout_tests-specific wrapper around
the metered stream. All of the intelligence of how and when to
actually write (or erase) lines and how things interact with
logging moves into the metered stream.

As of now, anything written to the metered stream *bypasses the
logging system*. If a logger is passed to the meter constructor,
the metered stream will also attach a log handler so that all
messages fed to the logger will also be written to the metered
stream. This detangles the logic that used to exist where
sometimes the meter would write to the logger and sometimes the
logger would write to the meter.

All of this makes the logic generic and reusable for
test-webkitpy (coming in another patch). It also helps clarify
what the mysterious "configure_logging" parameter to the printer
constructor used to do (that parameter itself is gone now, and
by default the printer and metered_stream will not ever touch
the logging system; this makes a bunch of tests less fragile).

All of the above should produce no user-visible changes.

However, to also fix the bug in question, we change the message
format in --verbose mode to %H:%M:%S.%frac %pid %message,
eliminating the date, file:lineno, and level parameters. I am
making this change at the same time because it would be
difficult to write things consistently between the logs and the
metered stream if we were still logging the file:lineno.

* Scripts/webkitpy/layout_tests/controllers/manager_unittest.py:
  Remove the configure_logging parameter
* Scripts/webkitpy/layout_tests/controllers/worker.py:
  Use metered stream to configure the logging (we don't need a printer)
  and be careful about when and how we manipulate the log level
  and handlers on the root logger.
* Scripts/webkitpy/layout_tests/run_webkit_tests.py:
  Pass in the root logger so that log messages are formatted
  properly, and set the log level outside of any routines called
  by unit tests so as to not interfere.
* Scripts/webkitpy/layout_tests/views/manager_worker_broker.py:
  remove a duplicate log message.
* Scripts/webkitpy/layout_tests/views/metered_stream.py:
  complete rewrite :).
* Scripts/webkitpy/layout_tests/views/metered_stream_unittest.py:
  complete rewrite :).
* Scripts/webkitpy/layout_tests/views/printing.py:
  move the logging configuration into metered_stream, and also
  move the "when should I log progress messages" into metered stream.
* Scripts/webkitpy/layout_tests/views/printing_unittest.py:
  remove tests that are no longer necessary.
* Scripts/webkitpy/performance_tests/perftestsrunner.py:
  remove the configure_logging parameter.
* Scripts/webkitpy/performance_tests/perftestsrunner_unittest.py:
  update the test; since the printer no longer writes to the log,
  we need to check what is written to the regular_output instead.
  (test_run_test_pause_before_testing):

git-svn-id: https://svn.webkit.org/repository/webkit/trunk@112014 268f45cc-cd09-0410-ab3c-d52691b4dbfc

12 files changed:
Tools/ChangeLog
Tools/Scripts/webkitpy/layout_tests/controllers/manager_unittest.py
Tools/Scripts/webkitpy/layout_tests/controllers/manager_worker_broker.py
Tools/Scripts/webkitpy/layout_tests/controllers/worker.py
Tools/Scripts/webkitpy/layout_tests/controllers/worker_unittest.py
Tools/Scripts/webkitpy/layout_tests/run_webkit_tests.py
Tools/Scripts/webkitpy/layout_tests/views/metered_stream.py
Tools/Scripts/webkitpy/layout_tests/views/metered_stream_unittest.py
Tools/Scripts/webkitpy/layout_tests/views/printing.py
Tools/Scripts/webkitpy/layout_tests/views/printing_unittest.py
Tools/Scripts/webkitpy/performance_tests/perftestsrunner.py
Tools/Scripts/webkitpy/performance_tests/perftestsrunner_unittest.py

index 8c0e584d6f41c03220ad6be499506c91456f7225..bba4488ef70d82c4d2241d1b7ee9d729ca3dc671 100644 (file)
@@ -1,3 +1,71 @@
+2012-03-24  Dirk Pranke  <dpranke@chromium.org>
+
+        clean up NRWT logging/metering, be less verbose
+        https://bugs.webkit.org/show_bug.cgi?id=73846
+
+        Reviewed by Ojan Vafai.
+
+        This patch totally rewrites the metered_stream module and
+        changes the way it and the printing module now interact with the
+        logging subsystem.
+
+        The printing module becomes a dumb layout_tests-specific wrapper around
+        the metered stream. All of the intelligence of how and when to
+        actually write (or erase) lines and how things interact with
+        logging moves into the metered stream.
+
+        As of now, anything written to the metered stream *bypasses the
+        logging system*. If a logger is passed to the meter constructor,
+        the metered stream will also attach a log handler so that all
+        messages fed to the logger will also be written to the metered
+        stream. This detangles the logic that used to exist where
+        sometimes the meter would write to the logger and sometimes the
+        logger would write to the meter.
+
+        All of this makes the logic generic and reusable for
+        test-webkitpy (coming in another patch). It also helps clarify
+        what the mysterious "configure_logging" parameter to the printer
+        constructor used to do (that parameter itself is gone now, and
+        by default the printer and metered_stream will not ever touch
+        the logging system; this makes a bunch of tests less fragile).
+
+        All of the above should produce no user-visible changes.
+
+        However, to also fix the bug in question, we change the message
+        format in --verbose mode to %H:%M:%S.%frac %pid %message,
+        eliminating the date, file:lineno, and level parameters. I am
+        making this change at the same time because it would be
+        difficult to write things consistently between the logs and the
+        metered stream if we were still logging the file:lineno.
+
+        * Scripts/webkitpy/layout_tests/controllers/manager_unittest.py:
+          Remove the configure_logging parameter
+        * Scripts/webkitpy/layout_tests/controllers/worker.py:
+          Use metered stream to configure the logging (we don't need a printer)
+          and be careful about when and how we manipulate the log level
+          and handlers on the root logger.
+        * Scripts/webkitpy/layout_tests/run_webkit_tests.py:
+          Pass in the root logger so that log messages are formatted
+          properly, and set the log level outside of any routines called
+          by unit tests so as to not interfere.
+        * Scripts/webkitpy/layout_tests/views/manager_worker_broker.py:
+          remove a duplicate log message.
+        * Scripts/webkitpy/layout_tests/views/metered_stream.py:
+          complete rewrite :).
+        * Scripts/webkitpy/layout_tests/views/metered_stream_unittest.py:
+          complete rewrite :).
+        * Scripts/webkitpy/layout_tests/views/printing.py:
+          move the logging configuration into metered_stream, and also
+          move the "when should I log progress messages" into metered stream.
+        * Scripts/webkitpy/layout_tests/views/printing_unittest.py:
+          remove tests that are no longer necessary.
+        * Scripts/webkitpy/performance_tests/perftestsrunner.py:
+          remove the configure_logging parameter.
+        * Scripts/webkitpy/performance_tests/perftestsrunner_unittest.py:
+          update the test; since the printer no longer writes to the log,
+          we need to check what is written to the regular_output instead.
+          (test_run_test_pause_before_testing):
+
 2012-03-24  Gustavo Noronha Silva  <gns@gnome.org>
 
         Add myself and Martin Robinson to:
index 8bc6afffe1386ea5153ed396917be6214899c60f..3f58e7b4c51b1a87eed05fb108a053db0384f25f 100644 (file)
@@ -214,7 +214,7 @@ class ManagerTest(unittest.TestCase):
         host = MockHost()
         port = host.port_factory.get(port_name=options.platform, options=options)
         run_webkit_tests._set_up_derived_options(port, options)
-        printer = printing.Printer(port, options, StringIO.StringIO(), StringIO.StringIO(), configure_logging=False)
+        printer = printing.Printer(port, options, StringIO.StringIO(), StringIO.StringIO())
         manager = LockCheckingManager(port, options, printer)
         manager.collect_tests(args)
         manager.parse_expectations()
index 70c43a6d415d34065b14a73e3e1def781ffa23ff..08c059a9576c919d34869eec26b4b2cb7a8d1cc5 100755 (executable)
@@ -274,7 +274,6 @@ class AbstractWorker(BrokerClient):
         """Callback for the worker to start executing. Typically does any
         remaining initialization and then calls broker_connection.run_message_loop()."""
         exception_msg = ""
-        _log.debug("%s starting" % self._name)
 
         try:
             self._worker_connection.run_message_loop()
index 22c0a5f0423105e30938b8ef3527dc67e2029aa2..07a20c9c305abd7ec1edad8ddddc94c8f33b78bc 100644 (file)
@@ -38,7 +38,7 @@ from webkitpy.layout_tests.controllers import manager_worker_broker
 from webkitpy.layout_tests.controllers import single_test_runner
 from webkitpy.layout_tests.models import test_expectations
 from webkitpy.layout_tests.models import test_results
-from webkitpy.layout_tests.views import printing
+from webkitpy.layout_tests.views import metered_stream
 
 
 _log = logging.getLogger(__name__)
@@ -65,7 +65,7 @@ class Worker(manager_worker_broker.AbstractWorker):
         self._driver = None
         self._tests_run_file = None
         self._tests_run_filename = None
-        self._printer = None
+        self._meter = None
 
     def __del__(self):
         self.cleanup()
@@ -82,41 +82,58 @@ class Worker(manager_worker_broker.AbstractWorker):
         tests_run_filename = self._filesystem.join(self._results_directory, "tests_run%d.txt" % self._worker_number)
         self._tests_run_file = self._filesystem.open_text_file_for_writing(tests_run_filename)
 
+    def _set_up_logging(self):
+        # The unix multiprocessing implementation clones the MeteredStream log handler
+        # into the child process, so we need to remove it before we can
+        # add a new one to get the correct pid logged.
+        root_logger = logging.getLogger()
+        handler_to_remove = None
+        for h in root_logger.handlers:
+            if h.name == metered_stream.LOG_HANDLER_NAME:
+                handler_to_remove = h
+                break
+        if handler_to_remove:
+            root_logger.removeHandler(handler_to_remove)
+
+        # FIXME: This won't work if the calling process is logging
+        # somewhere other than sys.stderr, but I'm not sure
+        # if this will be an issue in practice. Also, it would be
+        # nice if we trapped all of the messages for a given test
+        # and sent them back in finished_test() rather than logging
+        # them to stderr.
+        if not root_logger.handlers:
+            options = self._options
+            root_logger.setLevel(logging.DEBUG if options.verbose else logging.INFO)
+            self._meter = metered_stream.MeteredStream(sys.stderr, options.verbose, logger=root_logger)
+
+    def _set_up_host_and_port(self):
+        options = self._options
+        if options.platform and 'test' in options.platform:
+            # It is lame to import mocks into real code, but this allows us to use the test port in multi-process tests as well.
+            from webkitpy.common.host_mock import MockHost
+            host = MockHost()
+        else:
+            host = Host()
+        self._port = host.port_factory.get(options.platform, options)
+
     def set_inline_arguments(self, port):
         self._port = port
 
     def run(self):
         if not self._port:
-            # We are running in a child process and need to create a new Host.
-            if self._options.platform and 'test' in self._options.platform:
-                # It is lame to import mocks into real code, but this allows us to use the test port in multi-process tests as well.
-                from webkitpy.common.host_mock import MockHost
-                host = MockHost()
-            else:
-                host = Host()
-
-            options = self._options
-            self._port = host.port_factory.get(options.platform, options)
-
-            # The unix multiprocessing implementation clones the
-            # log handler configuration into the child processes,
-            # but the win implementation doesn't.
-            configure_logging = (sys.platform == 'win32')
-
-            # FIXME: This won't work if the calling process is logging
-            # somewhere other than sys.stderr and sys.stdout, but I'm not sure
-            # if this will be an issue in practice.
-            self._printer = printing.Printer(self._port, options, sys.stderr, sys.stdout, configure_logging)
+            # We are running in a child process and need to initialize things.
+            self._set_up_logging()
+            self._set_up_host_and_port()
 
         self.safe_init()
-
         try:
             _log.debug("%s starting" % self._name)
             super(Worker, self).run()
         finally:
+            self.kill_driver()
             self._worker_connection.post_message('done')
-            self.cleanup()
             _log.debug("%s exiting" % self._name)
+            self.cleanup()
 
     def handle_test_list(self, src, list_name, test_list):
         start_time = time.time()
@@ -153,9 +170,9 @@ class Worker(manager_worker_broker.AbstractWorker):
         if self._tests_run_file:
             self._tests_run_file.close()
             self._tests_run_file = None
-        if self._printer:
-            self._printer.cleanup()
-            self._printer = None
+        if self._meter:
+            self._meter.cleanup()
+            self._meter = None
 
     def timeout(self, test_input):
         """Compute the appropriate timeout value for a test."""
index 6fd5202d9c4007f0ee84d9c1356afcfaa0d9f591..ebb4e7a5bb5ae687471cba3200a08b31b58b136b 100644 (file)
@@ -46,8 +46,7 @@ class WorkerTest(unittest.TestCase):
         # if we didn't specify a port with the --platform flag.
         worker_connection = FakeConnection()
         worker = Worker(worker_connection, WorkerArguments(1, '/tmp', MockOptions(platform=None, print_options=None, verbose=False, batch_size=0)))
-        worker._done = True
-        worker.run()
+        worker._set_up_host_and_port()
         self.assertNotEquals(worker._port, None)
 
 
index 6b0e3677d9aa6c3147138925a2d411005381eccc..c28b9113738e2f8ff883e2a000f6601345822a3a 100755 (executable)
@@ -85,7 +85,7 @@ def lint(port, options, expectations_class):
 def run(port, options, args, regular_output=sys.stderr, buildbot_output=sys.stdout):
     warnings = _set_up_derived_options(port, options)
 
-    printer = printing.Printer(port, options, regular_output, buildbot_output, configure_logging=True)
+    printer = printing.Printer(port, options, regular_output, buildbot_output, logger=logging.getLogger())
 
     for warning in warnings:
         _log.warning(warning)
@@ -479,6 +479,7 @@ def main():
         host = Host()
     host._initialize_scm()
     port = host.port_factory.get(options.platform, options)
+    logging.getLogger().setLevel(logging.DEBUG if options.verbose else logging.INFO)
     return run(port, options, args)
 
 
index b5c233b106a73e04a63540434e52fd54a6dab9b9..dfa49e4e810fb6c7c52398e78a5f3a2d6d642953 100644 (file)
@@ -1,5 +1,5 @@
 #!/usr/bin/env python
-# Copyright (C) 2010 Google Inc. All rights reserved.
+# Copyright (C) 2010, 2012 Google Inc. All rights reserved.
 #
 # Redistribution and use in source and binary forms, with or without
 # modification, are permitted provided that the following conditions are
 # (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
 # OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 
-"""
-Package that implements a stream wrapper that has 'meters' as well as
-regular output. A 'meter' is a single line of text that can be erased
-and rewritten repeatedly, without producing multiple lines of output. It
-can be used to produce effects like progress bars.
-
-This package should only be called by the printing module in the layout_tests
-package.
-"""
-
-
-class MeteredStream:
-    """This class is a wrapper around a stream that allows you to implement
-    meters (progress bars, etc.).
-
-    It can be used directly as a stream, by calling write(), but also provides
-    a method called update() that will overwite prior updates().
-   """
-
-    def __init__(self, stream):
-        """
-        Args:
-          stream: output stream to write to
-        """
-        self._stream = stream
-        self._dirty = False
-        self._last_update = ""
-
-    def write(self, txt):
-        """Write to the stream, overwriting and resetting the meter."""
-
-        # This routine is called by the logging infrastructure, and
-        # must not call back into logging. It is not a public function.
-        self._overwrite(txt)
-        self._reset()
-
-    def update(self, txt):
-        """Write a message that will be overwritten by subsequent update() or write() calls."""
-        self._overwrite(txt)
-
-    def _overwrite(self, txt):
-        # Print the necessary number of backspaces to erase the previous
-        # message.
-        if len(self._last_update):
-            self._stream.write("\b" * len(self._last_update) +
-                               " " * len(self._last_update) +
-                               "\b" * len(self._last_update))
-        self._stream.write(txt)
-        last_newline = txt.rfind("\n")
-        self._last_update = txt[(last_newline + 1):]
-        self._dirty = True
-
-    def _reset(self):
-        self._dirty = False
-        self._last_update = ''
+import logging
+import os
+import sys
+import time
+
+
+LOG_HANDLER_NAME = 'MeteredStreamLogHandler'
+
+
+class MeteredStream(object):
+    """
+    This class implements a stream wrapper that has 'meters' as well as
+    regular output. A 'meter' is a single line of text that can be erased
+    and rewritten repeatedly, without producing multiple lines of output. It
+    can be used to produce effects like progress bars.
+    """
+
+    @staticmethod
+    def _erasure(txt):
+        num_chars = len(txt)
+        return '\b' * num_chars + ' ' * num_chars + '\b' * num_chars
+
+    @staticmethod
+    def _ensure_newline(txt):
+        return txt if txt.endswith('\n') else txt + '\n'
+
+    def __init__(self, stream=None, verbose=False, logger=None, time_fn=None, pid=None):
+        self._stream = stream or sys.stderr
+        self._verbose = verbose
+        self._time_fn = time_fn or time.time
+        self._pid = pid or os.getpid()
+
+        self._isatty = self._stream.isatty()
+        self._erasing = self._isatty and not verbose
+        self._last_partial_line = ''
+        self._last_write_time = 0.0
+        self._throttle_delay_in_secs = 0.066 if self._erasing else 10.0
+
+        self._logger = logger
+        self._log_handler = None
+        if self._logger:
+            log_level = logging.DEBUG if verbose else logging.INFO
+            self._log_handler = _LogHandler(self)
+            self._log_handler.setLevel(log_level)
+            self._logger.addHandler(self._log_handler)
+
+    def __del__(self):
+        self.cleanup()
+
+    def cleanup(self):
+        if self._logger:
+            self._logger.removeHandler(self._log_handler)
+            self._log_handler = None
+
+    def write_throttled_update(self, txt):
+        now = self._time_fn()
+        if now - self._last_write_time >= self._throttle_delay_in_secs:
+            self.write_update(txt, now)
+
+    def write_update(self, txt, now=None):
+        self.write(txt, now)
+        if self._erasing:
+            self._last_partial_line = txt[txt.rfind('\n') + 1:]
+
+    def write(self, txt, now=None):
+        now = now or self._time_fn()
+        self._last_write_time = now
+        if self._last_partial_line:
+            self._erase_last_partial_line()
+        if self._verbose:
+            now_tuple = time.localtime(now)
+            msg = '%02d:%02d:%02d.%03d %d %s' % (now_tuple.tm_hour, now_tuple.tm_min, now_tuple.tm_sec, int((now * 1000) % 1000), self._pid, self._ensure_newline(txt))
+        elif self._isatty:
+            msg = txt
+        else:
+            msg = self._ensure_newline(txt)
+
+        self._stream.write(msg)
+
+    def writeln(self, txt, now=None):
+        self.write(self._ensure_newline(txt), now)
+
+    def _erase_last_partial_line(self):
+        num_chars = len(self._last_partial_line)
+        self._stream.write(self._erasure(self._last_partial_line))
+        self._last_partial_line = ''
+
+
+class _LogHandler(logging.Handler):
+    def __init__(self, meter):
+        logging.Handler.__init__(self)
+        self._meter = meter
+        self._name = LOG_HANDLER_NAME
+
+    def emit(self, record):
+        self._meter.writeln(record.msg, record.created)
index 359cfcf60f1393430dbcd3af1c7b1092dedd1329..4b376460bfb1b14b4f6bf16383f73e3dec3b71e4 100644 (file)
@@ -1,5 +1,5 @@
 #!/usr/bin/python
-# Copyright (C) 2010 Google Inc. All rights reserved.
+# Copyright (C) 2010, 2012 Google Inc. All rights reserved.
 #
 # Redistribution and use in source and binary forms, with or without
 # modification, are permitted provided that the following conditions are
 # (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
 # OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 
+import logging
+import re
 import StringIO
 import unittest
 
 from webkitpy.layout_tests.views.metered_stream import MeteredStream
 
 
-class TestMeteredStream(unittest.TestCase):
-    def test_regular(self):
-        a = StringIO.StringIO()
-        m = MeteredStream(a)
-        self.assertFalse(a.getvalue())
-
-        # basic test
-        m.write("foo")
-        exp = ['foo']
-        self.assertEquals(a.buflist, exp)
-
-        # now check that a second write() does not overwrite the first.
-        m.write("bar")
-        exp.append('bar')
-        self.assertEquals(a.buflist, exp)
-
-        m.update("batter")
-        exp.append('batter')
-        self.assertEquals(a.buflist, exp)
-
-        # The next update() should overwrite the laste update() but not the
-        # other text. Note that the cursor is effectively positioned at the
-        # end of 'foo', even though we had to erase three more characters.
-        m.update("foo")
-        exp.append('\b\b\b\b\b\b      \b\b\b\b\b\b')
-        exp.append('foo')
-        self.assertEquals(a.buflist, exp)
-
-        # now check that a write() does overwrite the update
-        m.write("foo")
-        exp.append('\b\b\b   \b\b\b')
-        exp.append('foo')
-        self.assertEquals(a.buflist, exp)
-
-        # Now test that we only back up to the most recent newline.
-
-        # Note also that we do not back up to erase the most recent write(),
-        # i.e., write()s do not get erased.
-        a = StringIO.StringIO()
-        m = MeteredStream(a)
-        m.update("foo\nbar")
-        m.update("baz")
-        self.assertEquals(a.buflist, ['foo\nbar', '\b\b\b   \b\b\b', 'baz'])
+class RegularTest(unittest.TestCase):
+    verbose = False
+    isatty = False
+
+    def setUp(self):
+        self.stream = StringIO.StringIO()
+        self.buflist = self.stream.buflist
+        self.stream.isatty = lambda: self.isatty
+
+        # configure a logger to test that log calls do normally get included.
+        self.logger = logging.getLogger(__name__)
+        self.logger.setLevel(logging.DEBUG)
+        self.logger.propagate = False
+
+        # add a dummy time counter for a default behavior.
+        self.times = range(10)
+
+        self.meter = MeteredStream(self.stream, self.verbose, self.logger, self.time_fn, 8675)
+
+    def tearDown(self):
+        if self.meter:
+            self.meter.cleanup()
+            self.meter = None
+
+    def time_fn(self):
+        return self.times.pop(0)
+
+    def test_logging_not_included(self):
+        # This tests that if we don't hand a logger to the MeteredStream,
+        # nothing is logged.
+        logging_stream = StringIO.StringIO()
+        handler = logging.StreamHandler(logging_stream)
+        root_logger = logging.getLogger()
+        orig_level = root_logger.level
+        root_logger.addHandler(handler)
+        root_logger.setLevel(logging.DEBUG)
+        try:
+            self.meter = MeteredStream(self.stream, self.verbose, None, self.time_fn, 8675)
+            self.meter.write_throttled_update('foo')
+            self.meter.write_update('bar')
+            self.meter.write('baz')
+            self.assertEquals(logging_stream.buflist, [])
+        finally:
+            root_logger.removeHandler(handler)
+            root_logger.setLevel(orig_level)
+
+    def _basic(self, times):
+        self.times = times
+        self.meter.write_update('foo')
+        self.meter.write_update('bar')
+        self.meter.write_throttled_update('baz')
+        self.meter.write_throttled_update('baz 2')
+        self.meter.writeln('done')
+        self.assertEquals(self.times, [])
+        return self.buflist
+
+    def test_basic(self):
+        buflist = self._basic([0, 1, 2, 13, 14])
+        self.assertEquals(buflist, ['foo\n', 'bar\n', 'baz 2\n', 'done\n'])
+
+    def _log_after_update(self):
+        self.meter.write_update('foo')
+        self.logger.info('bar')
+        return self.buflist
+
+    def test_log_after_update(self):
+        buflist = self._log_after_update()
+        self.assertEquals(buflist, ['foo\n', 'bar\n'])
+
+
+class TtyTest(RegularTest):
+    verbose = False
+    isatty = True
+
+    def test_basic(self):
+        buflist = self._basic([0, 1, 1.05, 1.1, 2])
+        self.assertEquals(buflist, ['foo',
+                                     MeteredStream._erasure('foo'), 'bar',
+                                     MeteredStream._erasure('bar'), 'baz 2',
+                                     MeteredStream._erasure('baz 2'), 'done\n'])
+
+    def test_log_after_update(self):
+        buflist = self._log_after_update()
+        self.assertEquals(buflist, ['foo',
+                                     MeteredStream._erasure('foo'), 'bar\n'])
+
+
+class VerboseTest(RegularTest):
+    isatty = False
+    verbose = True
+
+    def test_basic(self):
+        buflist = self._basic([0, 1, 2.1, 13, 14.1234])
+        self.assertEquals(buflist, ['16:00:00.000 8675 foo\n', '16:00:01.000 8675 bar\n', '16:00:13.000 8675 baz 2\n', '16:00:14.123 8675 done\n'])
+
+    def test_log_after_update(self):
+        buflist = self._log_after_update()
+        self.assertEquals(buflist[0], '16:00:00.000 8675 foo\n')
+
+        # The second argument should have a real timestamp and pid, so we just check the format.
+        self.assertEquals(len(buflist), 2)
+        self.assertTrue(re.match('\d\d:\d\d:\d\d.\d\d\d \d+ bar\n', buflist[1]))
 
 
 if __name__ == '__main__':
index 750c48df9e309534602a8850786c33103c8f0a67..3df2956c182618ed0dcf13ed6f185e510e487fba 100644 (file)
@@ -1,5 +1,5 @@
 #!/usr/bin/env python
-# Copyright (C) 2010 Google Inc. All rights reserved.
+# Copyright (C) 2010, 2012 Google Inc. All rights reserved.
 #
 # Redistribution and use in source and binary forms, with or without
 # modification, are permitted provided that the following conditions are
 
 """Package that handles non-debug, non-file output for run-webkit-tests."""
 
-import logging
 import optparse
-import time
 
 from webkitpy.common.net import resultsjsonparser
-from webkitpy.layout_tests.views.metered_stream import MeteredStream
 from webkitpy.layout_tests.models.test_expectations import TestExpectations
-
-
-_log = logging.getLogger(__name__)
-
+from webkitpy.layout_tests.views.metered_stream import MeteredStream
 
 NUM_SLOW_TESTS_TO_LOG = 10
-FAST_UPDATES_SECONDS = 0.03
-SLOW_UPDATES_SECONDS = 10.0
 
 PRINT_DEFAULT = "misc,one-line-progress,one-line-summary,unexpected,unexpected-results,updates"
 PRINT_EVERYTHING = "actual,config,expected,misc,one-line-progress,one-line-summary,slowest,timing,unexpected,unexpected-results,updates"
@@ -154,27 +146,6 @@ def parse_print_options(print_options, verbose):
     return switches
 
 
-def _configure_logging(stream, verbose):
-    log_fmt = '%(message)s'
-    log_datefmt = '%y%m%d %H:%M:%S'
-    log_level = logging.INFO
-    if verbose:
-        log_fmt = '%(asctime)s %(process)d %(filename)s:%(lineno)d %(levelname)s %(message)s'
-        log_level = logging.DEBUG
-
-    root = logging.getLogger()
-    handler = logging.StreamHandler(stream)
-    handler.setFormatter(logging.Formatter(log_fmt, None))
-    root.addHandler(handler)
-    root.setLevel(log_level)
-    return handler
-
-
-def _restore_logging(handler_to_remove):
-    root = logging.getLogger()
-    root.handlers.remove(handler_to_remove)
-
-
 class Printer(object):
     """Class handling all non-debug-logging printing done by run-webkit-tests.
 
@@ -187,7 +158,7 @@ class Printer(object):
 
     By default the buildbot-parsed code gets logged to stdout, and regular
     output gets logged to stderr."""
-    def __init__(self, port, options, regular_output, buildbot_output, configure_logging):
+    def __init__(self, port, options, regular_output, buildbot_output, logger=None):
         """
         Args
           port               interface to port-specific routines
@@ -196,37 +167,16 @@ class Printer(object):
                              should be written
           buildbot_output    stream to which output intended to be read by
                              the buildbots (and humans) should be written
-          configure_loggign  Whether a logging handler should be registered
-
+          logger             optional logger to integrate into the stream.
         """
         self._port = port
         self._options = options
-        self._stream = regular_output
         self._buildbot_stream = buildbot_output
-        self._meter = None
-
-        # These are used for --print one-line-progress
-        self._last_remaining = None
-        self._last_update_time = None
-
+        self._meter = MeteredStream(regular_output, options.verbose, logger=logger)
         self.switches = parse_print_options(options.print_options, options.verbose)
 
-        self._logging_handler = None
-        if self._stream.isatty() and not options.verbose:
-            self._update_interval_seconds = FAST_UPDATES_SECONDS
-            self._meter = MeteredStream(self._stream)
-            if configure_logging:
-                self._logging_handler = _configure_logging(self._meter, options.verbose)
-        else:
-            self._update_interval_seconds = SLOW_UPDATES_SECONDS
-            if configure_logging:
-                self._logging_handler = _configure_logging(self._stream, options.verbose)
-
     def cleanup(self):
-        """Restore logging configuration to its initial settings."""
-        if self._logging_handler:
-            _restore_logging(self._logging_handler)
-            self._logging_handler = None
+        self._meter.cleanup()
 
     def __del__(self):
         self.cleanup()
@@ -350,27 +300,19 @@ class Printer(object):
         if self.disabled('one-line-progress'):
             return
 
-        now = time.time()
-        if self._last_update_time is None:
-            self._last_update_time = now
-
-        time_since_last_update = now - self._last_update_time
-        if time_since_last_update <= self._update_interval_seconds:
+        if result_summary.remaining == 0:
+            self._meter.write_update('')
             return
 
-        self._last_update_time = now
-
         percent_complete = 100 * (result_summary.expected +
             result_summary.unexpected) / result_summary.total
         action = "Testing"
         if retrying:
             action = "Retrying"
-        self._update("%s (%d%%): %d ran as expected, %d didn't, %d left" %
-                     (action, percent_complete, result_summary.expected,
-                      result_summary.unexpected, result_summary.remaining))
 
-        if result_summary.remaining == 0:
-            self._update('')
+        self._meter.write_throttled_update("%s (%d%%): %d ran as expected, %d didn't, %d left" %
+            (action, percent_complete, result_summary.expected,
+             result_summary.unexpected, result_summary.remaining))
 
     def print_unexpected_results(self, unexpected_results):
         """Prints a list of the unexpected results to the buildbot stream."""
@@ -458,7 +400,7 @@ class Printer(object):
     def print_update(self, msg):
         if self.disabled('updates'):
             return
-        self._update(msg)
+        self._meter.write_update(msg)
 
     def write(self, msg, option="misc"):
         if self.disabled(option):
@@ -466,10 +408,4 @@ class Printer(object):
         self._write(msg)
 
     def _write(self, msg):
-        _log.info(msg)
-
-    def _update(self, msg):
-        if self._meter:
-            self._meter.update(msg)
-        else:
-            self._write(msg)
+        self._meter.writeln(msg)
index 6899d2c5d4cdb0452709cd4df0ed9691fc5baf7d..8777fd8d6e322ba6de2357c444c88ee6861dd33b 100644 (file)
@@ -1,5 +1,5 @@
 #!/usr/bin/python
-# Copyright (C) 2010 Google Inc. All rights reserved.
+# Copyright (C) 2010, 2012 Google Inc. All rights reserved.
 #
 # Redistribution and use in source and binary forms, with or without
 # modification, are permitted provided that the following conditions are
@@ -29,7 +29,6 @@
 
 """Unit tests for printing.py."""
 
-import logging
 import optparse
 import StringIO
 import time
@@ -54,35 +53,6 @@ def get_options(args):
 
 
 class TestUtilityFunctions(unittest.TestCase):
-    def assertEmpty(self, stream):
-        self.assertFalse(stream.getvalue())
-
-    def assertNotEmpty(self, stream):
-        self.assertTrue(stream.getvalue())
-
-    def assertWritten(self, stream, contents):
-        self.assertEquals(stream.buflist, contents)
-
-    def test_configure_logging(self):
-        options, args = get_options([])
-        stream = StringIO.StringIO()
-        handler = printing._configure_logging(stream, options.verbose)
-        logging.info("this should be logged")
-        self.assertNotEmpty(stream)
-
-        stream = StringIO.StringIO()
-        logging.debug("this should not be logged")
-        self.assertEmpty(stream)
-
-        printing._restore_logging(handler)
-
-        stream = StringIO.StringIO()
-        options, args = get_options(['--verbose'])
-        handler = printing._configure_logging(stream, options.verbose)
-        logging.debug("this should be logged")
-        self.assertNotEmpty(stream)
-        printing._restore_logging(handler)
-
     def test_print_options(self):
         options, args = get_options([])
         self.assertTrue(options is not None)
@@ -144,8 +114,7 @@ class  Testprinter(unittest.TestCase):
         regular_output = StringIO.StringIO()
         regular_output.isatty = lambda: tty
         buildbot_output = StringIO.StringIO()
-        printer = printing.Printer(self._port, options, regular_output,
-                                   buildbot_output, configure_logging=True)
+        printer = printing.Printer(self._port, options, regular_output, buildbot_output)
         return printer, regular_output, buildbot_output
 
     def get_result(self, test_name, result_type=test_expectations.PASS, run_time=0):
@@ -350,7 +319,7 @@ class  Testprinter(unittest.TestCase):
                  'failures/expected/crash.html']
         paths, rs, exp = self.get_result_summary(tests, expectations)
 
-        # First, test that we print nothing.
+        # First, test that we print nothing when we shouldn't print anything.
         printer.print_progress(rs, False, paths)
         self.assertEmpty(out)
         self.assertEmpty(err)
@@ -359,55 +328,28 @@ class  Testprinter(unittest.TestCase):
         self.assertEmpty(out)
         self.assertEmpty(err)
 
-        self.times = [1, 2, 12, 13, 14, 23, 33]
-
-        def mock_time():
-            return self.times.pop(0)
-
-        orig_time = time.time
-        try:
-            time.time = mock_time
-
-            # Test printing progress updates to a file.
-            printer, err, out = self.get_printer(['--print', 'one-line-progress'])
-            printer.print_progress(rs, False, paths)
-            printer.print_progress(rs, False, paths)
-            self.assertEmpty(out)
-            self.assertEmpty(err)
-
-            printer.print_progress(rs, False, paths)
-            self.assertEmpty(out)
-            self.assertNotEmpty(err)
-
-            self.reset(err)
-            self.reset(out)
-            printer.print_progress(rs, True, paths)
-            self.assertEmpty(out)
-            self.assertEmpty(err)
-
-            printer.print_progress(rs, True, paths)
-            self.assertEmpty(out)
-            self.assertNotEmpty(err)
-
-            # Now reconfigure the printer to test printing to a TTY instead of a file.
-            self.times = [1, 1.01, 2, 3]
-            printer, err, out = self.get_printer(['--print', 'one-line-progress'], tty=True)
-            printer.print_progress(rs, False, paths)
-            printer.print_progress(rs, False, paths)
-            self.assertEmpty(out)
-            self.assertEmpty(err)
-
-            printer.print_progress(rs, False, paths)
-            self.assertEmpty(out)
-            self.assertNotEmpty(err)
-
-            self.reset(err)
-            self.reset(out)
-            printer.print_progress(rs, True, paths)
-            self.assertEmpty(out)
-            self.assertNotEmpty(err)
-        finally:
-            time.time = orig_time
+        # Now test that we do print things.
+        printer, err, out = self.get_printer(['--print', 'one-line-progress'])
+        printer.print_progress(rs, False, paths)
+        self.assertEmpty(out)
+        self.assertNotEmpty(err)
+
+        printer, err, out = self.get_printer(['--print', 'one-line-progress'])
+        printer.print_progress(rs, True, paths)
+        self.assertEmpty(out)
+        self.assertNotEmpty(err)
+
+        printer, err, out = self.get_printer(['--print', 'one-line-progress'])
+        rs.remaining = 0
+        printer.print_progress(rs, False, paths)
+        self.assertEmpty(out)
+        self.assertNotEmpty(err)
+
+        printer.print_progress(rs, True, paths)
+        self.assertEmpty(out)
+        self.assertNotEmpty(err)
+
+
 
     def test_write_nothing(self):
         printer, err, out = self.get_printer(['--print', 'nothing'])
index ce1c7e90385324cb56ddd86091f481f637616d9f..db15eb38ab7f19850ae6f899425f31eaa75c4d81 100644 (file)
@@ -62,7 +62,7 @@ class PerfTestsRunner(object):
             self._host = Host()
             self._port = self._host.port_factory.get(self._options.platform, self._options)
         self._host._initialize_scm()
-        self._printer = printing.Printer(self._port, self._options, regular_output, buildbot_output, configure_logging=False)
+        self._printer = printing.Printer(self._port, self._options, regular_output, buildbot_output)
         self._webkit_base_dir_len = len(self._port.webkit_base())
         self._base_path = self._port.perf_tests_dir()
         self._results = {}
index 1a287a7cf6ada3ca8b9bab646428748b0294e4e6..c5891d401361fec91c7103507219eca81d1012d7 100755 (executable)
@@ -182,7 +182,8 @@ max 1120
                 TestDriverWithStartCount.start_count += 1
 
         buildbot_output = StringIO.StringIO()
-        runner = self.create_runner(buildbot_output, args=["--pause-before-testing"], driver_class=TestDriverWithStartCount)
+        regular_output = StringIO.StringIO()
+        runner = self.create_runner(buildbot_output, args=["--pause-before-testing"], regular_output=regular_output, driver_class=TestDriverWithStartCount)
 
         dirname = runner._base_path + '/inspector/'
         tests = [dirname + 'pass.html']
@@ -193,9 +194,9 @@ max 1120
             unexpected_result_count = runner._run_tests_set(tests, runner._port)
             self.assertEqual(TestDriverWithStartCount.start_count, 1)
         finally:
-            _, stderr, logs = output.restore_output()
+            _, stderr, _ = output.restore_output()
             self.assertEqual(stderr, "Ready to run test?\n")
-            self.assertTrue("Running inspector/pass.html (1 of 1)" in logs)
+            self.assertTrue("Running inspector/pass.html (1 of 1)" in regular_output.getvalue())
 
     def test_run_test_set_for_parser_tests(self):
         buildbot_output = StringIO.StringIO()