Rev 4719: Fix bug #503886, errors setting up logging go to stderr. in http://bazaar.launchpad.net/~jameinel/bzr/2.0.4-trace-failure

[John Arbash Meinel]

At http://bazaar.launchpad.net/~jameinel/bzr/2.0.4-trace-failure

------------------------------------------------------------
revno: 4719
revision-id: john at arbash-meinel.com-20100106174615-cq1nckxhbuyemgjx
parent: pqm at pqm.ubuntu.com-20100105000154-t1mtm27efpc26gsl
committer: John Arbash Meinel <john at arbash-meinel.com>
branch nick: 2.0.4-trace-failure
timestamp: Wed 2010-01-06 11:46:15 -0600
message:
  Fix bug #503886, errors setting up logging go to stderr.
  
  The basic issue is that we were using logging to describe failures
  to set up logging. However, those fail with bad error messages
  rather than giving us the output we want. This was especially bad
  when the failure was occuring on the server. Since 'ssh' will pass
  back the stderr stream without bzr handling it at all.
-------------- next part --------------
=== modified file 'NEWS'
--- a/NEWS	2010-01-05 00:01:54 +0000
+++ b/NEWS	2010-01-06 17:46:15 +0000
@@ -38,6 +38,12 @@
 * Give a clearer message if the lockdir disappears after being apparently
   successfully taken.  (Martin Pool, #498378)
 
+* If we fail to open ``~/.bzr.log`` write a clear message to stderr rather
+  than using ``warning()``. The log file is opened before logging is set
+  up, and it leads to very confusing: 'no handlers for "bzr"' messages for
+  users, rather than something nicer.
+  (John Arbash Meinel, Barry Warsaw, #503886)
+
 * The 2a format wasn't properly restarting autopacks when something
   changed underneath it (like another autopack). Now concurrent
   autopackers will properly succeed. (John Arbash Meinel, #495000)

=== modified file 'bzrlib/tests/test_trace.py'
--- a/bzrlib/tests/test_trace.py	2009-09-03 02:59:56 +0000
+++ b/bzrlib/tests/test_trace.py	2010-01-06 17:46:15 +0000
@@ -27,6 +27,7 @@
 
 from bzrlib import (
     errors,
+    trace,
     )
 from bzrlib.tests import TestCaseInTempDir, TestCase
 from bzrlib.trace import (
@@ -238,6 +239,20 @@
             tmp1.close()
             tmp2.close()
 
+    def test__open_bzr_log_uses_stderr_for_failures(self):
+        # If _open_bzr_log cannot open the file, then we should write the
+        # warning to stderr. Since this is normally happening before logging is
+        # set up.
+        self.addCleanup(setattr, sys, 'stderr', sys.stderr)
+        self.addCleanup(setattr, trace, '_bzr_log_filename',
+                        trace._bzr_log_filename)
+        sys.stderr = StringIO()
+        # Set the log file to something that cannot exist
+        os.environ['BZR_LOG'] = os.getcwd() + '/no-dir/bzr.log'
+        logf = trace._open_bzr_log()
+        self.assertIs(None, logf)
+        self.assertContainsRe(sys.stderr.getvalue(),
+                              'failed to open trace file: .*/no-dir/bzr.log')
 
 class TestVerbosityLevel(TestCase):
 

=== modified file 'bzrlib/trace.py'
--- a/bzrlib/trace.py	2009-09-03 02:59:56 +0000
+++ b/bzrlib/trace.py	2010-01-06 17:46:15 +0000
@@ -237,7 +237,12 @@
             bzr_log_file.write("bug reports to https://bugs.launchpad.net/bzr/+filebug\n\n")
         return bzr_log_file
     except IOError, e:
-        warning("failed to open trace file: %s" % (e))
+        # If we are failing to open the log, then most likely logging has not
+        # been set up yet. So we just write to stderr rather than using
+        # 'warning()'. If we using warning(), users get the unhelpful 'no
+        # handlers registered for "bzr"' when something goes wrong on the
+        # server. (bug #503886)
+        sys.stderr.write("failed to open trace file: %s\n" % (e,))
     # TODO: What should happen if we fail to open the trace file?  Maybe the
     # objects should be pointed at /dev/null or the equivalent?  Currently
     # returns None which will cause failures later.