Merge lp:~jameinel/bzr/2.3-filter-tests into lp:bzr

[John A Meinel]

Remove 'log' information from "successful" tests

This changes TestCase so that it no longer includes the log information for what we consider to be non-failure cases. Specifically skip, xfail, and n/a.

This should shrink the pqm output considerably (and I'd be willing to backport it to 2.0 if we want it.)

It also should reduce some of the noise when running selftest -v. It doesn't change addSkip to report the 'reason' as a single line like we used to, though I would consider working on that if people would like it. (basically, if the details dict only contains reason, just display it, rather that doing the full formatting dance.)

For a specific example, before:
...tp.BoundSFTPBranch.test_bind_child_ahead_preserves_child(RemoteBranchFormat-v2) SKIP 967ms
Text attachment: log
------------
3.557 creating repository in file:///C:/users/jameinel/appdata/local/temp/testbzr-wo1wlh.tmp/.bzr/.

3.599 creating branch <bzrlib.branch.BzrBranchFormat7 object at 0x02E82690> in file:///C:/users/jam
einel/appdata/local/temp/testbzr-wo1wlh.tmp/
3.721 opening working tree 'C:/users/jameinel/appdata/local/temp/testbzr-wo1wlh.tmp'
3.831 opening working tree 'C:/users/jameinel/appdata/local/temp/testbzr-wo1wlh.tmp'
------------
Text attachment: reason
------------
Not a local URL
------------

after:
...tp.BoundSFTPBranch.test_bind_child_ahead_preserves_child(RemoteBranchFormat-v2) SKIP 200ms
Text attachment: reason
------------
Not a local URL
------------

And, of course, it used to be:
...tp.BoundSFTPBranch.test_bind_child_ahead_preserves_child(RemoteBranchFormat-v2) SKIP 200ms
Not a local URL

I went about it in this fashion, because we add the log (lazily) from setUp. Unfortunately, testtools itself doesn't provide anything like 'discardDetail()'.

The other option would be to figure out how to only add the detail once add(Failure/Error) was called. However, experience from addSkip is that there seem to be race conditions where testtools will have evaluated getDetails before we get a chance to do anything in our code.

I also chose this route so that it works with all possible result classes (--subunit and regular), rather that only patching our TestResult class. (I think if we added 'details' to our addSkip() we could do our own filtering.)

[Robert Collins (lifeless)]

so for skip I think keeping the log is important, it may well have
hints to why something gets skipped beyond the reason; for xfail this
makes sense to me.

Looking at the implementation, I'd rather see discardDetail in
testtools upstream - no need to do it in bzr at all.

But, I don't think its correct, you say that the log becomes part of
the reason, but that doesn't make sense at all.

Whats the size issue with PQM? We don't skip all that many tests...

-Rob

[John A Meinel (jameinel)]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 8/29/2010 3:34 AM, Robert Collins wrote:
> so for skip I think keeping the log is important, it may well have
> hints to why something gets skipped beyond the reason; for xfail this
> makes sense to me.
>
> Looking at the implementation, I'd rather see discardDetail in
> testtools upstream - no need to do it in bzr at all.
>
> But, I don't think its correct, you say that the log becomes part of
> the reason, but that doesn't make sense at all.
>
> Whats the size issue with PQM? We don't skip all that many tests...
>
> -Rob

We skip 2200 tests, and it causes the log file to become 7.2MB in size.
I would consider that both "many tests" and a "large output".

John
=:->
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Cygwin)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAkx6YGsACgkQJdeBCYSNAAPqZwCZAUQod44FAGp2akiiR5mS+5mV
4SkAn0SKZCP/szWfI8gXQbyLE8mWk4p9
=lx8l
-----END PGP SIGNATURE-----

[Martin Packman (gz)]

> It also should reduce some of the noise when running selftest -v. It doesn't
> change addSkip to report the 'reason' as a single line like we used to,
> though I would consider working on that if people would like it. (basically,
> if the details dict only contains reason, just display it, rather that doing
> the full formatting dance.)

The added noise is a straight-up regression from the switch to the testtools api, which I finally got round to filing as bug 625597 a couple of days back. That wants fixing regardless of whether we want to selectively clear logs like this, and mostly means submitting to an ever more testtools oriented style.

I'm not certain that clearing logs is the right thing. Generally I'd think it a bug if skipped tests have long log files. Some tests take a second to run, leak a thread, and just skip anyway.

Overall I think I'd prefer this happened in subunit. Passing tests also have logs, but I'm guessing subunit doesn't show their details at all.

[John A Meinel (jameinel)]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 8/29/2010 3:34 AM, Robert Collins wrote:
> so for skip I think keeping the log is important, it may well have
> hints to why something gets skipped beyond the reason; for xfail this
> makes sense to me.
>
> Looking at the implementation, I'd rather see discardDetail in
> testtools upstream - no need to do it in bzr at all.
>
> But, I don't think its correct, you say that the log becomes part of
> the reason, but that doesn't make sense at all.

            try:
                return addSkip(test, details=details)
            except TypeError:
                # have to convert
                reason = _details_to_str(details)

