Merge lp:~mbp/bzr/test-errors into lp:bzr

[Martin Pool]

multiple selftest improvements: print errors once; no traceback for xfail; no empty logs (bug 499713, bug 625597)

A few selftest annoyances fixed:

* Errors are printed only once, as they occur, not again at the end.
  If someone actually really likes this, the code is there and you can
  add a configuration to turn it on. (See bug 408192, bug 625597, though
  this is not exactly what was discussed.)

* UnicodeOrBytesToBytesWriter had the somewhat confusing behavior of
  printing the repr of the wrapped object.

* The indentation of test failures did not fit well with testtools' behavior
  of returning the whole traceback as part of the error string.

* We shouldn't print the whole traceback for known failures. Just
  the reason string is enough. (Bug 499713)

* To let the unicode-escaping code work, we need to pass it the error
  as a unicode string.

* Don't attach empty log files; as a consequence the log is not attached
  until the test completes. (However, it can still be read from
  TestCase.get_log()).

* Bugs in old subunits do not deserve a 'known failure' in bzr. Only
  things we could fix (without time travel) should get that.

[John A Meinel (jameinel)]

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

On 6/14/2011 5:51 AM, Martin Pool wrote:
> Martin Pool has proposed merging lp:~mbp/bzr/test-errors into lp:bzr.
>
> Requested reviews:
> bzr-core (bzr-core)
>
> For more details, see:
> https://code.launchpad.net/~mbp/bzr/test-errors/+merge/64485
>
> A few selftest annoyances fixed:
>
> * Errors are printed only once, as they occur, not again at the end.
> If someone actually really likes this, the code is there and you can
> add a configuration to turn it on. (See bug 408192, bug 625597, though
> this is not exactly what was discussed.)
>
> * UnicodeOrBytesToBytesWriter had the somewhat confusing behavior of
> printing the repr of the wrapped object.
>
> * The indentation of test failures did not fit well with testtools' behavior
> of returning the whole traceback as part of the error string.
>
> * We shouldn't print the whole traceback for known failures. Just
> the reason string is enough. (Bug 499713)

Yay!

>
> * To let the unicode-escaping code work, we need to pass it the error
> as a unicode string.
>
> * Don't attach empty log files; as a consequence the log is not attached
> until the test completes. (However, it can still be read from
> TestCase.get_log()).

This also seems nice.

>
> * Bugs in old subunits do not deserve a 'known failure' in bzr. Only
> things we could fix (without time travel) should get that.

"We know this fails under these conditions", that seems like known
failure to me. However, I guess it could just be skipped.

Anyway, the code all looks good to me.

 merge: approve

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

iEYEARECAAYFAk33eXgACgkQJdeBCYSNAAMXzgCaAik/3rhrICt85tsgBYVf584Z
hGUAoNC7d66TJ+xGIQYtT2GU85REikDc
=hh8p
-----END PGP SIGNATURE-----

review: Approve

[Martin Pool (mbp)]

On 14 June 2011 08:08, John Arbash Meinel <email address hidden> wrote:
>> * Bugs in old subunits do not deserve a 'known failure' in bzr.  Only
>>   things we could fix (without time travel) should get that.
>
> "We know this fails under these conditions", that seems like known
> failure to me. However, I guess it could just be skipped.

The distinction is supposed to be (in my mind, and I think in the
docs) that xfail is things that we should eventually come back and fix
in bzr; they should generally have a bug number. Skip is just things
that don't make sense to ever be tested. There are probably some that
are misclassified.

If there was a bug in a dependency, it would be reasonable to mark
that xfail until it's fixed. Once it is fixed, we might as well just
skip the test on old versions of that library, unless we choose to
also add a workaround in bzr itself. It is no longer a bug we need to
fix.

Thanks

[Martin Pool (mbp)]

sent to pqm by email

[Martin Packman (gz)]

What was the failure from PQM for this?

I'm a little scared by some of these changes, though I think overall it's moving in the right direction.

+ self.repeat_failures_at_end = False

My understanding of the proposed flag was it would be either during *or* at the end, never both.

+class BaseTextTestResult(ExtendedTestResult):

Why a new class rather than just putting the method you want to share on ExtendedTestResult?

+ u'ERROR: %s\n' % self._test_description(test))

Using u"" ascii literals is well intentioned but isn't really useful. This is something of a common misconception. All it amounts to is asking for an error from this interpolation rather than elsewhere in the stack. Having the file object reject non-ascii bytestrings is a better choice.

     def _finishLogFile(self):
...
+ log_contents = self.get_log()

Moving this logic scares me. Robert did a lot of complicated coding to make sure the log was available from test initialisation rather than only at the end, which is partly why this code is still strange. If we really don't want the log until _finishLogFile is called, most of the code can be removed and replaced with a single addDetails call here.

+ if type(codec) is tuple:
+ # Python 2.4
+ encode = codec[0]

This code being copied out to a helper method can lose the compat stuff now.

