Bug 1143727 - talos subclasses mozprocess and write to a log file - it doesn't need to. r=jmaher
authorJulien Pagès <j.parkouss@gmail.com>
Fri, 14 Aug 2015 17:25:00 +0200
changeset 993 55711f8341c5
parent 992 7fe8298e0aa2
child 994 869a812af5d2
push id683
push userj.parkouss@gmail.com
push dateFri, 14 Aug 2015 15:35:28 +0000
reviewersjmaher
bugs1143727
Bug 1143727 - talos subclasses mozprocess and write to a log file - it doesn't need to. r=jmaher
talos/TalosProcess.py
talos/cmanager.py
talos/config.py
talos/results.py
talos/run_tests.py
talos/talos_process.py
talos/talosconfig.py
talos/ttest.py
deleted file mode 100644
--- a/talos/TalosProcess.py
+++ /dev/null
@@ -1,114 +0,0 @@
-# This Source Code Form is subject to the terms of the Mozilla Public
-# License, v. 2.0. If a copy of the MPL was not distributed with this file,
-# You can obtain one at http://mozilla.org/MPL/2.0/.
-
-from mozprocess import ProcessHandler
-from threading import Thread
-import os
-import time
-import logging
-
-from utils import TalosError
-
-
-class TalosProcess(ProcessHandler):
-    """
-    Process handler for running peptests
-
-    After the browser prints __endTimestamp, we give it wait_for_quit_timeout
-    seconds to quit and kill it if it's still alive at that point.
-    """
-    def __init__(self, cmd, args=None, cwd=None,
-                 env=None,
-                 ignore_children=False,
-                 logfile=None,
-                 suppress_javascript_errors=False,
-                 wait_for_quit_timeout=5,
-                 **kwargs):
-
-        self.firstTime = int(time.time()) * 1000
-        self.logfile = logfile
-        self.results_file = None
-        self.suppress_javascript_errors = suppress_javascript_errors
-        self.wait_for_quit_timeout = wait_for_quit_timeout
-        if env is None:
-            env = os.environ.copy()
-
-        ProcessHandler.__init__(self, cmd, args=args, cwd=cwd, env=env,
-                                ignore_children=ignore_children,
-                                processOutputLine=self.processOutputLine,
-                                **kwargs)
-
-    def logToFile(self, msg):
-        if not self.logfile:
-            return
-
-        if not self.results_file:
-            self.results_file = open(self.logfile, 'w')
-
-        self.results_file.write(msg)
-
-    def closeLogFile(self):
-        if self.results_file:
-            self.results_file.close()
-
-    def waitForQuit(self):
-        for i in range(1, self.wait_for_quit_timeout):
-            if self.proc.returncode is not None:
-                self.logToFile(
-                    "__startBeforeLaunchTimestamp%d"
-                    "__endBeforeLaunchTimestamp\n"
-                    % self.firstTime
-                )
-                self.logToFile(
-                    "__startAfterTerminationTimestamp%d"
-                    "__endAfterTerminationTimestamp\n"
-                    % (int(time.time()) * 1000)
-                )
-                self.closeLogFile()
-                return
-            time.sleep(1)
-
-        logging.info(
-            "Browser shutdown timed out after {0} seconds, terminating"
-            " process.".format(self.wait_for_quit_timeout)
-        )
-        self.proc.kill()
-        self.logToFile(
-            "__startBeforeLaunchTimestamp%d__endBeforeLaunchTimestamp\n"
-            % self.firstTime
-        )
-        self.logToFile(
-            "__startAfterTerminationTimestamp%d__endAfterTerminationTimestamp"
-            "\n"
-            % (int(time.time()) * 1000)
-        )
-        self.closeLogFile()
-
-    def onTimeout(self):
-        """
-        When we timeout, dictate this in the log file.
-        """
-        if os.path.isfile(self.logfile):
-            os.chmod(self.logfile, 0777)
-        self.logToFile("\n__FAILbrowser frozen__FAIL\n")
-        self.closeLogFile()
-        raise TalosError("timeout")
-
-    def processOutputLine(self, line):
-        """
-        Callback called on each line of output
-        Search for signs of error
-        """
-        if line.find('__endTimestamp') != -1:
-            thread = Thread(target=self.waitForQuit)
-            thread.setDaemon(True)  # don't hang on quit
-            thread.start()
-
-        if self.suppress_javascript_errors and \
-                (line.startswith('JavaScript error:') or
-                 line.startswith('JavaScript warning:')):
-            return
-
-        print line
-        self.logToFile(line + "\n")
--- a/talos/cmanager.py
+++ b/talos/cmanager.py
@@ -46,37 +46,42 @@ else:  # mac
         as DefaultCounterManager
 
 
 class CounterManagement(object):
     def __init__(self, process, counters, resolution):
         """
         Public interface to manage counters.
 
-        On creation, automatically spawn a thread to collect counters.
+        On creation, create a thread to collect counters. Call :meth:`start`
+        to start collecting counters with that thread.
+
         Be sure to call :meth:`stop` to stop the thread.
         """
         assert counters
