Move server logging to rebaseline-o-matic.

It didn't really make sense to be part of auto-rebaseline except
for the special noneedsrebaseline entries, which I've decided are
not really useful anyways. More importantly, move it up means
that we actually log everything to the server, including the outer
git pull call and it means that we log asynchronously to the
auto-rebaseline command, which should make it a lot faster.

Also, make the git cl upload logging log stderr as well.

BUG=382248

Review URL: https://codereview.chromium.org/327443002

git-svn-id: svn://svn.chromium.org/blink/trunk@175828 bbb929c8-8fbe-4397-9dbb-9b2b20218538

third_party/WebKit/Tools/RebaselineLogServer/main.py

@@ -47,6 +47,8 @@ from google.appengine.ext.db import BadRequestError
 
 LOG_PARAM = "log"
 NEW_ENTRY_PARAM = "newentry"
+# FIXME: no_needs_rebaseline is never used anymore. Remove support for it.
+# Instead, add UI to logs.html to collapse short entries.
 NO_NEEDS_REBASELINE_PARAM = "noneedsrebaseline"
 NUM_LOGS_PARAM = "numlogs"
 BEFORE_PARAM = "before"
@@ -74,6 +76,7 @@ class UpdateLog(webapp2.RequestHandler):
         # avoid cluttering the log with useless empty posts. It just updates the
         # date of the entry so that users can see that rebaseline-o-matic is still
         # running.
+        # FIXME: no_needs_rebaseline is never used anymore. Remove support for it.
         no_needs_rebaseline = self.request.POST.get(NO_NEEDS_REBASELINE_PARAM) == "on"
 
         out = "Wrote new log entry."

third_party/WebKit/Tools/Scripts/webkitpy/tool/commands/rebaseline.py

@@ -659,65 +659,12 @@ class AutoRebaseline(AbstractParallelRebaselineCommand):
             self.no_optimize_option,
             # FIXME: Remove this option.
             self.results_directory_option,
-            optparse.make_option("--log-server", help="Server to send logs to.")
             ])
 
-    def _log_to_server(self, log_server, query):
-        if not log_server:
-            return
-        urllib2.urlopen("http://" + log_server + "/updatelog", data=urllib.urlencode(query))
-
-    # Logs when there are no NeedsRebaseline lines in TestExpectations.
-    # These entries overwrite the existing log entry if the existing
-    # entry is also a noneedsrebaseline entry. This is special cased
-    # so that the log doesn't get bloated with entries like this
-    # when there are no tests that needs rebaselining.
-    def _log_no_needs_rebaseline_lines(self, log_server):
-        self._log_to_server(log_server, {
-            "noneedsrebaseline": "on",
-        })
-
-    # Uploaded log entries append to the existing entry unless the
-    # newentry flag is set. In that case it starts a new entry to
-    # start appending to. So, we need to call this on any fresh run
-    # that is going to end up logging stuff (i.e. any run that isn't
-    # a noneedsrebaseline run).
-    def _start_new_log_entry(self, log_server):
-        self._log_to_server(log_server, {
-            "log": "",
-            "newentry": "on",
-        })
-
-    def _configure_logging(self, log_server):
-        if not log_server:
-            return
-
-        def _log_alias(query):
-            self._log_to_server(log_server, query)
-
-        class LogHandler(logging.Handler):
-            def __init__(self):
-                logging.Handler.__init__(self)
-                self._records = []
-
-            # Since this does not have the newentry flag, it will append
-            # to the most recent log entry (i.e. the one created by
-            # _start_new_log_entry.
-            def emit(self, record):
-                _log_alias({
-                    "log": record.getMessage(),
-                })
-
-        handler = LogHandler()
-        _log.setLevel(logging.DEBUG)
-        handler.setLevel(logging.DEBUG)
-        _log.addHandler(handler)
-
-    def bot_revision_data(self, log_server):
+    def bot_revision_data(self):
         revisions = []
         for result in self.builder_data().values():
             if result.run_was_interrupted():
-                self._start_new_log_entry(log_server)
                 _log.error("Can't rebaseline because the latest run on %s exited early." % result.builder_name())
                 return []
             revisions.append({
@@ -726,7 +673,7 @@ class AutoRebaseline(AbstractParallelRebaselineCommand):
             })
         return revisions
 
