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

-----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-----

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

sent to pqm by email

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.

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

> 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...

sent to pqm by email

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...

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.

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.

    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.

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

sent to pqm by email

failed pqm due to a merge conflict

sent to pqm by email

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...

-----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-----