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

Reviewed by Ojan Vafai.

Re-land r112014 with a build fix for Python 2.6 compatibility.

* Scripts/webkitpy/layout_tests/controllers/manager_unittest.py:
(ManagerTest.test_http_locking):
* Scripts/webkitpy/layout_tests/controllers/manager_worker_broker.py:
(AbstractWorker.run):
* Scripts/webkitpy/layout_tests/controllers/worker.py:
(Worker.__init__):
(Worker._set_up_logging):
(Worker):
(Worker._set_up_host_and_port):
(Worker.run):
(Worker.cleanup):
* Scripts/webkitpy/layout_tests/controllers/worker_unittest.py:
(WorkerTest.test_default_platform_in_worker):
* Scripts/webkitpy/layout_tests/run_webkit_tests.py:
(run):
(main):
* Scripts/webkitpy/layout_tests/views/metered_stream.py:
(MeteredStream):
(MeteredStream.implements):
(MeteredStream._erasure):
(MeteredStream._ensure_newline):
(MeteredStream.__init__):
(MeteredStream.__del__):
(MeteredStream.cleanup):
(MeteredStream.write_throttled_update):
(MeteredStream.write_update):
(MeteredStream.write):
(MeteredStream.writeln):
(MeteredStream._erase_last_partial_line):
(_LogHandler):
(_LogHandler.__init__):
(_LogHandler.emit):
* Scripts/webkitpy/layout_tests/views/metered_stream_unittest.py:
(RegularTest):
(RegularTest.setUp):
(RegularTest.tearDown):
(RegularTest.time_fn):
(RegularTest.test_logging_not_included):
(RegularTest._basic):
(RegularTest.test_basic):
(RegularTest._log_after_update):
(RegularTest.test_log_after_update):
(TtyTest):
(TtyTest.test_basic):
(TtyTest.test_log_after_update):
(VerboseTest):
(VerboseTest.test_basic):
(VerboseTest.test_log_after_update):
* Scripts/webkitpy/layout_tests/views/printing.py:
(parse_print_options):
(Printer.__init__):
(Printer.cleanup):
(Printer.print_progress):
(Printer.print_update):
(Printer._write):
* Scripts/webkitpy/layout_tests/views/printing_unittest.py:
(Testprinter.get_printer):
(Testprinter.test_print_progress):
* Scripts/webkitpy/performance_tests/perftestsrunner.py:
(PerfTestsRunner.__init__):
* Scripts/webkitpy/performance_tests/perftestsrunner_unittest.py:
(test_run_test_pause_before_testing):

git-svn-id: https://svn.webkit.org/repository/webkit/trunk@112140 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 3983bc1..5c8f01e 100644 (file)
@@ -1,3 +1,75 @@
+2012-03-26  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.
+
+        Re-land r112014 with a build fix for Python 2.6 compatibility.
+
+        * Scripts/webkitpy/layout_tests/controllers/manager_unittest.py:
+        (ManagerTest.test_http_locking):
+        * Scripts/webkitpy/layout_tests/controllers/manager_worker_broker.py:
+        (AbstractWorker.run):
+        * Scripts/webkitpy/layout_tests/controllers/worker.py:
+        (Worker.__init__):
+        (Worker._set_up_logging):
+        (Worker):
+        (Worker._set_up_host_and_port):
+        (Worker.run):
+        (Worker.cleanup):
+        * Scripts/webkitpy/layout_tests/controllers/worker_unittest.py:
+        (WorkerTest.test_default_platform_in_worker):
+        * Scripts/webkitpy/layout_tests/run_webkit_tests.py:
+        (run):
+        (main):
+        * Scripts/webkitpy/layout_tests/views/metered_stream.py:
+        (MeteredStream):
+        (MeteredStream.implements):
+        (MeteredStream._erasure):
+        (MeteredStream._ensure_newline):
+        (MeteredStream.__init__):
+        (MeteredStream.__del__):
+        (MeteredStream.cleanup):
+        (MeteredStream.write_throttled_update):
+        (MeteredStream.write_update):
+        (MeteredStream.write):
+        (MeteredStream.writeln):
+        (MeteredStream._erase_last_partial_line):
+        (_LogHandler):
+        (_LogHandler.__init__):
+        (_LogHandler.emit):
+        * Scripts/webkitpy/layout_tests/views/metered_stream_unittest.py:
+        (RegularTest):
+        (RegularTest.setUp):
+        (RegularTest.tearDown):
+        (RegularTest.time_fn):
+        (RegularTest.test_logging_not_included):
+        (RegularTest._basic):
+        (RegularTest.test_basic):
+        (RegularTest._log_after_update):
+        (RegularTest.test_log_after_update):
+        (TtyTest):
+        (TtyTest.test_basic):
+        (TtyTest.test_log_after_update):
+        (VerboseTest):
+        (VerboseTest.test_basic):
+        (VerboseTest.test_log_after_update):
+        * Scripts/webkitpy/layout_tests/views/printing.py:
+        (parse_print_options):
+        (Printer.__init__):
+        (Printer.cleanup):
+        (Printer.print_progress):
+        (Printer.print_update):
+        (Printer._write):
+        * Scripts/webkitpy/layout_tests/views/printing_unittest.py:
+        (Testprinter.get_printer):
+        (Testprinter.test_print_progress):
+        * Scripts/webkitpy/performance_tests/perftestsrunner.py:
+        (PerfTestsRunner.__init__):
+        * Scripts/webkitpy/performance_tests/perftestsrunner_unittest.py:
+        (test_run_test_pause_before_testing):
+
 2012-03-26  Raphael Kubo da Costa  <rakuco@FreeBSD.org>
 
         [jhbuild] Revert $MAKE environment hack introduced in r101929.
index 8bc6aff..3f58e7b 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 70c43a6..08c059a 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 22c0a5f..b0588ab 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,59 @@ 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:
+            # log handlers don't have names until python 2.7.
+            if getattr(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 +171,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 6fd5202..ebb4e7a 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 6b0e367..c28b911 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 b5c233b..0d5e66c 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 359cfcf..4b37646 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 750c48d..3df2956 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 6899d2c..8777fd8 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 ce1c7e9..db15eb3 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 1a287a7..c5891d4 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()