Merge lp:~jml/zope.testing/subunit-output-formatter into lp:~vcs-imports/zope.testing/trunk

[Jonathan Lange]

Add a subunit output formatter to zope.testing.

[Robert Collins (lifeless)]

Broad issues:
content and content_type are testtools modules; don't import from subunit, it only has them for compatibility glue.

Perhaps tag tests in layer foo with zope:layer:foo, not zope:testing:foo. In fact it looks like they are, and its simply a docstring bug to claim otherwise.

As subunit has a progress abstraction, the 'cannot support progress' statement confused me. Perhaps say 'cannot support zopes concept of progress because xxx'.

I see you've worked around the bug in subunit where there isn't a tag method on the test result; perhaps you could submit a patch for that ? the contract is(I think) clear, just 'not done'.

194 + Since subunit is a stream protocol format, it has no summary.
perhaps 'no need for a summary - when the stream is displayed a summary can be created then.

What is this?
+ def import_errors(self, import_errors):
221 + """Report test-module import errors (if any)."""
222 + # FIXME: Implement this.
... there is code here

235 + def _exc_info_to_details(self, exc_info):
236 + """Translate 'exc_info' into a details dictionary usable with subunit.
237 + """
238 + import subunit
239 + content_type = subunit.content_type.ContentType(
240 + 'text', 'x-traceback', dict(language='python', charset='utf8'))
241 + formatter = OutputFormatter(None)
242 + traceback = formatter.format_traceback(exc_info)
243 + return {
244 + 'traceback': subunit.content.Content(
245 + content_type, lambda: [traceback.encode('utf8')])}

This might be better as
import testtools.content
test = unittest.TestCase()
content = TracebackContent(exc_info, test)
return {'traceback': content}

