[patch] cleanups to trace/selftest

Martin Pool mbp at canonical.com
Thu Jul 6 08:54:33 BST 2006


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.

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


=== modified file 'bzr'
--- bzr	2006-06-19 14:40:19 +0000
+++ bzr	2006-07-05 05:59:35 +0000
@@ -61,7 +61,6 @@
 try:
     import bzrlib
     import bzrlib.commands
-    import bzrlib.trace
 except ImportError, e:
     sys.stderr.write("bzr: ERROR: "
                      "Couldn't import bzrlib and dependencies.\n"
@@ -76,9 +75,7 @@
             % (bzrlib.__path__, bzrlib.version_info))
 
 if __name__ == '__main__':
-    bzrlib.trace.enable_default_logging()
     exit_val = bzrlib.commands.main(sys.argv)
-
     if profiling:
         profile_imports.log_stack_info(sys.stderr)
     sys.exit(exit_val)

=== 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)
@@ -40,7 +40,7 @@
 from bzrlib.progress import DummyProgress, ProgressPhase
 from bzrlib.revision import common_ancestor
 from bzrlib.revisionspec import RevisionSpec
-from bzrlib.trace import mutter, note, log_error, warning, is_quiet, info
+from bzrlib.trace import mutter, note, warning
 from bzrlib.transport.local import LocalTransport
 import bzrlib.urlutils as urlutils
 from bzrlib.workingtree import WorkingTree
