[patch] cleanups to trace/selftest
John Arbash Meinel
john at arbash-meinel.com
Thu Jul 6 14:57:56 BST 2006
Martin Pool wrote:
> This simplifies and removes cruft from the trace code.
>
> Warning/note/error messages are now written out through the UI, which is
> responsible for clearing the progress bar or whatever if necessary.
>
> .bzr.log is removed.
>
> mutter statements are now separately tracked during logging. I plan to also
> make a separate patch that removes some of them, and gives a global -D to send them to stderr.
>
> Remove the --quiet global option, which only applied to one command and not
> very well.
Didn't --quiet switch to using the SilentUIFactory instead of Text? If
it didn't it probably should have. Which might be a reason to leave it in.
>
> This goes most of the way towards avoiding capturing stdout/stderr or the UI
> for tests, except for things that are explicitly blackbox tests.
>
> It removes the dependency on logging, which may have a slight peformance or
> load time gain. (We probably want to set that up explicitly when loading
> paramiko, which does use it, but that wasn't done perfectly before anyhow.)
>
logging costs about 12ms to load. So there is a gain, but not a huge one.
>
...
> === modified file 'bzrlib/builtins.py'
> --- bzrlib/builtins.py 2006-07-04 15:04:11 +0000
> +++ bzrlib/builtins.py 2006-07-05 07:53:58 +0000
> @@ -31,7 +31,7 @@
> from bzrlib.bundle.apply_bundle import install_bundle, merge_bundle
> from bzrlib.conflicts import ConflictList
> from bzrlib.commands import Command, display_command
> -from bzrlib.errors import (BzrError, BzrCheckError, BzrCommandError,
> +from bzrlib.errors import (BzrError, BzrCheckError, BzrCommandError,
> NotBranchError, DivergedBranches, NotConflicted,
> NoSuchFile, NoWorkingTree, FileInWrongBranch,
> NotVersionedError, NotABundle)
^-- What is your vim setup to detect trailing whitespace? These changes
are confusing, but if we get them fixed, we'll see less of them.
...
> @@ -1912,7 +1915,7 @@
> print '%10s: %s' % ('bzr', osutils.realpath(sys.argv[0]))
> print '%10s: %s' % ('bzrlib', bzrlib.__path__[0])
> print
> - info('running tests...')
> + print 'running tests...'
^- I kind of cringe at this.
1) info() used to go to stderr instead of stdout. Which for selftest,
going to stdout is fine.
By why 'print' instead of self.outf.write()?
...
> @@ -2131,26 +2134,17 @@
> interesting_files = None
> pb = ui.ui_factory.nested_progress_bar()
> try:
> - try:
> - conflict_count = merge(other, base, check_clean=(not force),
> - merge_type=merge_type,
> - reprocess=reprocess,
> - show_base=show_base,
> - pb=pb, file_list=interesting_files)
> - finally:
> - pb.finished()
> - if conflict_count != 0:
> - return 1
> - else:
> - return 0
> - except errors.AmbiguousBase, e:
> - m = ("sorry, bzr can't determine the right merge base yet\n"
> - "candidates are:\n "
> - + "\n ".join(e.bases)
> - + "\n"
> - "please specify an explicit base with -r,\n"
> - "and (if you want) report this to the bzr developers\n")
> - log_error(m)
> + conflict_count = merge(other, base, check_clean=(not force),
> + merge_type=merge_type,
> + reprocess=reprocess,
> + show_base=show_base,
> + pb=pb, file_list=interesting_files)
> + finally:
> + pb.finished()
> + if conflict_count != 0:
> + return 1
> + else:
> + return 0
^- So is this just assuming that AmbiguousBase will be reported properly
by the standard exception handler?
...
> @@ -451,10 +450,14 @@
> def setUp(self):
> unittest.TestCase.setUp(self)
> self._cleanEnvironment()
> - bzrlib.trace.disable_default_logging()
> self._startLogFile()
> + # TODO: would like to just silence the UI instead, but there are still
> + # tests (in the ftp server) that seem to rely on this.
> + ## self._silenceUI()
> + self._captureDebugLog()
> self._benchcalls = []
> self._benchtime = None
> + self._debug_log = []
What are the FTP server tests doing? I can see that they are calling
mutter, which was probably just a debugging thing for me. But because
they just go through the standard test_transport_implementations, I
don't believe the log is inspected for anything.
>
> def _ndiff_strings(self, a, b):
> """Return ndiff between two strings containing lines.
> @@ -542,31 +545,58 @@
> self.fail("%r is an instance of %s rather than %s" % (
> obj, obj.__class__, kls))
>
> + def _silenceUI(self):
> + """Set the default UI to be silent.
> +
> + This makes sure that any incidental warnings or notes don't get to the
> + real stdout/stderr. Blackbox commands that want to examine them can
> + call run_bzr_captured, or set up their own UI.
> + """
> + saved_ui_factory = ui.switch_ui_factory(ui.SilentUIFactory())
> + def release():
> + ui.switch_ui_factory(saved_ui_factory)
> + self.addCleanup(release)
> +
> + def _captureDebugLog(self):
> + """Redirect all mutter statements into a buffer in this test."""
> + def mutter_to_test_log(fmt, args):
> + if args:
> + self._debug_log.append((fmt % args) + '\n')
> + else:
> + self._debug_log.append(fmt + '\n')
> + saved = bzrlib.trace._mutter_impl
> + def release():
> + trace._mutter_impl = saved
> + trace._mutter_impl = mutter_to_test_log
> + self.addCleanup(release)
> +
I belive you need to have:
def mutter_to_test_log(fmt, *args):
^-important
So that you can pass multiple arguments. And so that if you pass a tuple
as the first argument it gets formatter properly.
> def _startLogFile(self):
> - """Send bzr and test log messages to a temporary file.
> -
> - The file is removed as the test is torn down.
> + """Capture bzr UI output into a log file.
> +
> + This prevents the stderr from the test run being polluted by any
> + messages or warnings that might happen to be emitted by bzrlib
> + while we're testing it.
> +
> + The file is removed as the test is torn down but its contents are
> + still accessible through self._get_debug_log().
> """
> fileno, name = tempfile.mkstemp(suffix='.log', prefix='testbzr')
> encoder, decoder, stream_reader, stream_writer = codecs.lookup('UTF-8')
> - self._log_file = stream_writer(os.fdopen(fileno, 'w+'))
> - self._log_nonce = bzrlib.trace.enable_test_log(self._log_file)
> + self._log_file = stream_writer(os.fdopen(fileno, 'w+', 1))
> self._log_file_name = name
> - self.addCleanup(self._finishLogFile)
^- Would it be possible to not put the log files in /tmp, we haven't
been very good about cleaning them up. (Though it may just be that we
weren't cleaning up skipped tests). 'ls /tmp' sometime, you'll see all
the old log messages.
> -
> - def _finishLogFile(self):
> - """Finished with the log file.
> -
> - Read contents into memory, close, and delete.
> - """
> - if self._log_file is None:
> - return
> - bzrlib.trace.disable_test_log(self._log_nonce)
> - self._log_file.seek(0)
> - self._log_contents = self._log_file.read()
> - self._log_file.close()
> - os.remove(self._log_file_name)
> - self._log_file = self._log_file_name = None
> + saved_ui_factory = ui.ui_factory
> + ui.ui_factory = bzrlib.tests.blackbox.TestUIFactory(
> + stdout=self._log_file,
> + stderr=self._log_file)
> + def _finishLogFile():
> + ui.ui_factory = saved_ui_factory
> + if self._log_file:
> + self._log_file.seek(0)
> + self._log_contents = self._log_file.read()
> + self._log_file.close()
> + os.remove(self._log_file_name)
> + self._log_file = self._log_file_name = None
> + self.addCleanup(_finishLogFile)
>
> def addCleanup(self, callable):
> """Arrange to run a callable when this case is torn down.
> @@ -591,7 +621,6 @@
> for name, value in new_env.iteritems():
> self._captureVar(name, value)
>
> -
> def _captureVar(self, name, newvalue):
> """Set an environment variable, preparing it to be reset when finished."""
> self.__old_env[name] = os.environ.get(name, None)
> @@ -652,13 +681,24 @@
> def log(self, *args):
> mutter(*args)
>
> + def _get_debug_log(self):
> + """Return as a string all the debug log messages from this test."""
> + return ''.join(self._debug_log)
> +
> def _get_log(self):
> - """Return as a string the log for this test"""
> + """Return as a string the log for this test
> +
> + The log accumulates all diagnostic messages from the program.
> +
> + This may be called multiple lines to look for lines arriving in
> + the log.
> + """
^- "may be called multiple times" not lines. I still wonder what the
difference is between the debug log and the real log. And why when a
test is run the contents are going to be scattered rather than serialized.
...
> This runs bzr through the interface that catches and reports
> errors, and with logging set to something approximating the
> - default, so that error reporting can be checked.
> + default, so that error reporting can be checked. The logs are sent to
> + a separate location from the regular output of the logs so that
> + any messages produced during test setup aren't caught here.
Is this the basic reason?
...
v- I think I would miss having the exact command arguments be logged.
Because many times the code may be iterating over a list, and you don't
know which one is failing.
> - self.log('run bzr: %r', argv)
> - # FIXME: don't call into logging here
> - handler = logging.StreamHandler(stderr)
> - handler.setLevel(logging.INFO)
> - logger = logging.getLogger('')
> - logger.addHandler(handler)
> - old_ui_factory = bzrlib.ui.ui_factory
> - bzrlib.ui.ui_factory = bzrlib.tests.blackbox.TestUIFactory(
> + ## stdout = codecs.getwriter(encoding)(tempfile.TemporaryFile())
> + ## stderr = codecs.getwriter(encoding)(tempfile.TemporaryFile())
^-- stdout and stderr should really be defined as bytestreams. The
automatic translation was hurting us, which is why I added 'self.outf'.
Which will do the auto-translation, but let us have more control over
it. I'm not sure what you were testing here.
> + # TODO: Just set the ui factory and let messages come out through
> + # that...
> + new_factory = bzrlib.tests.blackbox.TestUIFactory(
> stdout=stdout,
> stderr=stderr)
> - bzrlib.ui.ui_factory.stdin = stdin
> + new_factory.stdin = stdin
> + old_ui_factory = ui.switch_ui_factory(new_factory)
> try:
> result = self.apply_redirected(stdin, stdout, stderr,
> bzrlib.commands.run_bzr_catch_errors,
> argv)
> finally:
> - logger.removeHandler(handler)
> - bzrlib.ui.ui_factory = old_ui_factory
> -
> - out = stdout.getvalue()
> - err = stderr.getvalue()
> + ui.switch_ui_factory(old_ui_factory)
> + stdout.seek(0)
> + out = stdout.read()
> + stderr.seek(0)
> + err = stderr.read()
^- Why seek instead of just using stdout.getvalue()?
It looks like you used a temp file for a while. Maybe that is why.
> === modified file 'bzrlib/tests/blackbox/test_selftest.py'
> --- bzrlib/tests/blackbox/test_selftest.py 2006-06-06 12:06:20 +0000
> +++ bzrlib/tests/blackbox/test_selftest.py 2006-07-03 14:19:10 +0000
> @@ -83,10 +83,7 @@
> # should result in 0 rests run.
> out, err = self.run_bzr('selftest', '--benchmark', 'workingtree_implementations')
> self.assertContainsRe(out, 'Ran 0 tests.*\n\nOK')
> - self.assertEqual(
> - 'running tests...\ntests passed\n',
> - err)
> -
> +
^- you moved the 'running tests...' to sys.stdout, it might be
reasonable to look for it there.
At the very least, you probably should assert that 'err' is empty
...
> - log = self._get_log()
> - self.failUnless('All changes applied successfully.\n' in log)
> + # we used to look in the UI output from merge, but this is a bit of a
> + # layering violation - only blackbox tests should look at that --
> + # merge should probably give some kind of structured report on what
> + # was done -- mbp 20060706
> + ## log = self._get_log()
> + ## self.failUnless('All changes applied successfully.\n' in log)
^- I'm a little concerned that until merge does create a structured
report, that we might miss stuff. Obviously the test is now not
asserting the same consistency it used to.
...
> class MetaTestLog(TestCase):
>
> def test_logging(self):
> - """Test logs are captured when a test fails."""
> + """Debug messages from tests are captured."""
> self.log('a test message')
> self._log_file.flush()
> - self.assertContainsRe(self._get_log(), 'a test message\n')
> + self.assertContainsRe(self._get_debug_log(), 'a test message\n')
^- If you are flushing in _get_debug_log() do we need to flush here?
> +
> + def test_fails(self):
> + return
> + self.log('something from mutter')
> + self.fail()
^- At least put a comment that this is for testing. Otherwise it looks
like a whole lot of cruft.
...
> === modified file 'bzrlib/tests/test_trace.py'
> --- bzrlib/tests/test_trace.py 2006-06-20 03:30:14 +0000
> +++ bzrlib/tests/test_trace.py 2006-07-06 06:57:13 +0000
> @@ -23,8 +23,9 @@
> import sys
> from StringIO import StringIO
>
> +from bzrlib import trace, tests
> from bzrlib.tests import TestCaseInTempDir, TestCase
> -from bzrlib.trace import mutter, report_exception
> +from bzrlib.trace import mutter, report_exception, note, warning
> from bzrlib.errors import NotBranchError
>
>
> @@ -35,7 +36,7 @@
> return buf.getvalue()
>
>
> -class TestTrace(TestCase):
> +class TestTrace(TestCase): ## tests.TestCaseWithTransport):
^- looks like something that should be cleaned up one way or another.
>
> def test_format_sys_exception(self):
> try:
> @@ -80,8 +81,6 @@
> def test_trace_unicode(self):
> """Write Unicode to trace log"""
> self.log(u'the unicode character for benzene is \N{BENZENE RING}')
> - self.assertContainsRe('the unicode character',
> - self._get_log())
^- This was testing that we could log a unicode character and not die,
and that the text was actually in the log. It seems like we should keep
some sort of check here. Maybe it should be self._get_debug_log().
It looks like self.log() is going through mutter(), which is now
silenced unless we are running a run_bzr() command.
Something isn't sitting right with me about this. I do want a way to
test that mutter(u'Unicode string') won't die.
And never muttering anything doesn't seem the right fix.
>
> def test_report_broken_pipe(self):
> try:
> @@ -97,12 +96,18 @@
> # raise an exception
> mutter(u'Writing a greek mu (\xb5) works in a unicode string')
> mutter('But fails in an ascii string \xb5')
> - # TODO: jam 20051227 mutter() doesn't flush the log file, and
> - # self._get_log() opens the file directly and reads it.
> - # So we need to manually flush the log file
> - import bzrlib.trace
> - bzrlib.trace._trace_file.flush()
> - log = self._get_log()
> - self.assertContainsRe(log, 'Writing a greek mu')
> - self.assertContainsRe(log, 'UnicodeError')
> - self.assertContainsRe(log, "'But fails in an ascii string")
> + # this test just wants to make sure that writing them doesn't fail, so
> + # we don't check anywhere that they were written
> +
But if they aren't written anywhere, we don't know if they would fail if
they were *really* being written somewhere.
We need some way to really test mutter.
It may be that for these tests we need to hook mutter up to actually log
stuff. But I really don't like having the tests passing because mutter()
isn't doing anything.
> + def test_warning_in_test_log(self):
> + warning('this is a sample note')
> + self.assertContainsRe(self._get_log(), 'this is a sample note')
> +
> + def test_note_in_test_log(self):
> + note('this is a sample note')
> + self.assertContainsRe(self._get_log(), 'this is a sample note')
> +
> + def test_error_in_test_log(self):
> + trace.error('this is a sample error')
> + self.assertContainsRe(self._get_log(),
> + r'bzr: ERROR: this is a sample error')
^- These seem pretty good. I suppose we could do the unicode tests here.
...
> +
> +def note(*args):
> + """Write a diagnostic message to the user"""
> + ui.ui_factory.show_note((args[0] % args[1:]))
I think it is better to write these as:
def note(fmt, *args):
ui.ui_factory.show_note(fmt % args)
That way you get a TypeError about missing an argument, rather than an
index error.
Also, why the double parenthesis? Where you planning on passing a tuple?
You need an extra comma for that.
I'm also concerned that there is a cyclical import here. Where trace
imports ui, and ui imports trace.
> +
> +
> +def warning(*args):
> + """Write a warning to the user.
> +
> + Typically used when the user has done something that may be a problem
> + but that shouldn't raise an exception.
> + """
> + ui.ui_factory.show_warning((args[0] % args[1:]))
> +
> +
> +def error(*args):
> + ui.ui_factory.show_error((args[0] % args[1:]))
> +
> +
> +_mutter_impl = None
^- these are the same. I also notice it is how you kept mutter()
Though I suppose it is arguable that is because you don't want to format
a string if you aren't doing anything with the result.
...
> === modified file 'bzrlib/ui/__init__.py'
> --- bzrlib/ui/__init__.py 2006-06-20 03:57:11 +0000
> +++ bzrlib/ui/__init__.py 2006-07-06 07:02:54 +0000
> @@ -1,4 +1,4 @@
> -# Copyright (C) 2005 Canonical Ltd
> +# Copyright (C) 2005, 2006 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
^- if you are fixing the copyright, shouldn't you fix the blank lines?
> @@ -86,6 +86,32 @@
> """
> raise NotImplementedError(self.get_boolean)
>
> + def _show_message(self, msg):
> + """Write a message to the user.
> +
> + This is typically sent to stderr, after clearing a progress bar if
> + necessary.
> + """
> + self.clear_term()
> + # FIXME note always emits utf-8, regardless of the terminal encoding
> + if isinstance(msg, unicode):
> + enc = getattr(self.stderr, 'encoding', 'ascii') or 'ascii'
> + msg = msg.encode(enc, 'replace')
> + self.stderr.write(msg + '\n')
> + # XXX: should be redundant; stderr should always be line-buffered
> + self.stderr.flush()
> +
> + def show_note(self, msg):
> + # XXX: This seems redundant with self.note(), which passes through to
> + # the progress bar?
> + self._show_message(msg)
> +
> + def show_warning(self, msg):
> + self._show_message('bzr: warning: ' + msg)
> +
> + def show_error(self, msg):
> + self._show_message('bzr: ERROR: ' + msg)
> +
>
> class CLIUIFactory(UIFactory):
> """Common behaviour for command line UI factories."""
> @@ -132,6 +158,9 @@
> def clear_term(self):
> pass
>
> + def _show_message(self, msg):
> + return
> +
>
> def clear_decorator(func, *args, **kwargs):
> """Decorator that clears the term"""
> @@ -142,3 +171,16 @@
> ui_factory = SilentUIFactory()
> """IMPORTANT: never import this symbol directly. ONLY ever access it as
> ui.ui_factory."""
> +
> +
> +def switch_ui_factory(new_factory):
> + """Set the factory and return the old one.
> +
> + The old factory is returned so that you can use this in a try/finally
> + block to use a different UI only within a particular scope, such as a
> + test.
> + """
> + global ui_factory
> + old = ui_factory
> + ui_factory= new_factory
> + return old
^- ui_factory = new_factory
I think I like the overall direction of this. I'm just concerned about
some of the entries which stop testing code, especially whether mutter()
is unicode safe.
John
=:->
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 254 bytes
Desc: OpenPGP digital signature
Url : https://lists.ubuntu.com/archives/bazaar/attachments/20060706/4fc9cd74/attachment.pgp
More information about the bazaar
mailing list