-        self._manager = DefaultCounterManager(process, counters)
         self._raw_counters = counters
+        self._process = process
         self._counter_results = \
             dict([(counter, []) for counter in self._raw_counters])
 
         self._resolution = resolution
         self._stop = threading.Event()
         self._thread = threading.Thread(target=self._collect)
-        self._thread.start()
 
     def _collect(self):
+        manager = DefaultCounterManager(self._process, self._raw_counters)
         while not self._stop.wait(self._resolution):
             # Get the output from all the possible counters
             for count_type in self._raw_counters:
-                val = self._manager.getCounterValue(count_type)
+                val = manager.getCounterValue(count_type)
                 if val:
                     self._counter_results[count_type].append(val)
 
+    def start(self):
+        self._thread.start()
+
     def stop(self):
         self._stop.set()
         self._thread.join()
 
     def results(self):
         assert not self._thread.is_alive()
         return self._counter_results
--- a/talos/config.py
+++ b/talos/config.py
@@ -73,19 +73,16 @@ def parse_args(argv=None):
     add_arg('--fast', action='store_true',
             help="Run tp tests as tp_fast")
     add_arg('--symbolsPath', dest='symbols_path',
             help="Path to the symbols for the build we are testing")
     add_arg('--xperf_path',
             help="Path to windows performance tool xperf.exe")
     add_arg('--test_timeout', type=int, default=1200,
             help="Time to wait for the browser to output to the log file")