unless the formatter.format_traceback(exc_info) is doing something nonobvious (and if it is, perhaps you should mention that. If its doing something nonobvious, then I suggest subclassing testtools.content.Content similarly to testtools.content.TracebackContent.

Also, you might want a global import rather than a scope local.

270 + # XXX: Since the subunit stream is designed for machine reading, we
271 + # should really dump the binary profiler stats here. Sadly, the
272 + # "content" API doesn't support this yet. Instead, we dump the
273 + # stringified version of the stats dict, which is functionally the
274 + # same thing. -- jml, 2010-02-14.
275 + plain_text = subunit.content_type.ContentType(
276 + 'text', 'plain', {'charset': 'utf8'})
277 + details = {
278 + 'profiler-stats': subunit.content.Content(
279 + plain_text, lambda: [unicode(stats.stats).encode('utf8')])}

meta: where some dependency is insufficient, it might be nice to file a bug saying 'please provide X', and then reference the bug in this patch. That way, when your later self returns, they have something to prompt the memory.
That said, I'm not sure what subunit is missing here:
(see application/octet-stream in http://www.rfc-editor.org/rfc/rfc2046.txt for details)
cprofile_type = testtools.content_type.ContentType('application', 'octet-stream', {'type':'cProfile'})
content = testtools.content.Content(cprofile_type, lambda: [bpickle(stats)])
return {'profiler-stats': content}

You can also make the content types attributes on self to avoid calculating them every time; they are 'Value Objec...

[Robert Collins (lifeless)]

Oh, I forgot to mention; for profiling, using bzrlib.lsprof.profile you can get kcachegrind output out really easily; I love it much more than the damaged cProfile output, and it is actually plain text anyway :).

[Jonathan Lange (jml)]

> Broad issues:
...
> As subunit has a progress abstraction, the 'cannot support progress' statement
> confused me. Perhaps say 'cannot support zopes concept of progress because
> xxx'.
>

Changed to:
    # subunit output is designed for computers, so displaying a progress bar
    # isn't helpful.

Which isn't _strictly_ true, since displaying a progress bar might help the humans running the process. The real reason is it's too hard.

> I see you've worked around the bug in subunit where there isn't a tag method
> on the test result; perhaps you could submit a patch for that ? the contract
> is(I think) clear, just 'not done'.
>

...

> 194 + Since subunit is a stream protocol format, it has no summary.
> perhaps 'no need for a summary - when the stream is displayed a summary can be
> created then.
...

Now says:
        Since subunit is a stream protocol format, it has no need for a
        summary. When the stream is finished other tools can generate a
        summary if so desired.

> 235 + def _exc_info_to_details(self, exc_info):
> 236 + """Translate 'exc_info' into a details dictionary usable with
> subunit.
> 237 + """
> 238 + import subunit
> 239 + content_type = subunit.content_type.ContentType(
> 240 + 'text', 'x-traceback', dict(language='python', charset='utf8'))
> 241 + formatter = OutputFormatter(None)
> 242 + traceback = formatter.format_traceback(exc_info)
> 243 + return {
> 244 + 'traceback': subunit.content.Content(
> 245 + content_type, lambda: [traceback.encode('utf8')])}
>
> This might be better as
> import testtools.content
> test = unittest.TestCase()
> content = TracebackContent(exc_info, test)
> return {'traceback': content}
>
> unless the formatter.format_traceback(exc_info) is doing something nonobvious
> (and if it is, perhaps you should mention that. If its doing something
> nonobvious, then I suggest subclassing testtools.content.Content similarly to
> testtools.content.TracebackContent.
>

It's the non-obvious thing. Added this comment:
        # In an ideal world, we'd use the pre-bundled 'TracebackContent' class
        # from testtools. However, 'OutputFormatter' contains special logic to
        # handle errors from doctests, so we have to use that and manually
        # create an object equivalent to an instance of 'TracebackContent'.

> Also, you might want a global import rather than a scope local.
>

Yeah, good point.

I've changed it to be a global import. Note that it's still a soft dependency.

>
> 270 + # XXX: Since the subunit stream is designed for machine reading, we
> 271 + # should really dump the binary profiler stats here. Sadly, the
> 272 + # "content" API doesn't support this yet. Instead, we dump the
> 273 + # stringified version of the stats dict, which is functionally the
> 274 + # same thing. -- jml, 2010-02-14.
> 275 + plain_text = subunit.content_type.ContentType(
> 276 + 'text', 'plain', {'charset': 'utf8'})
> 277 + details = {
> 278 + 'profiler-stats': subunit.content.Content(
> 279 + plain_text, lambda: [unicode(stats.stats).encode('utf8')])}
>
> meta: where some dependency is insuffic...

[Jonathan Lange (jml)]

OK, I think this is ready for landing into trunk. Would appreciate a review and guidance through whatever hoops I must jump through to get this landed.

[Robert Collins (lifeless)]

On Thu, 2010-03-11 at 20:31 +0000, Jonathan Lange wrote:
> > Broad issues:
> ...
> > As subunit has a progress abstraction, the 'cannot support progress' statement
> > confused me. Perhaps say 'cannot support zopes concept of progress because
> > xxx'.
> >
>
> Changed to:
> # subunit output is designed for computers, so displaying a progress bar
> # isn't helpful.
>
> Which isn't _strictly_ true, since displaying a progress bar might
> help the humans running the process. The real reason is it's too hard.

This still leaves me confused: subunit can fairly easily do a progress
bar, in-process or out-of-process. I was guessing that zopes concept of
progress was strange or something.

> > I think its great you've written docs/tests for this. I worry that they will
> > be fragile because they encode the subunit stream representation, but thats
> > not what you wrote: you wrote some object calls against subunit. I suggest you
> > use the guts from things like subunit-ls, subunit2pyunit, subunit-stats to
> > make your tests be done at the same level as the code wrote: to the object
> > API. This will prevent you having to e.g. include multipart MIME or http
> > chunking in the tests. Specifically I suspect you are really writing smoke
> > tests, and just a stats output will do great for your needs [most of the
> > time].
> >
>
> I suspect you are right. However, at this point I can't be bothered making that change. :)

It's your dime ;)

Let me know of anything I can do to help.

-Rob

[lp:~jml/zope.testing/subunit-output-formatter]

377. By Jonathan Lange on 2010-03-11

Correct versions for testtools and subunit

=== added file '.bzrignore'
--- .bzrignore	1970-01-01 00:00:00 +0000
+++ .bzrignore	2010-03-11 22:36:30 +0000
@@ -0,0 +1,6 @@
+.installed.cfg
+bin
+develop-eggs
+documentation.txt
+src/zope.testing.egg-info
+parts

=== modified file 'src/zope/testing/testrunner/formatter.py'
--- src/zope/testing/testrunner/formatter.py	2009-12-23 21:21:53 +0000
+++ src/zope/testing/testrunner/formatter.py	2010-03-11 22:36:30 +0000
@@ -16,9 +16,12 @@
 $Id: __init__.py 86207 2008-05-03 13:25:02Z ctheune $
 """
 
+from datetime import datetime, timedelta
 import doctest
+import os
 import sys
 import re
+import tempfile
 import traceback
 
 from zope.testing.exceptions import DocTestFailureException
@@ -647,3 +650,405 @@
             else:
                 print self.colorize('exception', line)
         print
+
+
+class FakeTest(object):
+    """A fake test object that only has an id."""
+
+    failureException = None
+
+    def __init__(self, test_id):
+        self._id = test_id
+
+    def id(self):
+        return self._id
+
+
+# Conditional imports, we don't want zope.testing to have a hard dependency on
+# subunit.
+try:
+    import subunit
+    from subunit.iso8601 import Utc
+except ImportError:
+    subunit = None
+
+
+# testtools is a hard dependency of subunit itself, guarding separately for
+# richer error messages.
+try:
+    from testtools import content
+except ImportError:
+    content = None
+
+
+class SubunitOutputFormatter(object):
+    """A subunit output formatter.
+
+    This output formatter generates subunit compatible output (see
+    https://launchpad.net/subunit). Subunit output is essentially a stream of
+    results of unit tests. In this formatter, non-test events (such as layer
+    set up) are encoded as specially tagged tests and summary-generating
+    methods (such as modules_with_import_problems) deliberately do nothing.
+
+    In particular, for a layer 'foo', the fake tests related to layer set up
+    and tear down are tagged with 'zope:layer' and are called 'foo:setUp' and
+    'foo:tearDown'. Any tests within layer 'foo' are tagged with
+    'zope:layer:foo'.
+
+    Note that all tags specific to this formatter begin with 'zope:'
+    """
+
+    # subunit output is designed for computers, so displaying a progress bar
+    # isn't helpful.
+    progress = False
+    verbose = property(lambda self: self.options.verbose)
+
+    TAG_INFO_SUBOPTIMAL = 'zope:info_suboptimal'
+    TAG_ERROR_WITH_BANNER = 'zope:error_with_banner'
+    TAG_LAYER = 'zope:layer'
+    TAG_IMPORT_ERROR = 'zope:import_error'
+    TAG_PROFILER_STATS = 'zope:profiler_stats'
+    TAG_GARBAGE = 'zope:garbage'
+    TAG_THREADS = 'zope:threads'
+    TAG_REFCOUNTS = 'zope:refcounts'
+
+    def __init__(self, options):
+        if subunit is None:
+            raise Exception("Requires subunit 0.0.5 or better")
+        if content is None:
+            raise Exception("Requires testtools 0.9.2 or better")
+        self.options = options
+        self._stream = sys.stdout
+        self._subunit = subunit.TestProtocolClient(self._stream)
+        # Used to track the last layer that was set up or torn down. Either
+        # None or (layer_name, last_touched_time).
+        self._last_layer = None
+        self.UTC = Utc()
+        # Content types used in the output.
+        self.TRACEBACK_CONTENT_TYPE = content.ContentType(
+            'text', 'x-traceback', dict(language='python', charset='utf8'))
+        self.PROFILE_CONTENT_TYPE = content.ContentType(
+            'application', 'x-binary-profile')
+        self.PLAIN_TEXT = content.ContentType(
+            'text', 'plain', {'charset': 'utf8'})
+
+    @property
+    def _time_tests(self):
+        return self.verbose > 2
+
+    def _emit_timestamp(self, now=None):
+        """Emit a timestamp to the subunit stream.
+
+        If 'now' is not specified, use the current time on the system clock.
+        """
+        if now is None:
+            now = datetime.now(self.UTC)
+        self._subunit.time(now)
+        return now
+
+    def _emit_tag(self, tag):
+        self._stream.write('tags: %s\n' % (tag,))
+
+    def _stop_tag(self, tag):
+        self._stream.write('tags: -%s\n' % (tag,))
+
+    def _emit_fake_test(self, message, tag, details=None):
+        """Emit a successful fake test to the subunit stream.
+
+        Use this to print tagged informative messages.
+        """
+        test = FakeTest(message)
+        self._subunit.startTest(test)
+        self._emit_tag(tag)
+        self._subunit.addSuccess(test, details)
+
+    def _emit_error(self, error_id, tag, exc_info):
+        """Emit an error to the subunit stream.
+
+        Use this to pass on information about errors that occur outside of
+        tests.
+        """
+        test = FakeTest(error_id)
+        self._subunit.startTest(test)
+        self._emit_tag(tag)
+        self._subunit.addError(test, exc_info)
+
+    def info(self, message):
+        """Print an informative message, but only if verbose."""
+        # info() output is not relevant to actual test results. It only says
+        # things like "Running tests" or "Tearing down left over layers",
+        # things that are communicated already by the subunit stream. Just
+        # suppress the info() output.
+        pass
+
+    def info_suboptimal(self, message):
+        """Print an informative message about losing some of the features.
+
+        For example, when you run some tests in a subprocess, you lose the
+        ability to use the debugger.
+        """
+        # Used _only_ to indicate running in a subprocess.
+        self._emit_fake_test(message.strip(), self.TAG_INFO_SUBOPTIMAL)
+
+    def error(self, message):
+        """Report an error."""
+        # XXX: Mostly used for user errors, sometimes used for errors in the
+        # test framework, sometimes used to record layer setUp failure (!!!).
+        # How should this be encoded?
+        raise NotImplementedError(self.error)
+
+    def error_with_banner(self, message):
+        """Report an error with a big ASCII banner."""
+        # Either "Could not communicate with subprocess"
+        # Or "Can't post-mortem debug when running a layer as a subprocess!"
+        self._emit_fake_test(message, self.TAG_ERROR_WITH_BANNER)
+
+    def _enter_layer(self, layer_name):
+        """Signal in the subunit stream that we are entering a layer."""
+        self._emit_tag('zope:layer:%s' % (layer_name,))
+
+    def _exit_layer(self, layer_name):
+        """Signal in the subunit stream that we are leaving a layer."""
+        self._stop_tag('zope:layer:%s' % (layer_name,))
+
+    def start_set_up(self, layer_name):
+        """Report that we're setting up a layer.
+
+        We do this by emitting a tag of the form 'layer:$LAYER_NAME'.
+        """
+        now = self._emit_timestamp()
+        self._subunit.startTest(FakeTest('%s:setUp' % (layer_name,)))
+        self._emit_tag(self.TAG_LAYER)
+        self._last_layer = (layer_name, now)
+
+    def stop_set_up(self, seconds):
+        layer_name, start_time = self._last_layer
+        self._last_layer = None
+        self._emit_timestamp(start_time + timedelta(seconds=seconds))
+        self._subunit.addSuccess(FakeTest('%s:setUp' % (layer_name,)))
+        self._enter_layer(layer_name)
+
+    def start_tear_down(self, layer_name):
+        """Report that we're tearing down a layer.
+
+        We do this by removing a tag of the form 'layer:$LAYER_NAME'.
+        """
+        self._exit_layer(layer_name)
+        now = self._emit_timestamp()
+        self._subunit.startTest(FakeTest('%s:tearDown' % (layer_name,)))
+        self._emit_tag(self.TAG_LAYER)
+        self._last_layer = (layer_name, now)
+
+    def stop_tear_down(self, seconds):
+        layer_name, start_time = self._last_layer
+        self._last_layer = None
+        self._emit_timestamp(start_time + timedelta(seconds=seconds))
+        self._subunit.addSuccess(FakeTest('%s:tearDown' % (layer_name,)))
+
+    def tear_down_not_supported(self):
+        """Report that we could not tear down a layer.
+
+        Should be called right after start_tear_down().
+        """
+        layer_name, start_time = self._last_layer
+        self._last_layer = None
+        self._emit_timestamp(datetime.now(self.UTC))
+        self._subunit.addSkip(
+            FakeTest('%s:tearDown' % (layer_name,)), "tearDown not supported")
+
+    def summary(self, n_tests, n_failures, n_errors, n_seconds):
+        """Print out a summary.
+
+        Since subunit is a stream protocol format, it has no need for a
+        summary. When the stream is finished other tools can generate a
+        summary if so desired.
+        """
+        pass
+
+    def start_test(self, test, tests_run, total_tests):
+        """Report that we're about to run a test.
+
+        The next output operation should be test_success(), test_error(), or
+        test_failure().
+        """
+        if self._time_tests:
+            self._emit_timestamp()
+        # Note that this always emits newlines, so it will function as well as
+        # other start_test implementations if we are running in a subprocess.
+        self._subunit.startTest(test)
+
+    def stop_test(self, test):
+        """Clean up the output state after a test."""
+        self._subunit.stopTest(test)
+        self._stream.flush()
+
+    def stop_tests(self):
+        """Clean up the output state after a collection of tests."""
+        self._stream.flush()
+
+    def test_success(self, test, seconds):
+        if self._time_tests:
+            self._emit_timestamp()
+        self._subunit.addSuccess(test)
+
+    def import_errors(self, import_errors):
+        """Report test-module import errors (if any)."""
+        if not import_errors:
+            return
+        for error in import_errors:
+            self._emit_error(
+                error.module, self.TAG_IMPORT_ERROR, error.exc_info)
+
+    def modules_with_import_problems(self, import_errors):
+        """Report names of modules with import problems (if any)."""
+        # This is simply a summary method, and subunit output doesn't benefit
+        # from summaries.
+        pass
+
+    def _exc_info_to_details(self, exc_info):
+        """Translate 'exc_info' into a details dictionary usable with subunit.
+        """
+        # In an ideal world, we'd use the pre-bundled 'TracebackContent' class
+        # from testtools. However, 'OutputFormatter' contains special logic to
+        # handle errors from doctests, so we have to use that and manually
+        # create an object equivalent to an instance of 'TracebackContent'.
+        formatter = OutputFormatter(None)
+        traceback = formatter.format_traceback(exc_info)
+        return {
+            'traceback': content.Content(
+                self.TRACEBACK_CONTENT_TYPE, lambda: [traceback.encode('utf8')])}
+
+    def test_error(self, test, seconds, exc_info):
+        """Report that an error occurred while running a test.
+
+        Should be called right after start_test().
+
+        The next output operation should be stop_test().
+        """
+        if self._time_tests:
+            self._emit_timestamp()
+        details = self._exc_info_to_details(exc_info)
+        self._subunit.addError(test, details=details)
+
+    def test_failure(self, test, seconds, exc_info):
+        """Report that a test failed.
+
+        Should be called right after start_test().
+
+        The next output operation should be stop_test().
+        """
+        if self._time_tests:
+            self._emit_timestamp()
+        details = self._exc_info_to_details(exc_info)
+        self._subunit.addFailure(test, details=details)
+
+    def profiler_stats(self, stats):
+        """Report profiler stats."""
+        ignored, filename = tempfile.mkstemp()
+        try:
+            stats.dump_stats(filename)
+            profile_content = content.Content(
+                self.PROFILE_CONTENT_TYPE, open(filename).read)
+            details = {'profiler-stats': profile_content}
+        finally:
+            os.unlink(filename)
+        # Name the test 'zope:profiler_stats' just like its tag.
+        self._emit_fake_test(
+            self.TAG_PROFILER_STATS, self.TAG_PROFILER_STATS, details)
+
+    def tests_with_errors(self, errors):
+        """Report tests with errors.
+
+        Simply not supported by the subunit formatter. Fancy summary output
+        doesn't make sense.
+        """
+        pass
+
+    def tests_with_failures(self, failures):
+        """Report tests with failures.
+
+        Simply not supported by the subunit formatter. Fancy summary output
+        doesn't make sense.
+        """
+        pass
+
+    def totals(self, n_tests, n_failures, n_errors, n_seconds):
+        """Summarize the results of all layers.
+
+        Simply not supported by the subunit formatter. Fancy summary output
+        doesn't make sense.
+        """
+        pass
+
+    def list_of_tests(self, tests, layer_name):
+        """Report a list of test names."""
+        self._enter_layer(layer_name)
+        for test in tests:
+            self._subunit.startTest(test)
+            self._subunit.addSuccess(test)
+        self._exit_layer(layer_name)
+
+    def _get_text_details(self, name, text):
+        """Get a details dictionary that just has some plain text."""
+        return {
+            name: content.Content(
+                self.PLAIN_TEXT, lambda: [text.encode('utf8')])}
+
+    def garbage(self, garbage):
+        """Report garbage generated by tests."""
+        # XXX: Really, 'garbage', 'profiler_stats' and the 'refcounts' twins
+        # ought to add extra details to a fake test that represents the
+        # summary information for the whole suite. However, there's no event
+        # on output formatters for "everything is really finished, honest". --
+        # jml, 2010-02-14
+        details = self._get_text_details('garbage', unicode(garbage))
+        self._emit_fake_test(
+            self.TAG_GARBAGE, self.TAG_GARBAGE, details)
+
+    def test_garbage(self, test, garbage):
+        """Report garbage generated by a test.
+
+        Encoded in the subunit stream as a test error. Clients can filter out
+        these tests based on the tag if they don't think garbage should fail
+        the test run.
+        """
+        # XXX: Perhaps 'test_garbage' and 'test_threads' ought to be within
+        # the output for the actual test, appended as details to whatever
+        # result the test gets. Not an option with the present API, as there's
+        # no event for "no more output for this test". -- jml, 2010-02-14
+        self._subunit.startTest(test)
+        self._emit_tag(self.TAG_GARBAGE)
+        self._subunit.addError(
+            test, self._get_text_details('garbage', unicode(garbage)))
+
+    def test_threads(self, test, new_threads):
+        """Report threads left behind by a test.
+
+        Encoded in the subunit stream as a test error. Clients can filter out
+        these tests based on the tag if they don't think left-over threads
+        should fail the test run.
+        """
+        self._subunit.startTest(test)
+        self._emit_tag(self.TAG_THREADS)
+        self._subunit.addError(
+            test, self._get_text_details('garbage', unicode(new_threads)))
+
+    def refcounts(self, rc, prev):
+        """Report a change in reference counts."""
+        details = self._get_text_details('sys-refcounts', str(rc))
+        details.update(
+            self._get_text_details('changes', str(rc - prev)))
+        # XXX: Emit the details dict as JSON?
+        self._emit_fake_test(
+            self.TAG_REFCOUNTS, self.TAG_REFCOUNTS, details)
+
+    def detailed_refcounts(self, track, rc, prev):
+        """Report a change in reference counts, with extra detail."""
+        details = self._get_text_details('sys-refcounts', str(rc))
+        details.update(
+            self._get_text_details('changes', str(rc - prev)))
+        details.update(
+            self._get_text_details('track', str(track.delta)))
+
+        self._emit_fake_test(
+            self.TAG_REFCOUNTS, self.TAG_REFCOUNTS, details)

=== modified file 'src/zope/testing/testrunner/options.py'
--- src/zope/testing/testrunner/options.py	2009-12-18 08:23:21 +0000
+++ src/zope/testing/testrunner/options.py	2010-03-11 22:36:30 +0000
@@ -22,7 +22,11 @@
 import sys
 
 from zope.testing.testrunner.profiling import available_profilers
-from zope.testing.testrunner.formatter import OutputFormatter, ColorfulOutputFormatter
+from zope.testing.testrunner.formatter import (
+    OutputFormatter,
+    ColorfulOutputFormatter,
+    SubunitOutputFormatter,
+    )
 from zope.testing.testrunner.formatter import terminal_has_colors
 
 
@@ -192,6 +196,12 @@
 """)
 
 reporting.add_option(
+    '--subunit', action="store_true", dest='subunit',
+    help="""\
+Use subunit output. Will not be colorized.
+""")
+
+reporting.add_option(
     '--slow-test', type='float', dest='slow_test_threshold', metavar='N',
     help="""\
 With -c and -vvv, highlight tests that take longer than N seconds (default:
@@ -531,7 +541,19 @@
     options, positional = parser.parse_args(args[1:], defaults)
     options.original_testrunner_args = args
 
-    if options.color:
+    if options.subunit:
+        try:
+            import subunit
+        except ImportError:
+            print """\
+        Subunit is not installed. Please install Subunit
+        to generate subunit output.
+        """
+            options.fail = True
+            return options
+        else:
+            options.output = SubunitOutputFormatter(options)
+    elif options.color:
         options.output = ColorfulOutputFormatter(options)
         options.output.slow_test_threshold = options.slow_test_threshold
     else:

=== modified file 'src/zope/testing/testrunner/testrunner-leaks.txt'
--- src/zope/testing/testrunner/testrunner-leaks.txt	2008-05-05 18:50:48 +0000
+++ src/zope/testing/testrunner/testrunner-leaks.txt	2010-03-11 22:36:30 +0000
@@ -16,7 +16,7 @@
     >>> from zope.testing import testrunner
     
     >>> sys.argv = 'test --layer Layer11$ --layer Layer12$ -N4 -r'.split()
-    >>> _ = testrunner.run(defaults)
+    >>> _ = testrunner.run_internal(defaults)
     Running samplelayers.Layer11 tests:
       Set up samplelayers.Layer1 in 0.000 seconds.
       Set up samplelayers.Layer11 in 0.000 seconds.
@@ -60,7 +60,7 @@
 Let's look at an example test that leaks:
 
     >>> sys.argv = 'test --tests-pattern leak -N4 -r'.split()
-    >>> _ = testrunner.run(defaults)
+    >>> _ = testrunner.run_internal(defaults)
     Running zope.testing.testrunner.layer.UnitTests tests:...
     Iteration 1
       Ran 1 tests with 0 failures and 0 errors in 0.000 seconds.
@@ -81,7 +81,7 @@
 type (or class):
 
     >>> sys.argv = 'test --tests-pattern leak -N5 -r -v'.split()
-    >>> _ = testrunner.run(defaults)
+    >>> _ = testrunner.run_internal(defaults)
     Running tests at level 1
     Running zope.testing.testrunner.layer.UnitTests tests:...
     Iteration 1

=== added file 'src/zope/testing/testrunner/testrunner-subunit-err.txt'
--- src/zope/testing/testrunner/testrunner-subunit-err.txt	1970-01-01 00:00:00 +0000
+++ src/zope/testing/testrunner/testrunner-subunit-err.txt	2010-03-11 22:36:30 +0000
@@ -0,0 +1,20 @@
+Using subunit output without subunit installed
+==============================================
+
+To use the --subunit reporting option, you must have subunit installed. If you
+do not, you will get an error message:
+
+    >>> import os.path, sys
+    >>> directory_with_tests = os.path.join(this_directory, 'testrunner-ex')
+    >>> defaults = [
+    ...     '--path', directory_with_tests,
+    ...     '--tests-pattern', '^sampletestsf?$',
+    ...     ]
+
+    >>> from zope.testing import testrunner
+
+    >>> sys.argv = 'test --subunit'.split()
+    >>> _ = testrunner.run_internal(defaults)
+            Subunit is not installed. Please install Subunit
+            to generate subunit output.
+    <BLANKLINE>

=== added file 'src/zope/testing/testrunner/testrunner-subunit-leaks.txt'
--- src/zope/testing/testrunner/testrunner-subunit-leaks.txt	1970-01-01 00:00:00 +0000
+++ src/zope/testing/testrunner/testrunner-subunit-leaks.txt	2010-03-11 22:36:30 +0000
@@ -0,0 +1,107 @@
+Debugging Memory Leaks with subunit output
+==========================================
+
+The --report-refcounts (-r) option can be used with the --repeat (-N)
+option to detect and diagnose memory leaks.  To use this option, you
+must configure Python with the --with-pydebug option. (On Unix, pass
+this option to configure and then build Python.)
+
+For more detailed documentation, see testrunner-leaks.txt.
+
+    >>> import os.path, sys
+    >>> directory_with_tests = os.path.join(this_directory, 'testrunner-ex')
+    >>> defaults = [
+    ...     '--path', directory_with_tests,
+    ...     '--tests-pattern', '^sampletestsf?$',
+    ...     ]
+
+    >>> from zope.testing import testrunner
+
+Each layer is repeated the requested number of times.  For each
+iteration after the first, the system refcount and change in system
+refcount is shown. The system refcount is the total of all refcount in
+the system.  When a refcount on any object is changed, the system
+refcount is changed by the same amount.  Tests that don't leak show
+zero changes in system refcount.
+
+Let's look at an example test that leaks:
+
+    >>> sys.argv = 'test --subunit --tests-pattern leak -N2 -r'.split()
+    >>> _ = testrunner.run_internal(defaults)
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: zope.testing.testrunner.layer.UnitTests:setUp
+    tags: zope:layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    successful: zope.testing.testrunner.layer.UnitTests:setUp
+    tags: zope:layer:zope.testing.testrunner.layer.UnitTests
+    test: leak.TestSomething.testleak
+    successful: leak.TestSomething.testleak
+    test: leak.TestSomething.testleak
+    successful: leak.TestSomething.testleak
+    test: zope:refcounts
+    tags: zope:refcounts
+    successful: zope:refcounts [ multipart
+    Content-Type: text/plain;charset=utf8
+    ...
+    ...\r
+    <BLANKLINE>
+    ...\r
+    <BLANKLINE>
+    Content-Type: text/plain;charset=utf8
+    ...
+    ...\r
+    <BLANKLINE>
+    ...\r
+    <BLANKLINE>
+    ]
+    tags: -zope:layer:zope.testing.testrunner.layer.UnitTests
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: zope.testing.testrunner.layer.UnitTests:tearDown
+    tags: zope:layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    successful: zope.testing.testrunner.layer.UnitTests:tearDown
+
+Here we see that the system refcount is increasing.  If we specify a
+verbosity greater than one, we can get details broken out by object
+type (or class):
+
+    >>> sys.argv = 'test --subunit --tests-pattern leak -N2 -v -r'.split()
+    >>> _ = testrunner.run_internal(defaults)
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: zope.testing.testrunner.layer.UnitTests:setUp
+    tags: zope:layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    successful: zope.testing.testrunner.layer.UnitTests:setUp
+    tags: zope:layer:zope.testing.testrunner.layer.UnitTests
+    test: leak.TestSomething.testleak
+    successful: leak.TestSomething.testleak
+    test: leak.TestSomething.testleak
+    successful: leak.TestSomething.testleak
+    test: zope:refcounts
+    tags: zope:refcounts
+    successful: zope:refcounts [ multipart
+    Content-Type: text/plain;charset=utf8
+    ...
+    ...\r
+    <BLANKLINE>
+    ...\r
+    <BLANKLINE>
+    Content-Type: text/plain;charset=utf8
+    ...
+    ...\r
+    <BLANKLINE>
+    ...\r
+    <BLANKLINE>
+    Content-Type: text/plain;charset=utf8
+    ...
+    ...\r
+    <BLANKLINE>
+    ...
+    <BLANKLINE>
+    ]
+    tags: -zope:layer:zope.testing.testrunner.layer.UnitTests
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: zope.testing.testrunner.layer.UnitTests:tearDown
+    tags: zope:layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    successful: zope.testing.testrunner.layer.UnitTests:tearDown

=== added file 'src/zope/testing/testrunner/testrunner-subunit.txt'
--- src/zope/testing/testrunner/testrunner-subunit.txt	1970-01-01 00:00:00 +0000
+++ src/zope/testing/testrunner/testrunner-subunit.txt	2010-03-11 22:36:30 +0000
@@ -0,0 +1,678 @@
+Subunit Output
+==============
+
+Subunit is a streaming protocol for interchanging test results. More
+information can be found at https://launchpad.net/subunit.
+
+    >>> import os.path, sys
+    >>> directory_with_tests = os.path.join(this_directory, 'testrunner-ex')
+    >>> defaults = [
+    ...     '--path', directory_with_tests,
+    ...     '--tests-pattern', '^sampletestsf?$',
+    ...     ]
+
+    >>> from zope.testing import testrunner
+
+
+Basic output
+------------
+
+Subunit output is line-based, with a 'test:' line for the start of each test
+and a 'successful:' line for each successful test.
+
+Zope layer set up and tear down events are represented as tests tagged with
+'zope:layer'. This allows them to be distinguished from actual tests, provides
+a place for the layer timing information in the subunit stream and allows us
+to include error information if necessary.
+
+Once the layer is set up, all future tests are tagged with
+'zope:layer:LAYER_NAME'.
+
+    >>> sys.argv = 'test --layer 122 --subunit -t TestNotMuch'.split()
+    >>> testrunner.run_internal(defaults)
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: samplelayers.Layer1:setUp
+    tags: zope:layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    successful: samplelayers.Layer1:setUp
+    tags: zope:layer:samplelayers.Layer1
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: samplelayers.Layer12:setUp
+    tags: zope:layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    successful: samplelayers.Layer12:setUp
+    tags: zope:layer:samplelayers.Layer12
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: samplelayers.Layer122:setUp
+    tags: zope:layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    successful: samplelayers.Layer122:setUp
+    tags: zope:layer:samplelayers.Layer122
+    test: sample1.sampletests.test122.TestNotMuch.test_1
+    successful: sample1.sampletests.test122.TestNotMuch.test_1
+    test: sample1.sampletests.test122.TestNotMuch.test_2
+    successful: sample1.sampletests.test122.TestNotMuch.test_2
+    test: sample1.sampletests.test122.TestNotMuch.test_3
+    successful: sample1.sampletests.test122.TestNotMuch.test_3
+    test: sampletests.test122.TestNotMuch.test_1
+    successful: sampletests.test122.TestNotMuch.test_1
+    test: sampletests.test122.TestNotMuch.test_2
+    successful: sampletests.test122.TestNotMuch.test_2
+    test: sampletests.test122.TestNotMuch.test_3
+    successful: sampletests.test122.TestNotMuch.test_3
+    tags: -zope:layer:samplelayers.Layer122
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: samplelayers.Layer122:tearDown
+    tags: zope:layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    successful: samplelayers.Layer122:tearDown
+    tags: -zope:layer:samplelayers.Layer12
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: samplelayers.Layer12:tearDown
+    tags: zope:layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    successful: samplelayers.Layer12:tearDown
+    tags: -zope:layer:samplelayers.Layer1
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: samplelayers.Layer1:tearDown
+    tags: zope:layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    successful: samplelayers.Layer1:tearDown
+    False
+
+
+Timing tests
+------------
+
+When verbosity is high enough, the subunit stream includes timing information
+for the actual tests, as well as for the layers.
+
+    >>> sys.argv = 'test --layer 122 -vvv --subunit -t TestNotMuch'.split()
+    >>> testrunner.run_internal(defaults)
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: samplelayers.Layer1:setUp
+    tags: zope:layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    successful: samplelayers.Layer1:setUp
+    tags: zope:layer:samplelayers.Layer1
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: samplelayers.Layer12:setUp
+    tags: zope:layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    successful: samplelayers.Layer12:setUp
+    tags: zope:layer:samplelayers.Layer12
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: samplelayers.Layer122:setUp
+    tags: zope:layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    successful: samplelayers.Layer122:setUp
+    tags: zope:layer:samplelayers.Layer122
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: sample1.sampletests.test122.TestNotMuch.test_1
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    successful: sample1.sampletests.test122.TestNotMuch.test_1
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: sample1.sampletests.test122.TestNotMuch.test_2
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    successful: sample1.sampletests.test122.TestNotMuch.test_2
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: sample1.sampletests.test122.TestNotMuch.test_3
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    successful: sample1.sampletests.test122.TestNotMuch.test_3
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: sampletests.test122.TestNotMuch.test_1
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    successful: sampletests.test122.TestNotMuch.test_1
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: sampletests.test122.TestNotMuch.test_2
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    successful: sampletests.test122.TestNotMuch.test_2
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: sampletests.test122.TestNotMuch.test_3
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    successful: sampletests.test122.TestNotMuch.test_3
+    tags: -zope:layer:samplelayers.Layer122
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: samplelayers.Layer122:tearDown
+    tags: zope:layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    successful: samplelayers.Layer122:tearDown
+    tags: -zope:layer:samplelayers.Layer12
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: samplelayers.Layer12:tearDown
+    tags: zope:layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    successful: samplelayers.Layer12:tearDown
+    tags: -zope:layer:samplelayers.Layer1
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: samplelayers.Layer1:tearDown
+    tags: zope:layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    successful: samplelayers.Layer1:tearDown
+    False
+
+
+Listing tests
+-------------
+
+A subunit stream is a stream of test results, more or less, so the most
+natural way of listing tests in subunit is to simply emit successful test
+results without actually running the tests.
+
+Note that in this stream, we don't emit fake tests for the layer set up and
+tear down, because it simply doesn't happen.
+
+We also don't include the dependent layers in the stream (in this case Layer1
+and Layer12), since they are not provided to the reporter.
+
+    >>> sys.argv = (
+    ...     'test --layer 122 --list-tests --subunit -t TestNotMuch').split()
+    >>> testrunner.run_internal(defaults)
+    tags: zope:layer:samplelayers.Layer122
+    test: sample1.sampletests.test122.TestNotMuch.test_1
+    successful: sample1.sampletests.test122.TestNotMuch.test_1
+    test: sample1.sampletests.test122.TestNotMuch.test_2
+    successful: sample1.sampletests.test122.TestNotMuch.test_2
+    test: sample1.sampletests.test122.TestNotMuch.test_3
+    successful: sample1.sampletests.test122.TestNotMuch.test_3
+    test: sampletests.test122.TestNotMuch.test_1
+    successful: sampletests.test122.TestNotMuch.test_1
+    test: sampletests.test122.TestNotMuch.test_2
+    successful: sampletests.test122.TestNotMuch.test_2
+    test: sampletests.test122.TestNotMuch.test_3
+    successful: sampletests.test122.TestNotMuch.test_3
+    tags: -zope:layer:samplelayers.Layer122
+    False
+
+
+Profiling tests
+---------------
+
+Test suites often cover a lot of code, and the performance of test suites
+themselves is often a critical part of the development process. Thus, it's
+good to be able to profile a test run.
+
+    >>> sys.argv = (
+    ...     'test --layer 122 --profile=cProfile --subunit '
+    ...     '-t TestNotMuch').split()
+    >>> testrunner.run_internal(defaults)
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: samplelayers.Layer1:setUp
+    ...
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    successful: samplelayers.Layer1:tearDown
+    test: zope:profiler_stats
+    tags: zope:profiler_stats
+    successful: zope:profiler_stats [ multipart
+    Content-Type: application/x-binary-profile
+    profiler-stats
+    ...\r
+    <BLANKLINE>
+    ...
+    <BLANKLINE>
+    ]
+    False
+
+
+Errors
+------
+
+Errors are recorded in the subunit stream as MIME-encoded chunks of text.
+
+    >>> sys.argv = [
+    ...     'test', '--subunit' , '--tests-pattern', '^sampletests_e$',
+    ...     ]
+    >>> testrunner.run_internal(defaults)
+    time: 2010-02-05 15:27:05.113541Z
+    test: zope.testing.testrunner.layer.UnitTests:setUp
+    tags: zope:layer
+    time: 2010-02-05 15:27:05.113545Z
+    successful: zope.testing.testrunner.layer.UnitTests:setUp
+    tags: zope:layer:zope.testing.testrunner.layer.UnitTests
+    test: sample2.sampletests_e.eek
+    failure: sample2.sampletests_e.eek [ multipart
+    Content-Type: text/x-traceback;charset=utf8,language=python
+    traceback
+    4B6\r
+    <BLANKLINE>
+    Failed doctest test for sample2.sampletests_e.eek
+      File "/home/jml/src/zope.testing/subunit-output-formatter/src/zope/testing/testrunner/testrunner-ex/sample2/sampletests_e.py", line 29, in eek
+    <BLANKLINE>
+    ----------------------------------------------------------------------
+    File "/home/jml/src/zope.testing/subunit-output-formatter/src/zope/testing/testrunner/testrunner-ex/sample2/sampletests_e.py", line 31, in sample2.sampletests_e.eek
+    Failed example:
+        f()
+    Exception raised:
+        Traceback (most recent call last):
+          File "/home/jml/src/zope.testing/subunit-output-formatter/src/zope/testing/doctest/__init__.py", line 1355, in __run
+            compileflags, 1) in test.globs
+          File "<doctest sample2.sampletests_e.eek[line 2, example 0]>", line 1, in <module>
+            f()
+          File "/home/jml/src/zope.testing/subunit-output-formatter/src/zope/testing/testrunner/testrunner-ex/sample2/sampletests_e.py", line 19, in f
+            g()
+          File "/home/jml/src/zope.testing/subunit-output-formatter/src/zope/testing/testrunner/testrunner-ex/sample2/sampletests_e.py", line 25, in g
+            x = y + 1
+           - __traceback_info__: I don't know what Y should be.
+        NameError: global name 'y' is not defined
+    0\r
+    <BLANKLINE>
+    ]
+    test: sample2.sampletests_e.Test.test1
+    successful: sample2.sampletests_e.Test.test1
+    test: sample2.sampletests_e.Test.test2
+    successful: sample2.sampletests_e.Test.test2
+    test: sample2.sampletests_e.Test.test3
+    error: sample2.sampletests_e.Test.test3 [ multipart
+    Content-Type: text/x-traceback;charset=utf8,language=python
+    traceback
+    29F\r
+    <BLANKLINE>
+    Traceback (most recent call last):
+      File "/usr/lib/python2.6/unittest.py", line 279, in run
+        testMethod()
+      File "/home/jml/src/zope.testing/subunit-output-formatter/src/zope/testing/testrunner/testrunner-ex/sample2/sampletests_e.py", line 44, in test3
+        f()
+      File "/home/jml/src/zope.testing/subunit-output-formatter/src/zope/testing/testrunner/testrunner-ex/sample2/sampletests_e.py", line 19, in f
+        g()
+      File "/home/jml/src/zope.testing/subunit-output-formatter/src/zope/testing/testrunner/testrunner-ex/sample2/sampletests_e.py", line 25, in g
+        x = y + 1
+       - __traceback_info__: I don't know what Y should be.
+    NameError: global name 'y' is not defined
+    0\r
+    <BLANKLINE>
+    ]
+    test: sample2.sampletests_e.Test.test4
+    successful: sample2.sampletests_e.Test.test4
+    test: sample2.sampletests_e.Test.test5
+    successful: sample2.sampletests_e.Test.test5
+    test: e_txt
+    failure: e_txt [
+    multipart
+    Content-Type: text/x-traceback;charset=utf8,language=python
+    traceback
+    329\r
+    <BLANKLINE>
+    Failed doctest test for e.txt
+      File "/home/jml/src/zope.testing/subunit-output-formatter/src/zope/testing/testrunner/testrunner-ex/sample2/e.txt", line 0
+    <BLANKLINE>
+    ----------------------------------------------------------------------
+    File "/home/jml/src/zope.testing/subunit-output-formatter/src/zope/testing/testrunner/testrunner-ex/sample2/e.txt", line 4, in e.txt
+    Failed example:
+        f()
+    Exception raised:
+        Traceback (most recent call last):
+          File "/home/jml/src/zope.testing/subunit-output-formatter/src/zope/testing/doctest/__init__.py", line 1355, in __run
+            compileflags, 1) in test.globs
+          File "<doctest e.txt[line 4, example 1]>", line 1, in <module>
+            f()
+          File "<doctest e.txt[line 1, example 0]>", line 2, in f
+            return x
+        NameError: global name 'x' is not defined
+    0\r
+    <BLANKLINE>
+    ]
+    tags: -zope:layer:zope.testing.testrunner.layer.UnitTests
+    time: 2010-02-05 15:27:05.147082Z
+    test: zope.testing.testrunner.layer.UnitTests:tearDown
+    tags: zope:layer
+    time: 2010-02-05 15:27:05.147088Z
+    successful: zope.testing.testrunner.layer.UnitTests:tearDown
+    True
+
+
+Layers that can't be torn down
+------------------------------
+
+A layer can have a tearDown method that raises NotImplementedError. If this is
+the case and there are no remaining tests to run, the subunit stream will say
+that the layer skipped its tearDown.
+
+    >>> import os.path, sys
+    >>> directory_with_tests = os.path.join(this_directory, 'testrunner-ex')
+    >>> from zope.testing import testrunner
+    >>> defaults = [
+    ...     '--subunit',
+    ...     '--path', directory_with_tests,
+    ...     '--tests-pattern', '^sampletestsf?$',
+    ...     ]
+
+    >>> sys.argv = 'test -ssample2 --tests-pattern sampletests_ntd$'.split()
+    >>> testrunner.run_internal(defaults)
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: sample2.sampletests_ntd.Layer:setUp
+    tags: zope:layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    successful: sample2.sampletests_ntd.Layer:setUp
+    tags: zope:layer:sample2.sampletests_ntd.Layer
+    test: sample2.sampletests_ntd.TestSomething.test_something
+    successful: sample2.sampletests_ntd.TestSomething.test_something
+    tags: -zope:layer:sample2.sampletests_ntd.Layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: sample2.sampletests_ntd.Layer:tearDown
+    tags: zope:layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    skip: sample2.sampletests_ntd.Layer:tearDown [
+    tearDown not supported
+    ]
+    False
+
+
+Module import errors
+--------------------
+
+We report module import errors too. They get encoded as tests with errors. The
+name of the test is the module that could not be imported, the test's result
+is an error containing the traceback. These "tests" are tagged with
+zope:import_error.
+
+Let's create a module with some bad syntax:
+
+    >>> badsyntax_path = os.path.join(directory_with_tests,
+    ...                               "sample2", "sampletests_i.py")
+    >>> f = open(badsyntax_path, "w")
+    >>> print >> f, "importx unittest"  # syntax error
+    >>> f.close()
+
+And then run the tests:
+
+    >>> sys.argv = (
+    ...     'test --subunit --tests-pattern ^sampletests(f|_i)?$ --layer 1 '
+    ...     ).split()
+    >>> testrunner.run_internal(defaults)
+    test: sample2.sampletests_i
+    tags: zope:import_error
+    error: sample2.sampletests_i [
+    Traceback (most recent call last):
+     testrunner-ex/sample2/sampletests_i.py", line 1
+        importx unittest
+                       ^
+    SyntaxError: invalid syntax
+    ]
+    test: sample2.sample21.sampletests_i
+    tags: zope:import_error
+    error: sample2.sample21.sampletests_i [
+    Traceback (most recent call last):
+     testrunner-ex/sample2/sample21/sampletests_i.py", Line NNN, in ?
+        import zope.testing.huh
+    ImportError: No module named huh
+    ]
+    test: sample2.sample23.sampletests_i
+    tags: zope:import_error
+    error: sample2.sample23.sampletests_i [
+    Traceback (most recent call last):
+     testrunner-ex/sample2/sample23/sampletests_i.py", Line NNN, in ?
+        class Test(unittest.TestCase):
+     testrunner-ex/sample2/sample23/sampletests_i.py", Line NNN, in Test
+        raise TypeError('eek')
+    TypeError: eek
+    ]
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: samplelayers.Layer1:setUp
+    tags: zope:layer
+    ...
+    True
+
+Of course, because we care deeply about test isolation, we're going to have to
+delete the module with bad syntax now, lest it contaminate other tests or even
+future test runs.
+
+    >>> os.unlink(badsyntax_path)
+
+
+Tests in subprocesses
+---------------------
+
+If the tearDown method raises NotImplementedError and there are remaining
+layers to run, the test runner will restart itself as a new process,
+resuming tests where it left off:
+
+    >>> sys.argv = [testrunner_script, '--tests-pattern', 'sampletests_ntd$']
+    >>> testrunner.run_internal(defaults)
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: sample1.sampletests_ntd.Layer:setUp
+    tags: zope:layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    successful: sample1.sampletests_ntd.Layer:setUp
+    tags: zope:layer:sample1.sampletests_ntd.Layer
+    test: sample1.sampletests_ntd.TestSomething.test_something
+    successful: sample1.sampletests_ntd.TestSomething.test_something
+    tags: -zope:layer:sample1.sampletests_ntd.Layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: sample1.sampletests_ntd.Layer:tearDown
+    tags: zope:layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    skip: sample1.sampletests_ntd.Layer:tearDown [
+    tearDown not supported
+    ]
+    test: Running in a subprocess.
+    tags: zope:info_suboptimal
+    successful: Running in a subprocess.
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: sample2.sampletests_ntd.Layer:setUp
+    tags: zope:layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    successful: sample2.sampletests_ntd.Layer:setUp
+    tags: zope:layer:sample2.sampletests_ntd.Layer
+    test: sample2.sampletests_ntd.TestSomething.test_something
+    successful: sample2.sampletests_ntd.TestSomething.test_something
+    tags: -zope:layer:sample2.sampletests_ntd.Layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: sample2.sampletests_ntd.Layer:tearDown
+    tags: zope:layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    skip: sample2.sampletests_ntd.Layer:tearDown [
+    tearDown not supported
+    ]
+    test: Running in a subprocess.
+    tags: zope:info_suboptimal
+    successful: Running in a subprocess.
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: sample3.sampletests_ntd.Layer:setUp
+    tags: zope:layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    successful: sample3.sampletests_ntd.Layer:setUp
+    tags: zope:layer:sample3.sampletests_ntd.Layer
+    test: sample3.sampletests_ntd.TestSomething.test_error1
+    error: sample3.sampletests_ntd.TestSomething.test_error1 [ multipart
+    Content-Type: text/x-traceback;charset=utf8,language=python
+    traceback
+    14F\r
+    <BLANKLINE>
+    Traceback (most recent call last):
+     testrunner-ex/sample3/sampletests_ntd.py", Line NNN, in test_error1
+        raise TypeError("Can we see errors")
+    TypeError: Can we see errors
+    0\r
+    <BLANKLINE>
+    ]
+    test: sample3.sampletests_ntd.TestSomething.test_error2
+    error: sample3.sampletests_ntd.TestSomething.test_error2 [ multipart
+    Content-Type: text/x-traceback;charset=utf8,language=python
+    traceback
+    13F\r
+    <BLANKLINE>
+    Traceback (most recent call last):
+     testrunner-ex/sample3/sampletests_ntd.py", Line NNN, in test_error2
+        raise TypeError("I hope so")
+    TypeError: I hope so
+    0\r
+    <BLANKLINE>
+    ]
+    test: sample3.sampletests_ntd.TestSomething.test_fail1
+    failure: sample3.sampletests_ntd.TestSomething.test_fail1 [ multipart
+    Content-Type: text/x-traceback;charset=utf8,language=python
+    traceback
+    1AA\r
+    <BLANKLINE>
+    Traceback (most recent call last):
+     testrunner-ex/sample3/sampletests_ntd.py", Line NNN, in test_fail1
+        self.assertEqual(1, 2)
+    AssertionError: 1 != 2
+    0\r
+    <BLANKLINE>
+    ]
+    test: sample3.sampletests_ntd.TestSomething.test_fail2
+    failure: sample3.sampletests_ntd.TestSomething.test_fail2 [ multipart
+    Content-Type: text/x-traceback;charset=utf8,language=python
+    traceback
+    1AA\r
+    <BLANKLINE>
+    Traceback (most recent call last):
+     testrunner-ex/sample3/sampletests_ntd.py", Line NNN, in test_fail2
+        self.assertEqual(1, 3)
+    AssertionError: 1 != 3
+    0\r
+    <BLANKLINE>
+    ]
+    test: sample3.sampletests_ntd.TestSomething.test_something
+    successful: sample3.sampletests_ntd.TestSomething.test_something
+    test: sample3.sampletests_ntd.TestSomething.test_something_else
+    successful: sample3.sampletests_ntd.TestSomething.test_something_else
+    tags: -zope:layer:sample3.sampletests_ntd.Layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    test: sample3.sampletests_ntd.Layer:tearDown
+    tags: zope:layer
+    time: YYYY-MM-DD HH:MM:SS.mmmmmmZ
+    skip: sample3.sampletests_ntd.Layer:tearDown [
+    tearDown not supported
+    ]
+    True
+
+Note that debugging doesn't work when running tests in a subprocess:
+
+    >>> sys.argv = [testrunner_script, '--tests-pattern', 'sampletests_ntd$',
+    ...             '-D', ]
+    >>> testrunner.run_internal(defaults)
+    time: 2010-02-10 22:41:25.279692Z
+    test: sample1.sampletests_ntd.Layer:setUp
+    tags: zope:layer
+    time: 2010-02-10 22:41:25.279695Z
+    successful: sample1.sampletests_ntd.Layer:setUp
+    tags: zope:layer:sample1.sampletests_ntd.Layer
+    test: sample1.sampletests_ntd.TestSomething.test_something
+    successful: sample1.sampletests_ntd.TestSomething.test_something
+    tags: -zope:layer:sample1.sampletests_ntd.Layer
+    time: 2010-02-10 22:41:25.310078Z
+    test: sample1.sampletests_ntd.Layer:tearDown
+    tags: zope:layer
+    time: 2010-02-10 22:41:25.310171Z
+    skip: sample1.sampletests_ntd.Layer:tearDown [
+    tearDown not supported
+    ]
+    test: Running in a subprocess.
+    tags: zope:info_suboptimal
+    successful: Running in a subprocess.
+    time: 2010-02-10 22:41:25.753076Z
+    test: sample2.sampletests_ntd.Layer:setUp
+    tags: zope:layer
+    time: 2010-02-10 22:41:25.753079Z
+    successful: sample2.sampletests_ntd.Layer:setUp
+    tags: zope:layer:sample2.sampletests_ntd.Layer
+    test: sample2.sampletests_ntd.TestSomething.test_something
+    successful: sample2.sampletests_ntd.TestSomething.test_something
+    tags: -zope:layer:sample2.sampletests_ntd.Layer
+    time: 2010-02-10 22:41:25.779256Z
+    test: sample2.sampletests_ntd.Layer:tearDown
+    tags: zope:layer
+    time: 2010-02-10 22:41:25.779326Z
+    skip: sample2.sampletests_ntd.Layer:tearDown [
+    tearDown not supported
+    ]
+    test: Running in a subprocess.
+    tags: zope:info_suboptimal
+    successful: Running in a subprocess.
+    time: 2010-02-10 22:41:26.310296Z
+    test: sample3.sampletests_ntd.Layer:setUp
+    tags: zope:layer
+    time: 2010-02-10 22:41:26.310299Z
+    successful: sample3.sampletests_ntd.Layer:setUp
+    tags: zope:layer:sample3.sampletests_ntd.Layer
+    test: sample3.sampletests_ntd.TestSomething.test_error1
+    error: sample3.sampletests_ntd.TestSomething.test_error1 [ multipart
+    Content-Type: text/x-traceback;charset=utf8,language=python
+    traceback
+    16A\r
+    <BLANKLINE>
+    Traceback (most recent call last):
+      File "/usr/lib/python2.6/unittest.py", line 305, in debug
+        getattr(self, self._testMethodName)()
+      File "/home/jml/src/zope.testing/subunit-output-formatter/src/zope/testing/testrunner/testrunner-ex/sample3/sampletests_ntd.py", line 42, in test_error1
+        raise TypeError("Can we see errors")
+    TypeError: Can we see errors
+    0\r
+    <BLANKLINE>
+    ]
+    test: Can't post-mortem debug when running a layer as a subprocess!
+    tags: zope:error_with_banner
+    successful: Can't post-mortem debug when running a layer as a subprocess!
+    test: sample3.sampletests_ntd.TestSomething.test_error2
+    error: sample3.sampletests_ntd.TestSomething.test_error2 [ multipart
+    Content-Type: text/x-traceback;charset=utf8,language=python
+    traceback
+    15A\r
+    <BLANKLINE>
+    Traceback (most recent call last):
+      File "/usr/lib/python2.6/unittest.py", line 305, in debug
+        getattr(self, self._testMethodName)()
+      File "/home/jml/src/zope.testing/subunit-output-formatter/src/zope/testing/testrunner/testrunner-ex/sample3/sampletests_ntd.py", line 45, in test_error2
+        raise TypeError("I hope so")
+    TypeError: I hope so
+    0\r
+    <BLANKLINE>
+    ]
+    test: Can't post-mortem debug when running a layer as a subprocess!
+    tags: zope:error_with_banner
+    successful: Can't post-mortem debug when running a layer as a subprocess!
+    test: sample3.sampletests_ntd.TestSomething.test_fail1
+    error: sample3.sampletests_ntd.TestSomething.test_fail1 [ multipart
+    Content-Type: text/x-traceback;charset=utf8,language=python
+    traceback
+    1C5\r
+    <BLANKLINE>
+    Traceback (most recent call last):
+      File "/usr/lib/python2.6/unittest.py", line 305, in debug
+        getattr(self, self._testMethodName)()
+      File "/home/jml/src/zope.testing/subunit-output-formatter/src/zope/testing/testrunner/testrunner-ex/sample3/sampletests_ntd.py", line 48, in test_fail1
+        self.assertEqual(1, 2)
+      File "/usr/lib/python2.6/unittest.py", line 350, in failUnlessEqual
+        (msg or '%r != %r' % (first, second))
+    AssertionError: 1 != 2
+    0\r
+    <BLANKLINE>
+    ]
+    test: Can't post-mortem debug when running a layer as a subprocess!
+    tags: zope:error_with_banner
+    successful: Can't post-mortem debug when running a layer as a subprocess!
+    test: sample3.sampletests_ntd.TestSomething.test_fail2
+    error: sample3.sampletests_ntd.TestSomething.test_fail2 [ multipart
+    Content-Type: text/x-traceback;charset=utf8,language=python
+    traceback
+    1C5\r
+    <BLANKLINE>
+    Traceback (most recent call last):
+      File "/usr/lib/python2.6/unittest.py", line 305, in debug
+        getattr(self, self._testMethodName)()
+      File "/home/jml/src/zope.testing/subunit-output-formatter/src/zope/testing/testrunner/testrunner-ex/sample3/sampletests_ntd.py", line 51, in test_fail2
+        self.assertEqual(1, 3)
+      File "/usr/lib/python2.6/unittest.py", line 350, in failUnlessEqual
+        (msg or '%r != %r' % (first, second))
+    AssertionError: 1 != 3
+    0\r
+    <BLANKLINE>
+    ]
+    test: Can't post-mortem debug when running a layer as a subprocess!
+    tags: zope:error_with_banner
+    successful: Can't post-mortem debug when running a layer as a subprocess!
+    test: sample3.sampletests_ntd.TestSomething.test_something
+    successful: sample3.sampletests_ntd.TestSomething.test_something
+    test: sample3.sampletests_ntd.TestSomething.test_something_else
+    successful: sample3.sampletests_ntd.TestSomething.test_something_else
+    tags: -zope:layer:sample3.sampletests_ntd.Layer
+    time: 2010-02-10 22:41:26.340878Z
+    test: sample3.sampletests_ntd.Layer:tearDown
+    tags: zope:layer
+    time: 2010-02-10 22:41:26.340945Z
+    skip: sample3.sampletests_ntd.Layer:tearDown [
+    tearDown not supported
+    ]
+    True

=== modified file 'src/zope/testing/testrunner/tests.py'
--- src/zope/testing/testrunner/tests.py	2009-12-18 08:23:21 +0000
+++ src/zope/testing/testrunner/tests.py	2010-03-11 22:36:30 +0000
@@ -103,6 +103,8 @@
         (re.compile(r'\d+[.]\d\d\d seconds'), 'N.NNN seconds'),
         (re.compile(r'\d+[.]\d\d\d s'), 'N.NNN s'),
         (re.compile(r'\d+[.]\d\d\d{'), 'N.NNN{'),
+        (re.compile(r'\d{4}-\d\d-\d\d \d\d:\d\d:\d\d\.\d+'),
+         'YYYY-MM-DD HH:MM:SS.mmmmmm'),
         (re.compile('( |")[^\n]+testrunner-ex'), r'\1testrunner-ex'),
         (re.compile('( |")[^\n]+testrunner.py'), r'\1testrunner.py'),
         (re.compile(r'> [^\n]*(doc|unit)test[.]py\(\d+\)'),
@@ -251,4 +253,29 @@
             checker=checker,
             )
         )
+
+    try:
+        import subunit
+    except ImportError:
+        suites.append(
+            doctest.DocFileSuite(
+                'testrunner-subunit-err.txt',
+                setUp=setUp, tearDown=tearDown,
+                optionflags=doctest.ELLIPSIS + doctest.NORMALIZE_WHITESPACE,
+                checker=checker))
+    else:
+        suites.append(
+            doctest.DocFileSuite(
+                'testrunner-subunit.txt',
+                setUp=setUp, tearDown=tearDown,
+                optionflags=doctest.ELLIPSIS + doctest.NORMALIZE_WHITESPACE,
+                checker=checker))
+        if hasattr(sys, 'gettotalrefcount'):
+            suites.append(
+                doctest.DocFileSuite(
+                    'testrunner-subunit-leaks.txt',
+                    setUp=setUp, tearDown=tearDown,
+                    optionflags=doctest.ELLIPSIS + doctest.NORMALIZE_WHITESPACE,
+                    checker=checker))
+
     return unittest.TestSuite(suites)