Merge lp:~jml/launchpad/subunit-by-default into lp:launchpad

[Jonathan Lange]

Generate subunit output on ec2 test, leaving nicer summary output and more analyzable test failures. Make --headless the default for ec2 test.

[Jonathan Lange (jml)]

= Purpose =

This branch is intended to make debugging of test failures on EC2 easier by providing subunit output and by providing better error messages.

It also changes the default behaviour of the 'ec2 test' command to run in headless mode, deletes the '--headless' option and creates a new '--attached' option that is the inverse of the old '--headless' option.

= Implementation =

Most of the command changes are fairly boring. The interesting changes are in ec2test-remote and testrunner.py

In ec2test-remote, I deleted the JS checker, which is no longer used. I also removed the regex-based mechanic for producing output summary.

Instead, the full output is produced via subunit and interpreted using a component from subunit that drives a Python standard library TestResult object. I made my own TestResult object that prints out errors and failures as they occur.

I also rejiggered the subprocess code to have less nesting. I think this has made the behaviour clearer.

Finally, the subunit output is attached to the failure email. The attachment should have the correct mime type and a useful filename.

= Testing =

I've done several test runs through ec2 at various stages of development, including the final stage.

[Jonathan Lange (jml)]

I forgot to mention. There is an evil hack that makes sure that subunit is available to ec2test-remote.py. I'd love to be able to get rid of it, but I don't know how.

[Gavin Panella (allenap)]

Looks good. I have a couple of questions/suggestions. I'm going to
borrow SummaryResult if that's okay, for my very-long-in-the-tooth-
but-still-going parallelization branch.

> === modified file 'lib/devscripts/ec2test/ec2test-remote.py'
> --- lib/devscripts/ec2test/ec2test-remote.py 2009-10-09 15:04:24 +0000
> +++ lib/devscripts/ec2test/ec2test-remote.py 2010-02-02 13:45:04 +0000
> @@ -106,80 +129,82 @@
> call = self.build_test_command()
>
> try:
> + popen = subprocess.Popen(
> + call, bufsize=-1,
> + stdout=subprocess.PIPE, stderr=subprocess.STDOUT,
> + cwd=self.test_dir)
> +
> + self._gather_test_output(popen.stdout, summary_file, out_file)
> +
> + # Grab the testrunner exit status
> + result = popen.wait()
> +
> + if self.pqm_message is not None:
> + subject = self.pqm_message.get('Subject')
> + if result:
> + # failure
> + summary_file.write(
> + '\n\n**NOT** submitted to PQM:\n%s\n' % (subject,))
> + else:
> + # success
> + conn = bzrlib.smtp_connection.SMTPConnection(config)
> + conn.send_email(self.pqm_message)
> + summary_file.write(
> + '\n\nSUBMITTED TO PQM:\n%s\n' % (subject,))
> + except:
> + summary_file.write('\n\nERROR IN TESTRUNNER\n\n')
> + traceback.print_exc(file=summary_file)
> + result = 1
> + raise
> + finally:
> + # It probably isn't safe to close the log files ourselves,
> + # since someone else might try to write to them later.
> try:
> - try:
> - popen = subprocess.Popen(
> - call, bufsize=-1,
> - stdout=subprocess.PIPE, stderr=subprocess.STDOUT,
> - cwd=self.test_dir)
> -
> - self._gather_test_output(popen, summary_file, out_file)
> -
> - # Grab the testrunner exit status
> - result = popen.wait()
> -
> - if self.pqm_message is not None:
> - subject = self.pqm_message.get('Subject')
> - if result:
> - # failure
> - summary_file.write(
> - '\n\n**NOT** submitted to PQM:\n%s\n' %
> - (subject,))
> - else:
> - # success
> - conn = bzrlib.smtp_connection.SMTPConnection(
> - config)
> - conn.send_email(self.pqm_message)
> - summary_file.write('\n\nSUBMITTED TO PQM:\n%s\n' %
> - (subject,))
> - except:
> - summary_file.write('\n\nERROR IN TESTRUNNER\n\n')
> - traceback.print_exc(file=summary_file)
> - ...