-    def tests_to_rebaseline(self, tool, min_revision, print_revisions, log_server):
+    def tests_to_rebaseline(self, tool, min_revision, print_revisions):
         port = tool.port_factory.get()
         expectations_file_path = port.path_to_generic_test_expectations_file()
 
@@ -745,8 +692,6 @@ class AutoRebaseline(AbstractParallelRebaselineCommand):
             if "NeedsRebaseline" not in line_without_comments:
                 continue
 
-            if not has_any_needs_rebaseline_lines:
-                self._start_new_log_entry(log_server)
             has_any_needs_rebaseline_lines = True
 
             parsed_line = re.match("^(\S*)[^(]*\((\S*).*?([^ ]*)\ \[[^[]*$", line_without_comments)
@@ -817,17 +762,22 @@ class AutoRebaseline(AbstractParallelRebaselineCommand):
         if options.verbose:
             subprocess_command.append('--verbose')
 
-        process = self._tool.executive.popen(subprocess_command, stdout=self._tool.executive.PIPE)
+        process = self._tool.executive.popen(subprocess_command, stdout=self._tool.executive.PIPE, stderr=self._tool.executive.PIPE)
         last_output_time = time.time()
 
         # git cl sometimes completely hangs. Bail if we haven't gotten any output to stdout/stderr in a while.
         while process.poll() == None and time.time() < last_output_time + self.SECONDS_BEFORE_GIVING_UP:
-            # FIXME: Also log stderr.
+            # FIXME: This isn't awesome. It may improperly interleave stdout and stderr?
             out = process.stdout.readline().rstrip('\n')
             if out:
                 last_output_time = time.time()
                 _log.info(out)
 
+            err = process.stdout.readline().rstrip('\n')
+            if err:
+                last_output_time = time.time()
+                _log.error(err)
+
         if process.poll() == None:
             _log.error('Command hung: %s' % subprocess_command)
             return False
@@ -852,18 +802,12 @@ class AutoRebaseline(AbstractParallelRebaselineCommand):
             _log.error("Cannot proceed with working directory changes. Clean working directory first.")
             return
 
-        self._configure_logging(options.log_server)
-
-        revision_data = self.bot_revision_data(options.log_server)
+        revision_data = self.bot_revision_data()
         if not revision_data:
             return
 
         min_revision = int(min([item["revision"] for item in revision_data]))
-        tests, revision, author, bugs, has_any_needs_rebaseline_lines = self.tests_to_rebaseline(tool, min_revision, print_revisions=options.verbose, log_server=options.log_server)
-
-        if not has_any_needs_rebaseline_lines:
-            self._log_no_needs_rebaseline_lines(options.log_server)
-            return
+        tests, revision, author, bugs, has_any_needs_rebaseline_lines = self.tests_to_rebaseline(tool, min_revision, print_revisions=options.verbose)
 
         if options.verbose:
             _log.info("Min revision across all bots is %s." % min_revision)
@@ -920,20 +864,46 @@ class RebaselineOMatic(AbstractDeclarativeCommand):
     show_in_main_help = True
 
     SLEEP_TIME_IN_SECONDS = 30
+    LOG_SERVER = 'blinkrebaseline.appspot.com'
+
+    # Uploaded log entries append to the existing entry unless the
+    # newentry flag is set. In that case it starts a new entry to
+    # start appending to.
+    def _log_to_server(self, log='', is_new_entry=False):
+        query = {
+            'log': log,
+        }
+        if is_new_entry:
+            query['newentry'] = 'on'
+        urllib2.urlopen("http://" + self.LOG_SERVER + "/updatelog", data=urllib.urlencode(query))
+
+    def _run_logged_command(self, command):
+        process = self._tool.executive.popen(command, stdout=self._tool.executive.PIPE, stderr=self._tool.executive.PIPE)
+        while process.poll() == None:
+            # FIXME: This should probably batch up lines if they're available and log to the server once.
+            out = process.stdout.readline()
+            if out:
+                self._log_to_server(out)
+
+            err = process.stderr.readline()
+            if err:
+                self._log_to_server(err)
+
+    def _do_one_rebaseline(self, verbose):
+        try:
+            old_branch_name = self._tool.scm().current_branch()
+            self._log_to_server(is_new_entry=True)
+            self._run_logged_command(['git', 'pull'])
+            rebaseline_command = [self._tool.filesystem.join(self._tool.scm().checkout_root, 'Tools', 'Scripts', 'webkit-patch'), 'auto-rebaseline']
+            if verbose:
+                rebaseline_command.append('--verbose')
+            self._run_logged_command(rebaseline_command)
+        except:
+            traceback.print_exc(file=sys.stderr)
+            # Sometimes git crashes and leaves us on a detached head.
+            self._tool.scm().checkout_branch(old_branch_name)
 
     def execute(self, options, args, tool):
         while True:
-            try:
-                old_branch_name = tool.scm().current_branch()
-                tool.executive.run_command(['git', 'pull'])
-                rebaseline_command = [tool.filesystem.join(tool.scm().checkout_root, 'Tools', 'Scripts', 'webkit-patch'), 'auto-rebaseline', '--log-server', 'blinkrebaseline.appspot.com']
-                if options.verbose:
-                    rebaseline_command.append('--verbose')
-                # Use call instead of run_command so that stdout doesn't get swallowed.
-                tool.executive.call(rebaseline_command)
-            except:
-                traceback.print_exc(file=sys.stderr)
-                # Sometimes git crashes and leaves us on a detached head.
-                tool.scm().checkout_branch(old_branch_name)
-
+            self._do_one_rebaseline(options.verbose)
             time.sleep(self.SLEEP_TIME_IN_SECONDS)

third_party/WebKit/Tools/Scripts/webkitpy/tool/commands/rebaseline_unittest.py

@@ -873,8 +873,8 @@ class TestAutoRebaseline(_BaseTestCase):
 
     def setUp(self):
         super(TestAutoRebaseline, self).setUp()
-        self.command.latest_revision_processed_on_all_bots = lambda log_server: 9000
-        self.command.bot_revision_data = lambda log_server: [{"builder": "Mock builder", "revision": "9000"}]
+        self.command.latest_revision_processed_on_all_bots = lambda: 9000
+        self.command.bot_revision_data = lambda: [{"builder": "Mock builder", "revision": "9000"}]
 
     def test_release_builders(self):
         old_exact_matches = builders._exact_matches
@@ -902,7 +902,7 @@ class TestAutoRebaseline(_BaseTestCase):
         self.tool.scm().blame = blame
 
         min_revision = 9000