John
=:->
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Cygwin)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAkx6nNUACgkQJdeBCYSNAAP+aACg1hSD+eXY7BtAHVZkNSgz4sOp
dosAnjvRBFQ8zZ4FNiVwVSMq3HQIk8Cf
=FHMt
-----END PGP SIGNATURE-----

[Robert Collins (lifeless)]

So, 2200 tests is 10% of the total, the other 90% still gather all the logs.

That try:finally: demonstrates that bzr *just needs to update its API*
- its going via the compatibility code path.

[Vincent Ladeuil (vila)]

As a data point, I still can't get any email from PQM on failures.

I just had to reproduce a problem and the raw selftest.log containing the uncompressed,
unfiltered, selftest.log is 47M.

I'm not quite sure about which stream is sent on failure but I suspect it is this one.

So, for debugging purposes, I don't like removing stuff.
But I currently get *nothing* so can we step back a bit and addresses this
problem once and for all ?

Should we send a very short mail on failures with an url to get the whole stream for example ?

[John A Meinel (jameinel)]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 8/29/2010 2:58 PM, Robert Collins wrote:
> So, 2200 tests is 10% of the total, the other 90% still gather all the logs.
>
> That try:finally: demonstrates that bzr *just needs to update its API*
> - its going via the compatibility code path.

except doesn't subunit as well...

But you bring up a good point. I didn't realize that success was also
generating log output, which I would also like to suppress.

It is still 7MB as an email, which means that we are failing to get
failure emails sometimes.

John
=:->
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Cygwin)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAkx71LgACgkQJdeBCYSNAAPeMACgvRlxuJqN+rktJhYl4OhAdRou
fVAAoIO8aM4md+G5J6BkM7BzML9Iapry
=BX5H
-----END PGP SIGNATURE-----

[John A Meinel (jameinel)]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 8/30/2010 9:53 AM, Vincent Ladeuil wrote:
> As a data point, I still can't get any email from PQM on failures.
>
> I just had to reproduce a problem and the raw selftest.log containing the uncompressed,
> unfiltered, selftest.log is 47M.
>
> I'm not quite sure about which stream is sent on failure but I suspect it is this one.
>
> So, for debugging purposes, I don't like removing stuff.
> But I currently get *nothing* so can we step back a bit and addresses this
> problem once and for all ?
>
> Should we send a very short mail on failures with an url to get the whole stream for example ?

Do you really feel that including the log output for xfail, skip, and
success is adding useful info? *I* feel it is just adding a lot of noise
with almost 0 signal...

I guess we've reached the point of
a) Bringing it to the main list.
b) Intelligent people disagreeing, so we need a vote/proclamation to
resolve.

John
=:->
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Cygwin)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAkx71QQACgkQJdeBCYSNAAN00ACgg+SJtQXxn82gzddD4lwbC7oR
bhwAoMQCynk7MyVt/YTocoGwePfBVxAz
=aQpv
-----END PGP SIGNATURE-----

[Vincent Ladeuil (vila)]

>>>>> John Arbash Meinel <email address hidden> writes:

    > On 8/30/2010 9:53 AM, Vincent Ladeuil wrote:
    >> As a data point, I still can't get any email from PQM on failures.
    >>
    >> I just had to reproduce a problem and the raw selftest.log containing the uncompressed,
    >> unfiltered, selftest.log is 47M.
    >>
    >> I'm not quite sure about which stream is sent on failure but I suspect it is this one.
    >>
    >> So, for debugging purposes, I don't like removing stuff.
    >> But I currently get *nothing* so can we step back a bit and addresses this
    >> problem once and for all ?
    >>
    >> Should we send a very short mail on failures with an url to get the whole stream for example ?

    > Do you really feel that including the log output for xfail, skip, and
    > success is adding useful info?

No. But you forgot 'not applicable' :-P

    > *I* feel it is just adding a lot of noise with almost 0 signal...

Right, so ISTM that we agree about two things:

- we want the list of tests and their status (pass/fail/skip etc.)
- we care about log only for failures.

Don't we get that by simply *not* using subunit on pqm ?

Or is pqm.bazaar-cvs.org *requiring* subunit ?

[Robert Collins (lifeless)]

we did two simultaneous things a while back:
 - turned off -1, so that we get *all* failures
 - turned on subunit, so that the failures are machine driven

The emails are meant to be compressed, so you should in principle be
able get it reliably.