+ # This isn't an expected failure in bzr, because there's nothing
+ # reasonable we can do about old buggy subunits.

This was an expected failure because we want to depend on a minimum subunit version to avoid failures, and remove the need for the hack in the test, see bug 531667.

review: Needs Information

[Martin Pool (mbp)]

test_trace.TestTrace.test_mutter_never_failsERROR 0ms
   lost connection during error report of test 'bzrlib.tests.test_trace.TestTrace.test_mutter_never_fails'

thanks for the review comments

[Martin Pool (mbp)]

> What was the failure from PQM for this?
>
> I'm a little scared by some of these changes, though I think overall it's
> moving in the right direction.
>
> + self.repeat_failures_at_end = False
>
> My understanding of the proposed flag was it would be either during *or* at
> the end, never both.

This was a bit of a compromise towards people wanting it at the end. I think I will just pull it out. <https://bugs.launchpad.net/bzr/+bug/625597>.

>
> +class BaseTextTestResult(ExtendedTestResult):
>
> Why a new class rather than just putting the method you want to share on
> ExtendedTestResult?

My idea was that it could be good to separate out "general extended test result" from "... formatted as text." If the parent class already has text-specific methods there may be no point (or perhaps even if it doesn't.) I'll look.

> + u'ERROR: %s\n' % self._test_description(test))
>
> Using u"" ascii literals is well intentioned but isn't really useful. This is
> something of a common misconception. All it amounts to is asking for an error
> from this interpolation rather than elsewhere in the stack. Having the file
> object reject non-ascii bytestrings is a better choice.

This was actually done in response to a test failure and I think it does actually make sense. We want to keep it as unicode as late as possible, and then the file can either reject it or (what we actually want) discard unrepresentable characters.

> def _finishLogFile(self):
> ...
> + log_contents = self.get_log()
>
> Moving this logic scares me. Robert did a lot of complicated coding to make
> sure the log was available from test initialisation rather than only at the
> end, which is partly why this code is still strange. If we really don't want
> the log until _finishLogFile is called, most of the code can be removed and
> replaced with a single addDetails call here.

What behaviour do we actually want from the log file while testing? And secondly, how many tests count on the existing behaviour?

It seems to me that having tests able to inspect the log of every message emitted since the test started is not really a good idea. I have written such tests myself but they are fairly imprecise: if we are trying to check that a particular operation writes some debug messages, we will normally want to check that happens during a particular call, not during the whole run to date. I believe that holding the whole log in memory has also caused excess memory usage (and maybe you, gz, fixed it?)

I'll have a look into whether we can simplify this more.

>
> + if type(codec) is tuple:
> + # Python 2.4
> + encode = codec[0]
>
> This code being copied out to a helper method can lose the compat stuff now.

Thanks.

>
> + # This isn't an expected failure in bzr, because there's nothing
> + # reasonable we can do about old buggy subunits.
>
> This was an expected failure because we want to depend on a minimum subunit
> version to avoid failures, and remove the need for the hack in the test, see
> bug 531667.

OK, I see. I think we should only have xfails for things that would be valid bugs against bzr...

[Martin Pool (mbp)]

sent to pqm by email

[Martin Pool (mbp)]

This fails in pqm with some kind of unicode error in subunit integration:

bzr: ERROR: exceptions.UnicodeDecodeError: 'ascii' codec can't decode byte 0xc2 in position 30: ordinal not in range(128)

Traceback (most recent call last):
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/commands.py", line 946, in exception_to_return_code
   return the_callable(*args, **kwargs)
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/commands.py", line 1150, in run_bzr
   ret = run(*run_argv)
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/commands.py", line 699, in run_argv_aliases
   return self.run(**all_cmd_args)
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/commands.py", line 721, in run
   return self._operation.run_simple(*args, **kwargs)
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/cleanup.py", line 135, in run_simple
   self.cleanups, self.func, *args, **kwargs)
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/cleanup.py", line 165, in _do_with_cleanups
   result = func(*args, **kwargs)
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/builtins.py", line 3788, in run
   result = tests.selftest(**selftest_kwargs)
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/tests/__init__.py", line 3709, in selftest
   result_decorators=result_decorators,
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/tests/__init__.py", line 3217, in run_suite
   result = runner.run(suite)
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/tests/__init__.py", line 4758, in run
   test.run(result)
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/tests/__init__.py", line 3331, in run
   return super(CountingDecorator, self).run(result)
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/tests/__init__.py", line 3320, in run
   test.run(result)
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/tests/TestUtil.py", line 89, in run
   tests.pop().run(result)
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/tests/TestUtil.py", line 89, in run
   tests.pop().run(result)
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/tests/TestUtil.py", line 89, in run
   tests.pop().run(result)
 File "/usr/lib/python2.6/dist-packages/testtools/testcase.py", line 420, in run
   return self.__RunTest(self, self.exception_handlers).run(result)
 File "/usr/lib/python2.6/dist-packages/testtools/runtest.py", line 67, in run
   return self._run_one(actual_result)
 File "/usr/lib/python2.6/dist-packages/testtools/runtest.py", line 81, in _run_one
   return self._run_prepared_result(ExtendedToOriginalDecorator(result))
 File "/usr/lib/python2.6/dist-packages/testtools/runtest.py", line 100, in _run_prepared_result
   handler(self.case, self.result, e)
 File "/usr/lib/python2.6/dist-packages/testtools/testcase.py", line 388, in _report_error
   result.addError(self, details=self.getDetails())
 File "/usr/lib/python2.6/dist-packages/testtools/testresult/real.py", line 399, in addError
   return self.decorated.addError(test, details=details)
 File "/usr/lib/python2.6/dist-packages/subunit/test_results.py", line 118, in addError
   return self.super.addError(test, err, details=details)
 File "/usr/lib/python2.6/dist-packages/subunit/test_results.py", line 56, in add...