review: Approve

[Gavin Panella (allenap)]

Maybe it's worth adding the subunit PPA <https://launchpad.net/~subunit/+archive/ppa> to the EC2 host and installing from there, instead of doing the sys.path hack? It's not clear that it's a lot cleaner though.

[Jonathan Lange (jml)]

On Tue, Feb 2, 2010 at 2:01 PM, Gavin Panella
<email address hidden> wrote:
> Review: Approve
> Looks good. I have a couple of questions/suggestions. I'm going to
> borrow SummaryResult if that's okay, for my very-long-in-the-tooth-
> but-still-going parallelization branch.
>

It's fine. It'll be in trunk, of course, by the time you get there :)

>
>> === modified file 'lib/devscripts/ec2test/ec2test-remote.py'
>> --- lib/devscripts/ec2test/ec2test-remote.py  2009-10-09 15:04:24 +0000
>> +++ lib/devscripts/ec2test/ec2test-remote.py  2010-02-02 13:45:04 +0000
>> @@ -106,80 +129,82 @@
>>          call = self.build_test_command()
>>
>>          try:
>> +            popen = subprocess.Popen(
>> +                call, bufsize=-1,
>> +                stdout=subprocess.PIPE, stderr=subprocess.STDOUT,
>> +                cwd=self.test_dir)
>> +
>> +            self._gather_test_output(popen.stdout, summary_file, out_file)
>> +
>> +            # Grab the testrunner exit status
>> +            result = popen.wait()
>> +
>> +            if self.pqm_message is not None:
>> +                subject = self.pqm_message.get('Subject')
>> +                if result:
>> +                    # failure
>> +                    summary_file.write(
>> +                        '\n\n**NOT** submitted to PQM:\n%s\n' % (subject,))
>> +                else:
>> +                    # success
>> +                    conn = bzrlib.smtp_connection.SMTPConnection(config)
>> +                    conn.send_email(self.pqm_message)
>> +                    summary_file.write(
>> +                        '\n\nSUBMITTED TO PQM:\n%s\n' % (subject,))
>> +        except:
>> +            summary_file.write('\n\nERROR IN TESTRUNNER\n\n')
>> +            traceback.print_exc(file=summary_file)
>> +            result = 1
>> +            raise
>> +        finally:
>> +            # It probably isn't safe to close the log files ourselves,
>> +            # since someone else might try to write to them later.
>>              try:
>> -                try:
>> -                    popen = subprocess.Popen(
>> -                        call, bufsize=-1,
>> -                        stdout=subprocess.PIPE, stderr=subprocess.STDOUT,
>> -                        cwd=self.test_dir)
>> -
>> -                    self._gather_test_output(popen, summary_file, out_file)
>> -
>> -                    # Grab the testrunner exit status
>> -                    result = popen.wait()
>> -
>> -                    if self.pqm_message is not None:
>> -                        subject = self.pqm_message.get('Subject')
>> -                        if result:
>> -                            # failure
>> -                            summary_file.write(
>> -                                '\n\n**NOT** submitted to PQM:\n%s\n' %
>> -                                (subject,))
>> -                        else:
>> -                            # success
>> -                            conn = bzrlib.smtp_connection.SMTPConnection(
>> -                                config)
>> -                            conn.send_email(self.pqm_message)
>> -                            summary_file.write('\n\nSUBMITTED TO PQM:\n%s\n' %
>...

[Gavin Panella (allenap)]

> > An alternative for all the logs is to open them line buffered,
> > assuming that works as advertised.
>
> How do you do that?
>
> jml

For stdout I think you can open a new file object with line buffering
enabled (untested):

  my_stdout = os.fdopen(sys.stdout.fileno(), 'w', 1)

For regular files, it's similar:

  fd = open('fred.txt', 'w', 1)

[Jonathan Lange (jml)]

Gavin,

Thanks for the reviews & for the line buffering tip.

I don't think the output of this branch is really where I want it to be for landing, and I don't even think it's an incremental improvement. Also, with further integration testing, I've noticed odd behaviours (although these may be the xvfb bugs people keep mentioning).

In any case, it's not ready to land yet.

jml

[Jonathan Lange (jml)]

Hello,

Now that the new zope.testing with improved subunit support has landed, I feel comfortable and confident that this branch is ready to land also.

Leaving it up for review, since there has been some change since it was last reviewed.

jml

[Gavin Panella (allenap)]

Revs 10207, 10208, 10210 and 10211 all look good.

review: Approve

=== modified file 'lib/devscripts/ec2test/builtins.py'
--- lib/devscripts/ec2test/builtins.py	2010-03-18 10:38:14 +0000
+++ lib/devscripts/ec2test/builtins.py	2010-04-14 13:31:40 +0000
@@ -109,6 +109,12 @@
           'and/or of this script.'))
 
 