@@ -265,16 +265,19 @@
     add them.
     """
     takes_args = ['file*']
-    takes_options = ['no-recurse', 'dry-run', 'verbose']
+    takes_options = ['no-recurse', 'dry-run', 'verbose',
+                     Option('quiet'),
+                     ]
     encoding_type = 'replace'
 
-    def run(self, file_list, no_recurse=False, dry_run=False, verbose=False):
+    def run(self, file_list, no_recurse=False, dry_run=False, verbose=False,
+            quiet=False):
         import bzrlib.add
 
         action = bzrlib.add.AddAction(to_file=self.outf,
-            should_print=(not is_quiet()))
+                                      should_print=(not quiet))
 
-        added, ignored = bzrlib.add.smart_add(file_list, not no_recurse, 
+        added, ignored = bzrlib.add.smart_add(file_list, not no_recurse,
                                               action=action, save=not dry_run)
         if len(ignored) > 0:
             if verbose:
@@ -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...'
         try:
             ui.ui_factory = ui.SilentUIFactory()
             if testspecs_list is not None:
@@ -1927,17 +1930,17 @@
                 test_suite_factory = None
                 if verbose is None:
                     verbose = False
-            result = selftest(verbose=verbose, 
+            result = selftest(verbose=verbose,
                               pattern=pattern,
-                              stop_on_failure=one, 
+                              stop_on_failure=one,
                               keep_output=keep_output,
                               transport=transport,
                               test_suite_factory=test_suite_factory,
                               lsprof_timed=lsprof_timed)
             if result:
-                info('tests passed')
+                print 'tests passed'
             else:
-                info('tests failed')
+                print 'tests failed'
             return int(not result)
         finally:
             ui.ui_factory = save_ui
@@ -2078,7 +2081,7 @@
     def help(self):
         from merge import merge_type_help
         from inspect import getdoc
-        return getdoc(self) + '\n' + merge_type_help() 
+        return getdoc(self) + '\n' + merge_type_help()
 
     def run(self, branch=None, revision=None, force=False, merge_type=None,
             show_base=False, reprocess=False, remember=False):
@@ -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
 
     # TODO: move up to common parent; this isn't merge-specific anymore. 
     def _get_remembered_parent(self, tree, supplied_location, verb_string):

=== modified file 'bzrlib/commands.py'
--- bzrlib/commands.py	2006-07-01 19:03:33 +0000
+++ bzrlib/commands.py	2006-07-05 07:54:16 +0000
@@ -45,7 +45,7 @@
 from bzrlib.revisionspec import RevisionSpec
 from bzrlib.symbol_versioning import (deprecated_method, zero_eight)
 from bzrlib import trace
-from bzrlib.trace import mutter, note, log_error, warning, be_quiet
+from bzrlib.trace import mutter, note, error, warning
 
 plugin_cmds = {}
 
@@ -74,8 +74,8 @@
         plugin_cmds[k_unsquished] = cmd
         return result
     else:
-        log_error('Two plugins defined the same command: %r' % k)
-        log_error('Not loading the one in %r' % sys.modules[cmd.__module__])
+        error('Two plugins defined the same command: %r' % k)
+        note('Not loading the one in %r' % sys.modules[cmd.__module__])
 
 
 def _squish_command_name(cmd):
@@ -605,8 +605,6 @@
             opt_no_aliases = True
         elif a == '--builtin':
             opt_builtin = True
-        elif a in ('--quiet', '-q'):
-            be_quiet()
         else:
             argv_copy.append(a)
         i += 1
@@ -647,17 +645,14 @@
         run = cmd_obj.run_argv_aliases
         run_argv = [argv, alias_argv]
 
-    try:
-        if opt_lsprof:
-            ret = apply_lsprofiled(opt_lsprof_file, run, *run_argv)
-        elif opt_profile:
-            ret = apply_profiled(run, *run_argv)
-        else:
-            ret = run(*run_argv)
-        return ret or 0
-    finally:
-        # reset, in case we may do other commands later within the same process
-        be_quiet(False)
+    if opt_lsprof:
+        ret = apply_lsprofiled(opt_lsprof_file, run, *run_argv)
+    elif opt_profile:
+        ret = apply_profiled(run, *run_argv)
+    else:
+        ret = run(*run_argv)
+    return ret or 0
+
 
 def display_command(func):
     """Decorator that suppresses pipe/interrupt errors."""

=== modified file 'bzrlib/merge.py'
--- bzrlib/merge.py	2006-07-03 13:48:52 +0000
+++ bzrlib/merge.py	2006-07-05 04:41:29 +0000
@@ -385,7 +385,7 @@
                 child_pb.finished()
             self.cook_conflicts(fs_conflicts)
             for conflict in self.cooked_conflicts:
-                warning(conflict)
+                warning('%s', conflict)
             self.pp.next_phase()
             results = self.tt.apply()
             self.write_modified(results)

=== modified file 'bzrlib/plugin.py'
--- bzrlib/plugin.py	2006-06-04 21:22:51 +0000
+++ bzrlib/plugin.py	2006-07-03 08:17:16 +0000
@@ -46,7 +46,7 @@
 
 import bzrlib
 from bzrlib.config import config_dir
-from bzrlib.trace import log_error, mutter, warning, \
+from bzrlib.trace import mutter, warning, \
         log_exception_quietly
 from bzrlib.errors import BzrError
 from bzrlib import plugins

=== modified file 'bzrlib/progress.py'
--- bzrlib/progress.py	2006-06-21 02:33:40 +0000
+++ bzrlib/progress.py	2006-07-05 08:19:17 +0000
@@ -41,9 +41,7 @@
 import os
 from collections import deque
 
-
 import bzrlib.errors as errors
-from bzrlib.trace import mutter 
 
 
 def _supports_progress(f):
@@ -298,8 +296,6 @@
                 pass
             elif self.last_cnt + child_fraction <= self.last_total:
                 self.child_fraction = child_fraction
-            else:
-                mutter('not updating child fraction')
         if self.last_msg is None:
             self.last_msg = ''
         self.tick()
@@ -443,8 +439,6 @@
         else:
             count = self.current+self.child_fraction
             if count > self.total:
-                if __debug__:
-                    mutter('clamping count of %d to %d' % (count, self.total))
                 count = self.total
         self.parent.child_update(self.message, count, self.total)
 

=== modified file 'bzrlib/tests/__init__.py'
--- bzrlib/tests/__init__.py	2006-06-30 15:13:19 +0000
+++ bzrlib/tests/__init__.py	2006-07-06 07:18:33 +0000
@@ -31,7 +31,6 @@
 import difflib
 import doctest
 import errno
-import logging
 import os
 import re
 import shlex
@@ -56,6 +55,7 @@
 except ImportError:
     # lsprof not available
     pass
+from bzrlib import trace, ui
 from bzrlib.merge import merge_inner
 import bzrlib.merge3
 import bzrlib.osutils
@@ -64,7 +64,6 @@
 import bzrlib.progress as progress
 from bzrlib.revision import common_ancestor
 import bzrlib.store
-import bzrlib.trace
 from bzrlib.transport import get_transport
 import bzrlib.transport
 from bzrlib.transport.local import LocalRelpathServer
@@ -275,13 +274,13 @@
         for test, err in errors:
             self.stream.writeln(self.separator1)
             self.stream.writeln("%s: %s" % (flavour, self.getDescription(test)))
-            if getattr(test, '_get_log', None) is not None:
+            if getattr(test, '_get_debug_log', None) is not None:
                 print >>self.stream
                 print >>self.stream, \
-                        ('vvvv[log from %s]' % test.id()).ljust(78,'-')
-                print >>self.stream, test._get_log()
+                        ('vvvv[debug log from %s]' % test.id()).ljust(78,'-')
+                self.stream.write(test._get_debug_log())
                 print >>self.stream, \
-                        ('^^^^[log from %s]' % test.id()).ljust(78,'-')
+                        ('^^^^[debug log from %s]' % test.id()).ljust(78,'-')
             self.stream.writeln(self.separator2)
             self.stream.writeln("%s" % err)
 
@@ -426,7 +425,7 @@
 
     Error and debug log messages are redirected from their usual
     location into a temporary file, the contents of which can be
-    retrieved by _get_log().  We use a real OS file, not an in-memory object,
+    retrieved by _get_debug_log().  We use a real OS file, not an in-memory object,
     so that it can also capture file IO.  When the test completes this file
     is read into memory and removed from disk.
        
@@ -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 = []
 
     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)
+
     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)
-
-    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.
+        """
+        ## import pdb;pdb.set_trace()
         if self._log_file_name:
+            self._log_file.flush()
             return open(self._log_file_name).read()
         else:
             return self._log_contents
-        # TODO: Delete the log after it's been read in
 
     def capture(self, cmd, retcode=0):
         """Shortcut that splits cmd into words, runs, and returns stdout"""
@@ -674,12 +714,11 @@
         overall behavior of the bzr application (rather than a unit test
         or a functional test of the library.)
 
-        Much of the old code runs bzr by forking a new copy of Python, but
-        that is slower, harder to debug, and generally not necessary.
-
         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.
 
         :param argv: arguments to invoke bzr
         :param retcode: expected return code, or None for don't-care.
@@ -694,32 +733,29 @@
         stderr = StringIOWrapper()
         stdout.encoding = encoding
         stderr.encoding = encoding
-
-        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())
+        # 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()
         if out:
-            self.log('output:\n%r', out)
+            self.log('output:\n%s', out)
         if err:
-            self.log('errors:\n%r', err)
+            self.log('errors:\n%s', err)
         if retcode is not None:
             self.assertEquals(retcode, result)
         return out, err

=== modified file 'bzrlib/tests/blackbox/__init__.py'
--- bzrlib/tests/blackbox/__init__.py	2006-07-04 15:04:11 +0000
+++ bzrlib/tests/blackbox/__init__.py	2006-07-06 07:46:56 +0000
@@ -110,6 +110,9 @@
             return self.run_bzr_captured(args, retcode=retcode)
 
 
+# TODO: don't use the ui factory as the progress object; create a separate
+# do-nothing instance.
+
 class TestUIFactory(ui.CLIUIFactory):
     """A UI Factory for testing - hide the progress bar but emit note()s."""
 
@@ -117,6 +120,8 @@
                  stdout=None,
                  stderr=None):
         super(TestUIFactory, self).__init__()
+        # TODO: do we really want these defaults for stdout/stderr?  Should
+        # the test ever be writing to the real thing?
         if stdout is None:
             self.stdout = sys.stdout
         else:
@@ -138,6 +143,9 @@
     def finished(self):
         """See progress.ProgressBar.finished()."""
 
+    def get_password(self, prompt='', **kwargs):
+        return None
+
     def note(self, fmt_string, *args, **kwargs):
         """See progress.ProgressBar.note()."""
         self.stdout.write((fmt_string + "\n") % args)

=== modified file 'bzrlib/tests/blackbox/test_commit.py'
--- bzrlib/tests/blackbox/test_commit.py	2006-06-23 16:26:26 +0000
+++ bzrlib/tests/blackbox/test_commit.py	2006-07-05 04:41:29 +0000
@@ -189,7 +189,7 @@
             other_tree.unlock()
         self.merge(other_tree.branch, this_tree)
         os.chdir('this')
-        out,err = self.run_bzr("commit", "-m", "added")
+        out, err = self.run_bzr("commit", "-m", "added")
         os.chdir('..')
         self.assertEqual('', out)
         self.assertEqualDiff(

=== 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)
-        
+
 
 class TestRunBzr(ExternalBase):
 