-        self.assertEqual(self.command.tests_to_rebaseline(self.tool, min_revision, print_revisions=False, log_server=None), (
+        self.assertEqual(self.command.tests_to_rebaseline(self.tool, min_revision, print_revisions=False), (
                 set(['path/to/rebaseline-without-bug-number.html', 'path/to/rebaseline-with-modifiers.html', 'path/to/rebaseline-without-modifiers.html']),
                 5678,
                 'foobarbaz1@chromium.org',
@@ -922,7 +922,7 @@ class TestAutoRebaseline(_BaseTestCase):
             expected_list_of_tests.append("path/to/rebaseline-%s.html" % i)
 
         min_revision = 9000
-        self.assertEqual(self.command.tests_to_rebaseline(self.tool, min_revision, print_revisions=False, log_server=None), (
+        self.assertEqual(self.command.tests_to_rebaseline(self.tool, min_revision, print_revisions=False), (
                 set(expected_list_of_tests),
                 5678,
                 'foobarbaz1@chromium.org',
@@ -958,7 +958,7 @@ TBR=foo@chromium.org
 """
         self.tool.scm().blame = blame
 
-        self.command.execute(MockOptions(optimize=True, verbose=False, move_overwritten_baselines=False, results_directory=False, log_server=None), [], self.tool)
+        self.command.execute(MockOptions(optimize=True, verbose=False, move_overwritten_baselines=False, results_directory=False), [], self.tool)
         self.assertEqual(self.tool.executive.calls, [])
 
     def test_execute(self):
@@ -1030,12 +1030,12 @@ crbug.com/24182 path/to/locally-changed-lined.html [ NeedsRebaseline ]
             }
 
             self.command.tree_status = lambda: 'closed'
-            self.command.execute(MockOptions(optimize=True, verbose=False, move_overwritten_baselines=False, results_directory=False, log_server=None), [], self.tool)
+            self.command.execute(MockOptions(optimize=True, verbose=False, move_overwritten_baselines=False, results_directory=False), [], self.tool)
             self.assertEqual(self.tool.executive.calls, [])
 
             self.command.tree_status = lambda: 'open'
             self.tool.executive.calls = []
-            self.command.execute(MockOptions(optimize=True, verbose=False, move_overwritten_baselines=False, results_directory=False, log_server=None), [], self.tool)
+            self.command.execute(MockOptions(optimize=True, verbose=False, move_overwritten_baselines=False, results_directory=False), [], self.tool)
 
             self.assertEqual(self.tool.executive.calls, [
                 [
@@ -1118,7 +1118,7 @@ Bug(foo) fast/dom/prototype-taco.html [ NeedsRebaseline ]
             self.command.SECONDS_BEFORE_GIVING_UP = 0
             self.command.tree_status = lambda: 'open'
             self.tool.executive.calls = []
-            self.command.execute(MockOptions(optimize=True, verbose=False, move_overwritten_baselines=False, results_directory=False, log_server=None), [], self.tool)
+            self.command.execute(MockOptions(optimize=True, verbose=False, move_overwritten_baselines=False, results_directory=False), [], self.tool)
 
             self.assertEqual(self.tool.executive.calls, [
                 [
@@ -1179,7 +1179,7 @@ Bug(foo) fast/dom/prototype-taco.html [ NeedsRebaseline ]
             }
 
             self.command.tree_status = lambda: 'open'
-            self.command.execute(MockOptions(optimize=True, verbose=False, move_overwritten_baselines=False, results_directory=False, log_server=None), [], self.tool)
+            self.command.execute(MockOptions(optimize=True, verbose=False, move_overwritten_baselines=False, results_directory=False), [], self.tool)
             self.assertEqual(self.tool.executive.calls, [
                 [['echo', 'optimize-baselines', '--no-modify-scm', '--suffixes', '', 'fast/dom/prototype-taco.html']],
                 ['git', 'cl', 'upload', '-f'],
@@ -1194,3 +1194,44 @@ Bug(foo) [ Linux Win ] fast/dom/prototype-taco.html [ NeedsRebaseline ]
 """)
         finally:
             builders._exact_matches = old_exact_matches
+
+
+class TestRebaselineOMatic(_BaseTestCase):
+    command_constructor = RebaselineOMatic
+
+    def setUp(self):
+        super(TestRebaselineOMatic, self).setUp()
+        self._logs = []
+
+    def _mock_log_to_server(self, log='', is_new_entry=False):
+        self._logs.append({'log': log, 'newentry': is_new_entry})
+
+    def test_run_logged_command(self):
+        self.command._log_to_server = self._mock_log_to_server
+        self.command._run_logged_command(['echo', 'foo'])
+        self.assertEqual(self.tool.executive.calls, [['echo', 'foo']])
+        self.assertEqual(self._logs, [{'log': 'MOCK STDOUT\n', 'newentry': False}])
+
+    def test_do_one_rebaseline(self):
+        self.command._log_to_server = self._mock_log_to_server
+        self.command._do_one_rebaseline(verbose=False)
+        self.assertEqual(self.tool.executive.calls, [
+            ['git', 'pull'],
+            ['/mock-checkout/third_party/WebKit/Tools/Scripts/webkit-patch', 'auto-rebaseline'],
+        ])
+        self.assertEqual(self._logs, [
+            {'log': '', 'newentry': True},
+            {'log': 'MOCK STDOUT\n', 'newentry': False},
+        ])
+
+    def test_do_one_rebaseline_verbose(self):
+        self.command._log_to_server = self._mock_log_to_server
+        self.command._do_one_rebaseline(verbose=True)
+        self.assertEqual(self.tool.executive.calls, [
+            ['git', 'pull'],
+            ['/mock-checkout/third_party/WebKit/Tools/Scripts/webkit-patch', 'auto-rebaseline', '--verbose'],
+        ])
+        self.assertEqual(self._logs, [
+            {'log': '', 'newentry': True},
+            {'log': 'MOCK STDOUT\n', 'newentry': False},
+        ])