+attached_option = Option(
+    'attached',
+    help=("Remain attached, i.e. do not go headless. Implied by --postmortem "
+          "and --file."))
+
+
 def filename_type(filename):
     """An option validator for filenames.
 
@@ -182,6 +188,10 @@
     return branches, test_branch
 
 
+
+DEFAULT_TEST_OPTIONS = '--subunit -vvv'
+
+
 class cmd_test(EC2Command):
     """Run the test suite in ec2."""
 
@@ -240,11 +250,7 @@
                 'consulted; for remote branches "Launchpad PQM '
                 '<[e-mail]>" is used by default.')),
         postmortem_option,
-        Option(
-            'headless',
-            help=('After building the instance and test, run the remote '
-                  'tests headless.  Cannot be used with postmortem '
-                  'or file.')),
+        attached_option,
         debug_option,
         Option(
             'open-browser',
@@ -256,10 +262,10 @@
 
     def run(self, test_branch=None, branch=None, trunk=False, machine=None,
             instance_type=DEFAULT_INSTANCE_TYPE,
-            file=None, email=None, test_options='-vv', noemail=False,
-            submit_pqm_message=None, pqm_public_location=None,
+            file=None, email=None, test_options=DEFAULT_TEST_OPTIONS,
+            noemail=False, submit_pqm_message=None, pqm_public_location=None,
             pqm_submit_location=None, pqm_email=None, postmortem=False,
-            headless=False, debug=False, open_browser=False,
+            attached=False, debug=False, open_browser=False,
             include_download_cache_changes=False):
         if debug:
             pdb.set_trace()
@@ -267,10 +273,8 @@
             branch = []
         branches, test_branch = _get_branches_and_test_branch(
             trunk, branch, test_branch)
-        if ((postmortem or file) and headless):
-            raise BzrCommandError(
-                'Headless mode currently does not support postmortem or file '
-                ' options.')
+        if (postmortem or file):
+            attached = True
         if noemail:
             if email:
                 raise BzrCommandError(
@@ -279,12 +283,13 @@
             if email == []:
                 email = True
 
-        if headless and not (email or submit_pqm_message):
+        if not attached and not (email or submit_pqm_message):
             raise BzrCommandError(
                 'You have specified no way to get the results '
                 'of your headless test run.')
 
-        if test_options != '-vv' and submit_pqm_message is not None:
+        if (test_options != DEFAULT_TEST_OPTIONS
+            and submit_pqm_message is not None):
             raise BzrCommandError(
                 "Submitting to PQM with non-default test options isn't "
                 "supported")
@@ -295,7 +300,7 @@
 
         runner = EC2TestRunner(
             test_branch, email=email, file=file,
-            test_options=test_options, headless=headless,
+            test_options=test_options, headless=(not attached),
             branches=branches, pqm_message=submit_pqm_message,
             pqm_public_location=pqm_public_location,
             pqm_submit_location=pqm_submit_location,
@@ -304,7 +309,7 @@
             instance=instance, launchpad_login=instance._launchpad_login,
             timeout=480)
 
-        instance.set_up_and_run(postmortem, not headless, runner.run_tests)
+        instance.set_up_and_run(postmortem, attached, runner.run_tests)
 
 
 class cmd_land(EC2Command):
@@ -325,9 +330,7 @@
         Option(
             'force',
             help="Land the branch even if the proposal is not approved."),
-        Option(
-            'attached',
-            help="Remain attached, i.e. do not go headless."),
+        attached_option,
         ]
 
     takes_args = ['merge_proposal?']
@@ -337,8 +340,8 @@
         """Return the command that would need to be run to submit with ec2."""
         ec2_path = os.path.join(get_launchpad_root(), 'utilities', 'ec2')
         command = [ec2_path, 'test']
-        if not attached:
-            command.extend(['--headless'])
+        if attached:
+            command.extend(['--attached'])
         command.extend(['--email=%s' % email for email in emails])
         # 'ec2 test' has a bug where you cannot pass full URLs to branches to
         # the -b option. It has special logic for 'launchpad' branches, so we

=== modified file 'lib/devscripts/ec2test/ec2test-remote.py'
--- lib/devscripts/ec2test/ec2test-remote.py	2010-03-18 11:21:40 +0000
+++ lib/devscripts/ec2test/ec2test-remote.py	2010-04-14 13:31:40 +0000
@@ -10,12 +10,12 @@
 import optparse
 import os
 import pickle
-import re
 import subprocess
 import sys
 import textwrap
 import time
 import traceback
+import unittest
 
 from xml.sax.saxutils import escape
 
@@ -26,6 +26,66 @@
 import bzrlib.smtp_connection
 import bzrlib.workingtree
 
+import subunit
+
+
+class SummaryResult(unittest.TestResult):
+    """Test result object used to generate the summary."""
+
+    double_line = '=' * 70 + '\n'
+    single_line = '-' * 70 + '\n'
+
+    def __init__(self, output_stream):
+        super(SummaryResult, self).__init__()
+        self.stream = output_stream
+
+    def printError(self, flavor, test, error):
+        """Print an error to the output stream."""
+        self.stream.write(self.double_line)
+        self.stream.write('%s: %s\n' % (flavor, test))
+        self.stream.write(self.single_line)
+        self.stream.write('%s\n' % (error,))
+        self.stream.flush()
+
+    def addError(self, test, error):
+        super(SummaryResult, self).addError(test, error)
+        self.printError('ERROR', test, self._exc_info_to_string(error, test))
+
+    def addFailure(self, test, error):
+        super(SummaryResult, self).addFailure(test, error)
+        self.printError(
+            'FAILURE', test, self._exc_info_to_string(error, test))
+
+
+class FlagFallStream:
+    """Wrapper around a stream that only starts forwarding after a flagfall.
+    """
+
+    def __init__(self, stream, flag):
+        """Construct a `FlagFallStream` that wraps 'stream'.
+
+        :param stream: A stream, a file-like object.
+        :param flag: A string that needs to be written to this stream before
+            we start forwarding the output.
+        """
+        self._stream = stream
+        self._flag = flag
+        self._flag_fallen = False
+
+    def write(self, bytes):
+        if self._flag_fallen:
+            self._stream.write(bytes)
+        else:
+            index = bytes.find(self._flag)
+            if index == -1:
+                return
+            else:
+                self._stream.write(bytes[index:])
+                self._flag_fallen = True
+
+    def flush(self):
+        self._stream.flush()
+
 
 class BaseTestRunner:
 
@@ -35,10 +95,6 @@
         self.pqm_message = pqm_message
         self.public_branch = public_branch
         self.public_branch_revno = public_branch_revno
-
-        # Set up the testrunner options.
-        if test_options is None:
-            test_options = '-vv'
         self.test_options = test_options
 
         # Configure paths.
@@ -106,80 +162,75 @@
         call = self.build_test_command()
 
         try:
+            popen = subprocess.Popen(
+                call, bufsize=-1,
+                stdout=subprocess.PIPE, stderr=subprocess.STDOUT,
+                cwd=self.test_dir)
+
+            self._gather_test_output(popen.stdout, summary_file, out_file)
+
+            # Grab the testrunner exit status
+            result = popen.wait()
+
+            if self.pqm_message is not None:
+                subject = self.pqm_message.get('Subject')
+                if result:
+                    # failure
+                    summary_file.write(
+                        '\n\n**NOT** submitted to PQM:\n%s\n' % (subject,))
+                else:
+                    # success
+                    conn = bzrlib.smtp_connection.SMTPConnection(config)
+                    conn.send_email(self.pqm_message)
+                    summary_file.write(
+                        '\n\nSUBMITTED TO PQM:\n%s\n' % (subject,))
+        except:
+            summary_file.write('\n\nERROR IN TESTRUNNER\n\n')
+            traceback.print_exc(file=summary_file)
+            result = 1
+            raise
+        finally:
+            # It probably isn't safe to close the log files ourselves,
+            # since someone else might try to write to them later.
             try:
-                try:
-                    popen = subprocess.Popen(
-                        call, bufsize=-1,
-                        stdout=subprocess.PIPE, stderr=subprocess.STDOUT,
-                        cwd=self.test_dir)
-
-                    self._gather_test_output(popen, summary_file, out_file)
-
-                    # Grab the testrunner exit status
-                    result = popen.wait()
-
-                    if self.pqm_message is not None:
-                        subject = self.pqm_message.get('Subject')
-                        if result:
-                            # failure
-                            summary_file.write(
-                                '\n\n**NOT** submitted to PQM:\n%s\n' %
-                                (subject,))
-                        else:
-                            # success
-                            conn = bzrlib.smtp_connection.SMTPConnection(
-                                config)
-                            conn.send_email(self.pqm_message)
-                            summary_file.write('\n\nSUBMITTED TO PQM:\n%s\n' %
-                                               (subject,))
-                except:
-                    summary_file.write('\n\nERROR IN TESTRUNNER\n\n')
-                    traceback.print_exc(file=summary_file)
-                    result = 1
-                    raise
-            finally:
-                # It probably isn't safe to close the log files ourselves,
-                # since someone else might try to write to them later.
                 summary_file.close()
                 if self.email is not None:
                     subject = 'Test results: %s' % (
                         result and 'FAILURE' or 'SUCCESS')
                     summary_file = open(self.logger.summary_filename, 'r')
+                    out_file = open(self.logger.out_filename, 'r')
                     bzrlib.email_message.EmailMessage.send(
                         config, config.username(), self.email,
-                        subject, summary_file.read())
+                        subject, summary_file.read(),
+                        attachment=out_file.read(),
+                        attachment_filename='%s.log' % self.get_nick(),
+                        attachment_mime_subtype='subunit')
                     summary_file.close()
-        finally:
-            # we do this at the end because this is a trigger to ec2test.py
-            # back at home that it is OK to kill the process and take control
-            # itself, if it wants to.
-            out_file.close()
-            self.logger.close_logs()
-
-    def _gather_test_output(self, test_process, summary_file, out_file):
+            finally:
+                # we do this at the end because this is a trigger to
+                # ec2test.py back at home that it is OK to kill the process
+                # and take control itself, if it wants to.
+                out_file.close()
+                self.logger.close_logs()
+
+    def get_nick(self):
+        """Return the nick name of the branch that we are testing."""
+        return self.public_branch.strip('/').split('/')[-1]
+
+    def _gather_test_output(self, input_stream, summary_file, out_file):
         """Write the testrunner output to the logs."""
         # Only write to stdout if we are running as the foreground process.
         echo_to_stdout = not self.daemonized
-
-        last_line = ''
-        while 1:
-            data = test_process.stdout.read(256)
-            if data:
-                out_file.write(data)
-                out_file.flush()
-                if echo_to_stdout:
-                    sys.stdout.write(data)
-                    sys.stdout.flush()
-                lines = data.split('\n')
-                lines[0] = last_line + lines[0]
-                last_line = lines.pop()
-                for line in lines:
-                    if not self.ignore_line(line):
-                        summary_file.write(line + '\n')
-                summary_file.flush()
-            else:
-                summary_file.write(last_line)
-                break
+        result = SummaryResult(summary_file)
+        subunit_server = subunit.TestProtocolServer(
+            result, FlagFallStream(summary_file, 'Running tests.'))
+        for line in input_stream:
+            subunit_server.lineReceived(line)
+            out_file.write(line)
+            out_file.flush()
+            if echo_to_stdout:
+                sys.stdout.write(line)
+                sys.stdout.flush()
 
 
 class TestOnMergeRunner(BaseTestRunner):
@@ -190,31 +241,6 @@
         command = ['make', 'check', 'VERBOSITY=' + self.test_options]
         return command
 
-    # Used to filter lines in the summary log. See
-    # `BaseTestRunner.ignore_line()`.
-    ignore_line = re.compile(
-        r'( [\w\.\/\-]+( ?\([\w\.\/\-]+\))?|'
-        r'\s*Running.*|'
-        r'\d{4}\-\d{2}\-\d{2} \d{2}\:\d{2}\:\d{2} INFO.+|'
-        r'\s*Set up .+|'
-        r'\s*Tear down .*|'
-        r'  Ran \d+ tests with .+)$').match
-
-
-class JSCheckTestRunner(BaseTestRunner):
-    """Executes the Launchpad JavaScript integration test suite."""
-
-    def build_test_command(self):
-        """See BaseTestRunner.build_test_command()."""
-        # We use the xvfb server's convenience script, xvfb-run, to
-        # automagically set the display, start the command, shut down the
-        # display, and return the exit code.  (See the xvfb-run man page for
-        # details.)
-        return [
-            'xvfb-run',
-            '-s', '-screen 0 1024x768x24',
-            'make', 'jscheck']
-
 
 class WebTestLogger:
     """Logs test output to disk and a simple web page."""
@@ -428,9 +454,6 @@
         '--public-branch-revno', dest='public_branch_revno',
         type="int", default=None,
         help=('The revision number of the public branch being tested.'))
-    parser.add_option(
-        '--jscheck', dest='jscheck', default=False, action='store_true',
-        help=('Run the JavaScript integration test suite.'))
 
     options, args = parser.parse_args()
 
@@ -442,19 +465,12 @@
     else:
         pqm_message = None
 
-    if options.jscheck:
-        runner_type = JSCheckTestRunner
-    else:
-        # Use the default testrunner.
-        runner_type = TestOnMergeRunner
-
-    runner = runner_type(
+    runner = TestOnMergeRunner(
        options.email,
        pqm_message,
        options.public_branch,
        options.public_branch_revno,
-       ' '.join(args)
-    )
+       ' '.join(args))
 
     try:
         try:

=== modified file 'lib/devscripts/ec2test/testrunner.py'
--- lib/devscripts/ec2test/testrunner.py	2010-03-31 20:52:55 +0000
+++ lib/devscripts/ec2test/testrunner.py	2010-04-14 13:31:40 +0000
@@ -109,7 +109,7 @@
     message = image = None
     _running = False
 
-    def __init__(self, branch, email=False, file=None, test_options='-vv',
+    def __init__(self, branch, email=False, file=None, test_options=None,
                  headless=False, branches=(),
                  pqm_message=None, pqm_public_location=None,
                  pqm_submit_location=None,
@@ -483,7 +483,7 @@
             cmd.append('--public-branch-revno=%d' % branch_revno)
 
         # Add any additional options for ec2test-remote.py
-        cmd.extend(self.get_remote_test_options())
+        cmd.extend(['--', self.test_options])
         self.log(
             'Running tests... (output is available on '
             'http://%s/)\n' % self._instance.hostname)
@@ -519,17 +519,3 @@
                     'Writing abridged test results to %s.\n' % self.file)
                 user_connection.sftp.get('/var/www/summary.log', self.file)
         user_connection.close()
-
-    def get_remote_test_options(self):
-        """Return the test command that will be passed to ec2test-remote.py.
-
-        Returns a tuple of command-line options and switches.
-        """
-        if '--jscheck' in self.test_options:
-            # We want to run the JavaScript test suite.
-            return ('--jscheck',)
-        else:
-            # Run the normal testsuite with our Zope testrunner options.
-            # ec2test-remote.py wants the extra options to be after a double-
-            # dash.
-            return ('--', self.test_options)