=== modified file 'bzrlib/tests/test_merge.py'
--- bzrlib/tests/test_merge.py	2006-07-02 19:31:42 +0000
+++ bzrlib/tests/test_merge.py	2006-07-06 07:10:46 +0000
@@ -25,7 +25,6 @@
 from bzrlib.osutils import pathjoin
 from bzrlib.revision import common_ancestor
 from bzrlib.tests import TestCaseWithTransport
-from bzrlib.trace import (enable_test_log, disable_test_log)
 from bzrlib.workingtree import WorkingTree
 
 
@@ -125,21 +124,22 @@
 
     def test_ignore_zero_merge_inner(self):
         # Test that merge_inner's ignore zero paramter is effective
-        tree_a =self.make_branch_and_tree('a')
+        tree_a = self.make_branch_and_tree('a')
         tree_a.commit(message="hello")
         dir_b = tree_a.bzrdir.sprout('b')
         tree_b = dir_b.open_workingtree()
         tree_a.commit(message="hello again")
-        log = StringIO()
-        merge_inner(tree_b.branch, tree_a, tree_b.basis_tree(), 
+        merge_inner(tree_b.branch, tree_a, tree_b.basis_tree(),
                     this_tree=tree_b, ignore_zero=True)
-        log = self._get_log()
-        self.failUnless('All changes applied successfully.\n' not in log)
         tree_b.revert([])
-        merge_inner(tree_b.branch, tree_a, tree_b.basis_tree(), 
+        merge_inner(tree_b.branch, tree_a, tree_b.basis_tree(),
                     this_tree=tree_b, ignore_zero=False)
-        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)
 
     def test_merge_inner_conflicts(self):
         tree_a = self.make_branch_and_tree('a')

=== modified file 'bzrlib/tests/test_selftest.py'
--- bzrlib/tests/test_selftest.py	2006-07-03 05:38:39 +0000
+++ bzrlib/tests/test_selftest.py	2006-07-06 07:09:48 +0000
@@ -53,10 +53,15 @@
 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')
+
+    def test_fails(self):
+        return
+        self.log('something from mutter')
+        self.fail()
 
 
 class TestTreeShape(TestCaseInTempDir):
@@ -582,26 +587,6 @@
         self.inner_test.run(result)
         note("outer finish")
 
-    def test_trace_nesting(self):
-        # this tests that each test case nests its trace facility correctly.
-        # we do this by running a test case manually. That test case (A)
-        # should setup a new log, log content to it, setup a child case (B),
-        # which should log independently, then case (A) should log a trailer
-        # and return.
-        # we do two nested children so that we can verify the state of the 
-        # logs after the outer child finishes is correct, which a bad clean
-        # up routine in tearDown might trigger a fault in our test with only
-        # one child, we should instead see the bad result inside our test with
-        # the two children.
-        # the outer child test
-        original_trace = bzrlib.trace._trace_file
-        outer_test = TestTestCase("outer_child")
-        result = bzrlib.tests._MyResult(self._log_file,
-                                        descriptions=0,
-                                        verbosity=1)
-        outer_test.run(result)
-        self.assertEqual(original_trace, bzrlib.trace._trace_file)
-
     def method_that_times_a_bit_twice(self):
         # call self.time twice to ensure it aggregates
         self.time(time.sleep, 0.007)

=== 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):
 
     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())
 
     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
+
+    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')

=== modified file 'bzrlib/trace.py'
--- bzrlib/trace.py	2006-06-29 16:24:56 +0000
+++ bzrlib/trace.py	2006-07-06 07:52:36 +0000
@@ -20,137 +20,65 @@
 to be inserted into it.  The actual %-formatting is deferred to the log
 library so that it doesn't need to be done for messages that won't be emitted.
 