[Martin Packman (gz)]

I'll have a go at reproducing that problem locally, the traceback isn't useful. Looks like a (probably not introduced by this branch) knock-on error from an error (probably due to this branch) on one of the tests involving non-ascii output.

[Martin Packman (gz)]

Reproduce with `./bzr selftest --subunit -s bt.test_trace mutter_never_fails` or remove --subunit to see the underlying error. Note also --parallel=fork doesn't break while --parallel=subprocess does so this is a real regression due to moving the stream wrapping around.

[Martin Pool (mbp)]

    def test_mutter_never_fails(self):
        # Even if the decode/encode stage fails, mutter should not
        # raise an exception
        # This test checks that mutter doesn't fail; the current behaviour
        # is that it doesn't fail *and writes non-utf8*.
        mutter(u'Writing a greek mu (\xb5) works in a unicode string')
        mutter('But fails in an ascii string \xb5')
        mutter('and in an ascii argument: %s', '\xb5')
        log = self.get_log()
        self.assertContainsRe(log, 'Writing a greek mu')
        self.assertContainsRe(log, "But fails in an ascii string")
        # However, the log content object does unicode replacement on reading
        # to let it get unicode back where good data has been written. So we
        # have to do a replaceent here as well.
        self.assertContainsRe(log, "ascii argument: \xb5".decode('utf8',
            'replace'))

So, this test is passing in the way the comment describes: mutter
doesn't actually fail, but we're no longer writing what we expected
to.