If we're actually running into mailer limits, we can do a few things:
 - turn off subunit (will reduce some of the overhead - lots in a
success case, but in a it-all-goes-pear-shaped failure, you'll still
hit the limit and whatever undiagnosed and unfixed issue is biting you
now, will bite you then.
 - diagnose and fix the mailer path issue so that you receive the mails reliably
 - stop using email to send the results
 - filter the stream at source so success and other results that you
consider uninteresting are not included in the 'raw' stream. Note that
again, this will *leave the failure mode in place so when it goes bad
you will stop getting the responses*

Now, I'm not directly experiencing this anymore, so you need to do
what makes sense to you.

If subunit's API is out of date and messing up the reason formatting,
I'll happily fix it - I'm going to go peek and see if its addSkip is
stale right after mailing this.

To stop using email to send the results, we either need to design a
new thing and change PQM to do it, or reenable the LP API support,
which Tim requested we disable.

We previously *haven't* filtered at source as a defensive measure
against bugs. Python 2 is riddled with default-encoding pitfalls and
they made subunit + bzr very unreliable at one point. Possibly totally
fixed thanks to Martin[gz].

Personally, I would not take any action that leaves the problem fallow
waiting for a serious test failure to provoke it: that just means that
when you need it most it will fail. However, as I say above: you're
using this system, I'm rarely using it : do what makes sense to you. I
do strongly suggest that you change things in PQM itself if you want
filtering, rather than bzr. That will at least preserve the detailed
output for babune if you do need it in future.

As for the value of logs on success, xfail, skip etc : *if* they pass
incorrectly, I think the log will be invaluable, but you won't need it
till you need it.

-Rob

[Vincent Ladeuil (vila)]

>>>>> Robert Collins <email address hidden> writes:

    > we did two simultaneous things a while back:
    > - turned off -1, so that we get *all* failures

+1

    > - turned on subunit, so that the failures are machine driven

ECANTPARSE

    > The emails are meant to be compressed, so you should in principle
    > be able get it reliably.

In practice I only get failures for merge errors, any error in the test
suite and... it's not delivered.

    > If we're actually running into mailer limits, we can do a few
    > things:

    > - turn off subunit (will reduce some of the overhead - lots in a
    > success case, but in a it-all-goes-pear-shaped failure, you'll
    > still hit the limit and whatever undiagnosed and unfixed issue is
    > biting you now, will bite you then.

Yup, exactly my feeling.

    > - diagnose and fix the mailer path issue so that you receive the
    > mails reliably

As a data point, John got an email for a failure and *I* didn't get it
for the same failure (or so very closely the same failure that the
difference doesn't matter).

This means the problem is on my side but I don't know where exactly. I
use fetchmail and there is *nothing* in the logs so that also rules out
the delivery part. That leaves my ISP mail server... and I don't control
it. That's me, but it could apply to anybody else, we just don't know.

    > - stop using email to send the results

Or store the results somewhere (deleting them after a day/week/month
whatever).

Or send two mails:
- one indicating the failure
- one with the stream attached.

At least with that I will *know* there was a failure.

    > - filter the stream at source so success and other results that
    > you consider uninteresting are not included in the 'raw'
    > stream. Note that again, this will *leave the failure mode in
    > place so when it goes bad you will stop getting the responses*

Another idea would be to have a different pqm instance used only for
known failures and make the output for the regular pqm includes only
*failures* and get rid of *all* the rest.

    > Now, I'm not directly experiencing this anymore, so you need to do
    > what makes sense to you.

Thanks for your thoughts anyway.

    > If subunit's API is out of date and messing up the reason
    > formatting, I'll happily fix it - I'm going to go peek and see if
    > its addSkip is stale right after mailing this.

Cool, any feedback ?

    > To stop using email to send the results, we either need to design
    > a new thing and change PQM to do it, or reenable the LP API
    > support, which Tim requested we disable.

And what would that give us ? Failed run stream attached to the mp as an
attachment ?

    > We previously *haven't* filtered at source as a defensive measure
    > against bugs. Python 2 is riddled with default-encoding pitfalls
    > and they made subunit + bzr very unreliable at one point. Possibly
    > totally fixed thanks to Martin[gz].

I still expect a few (tiny but annoying) bugs to be fixed there...

    > Personally, I would not take any action that leaves the problem
    > fallow waiting for a serious test failure to provoke it: that just
    > means tha...

[John A Meinel (jameinel)]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

...

> > - turn off subunit (will reduce some of the overhead - lots in a
> > success case, but in a it-all-goes-pear-shaped failure, you'll
> > still hit the limit and whatever undiagnosed and unfixed issue is
> > biting you now, will bite you then.
>
> Yup, exactly my feeling.
>
> > - diagnose and fix the mailer path issue so that you receive the
> > mails reliably
>
> As a data point, John got an email for a failure and *I* didn't get it
> for the same failure (or so very closely the same failure that the
> difference doesn't matter).

Right. For that 'failure' there was a single test failing. And the size
of the compressed log is 3.2MB, which makes it about 7MB according to
Thunderbird. (Figure base64 encoding, and ?).

It is true that if you have a huge 'everything fails' case, you'll still
get into that range. Though I did have one of those recently that broke
the 10MB barrier and caused the mail to fail to reach me. Which was,
indeed, much harder for me to track down and fix.

However, getting rid of 7MB (of compressed+base64) success content would
get a lot more headroom for when a few tests fail (or even a few hundred
fail).

...

> > To stop using email to send the results, we either need to design
> > a new thing and change PQM to do it, or reenable the LP API
> > support, which Tim requested we disable.
>
> And what would that give us ? Failed run stream attached to the mp as an
> attachment ?

I don't think you can attach stuff to an MP. I think it would actually
try to set it as a message...

John
=:->
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Cygwin)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAkx9JG0ACgkQJdeBCYSNAAMWcQCgrPHen1zB4dpr7AR1vJToTKxc
3BwAnR8AFECkruco07VCTPhTpFYFu8Xt
=jceX
-----END PGP SIGNATURE-----

[Martin Pool (mbp)]

This is now a couple of weeks old and I'd like to wrap it up.

I think it would be reasonable to merge it, and at least see what we think about it. I cannot recall looking at the logs attached to an xfail, skip or notapplicable test for a long time. The normal and common thing is that they'll have a fairly selfexplanatory message about being either known broken, or skipped because of a missing dependency, or whatever. In the source, the code that raises that exception is normally pretty obvious. If the test is being wrongly skipped, then the logs probably won't help and you need to dig in with pdb or something.

There is some unhelpful data logged by bzr and we could push down on that too.

On the whole I'm ok to merge this; it seems like it's just a couple of lines to turn it back on if we need to.

review: Approve

[Martin Packman (gz)]

If this is going to land, there are some things that should really be fixed first.

+ self._suppress_log ()

No space.

+ def _report_skip(self, result, e):

Rather than adding this, put the call in _do_skip instead?

ExtendedTestResult.addSuccess appears to have a similar hack spelt in a different way:

        test._log_contents = ''

Remove that and add your new version instead?

Would really like some kind of test.

review: Needs Fixing

[Martin Packman (gz)]

On 22/09/2010, John Arbash Meinel <email address hidden> wrote:
>>
>> + def _report_skip(self, result, e):
>>
>> Rather than adding this, put the call in _do_skip instead?
>
> IIRC, there was a reason to put it in _report_skip. I don't remember
> exactly, but I think it was that _report_skip gets called for all code
> paths, but _do_skip doesn't. (NotAvailable, vs Skip, vs XFAIL?)

I think this is true for fallbacks, but we shouldn't be using any? If
it does need doing this way explaining why in the docstring would be
good.

>> ExtendedTestResult.addSuccess appears to have a similar hack spelt in a
>> different way:
>>
>> test._log_contents = ''
>>
>> Remove that and add your new version instead?
>
> Given that that one doesn't actually seem to work, I guess that would be
> reasonable.

Removing the log from successes would be the biggest win as you've noted.

>> Would really like some kind of test.
>
> I think I can work something out in test_selftest, about what details
> are present in the final result. I'll give it a poke and see what I get.
>
> I'd certainly also like to suppress the log details for success cases.
>
> John
> =:->

[John A Meinel (jameinel)]

Please re-review. I've:

a) Added tests about details, etc, when running locally
b) Added tests for what is contained in the subunit stream
c) Hopefully updated the docs sufficiently for Martin [gz].

[lp:~jameinel/bzr/2.3-filter-tests]

5391. By John A Meinel on 2010-09-24

Add tests for when we should and shouldn't get a 'log' in the details.

I'm not 100% happy, because sometimes we test the formatted stuff, and sometimes
we test the raw test object. But that seems to be how the apis work.

5392. By John A Meinel on 2010-09-24

add a failing test that the subunit stream doesn't contain the log info.

5393. By John A Meinel on 2010-09-25

Do a full test suite against all the subunit permutations.

[Martin Packman (gz)]

Let's land this. The tests are worth having even when the bzrlib ExtendedTestResult class is fixed to print less junk on the console or subunit starts being pickier about what it does with success results.

A couple of notes. Thanks for the reasoning for _report_skip, makes it clear the method can probably be removed when the bzrlib/testtools boundary starts treating exceptions properly. The new tests that use testtools.TestResult rather than ExtendedTestResult check some things that would fail if the class switched because the behaviours are still quite different in a number of areas, but they should probably be converging anyway.

review: Approve

[lp:~jameinel/bzr/2.3-filter-tests]

5394. By John A Meinel on 2010-09-25

Merge bzr.dev 5444 to resolve some small text conflicts.

5395. By John A Meinel on 2010-09-25

NEWS entry

5396. By John A Meinel on 2010-09-25

Have to handle when details is None

[John A Meinel (jameinel)]

I did a quick test run with an artificially failing test, and I saw that it did help, a lot. 7.3MB down to 1.3MB for the email. (Email size, not size of .gz not uncompressed size)

[John A Meinel (jameinel)]

sent to pqm by email

=== modified file 'NEWS'
--- NEWS	2010-09-24 12:53:00 +0000
+++ NEWS	2010-09-26 14:05:09 +0000
@@ -42,6 +42,10 @@
 Internals
 *********
 
+* When running ``bzr selftest --subunit`` the subunit stream will no
+  longer include the "log" information for tests which are considered to
+  be 'successes' (success, xfail, skip, etc) (John Arbash Meinel)
+
 Testing
 *******
 

=== modified file 'bzrlib/lazy_import.py'
--- bzrlib/lazy_import.py	2010-09-05 17:15:46 +0000
+++ bzrlib/lazy_import.py	2010-09-26 14:05:09 +0000
@@ -1,4 +1,4 @@
-# Copyright (C) 2006 Canonical Ltd
+# Copyright (C) 2006-2010 Canonical Ltd
 #
 # This program is free software; you can redistribute it and/or modify
 # it under the terms of the GNU General Public License as published by

=== modified file 'bzrlib/shelf.py'
--- bzrlib/shelf.py	2010-09-24 15:11:57 +0000
+++ bzrlib/shelf.py	2010-09-26 14:05:09 +0000
@@ -1,4 +1,4 @@
-# Copyright (C) 2008 Canonical Ltd
+# Copyright (C) 2008, 2009, 2010 Canonical Ltd
 #
 # This program is free software; you can redistribute it and/or modify
 # it under the terms of the GNU General Public License as published by

=== modified file 'bzrlib/strace.py'
--- bzrlib/strace.py	2010-09-01 19:38:55 +0000
+++ bzrlib/strace.py	2010-09-26 14:05:09 +0000
@@ -1,4 +1,4 @@
-# Copyright (C) 2007 Canonical Ltd
+# Copyright (C) 2007, 2009, 2010 Canonical Ltd
 #   Authors: Robert Collins <[e-mail]>
 #
 # This program is free software; you can redistribute it and/or modify

=== modified file 'bzrlib/tests/__init__.py'
--- bzrlib/tests/__init__.py	2010-09-17 14:27:27 +0000
+++ bzrlib/tests/__init__.py	2010-09-26 14:05:09 +0000
@@ -846,6 +846,22 @@
         import pdb
         pdb.Pdb().set_trace(sys._getframe().f_back)
 
+    def discardDetail(self, name):
+        """Extend the addDetail, getDetails api so we can remove a detail.
+
+        eg. bzr always adds the 'log' detail at startup, but we don't want to
+        include it for skipped, xfail, etc tests.
+
+        It is safe to call this for a detail that doesn't exist, in case this
+        gets called multiple times.
+        """
+        # We cheat. details is stored in __details which means we shouldn't
+        # touch it. but getDetails() returns the dict directly, so we can
+        # mutate it.
+        details = self.getDetails()
+        if name in details:
+            del details[name]
+
     def _clear_debug_flags(self):
         """Prevent externally set debug flags affecting tests.
 
@@ -1569,7 +1585,12 @@
         """This test has failed for some known reason."""
         raise KnownFailure(reason)
 
+    def _suppress_log(self):
+        """Remove the log info from details."""
+        self.discardDetail('log')
+
     def _do_skip(self, result, reason):
+        self._suppress_log()
         addSkip = getattr(result, 'addSkip', None)
         if not callable(addSkip):
             result.addSuccess(result)
@@ -1578,6 +1599,7 @@
 
     @staticmethod
     def _do_known_failure(self, result, e):
+        self._suppress_log()
         err = sys.exc_info()
         addExpectedFailure = getattr(result, 'addExpectedFailure', None)
         if addExpectedFailure is not None:
@@ -1591,6 +1613,7 @@
             reason = 'No reason given'
         else:
             reason = e.args[0]
+        self._suppress_log ()
         addNotApplicable = getattr(result, 'addNotApplicable', None)
         if addNotApplicable is not None:
             result.addNotApplicable(self, reason)
@@ -1598,8 +1621,29 @@
             self._do_skip(result, reason)
 
     @staticmethod
+    def _report_skip(self, result, err):
+        """Override the default _report_skip.
+
+        We want to strip the 'log' detail. If we waint until _do_skip, it has
+        already been formatted into the 'reason' string, and we can't pull it
+        out again.
+        """
+        self._suppress_log()
+        super(TestCase, self)._report_skip(self, result, err)
+
+    @staticmethod
+    def _report_expected_failure(self, result, err):
+        """Strip the log.
+
+        See _report_skip for motivation.
+        """
+        self._suppress_log()
+        super(TestCase, self)._report_expected_failure(self, result, err)
+
+    @staticmethod
     def _do_unsupported_or_skip(self, result, e):
         reason = e.args[0]
+        self._suppress_log()
         addNotSupported = getattr(result, 'addNotSupported', None)
         if addNotSupported is not None:
             result.addNotSupported(self, reason)
@@ -4459,10 +4503,20 @@
 try:
     from subunit import TestProtocolClient
     from subunit.test_results import AutoTimingTestResultDecorator
+    class SubUnitBzrProtocolClient(TestProtocolClient):
+
+        def addSuccess(self, test, details=None):
+            # The subunit client always includes the details in the subunit
+            # stream, but we don't want to include it in ours.
+            if details is not None and 'log' in details:
+                del details['log']
+            return super(SubUnitBzrProtocolClient, self).addSuccess(
+                test, details)
+
     class SubUnitBzrRunner(TextTestRunner):
         def run(self, test):
             result = AutoTimingTestResultDecorator(
-                TestProtocolClient(self.stream))
+                SubUnitBzrProtocolClient(self.stream))
             test.run(result)
             return result
 except ImportError:

=== modified file 'bzrlib/tests/per_bzrdir/__init__.py'
--- bzrlib/tests/per_bzrdir/__init__.py	2010-08-29 14:37:51 +0000
+++ bzrlib/tests/per_bzrdir/__init__.py	2010-09-26 14:05:09 +0000
@@ -1,4 +1,4 @@
-# Copyright (C) 2006-2010 Canonical Ltd
+# Copyright (C) 2010 Canonical Ltd
 # Authors: Robert Collins <[e-mail]>
 #          Jelmer Vernooij <[e-mail]>
 # -*- coding: utf-8 -*-

=== modified file 'bzrlib/tests/per_bzrdir/test_bzrdir.py'
--- bzrlib/tests/per_bzrdir/test_bzrdir.py	2010-08-29 15:03:22 +0000
+++ bzrlib/tests/per_bzrdir/test_bzrdir.py	2010-09-26 14:05:09 +0000
@@ -1,4 +1,4 @@
-# Copyright (C) 2006-2010 Canonical Ltd
+# Copyright (C) 2010 Canonical Ltd
 #
 # This program is free software; you can redistribute it and/or modify
 # it under the terms of the GNU General Public License as published by

=== modified file 'bzrlib/tests/test_bugtracker.py'
--- bzrlib/tests/test_bugtracker.py	2010-09-06 19:12:52 +0000
+++ bzrlib/tests/test_bugtracker.py	2010-09-26 14:05:09 +0000
@@ -1,4 +1,4 @@
-# Copyright (C) 2007 Canonical Ltd
+# Copyright (C) 2007-2010 Canonical Ltd
 #
 # This program is free software; you can redistribute it and/or modify
 # it under the terms of the GNU General Public License as published by

=== modified file 'bzrlib/tests/test_lazy_import.py'
--- bzrlib/tests/test_lazy_import.py	2010-09-05 17:15:46 +0000
+++ bzrlib/tests/test_lazy_import.py	2010-09-26 14:05:09 +0000
@@ -1,4 +1,4 @@
-# Copyright (C) 2006 Canonical Ltd
+# Copyright (C) 2006-2010 Canonical Ltd
 #
 # This program is free software; you can redistribute it and/or modify
 # it under the terms of the GNU General Public License as published by

=== modified file 'bzrlib/tests/test_rio.py'
--- bzrlib/tests/test_rio.py	2010-09-06 06:13:52 +0000
+++ bzrlib/tests/test_rio.py	2010-09-26 14:05:09 +0000
@@ -1,4 +1,4 @@
-# Copyright (C) 2005, 2006 Canonical Ltd
+# Copyright (C) 2005, 2006, 2007, 2009, 2010 Canonical Ltd
 #
 # This program is free software; you can redistribute it and/or modify
 # it under the terms of the GNU General Public License as published by

=== modified file 'bzrlib/tests/test_selftest.py'
--- bzrlib/tests/test_selftest.py	2010-09-17 14:27:27 +0000
+++ bzrlib/tests/test_selftest.py	2010-09-26 14:05:09 +0000
@@ -68,7 +68,7 @@
     test_sftp_transport,
     TestUtil,
     )
-from bzrlib.trace import note
+from bzrlib.trace import note, mutter
 from bzrlib.transport import memory
 from bzrlib.version import _get_bzr_source_tree
 
@@ -1690,6 +1690,108 @@
         self.assertEqual('original', obj.test_attr)
 
 
+class _MissingFeature(tests.Feature):
+    def _probe(self):
+        return False
+missing_feature = _MissingFeature()
+
+
+def _get_test(name):
+    """Get an instance of a specific example test.
+
+    We protect this in a function so that they don't auto-run in the test
+    suite.
+    """
+
+    class ExampleTests(tests.TestCase):
+
+        def test_fail(self):
+            mutter('this was a failing test')
+            self.fail('this test will fail')
+
+        def test_error(self):
+            mutter('this test errored')
+            raise RuntimeError('gotcha')
+
+        def test_missing_feature(self):
+            mutter('missing the feature')
+            self.requireFeature(missing_feature)
+
+        def test_skip(self):
+            mutter('this test will be skipped')
+            raise tests.TestSkipped('reason')
+
+        def test_success(self):
+            mutter('this test succeeds')
+
+        def test_xfail(self):
+            mutter('test with expected failure')
+            self.knownFailure('this_fails')
+
+        def test_unexpected_success(self):
+            mutter('test with unexpected success')
+            self.expectFailure('should_fail', lambda: None)
+
+    return ExampleTests(name)
+
+
+class TestTestCaseLogDetails(tests.TestCase):
+
+    def _run_test(self, test_name):
+        test = _get_test(test_name)
+        result = testtools.TestResult()
+        test.run(result)
+        return result
+
+    def test_fail_has_log(self):
+        result = self._run_test('test_fail')
+        self.assertEqual(1, len(result.failures))
+        result_content = result.failures[0][1]
+        self.assertContainsRe(result_content, 'Text attachment: log')
+        self.assertContainsRe(result_content, 'this was a failing test')
+
+    def test_error_has_log(self):
+        result = self._run_test('test_error')
+        self.assertEqual(1, len(result.errors))
+        result_content = result.errors[0][1]
+        self.assertContainsRe(result_content, 'Text attachment: log')
+        self.assertContainsRe(result_content, 'this test errored')
+
+    def test_skip_has_no_log(self):
+        result = self._run_test('test_skip')
+        self.assertEqual(['reason'], result.skip_reasons.keys())
+        skips = result.skip_reasons['reason']
+        self.assertEqual(1, len(skips))
+        test = skips[0]
+        self.assertFalse('log' in test.getDetails())
+
+    def test_missing_feature_has_no_log(self):
+        # testtools doesn't know about addNotSupported, so it just gets
+        # considered as a skip
+        result = self._run_test('test_missing_feature')
+        self.assertEqual([missing_feature], result.skip_reasons.keys())
+        skips = result.skip_reasons[missing_feature]
+        self.assertEqual(1, len(skips))
+        test = skips[0]
+        self.assertFalse('log' in test.getDetails())
+
+    def test_xfail_has_no_log(self):
+        result = self._run_test('test_xfail')
+        self.assertEqual(1, len(result.expectedFailures))
+        result_content = result.expectedFailures[0][1]
+        self.assertNotContainsRe(result_content, 'Text attachment: log')
+        self.assertNotContainsRe(result_content, 'test with expected failure')
+
+    def test_unexpected_success_has_log(self):
+        result = self._run_test('test_unexpected_success')
+        self.assertEqual(1, len(result.unexpectedSuccesses))
+        # Inconsistency, unexpectedSuccesses is a list of tests,
+        # expectedFailures is a list of reasons?
+        test = result.unexpectedSuccesses[0]
+        details = test.getDetails()
+        self.assertTrue('log' in details)
+
+
 class TestTestCloning(tests.TestCase):
     """Tests that test cloning of TestCases (as used by multiply_tests)."""
 
@@ -1883,7 +1985,7 @@
                 tree.branch.repository.bzrdir.root_transport)
 
 
-class SelfTestHelper:
+class SelfTestHelper(object):
 
     def run_selftest(self, **kwargs):
         """Run selftest returning its output."""
@@ -2040,6 +2142,83 @@
             load_list='missing file name', list_only=True)
 
 
+class TestSubunitLogDetails(tests.TestCase, SelfTestHelper):
+
+    _test_needs_features = [features.subunit]
+
+    def run_subunit_stream(self, test_name):
+        from subunit import ProtocolTestCase
+        def factory():
+            return TestUtil.TestSuite([_get_test(test_name)])
+        stream = self.run_selftest(runner_class=tests.SubUnitBzrRunner,
+            test_suite_factory=factory)
+        test = ProtocolTestCase(stream)
+        result = testtools.TestResult()
+        test.run(result)
+        content = stream.getvalue()
+        return content, result
+
+    def test_fail_has_log(self):
+        content, result = self.run_subunit_stream('test_fail')
+        self.assertEqual(1, len(result.failures))
+        self.assertContainsRe(content, '(?m)^log$')
+        self.assertContainsRe(content, 'this test will fail')
+
+    def test_error_has_log(self):
+        content, result = self.run_subunit_stream('test_error')
+        self.assertContainsRe(content, '(?m)^log$')
+        self.assertContainsRe(content, 'this test errored')
+
+    def test_skip_has_no_log(self):
+        content, result = self.run_subunit_stream('test_skip')
+        self.assertNotContainsRe(content, '(?m)^log$')
+        self.assertNotContainsRe(content, 'this test will be skipped')
+        self.assertEqual(['reason'], result.skip_reasons.keys())
+        skips = result.skip_reasons['reason']
+        self.assertEqual(1, len(skips))
+        test = skips[0]
+        # RemotedTestCase doesn't preserve the "details"
+        ## self.assertFalse('log' in test.getDetails())
+
+    def test_missing_feature_has_no_log(self):
+        content, result = self.run_subunit_stream('test_missing_feature')
+        self.assertNotContainsRe(content, '(?m)^log$')
+        self.assertNotContainsRe(content, 'missing the feature')
+        self.assertEqual(['_MissingFeature\n'], result.skip_reasons.keys())
+        skips = result.skip_reasons['_MissingFeature\n']
+        self.assertEqual(1, len(skips))
+        test = skips[0]
+        # RemotedTestCase doesn't preserve the "details"
+        ## self.assertFalse('log' in test.getDetails())
+
+    def test_xfail_has_no_log(self):
+        content, result = self.run_subunit_stream('test_xfail')
+        self.assertNotContainsRe(content, '(?m)^log$')
+        self.assertNotContainsRe(content, 'test with expected failure')
+        self.assertEqual(1, len(result.expectedFailures))
+        result_content = result.expectedFailures[0][1]
+        self.assertNotContainsRe(result_content, 'Text attachment: log')
+        self.assertNotContainsRe(result_content, 'test with expected failure')
+
+    def test_unexpected_success_has_log(self):
+        content, result = self.run_subunit_stream('test_unexpected_success')
+        self.assertContainsRe(content, '(?m)^log$')
+        self.assertContainsRe(content, 'test with unexpected success')
+        self.expectFailure('subunit treats "unexpectedSuccess"'
+                           ' as a plain success',
+            self.assertEqual, 1, len(result.unexpectedSuccesses))
+        self.assertEqual(1, len(result.unexpectedSuccesses))
+        test = result.unexpectedSuccesses[0]
+        # RemotedTestCase doesn't preserve the "details"
+        ## self.assertTrue('log' in test.getDetails())
+
+    def test_success_has_no_log(self):
+        content, result = self.run_subunit_stream('test_success')
+        self.assertEqual(1, result.testsRun)
+        self.assertNotContainsRe(content, '(?m)^log$')
+        self.assertNotContainsRe(content, 'this test succeeds')
+
+
 class TestRunBzr(tests.TestCase):
 
     out = ''

=== modified file 'bzrlib/tests/test_setup.py'
--- bzrlib/tests/test_setup.py	2010-09-02 00:49:06 +0000
+++ bzrlib/tests/test_setup.py	2010-09-26 14:05:09 +0000
@@ -1,4 +1,4 @@
-# Copyright (C) 2005, 2006 Canonical Ltd
+# Copyright (C) 2005, 2006, 2008, 2009, 2010 Canonical Ltd
 #
 # This program is free software; you can redistribute it and/or modify
 # it under the terms of the GNU General Public License as published by

=== modified file 'bzrlib/tests/test_status.py'
--- bzrlib/tests/test_status.py	2010-08-31 13:49:48 +0000
+++ bzrlib/tests/test_status.py	2010-09-26 14:05:09 +0000
@@ -1,4 +1,4 @@
-# Copyright (C) 2005 Canonical Ltd
+# Copyright (C) 2006-2010 Canonical Ltd
 #
 # This program is free software; you can redistribute it and/or modify
 # it under the terms of the GNU General Public License as published by

=== modified file 'bzrlib/tests/test_strace.py'
--- bzrlib/tests/test_strace.py	2010-09-01 19:38:55 +0000
+++ bzrlib/tests/test_strace.py	2010-09-26 14:05:09 +0000
@@ -1,4 +1,4 @@
-# Copyright (C) 2007, 2010 Canonical Ltd
+# Copyright (C) 2007-2010 Canonical Ltd
 #
 # This program is free software; you can redistribute it and/or modify
 # it under the terms of the GNU General Public License as published by

=== modified file 'bzrlib/tests/test_tuned_gzip.py'
--- bzrlib/tests/test_tuned_gzip.py	2010-08-29 18:29:22 +0000
+++ bzrlib/tests/test_tuned_gzip.py	2010-09-26 14:05:09 +0000
@@ -1,4 +1,4 @@
-# Copyright (C) 2006 Canonical Ltd
+# Copyright (C) 2006, 2009, 2010 Canonical Ltd
 #
 # This program is free software; you can redistribute it and/or modify
 # it under the terms of the GNU General Public License as published by

=== modified file 'bzrlib/tests/testui.py'
--- bzrlib/tests/testui.py	2010-09-14 08:14:22 +0000
+++ bzrlib/tests/testui.py	2010-09-26 14:05:09 +0000
@@ -1,4 +1,4 @@
-# Copyright (C) 2006-2010 Canonical Ltd
+# Copyright (C) 2010 Canonical Ltd
 #
 # This program is free software; you can redistribute it and/or modify
 # it under the terms of the GNU General Public License as published by

=== modified file 'bzrlib/tuned_gzip.py'
--- bzrlib/tuned_gzip.py	2010-08-29 18:30:45 +0000
+++ bzrlib/tuned_gzip.py	2010-09-26 14:05:09 +0000
@@ -1,4 +1,4 @@
-# Copyright (C) 2005, 2006 Canonical Ltd
+# Copyright (C) 2006-2010 Canonical Ltd
 # Written by Robert Collins <[e-mail]>
 #
 # This program is free software; you can redistribute it and/or modify