-Messages are classified by severity levels: critical, error, warning, info,
-and debug.
-
-They can be sent to two places: to stderr, and to ~/.bzr.log.  For purposes
-such as running the test suite, they can also be redirected away from both of
-those two places to another location.
-
-~/.bzr.log gets all messages, and full tracebacks for uncaught exceptions.
-This trace file is always in UTF-8, regardless of the user's default encoding,
-so that we can always rely on writing any message.
-
-Output to stderr depends on the mode chosen by the user.  By default, messages
-of info and above are sent out, which results in progress messages such as the
-list of files processed by add and commit.  In quiet mode, only warnings and
-above are shown.  In debug mode, stderr gets debug messages too.
+There are two separate types of message that can be send: messages to the user
+(including errors, warnings, and notes), and debug messages.  Debug messages
+are in a different category because they're handled differently during
+testing, and can be turned on and off during testing.  (For example, black box
+tests will typically want to examine the stderr output, but also record the
+debug messages separately.)
 
 Errors that terminate an operation are generally passed back as exceptions;
 others may be just emitted as messages.
-
-Exceptions are reported in a brief form to stderr so as not to look scary.
-BzrErrors are required to be able to format themselves into a properly
-explanatory message.  This is not true for builtin exceptions such as
-KeyError, which typically just str to "0".  They're printed in a different
-form.
 """
 
-# FIXME: Unfortunately it turns out that python's logging module
-# is quite expensive, even when the message is not printed by any handlers.
-# We should perhaps change back to just simply doing it here.
-
+# TODO: If bzr is run with a global -D option, send trace messages to stderr.
+#
+# TODO: When we get an IOError, KeyboardInterrupt, etc, we should perhaps show
+# the line number/method where the problem occurred.
 
 import errno
 import os
 import sys
-import logging
 
 import bzrlib
+from bzrlib import ui
 from bzrlib.errors import BzrError, BzrNewError
 from bzrlib.symbol_versioning import (deprecated_function,
         zero_nine,
         )
 
-_file_handler = None
-_stderr_handler = None
-_stderr_quiet = False
-_trace_file = None
-_trace_depth = 0
-_bzr_log_file = None
-
-
-# configure convenient aliases for output routines
-
-_bzr_logger = logging.getLogger('bzr')
-
-def note(*args, **kwargs):
-    # FIXME note always emits utf-8, regardless of the terminal encoding
-    import bzrlib.ui
-    bzrlib.ui.ui_factory.clear_term()
-    _bzr_logger.info(*args, **kwargs)
-
-def warning(*args, **kwargs):
-    import bzrlib.ui
-    bzrlib.ui.ui_factory.clear_term()
-    _bzr_logger.warning(*args, **kwargs)
-
-info = note
-log_error = _bzr_logger.error
-error =     _bzr_logger.error
+
+def note(*args):
+    """Write a diagnostic message to the user"""
+    ui.ui_factory.show_note((args[0] % args[1:]))
+
+
+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
 
 
 def mutter(fmt, *args):
-    if _trace_file is None:
-        return
-    if hasattr(_trace_file, 'closed') and _trace_file.closed:
-        return
-    if len(args) > 0:
-        # It seems that if we do ascii % (unicode, ascii) we can
-        # get a unicode cannot encode ascii error, so make sure that "fmt"
-        # is a unicode string
-        out = unicode(fmt) % args
-    else:
-        out = fmt
-    out += '\n'
-    try:
-        _trace_file.write(out)
-    except UnicodeError, e:
-        warning('UnicodeError: %s', e)
-        _trace_file.write(repr(out))
-    # TODO: jam 20051227 Consider flushing the trace file to help debugging
-    #_trace_file.flush()
-debug = mutter
-
-
-def _rollover_trace_maybe(trace_fname):
-    import stat
-    try:
-        size = os.stat(trace_fname)[stat.ST_SIZE]
-        if size <= 4 << 20:
-            return
-        old_fname = trace_fname + '.old'
-        from osutils import rename
-        rename(trace_fname, old_fname)
-    except OSError:
-        return
-
-
-def open_tracefile(tracefilename='~/.bzr.log'):
-    # Messages are always written to here, so that we have some
-    # information if something goes wrong.  In a future version this
-    # file will be removed on successful completion.
-    global _file_handler, _bzr_log_file
-    import codecs
-
-    trace_fname = os.path.join(os.path.expanduser(tracefilename))
-    _rollover_trace_maybe(trace_fname)
-    try:
-        LINE_BUFFERED = 1
-        tf = codecs.open(trace_fname, 'at', 'utf8', buffering=LINE_BUFFERED)
-        _bzr_log_file = tf
-        if tf.tell() == 0:
-            tf.write("\nthis is a debug log for diagnosing/reporting problems in bzr\n")
-            tf.write("you can delete or truncate this file, or include sections in\n")
-            tf.write("bug reports to bazaar-ng at lists.canonical.com\n\n")
-        _file_handler = logging.StreamHandler(tf)
-        fmt = r'[%(process)5d] %(asctime)s.%(msecs)03d %(levelname)s: %(message)s'
-        datefmt = r'%a %H:%M:%S'
-        _file_handler.setFormatter(logging.Formatter(fmt, datefmt))
-        _file_handler.setLevel(logging.DEBUG)
-        logging.getLogger('').addHandler(_file_handler)
-    except IOError, e:
-        warning("failed to open trace file: %s" % (e))
+    """Write debugging message.
+
+    When this is called from inside the test suite, the results are written
+    into a log displayed if the test fails.
+    """
+    # extra indirection so that callers that directly import mutter get the
+    # most up to date implementation.
+    if _mutter_impl:
+        _mutter_impl(fmt, args)
 
 
 @deprecated_function(zero_nine)
@@ -179,81 +107,6 @@
     debug(traceback.format_exc())
 
 
-def enable_default_logging():
-    """Configure default logging to stderr and .bzr.log"""
-    # FIXME: if this is run twice, things get confused
-    global _stderr_handler, _file_handler, _trace_file, _bzr_log_file
-    _stderr_handler = logging.StreamHandler()
-    logging.getLogger('').addHandler(_stderr_handler)
-    _stderr_handler.setLevel(logging.INFO)
-    if not _file_handler:
-        open_tracefile()
-    _trace_file = _bzr_log_file
-    if _file_handler:
-        _file_handler.setLevel(logging.DEBUG)
-    _bzr_logger.setLevel(logging.DEBUG)
-
-
-def be_quiet(quiet=True):
-    global _stderr_handler, _stderr_quiet
-    
-    _stderr_quiet = quiet
-    if quiet:
-        _stderr_handler.setLevel(logging.WARNING)
-    else:
-        _stderr_handler.setLevel(logging.INFO)
-
-
-def is_quiet():
-    global _stderr_quiet
-    return _stderr_quiet
-
-
-def disable_default_logging():
-    """Turn off default log handlers.
-
-    This is intended to be used by the test framework, which doesn't
-    want leakage from the code-under-test into the main logs.
-    """
-
-    l = logging.getLogger('')
-    l.removeHandler(_stderr_handler)
-    if _file_handler:
-        l.removeHandler(_file_handler)
-    _trace_file = None
-
-
-def enable_test_log(to_file):
-    """Redirect logging to a temporary file for a test
-    
-    returns an opaque reference that should be passed to disable_test_log
-    after the test completes.
-    """
-    disable_default_logging()
-    global _trace_file
-    global _trace_depth
-    hdlr = logging.StreamHandler(to_file)
-    hdlr.setLevel(logging.DEBUG)
-    hdlr.setFormatter(logging.Formatter('%(levelname)8s  %(message)s'))
-    _bzr_logger.addHandler(hdlr)
-    _bzr_logger.setLevel(logging.DEBUG)
-    result = hdlr, _trace_file, _trace_depth
-    _trace_file = to_file
-    _trace_depth += 1
-    return result
-
-
-def disable_test_log((test_log_hdlr, old_trace_file, old_trace_depth)):
-    _bzr_logger.removeHandler(test_log_hdlr)
-    test_log_hdlr.close()
-    global _trace_file
-    global _trace_depth
-    _trace_file = old_trace_file
-    _trace_depth = old_trace_depth
-    if not _trace_depth:
-        enable_default_logging()
-
-
 def report_exception(exc_info, err_file):
     exc_type, exc_object, exc_tb = exc_info
     if (isinstance(exc_object, IOError)

=== modified file 'bzrlib/transport/http/_urllib.py'
--- bzrlib/transport/http/_urllib.py	2006-06-20 03:57:11 +0000
+++ bzrlib/transport/http/_urllib.py	2006-07-06 05:52:53 +0000
@@ -81,7 +81,7 @@
             range_string = ranges
         else:
             range_string = 'all'
-        mutter("get_url %s [%s]" % (url, range_string))
+        mutter("get_url %s [%s]", url, range_string)
         manager = urllib2.HTTPPasswordMgrWithDefaultRealm()
         url = extract_auth(url, manager)
         auth_handler = urllib2.HTTPBasicAuthHandler(manager)

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


-- 
Martin




More information about the bazaar mailing list