Looking at what got written, it's consistent with the currently
documented behaviour: lines sent as unicode get written as utf8 and
lines sent as byte strings are sent through as such (therefore the
file's then not valid utf8.) I think this is still reasonable
behaviour.

(Pdb) p log
'0.232 Writing a greek mu (\xc2\xb5) works in a unicode string\n0.232
 But fails in an ascii string \xb5\n0.232 and in an ascii argument:
\xb5\n'

The main change we'd need then, is that when looking at the result, we
should just search for a non-utf8 string.

[Martin Pool (mbp)]

I'm going to send this in; post-review welcome.

review: Approve

[Martin Pool (mbp)]

sent to pqm by email

[Martin Pool (mbp)]

failed pqm due to a merge conflict

[lp:~mbp/bzr/test-errors]

5979. By Martin Pool on 2011-08-03

merge trunk

[Martin Pool (mbp)]

sent to pqm by email

[Martin Pool (mbp)]

failed again with

bzr: ERROR: exceptions.UnicodeDecodeError: 'ascii' codec can't decode byte 0xc2 in position 34: ordinal not in range(128)

Traceback (most recent call last):
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/commands.py", line 918, in exception_to_return_code
   return the_callable(*args, **kwargs)
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/commands.py", line 1118, in run_bzr
   ret = run(*run_argv)
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/commands.py", line 676, in run_argv_aliases
   return self.run(**all_cmd_args)
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/commands.py", line 698, in run
   return self._operation.run_simple(*args, **kwargs)
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/cleanup.py", line 135, in run_simple
   self.cleanups, self.func, *args, **kwargs)
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/cleanup.py", line 165, in _do_with_cleanups
   result = func(*args, **kwargs)
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/builtins.py", line 3836, in run
   result = tests.selftest(**selftest_kwargs)
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/tests/__init__.py", line 3735, in selftest
   result_decorators=result_decorators,
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/tests/__init__.py", line 3243, in run_suite
   result = runner.run(suite)
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/tests/__init__.py", line 4477, in run
   test.run(result)
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/tests/__init__.py", line 3357, in run
   return super(CountingDecorator, self).run(result)
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/tests/__init__.py", line 3346, in run
   test.run(result)
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/tests/TestUtil.py", line 89, in run
   tests.pop().run(result)
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/tests/TestUtil.py", line 89, in run
   tests.pop().run(result)
 File "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/tests/TestUtil.py", line 89, in run
   tests.pop().run(result)
 File "/usr/lib/python2.6/dist-packages/testtools/testcase.py", line 420, in run
   return self.__RunTest(self, self.exception_handlers).run(result)
 File "/usr/lib/python2.6/dist-packages/testtools/runtest.py", line 67, in run
   return self._run_one(actual_result)
 File "/usr/lib/python2.6/dist-packages/testtools/runtest.py", line 81, in _run_one
   return self._run_prepared_result(ExtendedToOriginalDecorator(result))
 File "/usr/lib/python2.6/dist-packages/testtools/runtest.py", line 100, in _run_prepared_result
   handler(self.case, self.result, e)
 File "/usr/lib/python2.6/dist-packages/testtools/testcase.py", line 388, in _report_error
   result.addError(self, details=self.getDetails())
 File "/usr/lib/python2.6/dist-packages/testtools/testresult/real.py", line 399, in addError
   return self.decorated.addError(test, details=details)
 File "/usr/lib/python2.6/dist-packages/subunit/test_results.py", line 118, in addError
   return self.super.addError(test, err, details=details)
 File "/usr/lib/python2.6/dist-packages/subunit/test_results.py", line 56, in addError
   return self.decorated.addError(test, err, det...

[John A Meinel (jameinel)]

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

On 8/4/2011 2:34 AM, Martin Pool wrote:
> failed again with
...

> File "/usr/lib/python2.6/dist-packages/subunit/chunked.py", line
> 148, in flush self.output.write(''.join(buffered_bytes)) File
> "/home/pqm/bzr-pqm-workdir/home/+trunk/bzrlib/ui/text.py", line 540,
> in write self.wrapped_stream.write(to_write) File
> "/usr/lib/python2.6/codecs.py", line 351, in write data, consumed =
> self.encode(object, self.errors) UnicodeDecodeError: 'ascii' codec
> can't decode byte 0xc2 in position 34: ordinal not in range(128)
>

buffered_bytes sure looks like something that *should* be all byte
strings, and not Unicode at that point. I wonder how a Unicode bit snuck
in...

Or maybe it was properly encoded into bytes, but we are using a codec
wrapper. And writing bytes to a wrapper silently upcasts it to Unicode
before downcasting it in its own encoding back to bytes.

wrapped_stream seems risky with a "buffered_bytes" parameter.

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

iEYEARECAAYFAk477QEACgkQJdeBCYSNAAMfHwCfW3sMTtzwp4W6X0ydSB/IpONo
fDIAoLR8PWxq+/PcsOtEwNYeN2PSIKyd
=vcS/
-----END PGP SIGNATURE-----

Unmerged revisions

5979. By Martin Pool on 2011-08-03

merge trunk

5978. By Martin Pool on 2011-08-01

Update test_mutter_never_fails to have more precise assertions and cope with getting non-ascii back

5977. By Martin Pool on 2011-06-29

Resolve conflicts

5976. By Martin Pool on 2011-06-14

Remove intentionally broken test

5975. By Martin Pool on 2011-06-14

Bugs in old subunits aren't bzr bugs

5974. By Martin Pool on 2011-06-14

Don't print traceback for xfail messages

5973. By Martin Pool on 2011-06-14

Unify code to report selftest failures

5972. By Martin Pool on 2011-06-14

Avoid excess indenting; handle unicode failures better in selftest -v

5971. By Martin Pool on 2011-06-14

Don't attach the log to the testtools object until the end when we know there are actual contents

5970. By Martin Pool on 2011-06-14

Send test output streams through the ui stream mechanism.

This gives them the default stream encoding, and should avoid clashing with progress bars.

=== modified file 'bzrlib/osutils.py'
--- bzrlib/osutils.py	2011-07-25 07:11:56 +0000
+++ bzrlib/osutils.py	2011-08-03 02:27:34 +0000
@@ -2319,8 +2319,17 @@
 
     def __init__(self, encode, stream, errors='strict'):
         codecs.StreamWriter.__init__(self, stream, errors)
+        self._underlying_stream = stream
+        self._errors = errors
         self.encode = encode
 
+    def __repr__(self):
+        return '%s(%r, %r, %r)' % (
+            self.__class__.__name__,
+            self.encode,
+            self._underlying_stream,
+            self._errors)
+
     def write(self, object):
         if type(object) is str:
             self.stream.write(object)
@@ -2328,6 +2337,7 @@
             data, _ = self.encode(object, self.errors)
             self.stream.write(data)
 
+
 if sys.platform == 'win32':
     def open_file(filename, mode='r', bufsize=-1):
         """This function is used to override the ``open`` builtin.

=== modified file 'bzrlib/tests/__init__.py'
--- bzrlib/tests/__init__.py	2011-08-02 01:10:27 +0000
+++ bzrlib/tests/__init__.py	2011-08-03 02:27:34 +0000
@@ -268,17 +268,25 @@
         self._first_thread_leaker_id = None
         self._tests_leaking_threads_count = 0
         self._traceback_from_test = None
+        self.repeat_failures_at_end = False
 
     def stopTestRun(self):
         run = self.testsRun
         actionTaken = "Ran"
         stopTime = time.time()
         timeTaken = stopTime - self.startTime
-        # GZ 2010-07-19: Seems testtools has no printErrors method, and though
-        #                the parent class method is similar have to duplicate
-        self._show_list('ERROR', self.errors)
-        self._show_list('FAIL', self.failures)
-        self.stream.write(self.sep2)
+        if self.repeat_failures_at_end:
+            # Normally, any failures or errors will be printed as they
+            # occur.  (For example this lets you choose to interrupt the
+            # test run as soon as something fails, or to immediately start
+            # debugging them while the test run continues.)
+            #
+            # GZ 2010-07-19: Seems testtools has no printErrors method, and
+            # though the parent class method is similar, we need duplicate
+            # code here.
+            self._show_list('ERROR', self.errors)
+            self._show_list('FAIL', self.failures)
+            self.stream.write(self.sep2)
         self.stream.write("%s %d test%s in %.3fs\n\n" % (actionTaken,
                             run, run != 1 and "s" or "", timeTaken))
         if not self.wasSuccessful():
@@ -552,7 +560,18 @@
         return self.wasSuccessful()
 
 
-class TextTestResult(ExtendedTestResult):
+class BaseTextTestResult(ExtendedTestResult):
+    """Common base for verbose and concise test results."""
+    
+    def report_error_details(self, err):
+        # Normally called with a StringException, which has its whole
+        # traceback in its value.
+        self.stream.write(u'%s\n'
+            % err[1])
+
+
+
+class TextTestResult(BaseTextTestResult):
     """Displays progress and results of tests in text form"""
 
     def __init__(self, stream, descriptions, verbosity,
@@ -621,22 +640,35 @@
         return self._shortened_test_description(test)
 
     def report_error(self, test, err):
-        self.stream.write('ERROR: %s\n    %s\n' % (
-            self._test_description(test),
-            err[1],
-            ))
+        """Report an unexpected error running a test.
+    
+        :param test: TestCase instance.
+        :param err: An error-tuple, but typically a testtools
+            StringException with the whole traceback already baked into the
+            string form.
+        """
+        self.stream.write(
+            u'ERROR: %s\n' % self._test_description(test))
+        self.report_error_details(err)
 
     def report_failure(self, test, err):
-        self.stream.write('FAIL: %s\n    %s\n' % (
-            self._test_description(test),
-            err[1],
-            ))
+        """Report a test failure.
+    
+        :param test: TestCase instance.
+        :param err: An error-tuple, but typically a testtools
+            StringException with the whole traceback already baked into the
+            string form.
+        """
+        self.stream.write(
+            u'FAIL: %s\n' % self._test_description(test))
+        self.report_error_details(err)
 
     def report_known_failure(self, test, err):
         pass
 
     def report_unexpected_success(self, test, reason):
-        self.stream.write('FAIL: %s\n    %s: %s\n' % (
+        self.stream.write(
+            u'FAIL: %s\n%s: %s\n' % (
             self._test_description(test),
             "Unexpected success. Should have failed",
             reason,
@@ -652,7 +684,7 @@
         """test cannot be run because feature is missing."""
 
 
-class VerboseTestResult(ExtendedTestResult):
+class VerboseTestResult(BaseTextTestResult):
     """Produce long output, with one line per test run plus times"""
 
     def _ellipsize_to_right(self, a_string, final_width):
@@ -681,50 +713,59 @@
         self.stream.flush()
 
     def _error_summary(self, err):
-        indent = ' ' * 4
-        return '%s%s' % (indent, err[1])
+        return unicode(err[1])
 
     def report_error(self, test, err):
-        self.stream.write('ERROR %s\n%s\n'
-                % (self._testTimeString(test),
-                   self._error_summary(err)))
+        self.stream.write(u'ERROR %s\n'
+            % (self._testTimeString(test),))
+        self.report_error_details(err)
 
     def report_failure(self, test, err):
-        self.stream.write(' FAIL %s\n%s\n'
-                % (self._testTimeString(test),
-                   self._error_summary(err)))
+        self.stream.write(u' FAIL %s\n'
+                % (self._testTimeString(test)))
+        self.report_error_details(err)
 
     def report_known_failure(self, test, err):
-        self.stream.write('XFAIL %s\n%s\n'
-                % (self._testTimeString(test),
-                   self._error_summary(err)))
+        self.stream.write(u'XFAIL %s\n'
+            % (self._testTimeString(test)))
+        # If possible, just give the short reason; people who want to work
+        # on this test and get it going know where to find it.
+        getDetails = getattr(test, 'getDetails', None)
+        if getDetails is None:
+            reason = None
+        else:
+            reason = test.getDetails().get('reason')
+        if reason:
+            self.stream.write(u'    %s\n' % (u''.join(reason.iter_text())))
+        else:
+            self.report_error_details(err)
 
     def report_unexpected_success(self, test, reason):
-        self.stream.write(' FAIL %s\n%s: %s\n'
+        self.stream.write(u' FAIL %s\n%s: %s\n'
                 % (self._testTimeString(test),
                    "Unexpected success. Should have failed",
                    reason))
 
     def report_success(self, test):
-        self.stream.write('   OK %s\n' % self._testTimeString(test))
+        self.stream.write(u'   OK %s\n' % self._testTimeString(test))
         for bench_called, stats in getattr(test, '_benchcalls', []):
-            self.stream.write('LSProf output for %s(%s, %s)\n' % bench_called)
+            self.stream.write(u'LSProf output for %s(%s, %s)\n' % bench_called)
             stats.pprint(file=self.stream)
         # flush the stream so that we get smooth output. This verbose mode is
         # used to show the output in PQM.
         self.stream.flush()
 
     def report_skip(self, test, reason):
-        self.stream.write(' SKIP %s\n%s\n'
+        self.stream.write(u' SKIP %s\n%s\n'
                 % (self._testTimeString(test), reason))
 
     def report_not_applicable(self, test, reason):
-        self.stream.write('  N/A %s\n    %s\n'
+        self.stream.write(u'  N/A %s\n    %s\n'
                 % (self._testTimeString(test), reason))
 
     def report_unsupported(self, test, feature):
         """test cannot be run because feature is missing."""
-        self.stream.write("NODEP %s\n    The feature '%s' is not available.\n"
+        self.stream.write(u"NODEP %s\n    The feature '%s' is not available.\n"
                 %(self._testTimeString(test), feature))
 
 
@@ -732,12 +773,13 @@
     stop_on_failure = False
 
     def __init__(self,
-                 stream=sys.stderr,
+                 stream=None,
                  descriptions=0,
                  verbosity=1,
                  bench_history=None,
                  strict=False,
                  result_decorators=None,
+                 output_encoding=None,
                  ):
         """Create a TextTestRunner.
 
@@ -746,22 +788,6 @@
             applied left to right - the first element in the list is the 
             innermost decorator.
         """
-        # stream may know claim to know to write unicode strings, but in older
-        # pythons this goes sufficiently wrong that it is a bad idea. (
-        # specifically a built in file with encoding 'UTF-8' will still try
-        # to encode using ascii.
-        new_encoding = osutils.get_terminal_encoding()
-        codec = codecs.lookup(new_encoding)
-        if type(codec) is tuple:
-            # Python 2.4
-            encode = codec[0]
-        else:
-            encode = codec.encode
-        # GZ 2010-09-08: Really we don't want to be writing arbitrary bytes,
-        #                so should swap to the plain codecs.StreamWriter
-        stream = osutils.UnicodeOrBytesToBytesWriter(encode, stream,
-            "backslashreplace")
-        stream.encoding = new_encoding
         self.stream = stream
         self.descriptions = descriptions
         self.verbosity = verbosity
@@ -1691,14 +1717,7 @@
 
         The file is removed as the test is torn down.
         """
-        pseudo_log_file = StringIO()
-        def _get_log_contents_for_weird_testtools_api():
-            return [pseudo_log_file.getvalue().decode(
-                "utf-8", "replace").encode("utf-8")]
-        self.addDetail("log", content.Content(content.ContentType("text",
-            "plain", {"charset": "utf8"}),
-            _get_log_contents_for_weird_testtools_api))
-        self._log_file = pseudo_log_file
+        self._log_file = StringIO()
         self._log_memento = trace.push_log_file(self._log_file)
         self.addCleanup(self._finishLogFile)
 
@@ -1711,6 +1730,18 @@
             # flush the log file, to get all content
             trace._trace_file.flush()
         trace.pop_log_file(self._log_memento)
+        log_contents = self.get_log()
+        if not log_contents:
+            return
+        def _get_log_contents_for_weird_testtools_api():
+            # testtools adds the file by being passed a function that returns
+            # an iterable of chunks.
+            return [log_contents.decode("utf-8", "replace")
+                .encode("utf-8")]
+        self.addDetail("log",
+            content.Content(content.ContentType("text",
+                "plain", {"charset": "utf8"}),
+                _get_log_contents_for_weird_testtools_api))
 
     def thisFailsStrictLockCheck(self):
         """It is known that this test would fail with -Dstrict_locks.
@@ -1893,7 +1924,7 @@
 
         Undecodable characters are replaced.
         """
-        return u"".join(self.getDetails()['log'].iter_text())
+        return self._log_file.getvalue()
 
     def requireFeature(self, feature):
         """This test requires a specific feature is available.
@@ -3175,8 +3206,6 @@
         verbosity = 1
     if runner_class is None:
         runner_class = TextTestRunner
-    if stream is None:
-        stream = sys.stdout
     runner = runner_class(stream=stream,
                             descriptions=0,
                             verbosity=verbosity,
@@ -3605,6 +3634,36 @@
 selftest_debug_flags = set()
 
 
+def _output_stream_for_tests(stream=None, output_encoding=None):
+    """Make a stream for test output that can safely encode anything.
+
+    This goes to 'stream' if it is specified (for testing), otherwise 
+    to the ui's output stream.
+
+    Specifically, on older Pythons a built in file with encoding 'UTF-8'
+    will still try to encode using ascii.
+    """
+    if stream is None:
+        stream = ui.ui_factory.make_output_stream(
+            None, 'backslashreplace')
+    else:
+        if output_encoding is None:
+            output_encoding = osutils.get_terminal_encoding()
+        codec = codecs.lookup(output_encoding)
+        if type(codec) is tuple:
+            # Python 2.4
+            encode = codec[0]
+        else:
+            encode = codec.encode
+        # GZ 2010-09-08: Really we don't want to be writing arbitrary bytes,
+        # so should swap to the plain codecs.StreamWriter, and fix up any
+        # tests that do try to send bytes.
+        stream = osutils.UnicodeOrBytesToBytesWriter(encode, stream,
+            "backslashreplace")
+        stream.encoding = output_encoding
+    return stream
+
+
 def selftest(verbose=False, pattern=".*", stop_on_failure=True,
              transport=None,
              test_suite_factory=None,
@@ -3630,6 +3689,7 @@
     from bzrlib import repository
     repository._deprecation_warning_done = True
 
+    stream = _output_stream_for_tests(stream, None)
     global default_transport
     if transport is None:
         transport = default_transport

=== modified file 'bzrlib/tests/test_selftest.py'
--- bzrlib/tests/test_selftest.py	2011-08-02 01:10:27 +0000
+++ bzrlib/tests/test_selftest.py	2011-08-03 02:27:34 +0000
@@ -79,20 +79,6 @@
     return [t.id() for t in tests.iter_suite_tests(test_suite)]
 
 
-class MetaTestLog(tests.TestCase):
-
-    def test_logging(self):
-        """Test logs are captured when a test fails."""
-        self.log('a test message')
-        details = self.getDetails()
-        log = details['log']
-        self.assertThat(log.content_type, Equals(ContentType(
-            "text", "plain", {"charset": "utf8"})))
-        self.assertThat(u"".join(log.iter_text()), Equals(self.get_log()))
-        self.assertThat(self.get_log(),
-            DocTestMatches(u"...a test message\n", doctest.ELLIPSIS))
-
-
 class TestTreeShape(tests.TestCaseInTempDir):
 
     def test_unicode_paths(self):
@@ -869,8 +855,8 @@
         self.assertContainsRe(lines[0], r'XFAIL *\d+ms$')
         if sys.version_info > (2, 7):
             self.expectFailure("_ExpectedFailure on 2.7 loses the message",
-                self.assertNotEqual, lines[1], '    ')
-        self.assertEqual(lines[1], '    foo')
+                self.assertNotEqual, lines[1], '')
+        self.assertEqual(lines[1], 'foo')
         self.assertEqual(2, len(lines))
 
     def get_passing_test(self):
@@ -1025,11 +1011,13 @@
         class Test(tests.TestCase):
             def known_failure_test(self):
                 self.expectFailure('failed', self.assertTrue, False)
+
+            def unexpected_failure_test(self):
+                self.fail("foo")
+
         test = unittest.TestSuite()
         test.addTest(Test("known_failure_test"))
-        def failing_test():
-            raise AssertionError('foo')
-        test.addTest(unittest.FunctionTestCase(failing_test))
+        test.addTest(Test("unexpected_failure_test"))
         stream = StringIO()
         runner = tests.TextTestRunner(stream=stream)
         result = self.run_test_runner(runner, test)
@@ -1037,21 +1025,17 @@
         self.assertContainsRe(stream.getvalue(),
             '(?sm)^bzr selftest.*$'
             '.*'
-            '^======================================================================\n'
-            '^FAIL: failing_test\n'
-            '^----------------------------------------------------------------------\n'
-            'Traceback \\(most recent call last\\):\n'
-            '  .*' # File .*, line .*, in failing_test' - but maybe not from .pyc
-            '    raise AssertionError\\(\'foo\'\\)\n'
-            '.*'
-            '^----------------------------------------------------------------------\n'
+            r'^FAIL: .*\.unexpected_failure_test'
+            '.*'
+            r'Traceback \(most recent call last\):'
+            '.*'
+            '^AssertionError: foo'
             '.*'
             'FAILED \\(failures=1, known_failure_count=1\\)'
             )
 
     def test_known_failure_ok_run(self):
-        # run a test that generates a known failure which should be printed in
-        # the final output.
+        """A test that generates a known failure is printed."""
         class Test(tests.TestCase):
             def known_failure_test(self):
                 self.knownFailure("Never works...")
@@ -1069,17 +1053,14 @@
     def test_unexpected_success_bad(self):
         class Test(tests.TestCase):
             def test_truth(self):
-                self.expectFailure("No absolute truth", self.assertTrue, True)
+                self.expectFailure("No absolute truth", self.assertTrue,
+                    True)
         runner = tests.TextTestRunner(stream=StringIO())
         result = self.run_test_runner(runner, Test("test_truth"))
         self.assertContainsRe(runner.stream.getvalue(),
-            "=+\n"
-            "FAIL: \\S+\.test_truth\n"
-            "-+\n"
-            "(?:.*\n)*"
-            "No absolute truth\n"
-            "(?:.*\n)*"
-            "-+\n"
+            "(?ms)FAIL: \\S+\.test_truth\n"
+            ".*No absolute truth\n"
+            ".*"
             "Ran 1 test in .*\n"
             "\n"
             "FAILED \\(failures=1\\)\n\\Z")
@@ -1243,9 +1224,9 @@
                 self.log(u"\u2606")
                 self.fail("Now print that log!")
         out = StringIO()
-        self.overrideAttr(osutils, "get_terminal_encoding",
-            lambda trace=False: "ascii")
-        result = self.run_test_runner(tests.TextTestRunner(stream=out),
+        runner = tests.TextTestRunner(
+            stream=tests._output_stream_for_tests(out, 'ascii'))
+        result = self.run_test_runner(runner,
             FailureWithUnicode("test_log_unicode"))
         self.assertContainsRe(out.getvalue(),
             "Text attachment: log\n"
@@ -1253,7 +1234,6 @@
             "\d+\.\d+  \\\\u2606\n"
             "-+\n")
 
-
 class SampleTestCase(tests.TestCase):
 
     def _test_pass(self):
@@ -1698,6 +1678,9 @@
             mutter('this was a failing test')
             self.fail('this test will fail')
 
+        def test_fail_nothing_logged(self):
+            self.fail('just fail')
+
         def test_error(self):
             mutter('this test errored')
             raise RuntimeError('gotcha')
@@ -1732,6 +1715,13 @@
         test.run(result)
         return result
 
+    def test_empty_log_not_attached(self):
+        result = self._run_test('test_fail_nothing_logged')
+        self.assertEqual(1, len(result.failures))
+        result_content = result.failures[0][1]
+        self.assertNotContainsRe(result_content,
+            'Text attachment: log')
+
     def test_fail_has_log(self):
         result = self._run_test('test_fail')
         self.assertEqual(1, len(result.failures))
@@ -2190,13 +2180,13 @@
         content, result = self.run_subunit_stream('test_unexpected_success')
         self.assertContainsRe(content, '(?m)^log$')
         self.assertContainsRe(content, 'test with unexpected success')
-        # GZ 2011-05-18: Old versions of subunit treat unexpected success as a
-        #                success, if a min version check is added remove this
+        # GZ 2011-05-18: Old versions of subunit treat unexpected success as
+        # a success, if a min version check is added remove this.
         from subunit import TestProtocolClient as _Client
         if _Client.addUnexpectedSuccess.im_func is _Client.addSuccess.im_func:
-            self.expectFailure('subunit treats "unexpectedSuccess"'
-                               ' as a plain success',
-                self.assertEqual, 1, len(result.unexpectedSuccesses))
+            # This isn't an expected failure in bzr, because there's nothing
+            # reasonable we can do about old buggy subunits.
+            self.skip("old subunit treats unexpectedSuccess as success")
         self.assertEqual(1, len(result.unexpectedSuccesses))
         test = result.unexpectedSuccesses[0]
         # RemotedTestCase doesn't preserve the "details"

=== modified file 'bzrlib/tests/test_trace.py'
--- bzrlib/tests/test_trace.py	2011-05-27 20:46:01 +0000
+++ bzrlib/tests/test_trace.py	2011-08-03 02:27:34 +0000
@@ -238,21 +238,21 @@
         self.assertEndsWith(log, ' "a string")\n')
 
     def test_mutter_never_fails(self):
-        # Even if the decode/encode stage fails, mutter should not
-        # raise an exception
-        # This test checks that mutter doesn't fail; the current behaviour
-        # is that it doesn't fail *and writes non-utf8*.
+        """Even if the decode/encode stage fails, mutter should not fail.
+        
+        This test checks that mutter doesn't fail; the current behaviour
+        is that it doesn't fail *and writes non-utf8*.
+        """
         mutter(u'Writing a greek mu (\xb5) works in a unicode string')
-        mutter('But fails in an ascii string \xb5')
-        mutter('and in an ascii argument: %s', '\xb5')
+        mutter('But fails in a byte string \xb5')
+        mutter('and in a byte string argument: %s', '\xb5')
         log = self.get_log()
         self.assertContainsRe(log, 'Writing a greek mu')
-        self.assertContainsRe(log, "But fails in an ascii string")
+        self.assertContainsRe(log, "But fails in a byte string")
         # However, the log content object does unicode replacement on reading
         # to let it get unicode back where good data has been written. So we
         # have to do a replaceent here as well.
-        self.assertContainsRe(log, "ascii argument: \xb5".decode('utf8',
-            'replace'))
+        self.assertTrue('byte string argument: \xb5' in log)
         
     def test_show_error(self):
         show_error('error1')