Move server logging to rebaseline-o-matic.

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

 # Copyright (c) 2010 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
 # met:
 #
 #     * Redistributions of source code must retain the above copyright
 # notice, this list of conditions and the following disclaimer.
 #     * Redistributions in binary form must reproduce the above
 # copyright notice, this list of conditions and the following disclaimer
@@ skipping 640 matching lines @@
     MAX_LINES_TO_REBASELINE = 200
 
     SECONDS_BEFORE_GIVING_UP = 300
 
     def __init__(self):
         super(AutoRebaseline, self).__init__(options=[
             # FIXME: Remove this option.
             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({
                 "builder": result.builder_name(),
                 "revision": result.blink_revision(),
             })
         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()
 
         tests = set()
         revision = None
         author = None
         bugs = set()
         has_any_needs_rebaseline_lines = False
 
         for line in tool.scm().blame(expectations_file_path).split("\n"):
             comment_index = line.find("#")
             if comment_index == -1:
                 comment_index = len(line)
             line_without_comments = re.sub(r"\s+", " ", line[:comment_index].strip())
 
             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)
 
             commit_hash = parsed_line.group(1)
             svn_revision = tool.scm().svn_revision_from_git_commit(commit_hash)
 
             test = parsed_line.group(3)
             if print_revisions:
                 _log.info("%s is waiting for r%s" % (test, svn_revision))
@@ skipping 50 matching lines @@
                 lines_to_remove[test].append(builder_name)
                 test_prefix_list[test][builder_name] = BASELINE_SUFFIX_LIST
 
         return test_prefix_list, lines_to_remove
 
     def _run_git_cl_command(self, options, command):
         subprocess_command = ['git', 'cl'] + command
         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
         return True
 
     # FIXME: Move this somewhere more general.
     def tree_status(self):
         blink_tree_status_url = "http://blink-status.appspot.com/status"
         status = urllib2.urlopen(blink_tree_status_url).read().lower()
         if status.find('closed') != -1 or status == "0":
             return 'closed'
         elif status.find('open') != -1 or status == "1":
             return 'open'
         return 'unknown'
 
     def execute(self, options, args, tool):
         if tool.scm().executable_name == "svn":
             _log.error("Auto rebaseline only works with a git checkout.")
             return
 
         if tool.scm().has_working_directory_changes():
             _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)
             for item in revision_data:
                 _log.info("%s: r%s" % (item["builder"], item["revision"]))
 
         if not tests:
             _log.debug('No tests to rebaseline.')
             return
 
@@ skipping 36 matching lines @@
             tool.scm().checkout_branch(old_branch_name)
             tool.scm().delete_branch(self.AUTO_REBASELINE_BRANCH_NAME)
 
 
 class RebaselineOMatic(AbstractDeclarativeCommand):
     name = "rebaseline-o-matic"
     help_text = "Calls webkit-patch auto-rebaseline in a loop."
     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_logging_command(self, command):

[Dirk Pranke, 2014/06/09 19:30:31]

nit: I might call this "run_logged_command" instead, since you're running the
command and doing something with the logging. "run_logging_command" sounds to me
like you're running a command that has something to do w/ logging, like turning
it on or something.

I might also separate out the running of the command from the uploading of the
logs. e.g.:

out, err = self._run_command()
self._upload_logs(out)
self._upload_logs(err)

or some such.

[ojan, 2014/06/09 21:15:09]

Done.
I want it to upload incrementally as the command is going. Not sure how to do
that with this suggestion.

+        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_logging_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_logging_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)