-    add_arg('--logFile', dest='browser_log',
-            default=os.path.abspath('browser_output.txt'),
-            help="Local log file to store the output from the browser in")
     add_arg('--errorFile', dest='error_filename',
             default=os.path.abspath('browser_failures.txt'),
             help="Filename to store the errors found during the test."
                  " Currently used for xperf only.")
     add_arg('--noShutdown', dest='shutdown', action='store_true',
             help="Record time browser takes to shutdown after testing")
     add_arg('--setPref', action='append', default=[], dest="extraPrefs",
             metavar="PREF=VALUE",
@@ -517,18 +514,17 @@ def tests(config):
     for test_name in activeTests:
         test_class = test_dict[test_name]
         tests.append(get_test(config, global_overrides, counters,
                               test_class()))
     config['tests'] = tests
 
 
 def get_browser_config(config):
-    required = ('preferences', 'extensions',
-                'browser_path', 'browser_log', 'browser_wait',
+    required = ('preferences', 'extensions', 'browser_path', 'browser_wait',
                 'extra_args', 'buildid', 'env', 'init_url')
     optional = {'bcontroller_config': '${talos}/bcontroller.json',
                 'branch_name': '',
                 'child_process': 'plugin-container',
                 'develop': False,
                 'e10s': False,
                 'process': '',
                 'repository': None,
--- a/talos/results.py
+++ b/talos/results.py
@@ -110,28 +110,23 @@ class TestResults(object):
 
     def add(self, results, counter_results=None):
         """
         accumulate one cycle of results
         - results : TalosResults instance or path to browser log
         - counter_results : counters accumulated for this cycle
         """
 
-        if isinstance(results, basestring):
-            # ensure the browser log exists
-            if not os.path.isfile(results):
-                raise utils.TalosError("no output from browser [%s]" % results)
-
-            # convert to a results class via parsing the browser log
-            browserLog = BrowserLogResults(
-                filename=results,
-                counter_results=counter_results,
-                global_counters=self.global_counters
-            )
-            results = browserLog.results()
+        # convert to a results class via parsing the browser log
+        browserLog = BrowserLogResults(
+            results,
+            counter_results=counter_results,
+            global_counters=self.global_counters
+        )
+        results = browserLog.results()
 
         self.using_xperf = browserLog.using_xperf
         # ensure the results format matches previous results
         if self.results:
             if not results.format == self.results[0].format:
                 raise utils.TalosError("Conflicting formats for results")
         else:
             self.format = results.format
@@ -326,38 +321,25 @@ class BrowserLogResults(object):
     # classes for results types
     classes = {'tsformat': TsResults,
                'tpformat': PageloaderResults}
 
     # If we are using xperf, we do not upload the regular results, only
     # xperf counters
     using_xperf = False
 
-    def __init__(self, filename=None, results_raw=None, counter_results=None,
+    def __init__(self, results_raw, counter_results=None,
                  global_counters=None):
         """
         - shutdown : whether to record shutdown results or not
         """
 
         self.counter_results = counter_results
         self.global_counters = global_counters
 
-        if not (results_raw or filename):
-            raise utils.TalosError("Must specify filename or results_raw")
-
-        self.filename = filename
-        if results_raw is None:
-            # read the file
-
-            if not os.path.isfile(filename):
-                raise utils.TalosError("File '%s' does not exist" % filename)
-
-            with open(filename, 'r') as f:
-                results_raw = f.read()
-
         self.results_raw = results_raw
 
         # parse the results
         try:
             match = self.RESULTS_REGEX_FAIL.search(self.results_raw)
             if match:
                 self.error(match.group(1))
                 raise utils.TalosError(match.group(1))
@@ -368,18 +350,16 @@ class BrowserLogResults(object):
             # information
             raise  # reraise failing exception
 
         # accumulate counter results
         self.counters(self.counter_results, self.global_counters)
 
     def error(self, message):
         """raise a TalosError for bad parsing of the browser log"""
-        if self.filename:
-            message += ' [%s]' % self.filename
         raise utils.TalosError(message)
 
     def parse(self):
         position = -1
 
         # parse the report
         for format, tokens in self.report_tokens:
             report, position = self.get_single_token(*tokens)
--- a/talos/run_tests.py
+++ b/talos/run_tests.py
@@ -213,17 +213,16 @@ def run_tests(config, browser_config):
         if httpd:
             httpd.start()
 
     # run the tests
     timer = utils.Timer()
     utils.stamped_msg(title, "Started")
     for test in tests:
         testname = test['name']
-        test['browser_log'] = browser_config['browser_log']
         utils.stamped_msg("Running test " + testname, "Started")
 
         mozfile.remove('logcat.log')
 
         try:
             mytest = TTest()
             if mytest:
                 talos_results.add(mytest.runTest(browser_config, test))
new file mode 100644
--- /dev/null
+++ b/talos/talos_process.py
@@ -0,0 +1,87 @@
+# This Source Code Form is subject to the terms of the Mozilla Public
+# License, v. 2.0. If a copy of the MPL was not distributed with this file,
+# You can obtain one at http://mozilla.org/MPL/2.0/.
+
+import time
+import logging
+from mozprocess import ProcessHandler
+from threading import Event
+
+from utils import TalosError
+
+
+class Reader(object):
+    def __init__(self, event):
+        self.output = []
+        self.got_end_timestamp = False
+        self.event = event
+
+    def __call__(self, line):
+        if line.find('__endTimestamp') != -1:
+            self.got_end_timestamp = True
+            self.event.set()
+
+        if not (line.startswith('JavaScript error:') or
+                line.startswith('JavaScript warning:')):
+            print line
+            self.output.append(line)
+
+
+def run_browser(command, timeout=None, on_started=None, **kwargs):
+    """
+    Run the browser using the given `command`.
+
+    After the browser prints __endTimestamp, we give it 5
+    seconds to quit and kill it if it's still alive at that point.
+
+    :param command: the commad (as a string list) to run the browser
+    :param timeout: if specified, timeout to wait for the browser before
+                    we raise a :class:`TalosError`
+    :param on_started: a callback that can be used to do things just after
+                       the browser has been started
+    :param kwargs: additional keyword arguments for the :class:`ProcessHandler`
+                   instance
+
+    Returns a tuple (pid, output) where output is a list of strings.
+    """
+    first_time = int(time.time()) * 1000
+    wait_for_quit_timeout = 5
+    event = Event()
+    reader = Reader(event)
+
+    kwargs['storeOutput'] = False
+    kwargs['processOutputLine'] = reader
+    kwargs['onFinish'] = event.set
+    proc = ProcessHandler(command, **kwargs)
+    proc.run()
+    try:
+        if on_started:
+            on_started()
+        # wait until we saw __endTimestamp in the proc output,
+        # or the browser just terminated - or we have a timeout
+        if not event.wait(timeout):
+            raise TalosError("timeout")
+        if reader.got_end_timestamp:
+            for i in range(1, wait_for_quit_timeout):
+                if proc.wait(1) is not None:
+                    break
+            if proc.returncode is not None:
+                logging.info(
+                    "Browser shutdown timed out after {0} seconds, terminating"
+                    " process.".format(wait_for_quit_timeout)
+                )
+    finally:
+        # this also handle KeyboardInterrupt
+        if proc.poll() is None:
+            proc.kill()
+            proc.wait(timeout=1)  # wait a bit for complete termination
+
+    reader.output.append(
+        "__startBeforeLaunchTimestamp%d__endBeforeLaunchTimestamp"
+        % first_time)
+    reader.output.append(
+        "__startAfterTerminationTimestamp%d__endAfterTerminationTimestamp"
+        % (int(time.time()) * 1000))
+
+    logging.info("Browser exited with error code: {0}".format(proc.returncode))
+    return proc.pid, reader.output
--- a/talos/talosconfig.py
+++ b/talos/talosconfig.py
@@ -4,18 +4,17 @@ import json
 
 def writeConfigFile(obj, vals):
     data = dict((opt, obj[opt]) for opt in (vals or obj.keys()))
     return json.dumps(data)
 
 
 def generateTalosConfig(command_line, browser_config, test_config, pid=None):
     bcontroller_vars = ['command', 'child_process', 'process', 'browser_wait',
-                        'test_timeout', 'browser_log', 'browser_path',
-                        'error_filename']
+                        'test_timeout', 'browser_path', 'error_filename']
 
     if 'xperf_path' in browser_config:
         bcontroller_vars.append('xperf_path')
         bcontroller_vars.extend(['buildid', 'sourcestamp', 'repository',
                                  'title'])
         if 'name' in test_config:
             bcontroller_vars.append('testname')
             browser_config['testname'] = test_config['name']
--- a/talos/ttest.py
+++ b/talos/ttest.py
@@ -8,30 +8,31 @@
      - tests the profile
      - gets metrics for the current test environment
      - loads the url
      - collects info on any counters while test runs
      - waits for a 'dump' from the browser
 """
 
 import os
+import sys
 import platform
 import results
 import traceback
 import subprocess
-import time
 import utils
 import mozcrash
 import talosconfig
 import shutil
 import mozfile
 import logging
 
 from talos.utils import TalosError, TalosCrash, TalosRegression
-from talos import ffprocess, TalosProcess
+from talos import ffprocess
+from talos.talos_process import run_browser
 from talos.ffsetup import FFSetup
 from talos.cmanager import CounterManagement
 
 
 class TTest(object):
 
     _pids = []
     if platform.system() == "Linux":
@@ -83,21 +84,16 @@ class TTest(object):
                                            test_name=test_name)
         mozfile.remove(minidumpdir)
 
         if found:
             raise TalosCrash("Found crashes after test run, terminating test")
 
     def testCleanup(self, browser_config, profile_dir, test_config):
         try:
-            if os.path.isfile(browser_config['browser_log']):
-                with open(browser_config['browser_log'], "r") as results_file:
-                    results_raw = results_file.read()
-                logging.info(results_raw)
-
             if profile_dir:
                 try:
                     self.cleanupAndCheckForCrashes(browser_config,
                                                    profile_dir,
                                                    test_config['name'])
                 except TalosError:
                     # ignore this error since we have already checked for
                     # crashes earlier
@@ -167,19 +163,18 @@ class TTest(object):
             # instantiate an object to hold test results
             test_results = results.TestResults(
                 test_config,
                 global_counters
             )
 
             for i in range(test_config['cycles']):
 
-                # remove the browser log file and error file
-                for key in ('browser_log', 'error_filename'):
-                    mozfile.remove(browser_config[key])
+                # remove the browser  error file
+                mozfile.remove(browser_config['error_filename'])
 
                 # reinstall any file whose stability we need to ensure across
                 # the cycles
                 if test_config.get('reinstall', ''):
                     for keep in test_config['reinstall']:
                         origin = os.path.join(test_config['profile_path'],
                                               keep)
                         dest = os.path.join(setup.profile_dir, keep)
@@ -220,50 +215,40 @@ class TTest(object):
                 mm_httpd = None
 
                 if test_config['name'] == 'media_tests':
                     from startup_test.media import media_manager
                     mm_httpd = media_manager.run_server(
                         os.path.dirname(os.path.realpath(__file__))
                     )
 
-                browser = TalosProcess.TalosProcess(
-                    command_args,
-                    env=setup.env,
-                    logfile=browser_config['browser_log'],
-                    suppress_javascript_errors=True,
-                    wait_for_quit_timeout=5
-                )
-                browser.run(timeout=timeout)
-                pid = browser.pid
-                self._pids.append(pid)
-
                 counter_management = None
                 if counters:
                     counter_management = CounterManagement(
                         browser_config['process'],
                         counters,
                         resolution
                     )
 
-                # todo: ctrl+c doesn't close the browser windows
                 try:
-                    code = browser.wait()
-                except KeyboardInterrupt:
-                    browser.kill()
-                    raise
+                    pid, browser_output = run_browser(
+                        command_args,
+                        timeout=timeout,
+                        env=setup.env,
+                        # start collecting counters as soon as possible
+                        on_started=(counter_management.start
+                                    if counter_management else None),
+                    )
                 finally:
                     if counter_management:
                         counter_management.stop()
                     if mm_httpd:
                         mm_httpd.stop()
-                logging.info(
-                    "Browser exited with error code: {0}".format(code)
-                )
-                browser = None
+
+                self._pids.append(pid)
 
                 if test_config['mainthread']:
                     rawlog = os.path.join(here, "mainthread_io.log")
                     if os.path.exists(rawlog):
                         processedlog = \
                             os.path.join(here, 'mainthread_io.json')
                         xre_path = \
                             os.path.dirname(browser_config['browser_path'])
@@ -284,51 +269,38 @@ class TTest(object):
 
                 if test_config['cleanup']:
                     # HACK: add the pid to support xperf where we require
                     # the pid in post processing
                     talosconfig.generateTalosConfig(command_args,
                                                     browser_config,
                                                     test_config,
                                                     pid=pid)
-                    cleanup = TalosProcess.TalosProcess(
-                        ['python'] + test_config['cleanup'].split(),
-                        env=os.environ.copy()
+                    subprocess.call(
+                        [sys.executable] + test_config['cleanup'].split()
                     )
-                    cleanup.run()
-                    cleanup.wait()
-
-                # allow mozprocess to terminate fully.
-                # It appears our log file is partial unless we wait
-                time.sleep(5)
 
                 # For startup tests, we launch the browser multiple times
                 # with the same profile
                 for fname in ('sessionstore.js', '.parentlock',
                               'sessionstore.bak'):
                     mozfile.remove(os.path.join(setup.profile_dir, fname))
 
-                # ensure the browser log exists
-                browser_log_filename = browser_config['browser_log']
-                if not os.path.isfile(browser_log_filename):
-                    raise TalosError("no output from browser [%s]"
-                                     % browser_log_filename)
-
                 # check for xperf errors
                 if os.path.exists(browser_config['error_filename']) or \
                    mainthread_error_count > 0:
                     raise TalosRegression(
                         "Talos has found a regression, if you have questions"
                         " ask for help in irc on #perf"
                     )
 
                 # add the results from the browser output
                 try:
                     test_results.add(
-                        browser_log_filename,
+                        '\n'.join(browser_output),
                         counter_results=(counter_management.results()
                                          if counter_management
                                          else None))
                 except Exception:
                     # Log the exception, but continue. One way to get here
                     # is if the browser hangs, and we'd still like to get
                     # symbolicated profiles in that case.
                     logging.exception("Unable to add results for cycle %d" % i)