Merge lp:~gz/brz/py3_crash_debug_trace into lp:brz

[Martin Packman]

Make tests pass on Python 3 for crash, debug, and trace modules

[Jelmer Vernooij (jelmer)]

review: Approve

[The Breezy Bot (the-breezy-bot)]

Running landing tests failed
http://10.242.247.184:8080/job/brz-dev/114/

[The Breezy Bot (the-breezy-bot)]

Running landing tests failed
http://10.242.247.184:8080/job/brz-dev/115/

[Martin Packman (gz)]

Intermittent failure.

ERROR: breezy.tests.test_test_server.TestTCPServerInAThread.test_handle_request_closes_if_it_doesnt_process(TestingTCPServer)

socket.error: [Errno 104] Connection reset by peer

=== modified file 'breezy/crash.py'
--- breezy/crash.py	2017-05-22 00:56:52 +0000
+++ breezy/crash.py	2017-06-10 22:21:19 +0000
@@ -226,7 +226,7 @@
 
 def _attach_log_tail(pr):
     try:
-        bzr_log = open(trace._get_bzr_log_filename(), 'rt')
+        bzr_log = open(trace._get_brz_log_filename(), 'rt')
     except (IOError, OSError) as e:
         pr['BzrLogTail'] = repr(e)
         return

=== modified file 'breezy/plugin.py'
--- breezy/plugin.py	2017-06-10 14:01:07 +0000
+++ breezy/plugin.py	2017-06-10 22:21:19 +0000
@@ -441,11 +441,13 @@
     return result
 
 
-def format_concise_plugin_list():
+def format_concise_plugin_list(state=None):
     """Return a string holding a concise list of plugins and their version.
     """
+    if state is None:
+        state = breezy.global_state
     items = []
-    for name, a_plugin in sorted(plugins().items()):
+    for name, a_plugin in sorted(state.plugins.items()):
         items.append("%s[%s]" %
             (name, a_plugin.__version__))
     return ', '.join(items)

=== modified file 'breezy/tests/blackbox/test_exceptions.py'
--- breezy/tests/blackbox/test_exceptions.py	2017-06-10 00:52:37 +0000
+++ breezy/tests/blackbox/test_exceptions.py	2017-06-10 22:21:19 +0000
@@ -40,8 +40,7 @@
             universal_newlines=True,
             retcode=errors.EXIT_INTERNAL_ERROR)
         self.assertEqual(4, errors.EXIT_INTERNAL_ERROR)
-        self.assertContainsRe(err,
-                r'exceptions\.AssertionError: always fails\n')
+        self.assertContainsRe(err, r'\nAssertionError: always fails\n')
         self.assertContainsRe(err, r'Bazaar has encountered an internal error')
 
     def test_undecodable_argv(self):

=== modified file 'breezy/tests/test_crash.py'
--- breezy/tests/test_crash.py	2017-05-22 00:56:52 +0000
+++ breezy/tests/test_crash.py	2017-06-10 22:21:19 +0000
@@ -19,6 +19,7 @@
 import os
 import sys
 
+import breezy
 from .. import (
     config,
     crash,
@@ -27,7 +28,7 @@
     tests,
     )
 from ..sixish import (
-    BytesIO,
+    StringIO,
     )
 from . import features
 
@@ -43,29 +44,23 @@
         self.assertEqual(crash_dir, config.crash_dir())
 
         self.overrideAttr(
-            plugin,
+            breezy.global_state,
             'plugin_warnings',
             {'example': ['Failed to load plugin foo']})
 
-        stderr = BytesIO()
+        stderr = StringIO()
 
         try:
             raise AssertionError("my error")
         except AssertionError as e:
-            pass
-
-        crash_filename = crash.report_bug_to_apport(sys.exc_info(),
-            stderr)
+            crash_filename = crash.report_bug_to_apport(sys.exc_info(), stderr)
 
         # message explaining the crash
         self.assertContainsRe(stderr.getvalue(),
             "    apport-bug %s" % crash_filename)
 
-        crash_file = open(crash_filename)
-        try:
+        with open(crash_filename) as crash_file:
             report = crash_file.read()
-        finally:
-            crash_file.close()
 
         self.assertContainsRe(report,
             '(?m)^BzrVersion:') # should be in the traceback
@@ -83,31 +78,27 @@
 
 class TestNonApportReporting(tests.TestCase):
     """Reporting of crash-type bugs without apport.
-    
+
     This should work in all environments.
     """
 
     def setup_fake_plugins(self):
-        def fake_plugins():
-            fake = plugin.PlugIn('fake_plugin', plugin)
-            fake.version_info = lambda: (1, 2, 3)
-            return {"fake_plugin": fake}
-        self.overrideAttr(plugin, 'plugins', fake_plugins)
+        fake = plugin.PlugIn('fake_plugin', plugin)
+        fake.version_info = lambda: (1, 2, 3)
+        fake_plugins = {"fake_plugin": fake}
+        self.overrideAttr(breezy.global_state, 'plugins', fake_plugins)
 
     def test_report_bug_legacy(self):
         self.setup_fake_plugins()
-        err_file = BytesIO()
+        err_file = StringIO()
         try:
             raise AssertionError("my error")
         except AssertionError as e:
-            pass
-        crash.report_bug_legacy(sys.exc_info(), err_file)
+            crash.report_bug_legacy(sys.exc_info(), err_file)
         report = err_file.getvalue()
         for needle in [
-            "brz: ERROR: exceptions.AssertionError: my error",
+            "brz: ERROR: AssertionError: my error",
             r"Traceback \(most recent call last\):",
             r"plugins: fake_plugin\[1\.2\.3\]",
             ]:
-            self.assertContainsRe(
-                    report,
-                    needle)
+            self.assertContainsRe(report, needle)

=== modified file 'breezy/tests/test_debug.py'
--- breezy/tests/test_debug.py	2017-05-22 00:56:52 +0000
+++ breezy/tests/test_debug.py	2017-06-10 22:21:19 +0000
@@ -27,17 +27,18 @@
 class TestDebugFlags(tests.TestCaseInTempDir):
 
     def test_set_no_debug_flags_from_config(self):
-        self.assertDebugFlags([], '')
+        self.assertDebugFlags([], b'')
 
     def test_set_single_debug_flags_from_config(self):
-        self.assertDebugFlags(['hpss'], 'debug_flags = hpss\n')
+        self.assertDebugFlags(['hpss'], b'debug_flags = hpss\n')
 
     def test_set_multiple_debug_flags_from_config(self):
-        self.assertDebugFlags(['hpss', 'error'], 'debug_flags = hpss, error\n')
+        self.assertDebugFlags(
+            ['hpss', 'error'], b'debug_flags = hpss, error\n')
 
     def assertDebugFlags(self, expected_flags, conf_bytes):
         conf = config.GlobalStack()
-        conf.store._load_from_string('[DEFAULT]\n' + conf_bytes)
+        conf.store._load_from_string(b'[DEFAULT]\n' + conf_bytes)
         conf.store.save()
         self.overrideAttr(debug, 'debug_flags', set())
         debug.set_debug_flags_from_config()

=== modified file 'breezy/tests/test_trace.py'
--- breezy/tests/test_trace.py	2017-05-22 00:56:52 +0000
+++ breezy/tests/test_trace.py	2017-06-10 22:21:19 +0000
@@ -31,7 +31,8 @@
     trace,
     )
 from ..sixish import (
-    BytesIO,
+    PY3,
+    StringIO,
     )
 from . import features, TestCaseInTempDir, TestCase
 from ..trace import (
@@ -46,7 +47,7 @@
 
 def _format_exception():
     """Format an exception as it would normally be displayed to the user"""
-    buf = BytesIO()
+    buf = StringIO()
     report_exception(sys.exc_info(), buf)
     return buf.getvalue()
 
@@ -61,10 +62,9 @@
         try:
             raise NotImplementedError("time travel")
         except NotImplementedError:
-            pass
-        err = _format_exception()
-        self.assertEqualDiff(err.splitlines()[0],
-                'brz: ERROR: exceptions.NotImplementedError: time travel')
+            err = _format_exception()
+        self.assertContainsRe(err,
+                '^brz: ERROR: NotImplementedError: time travel')
         self.assertContainsRe(err,
             'Bazaar has encountered an internal error.')
 
@@ -73,17 +73,14 @@
             raise KeyboardInterrupt()
         except KeyboardInterrupt:
             # XXX: Some risk that a *real* keyboard interrupt won't be seen
-            pass
-        msg = _format_exception()
-        self.assertTrue(len(msg) > 0)
-        self.assertEqualDiff(msg, 'brz: interrupted\n')
+            msg = _format_exception()
+        self.assertEqual(msg, 'brz: interrupted\n')
 
     def test_format_memory_error(self):
         try:
             raise MemoryError()
         except MemoryError:
-            pass
-        msg = _format_exception()
+            msg = _format_exception()
         self.assertEqual(msg,
             "brz: out of memory\nUse -Dmem_dump to dump memory to a file.\n")
 
@@ -93,8 +90,7 @@
         try:
             raise MemoryError()
         except MemoryError:
-            pass
-        msg = _format_exception()
+            msg = _format_exception()
         self.assertStartsWith(msg,
             "brz: out of memory\nMemory dumped to ")
 
@@ -103,22 +99,21 @@
             os.rmdir('nosuchfile22222')
         except OSError as e:
             e_str = str(e)
-        msg = _format_exception()
+            msg = _format_exception()
         # Linux seems to give "No such file" but Windows gives "The system
         # cannot find the file specified".
         self.assertEqual('brz: ERROR: %s\n' % (e_str,), msg)
 
     def test_format_io_error(self):
         try:
-            file('nosuchfile22222')
+            open('nosuchfile22222')
         except IOError:
-            pass
-        msg = _format_exception()
+            msg = _format_exception()
         # Even though Windows and Linux differ for 'os.rmdir', they both give
         # 'No such file' for open()
         # However it now gets translated so we can not test for a specific message
         self.assertContainsRe(msg,
-            r'^brz: ERROR: \[Errno .*\] .*nosuchfile')
+            '^brz: ERROR: \\[Errno .*\\] .*nosuchfile')
 
     def test_format_pywintypes_error(self):
         self.requireFeature(features.pywintypes)
@@ -126,63 +121,62 @@
         try:
             win32file.RemoveDirectory('nosuchfile22222')
         except pywintypes.error:
-            pass
-        msg = _format_exception()
+            msg = _format_exception()
         # GZ 2010-05-03: Formatting for pywintypes.error is basic, a 3-tuple
         #                with errno, function name, and locale error message
         self.assertContainsRe(msg,
-            r"^brz: ERROR: \(2, 'RemoveDirectory[AW]?', .*\)")
-            
+            "^brz: ERROR: \\(2, 'RemoveDirectory[AW]?', .*\\)")
+
     def test_format_sockets_error(self):
         try:
             import socket
             sock = socket.socket()
-            sock.send("This should fail.")
+            sock.send(b"This should fail.")
         except socket.error:
-            pass
-        msg = _format_exception()
-        
+            msg = _format_exception()
+
         self.assertNotContainsRe(msg,
-            r"Traceback (most recent call last):")
+            "Traceback \\(most recent call last\\):")
 
     def test_format_unicode_error(self):
         try:
             raise errors.BzrCommandError(u'argument foo\xb5 does not exist')
         except errors.BzrCommandError:
-            pass
-        msg = _format_exception()
+            msg = _format_exception()
+        if PY3:
+            expected = 'brz: ERROR: argument foo\xb5 does not exist\n'
+        else:
+            # GZ 2017-06-10: Pretty bogus, should encode per the output stream
+            expected = 'brz: ERROR: argument foo\xc2\xb5 does not exist\n'
+        self.assertEqual(msg, expected)
 
     def test_format_exception(self):
         """Short formatting of brz exceptions"""
         try:
             raise errors.NotBranchError('wibble')
         except errors.NotBranchError:
-            pass
-        msg = _format_exception()
-        self.assertTrue(len(msg) > 0)
-        self.assertEqualDiff(msg, 'brz: ERROR: Not a branch: \"wibble\".\n')
+            msg = _format_exception()
+        self.assertEqual(msg, 'brz: ERROR: Not a branch: \"wibble\".\n')
 
     def test_report_external_import_error(self):
         """Short friendly message for missing system modules."""
         try:
             import ImaginaryModule
         except ImportError as e:
-            pass
+            msg = _format_exception()
         else:
             self.fail("somehow succeeded in importing %r" % ImaginaryModule)
-        msg = _format_exception()
-        self.assertEqual(msg,
-            'brz: ERROR: No module named ImaginaryModule\n'
-            'You may need to install this Python library separately.\n')
+        self.assertContainsRe(msg,
+            "^brz: ERROR: No module named '?ImaginaryModule'?\n"
+            "You may need to install this Python library separately.\n$")
 
     def test_report_import_syntax_error(self):
         try:
             raise ImportError("syntax error")
         except ImportError as e:
-            pass
-        msg = _format_exception()
+            msg = _format_exception()
         self.assertContainsRe(msg,
-            r'Bazaar has encountered an internal error')
+            'Bazaar has encountered an internal error')
 
     def test_trace_unicode(self):
         """Write Unicode to trace log"""
@@ -212,17 +206,18 @@
         else:
             self.fail("expected error not raised")
 
-    def assertLogStartsWith(self, log, string):
-        """Like assertStartsWith, but skips the log timestamp."""
+    def assertLogContainsLine(self, log, string):
+        """Assert log contains a line including log timestamp."""
+        # Does not check absolute position in log as there may be kipple.
         self.assertContainsRe(log,
-            '^\\d+\\.\\d+  ' + re.escape(string))
+            '(?m)^\\d+\\.\\d+  ' + re.escape(string))
 
     def test_mutter_callsite_1(self):
         """mutter_callsite can capture 1 level of stack frame."""
         mutter_callsite(1, "foo %s", "a string")
         log = self.get_log()
         # begin with the message
-        self.assertLogStartsWith(log, 'foo a string\nCalled from:\n')
+        self.assertLogContainsLine(log, 'foo a string\nCalled from:\n')
         # should show two frame: this frame and the one above
         self.assertContainsRe(log,
             'test_trace\\.py", line \\d+, in test_mutter_callsite_1\n')
@@ -234,7 +229,7 @@
         mutter_callsite(2, "foo %s", "a string")
         log = self.get_log()
         # begin with the message
-        self.assertLogStartsWith(log, 'foo a string\nCalled from:\n')
+        self.assertLogContainsLine(log, 'foo a string\nCalled from:\n')
         # should show two frame: this frame and the one above
         self.assertContainsRe(log,
             'test_trace.py", line \d+, in test_mutter_callsite_2\n')
@@ -247,15 +242,15 @@
         # 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(b'But fails in an ascii string \xb5')
+        mutter(b'and in an ascii argument: %s', b'\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',
+        self.assertContainsRe(log, b"ascii argument: \xb5".decode('utf8',
             'replace'))
 
     def test_show_error(self):
@@ -303,10 +298,11 @@
             # as there's a timestamp at the front.
             tmp1.seek(0)
             self.assertContainsRe(tmp1.read(),
-                r"\d+\.\d+  comment to file1\n\d+\.\d+  again to file1\n")
+                b"\\d+\\.\\d+  comment to file1\n"
+                b"\\d+\\.\\d+  again to file1\n")
             tmp2.seek(0)
             self.assertContainsRe(tmp2.read(),
-                r"\d+\.\d+  comment to file2\n")
+                b"\\d+\\.\\d+  comment to file2\n")
         finally:
             tmp1.close()
             tmp2.close()
@@ -315,7 +311,7 @@
         # If _open_brz_log cannot open the file, then we should write the
         # warning to stderr. Since this is normally happening before logging is
         # set up.
-        self.overrideAttr(sys, 'stderr', BytesIO())
+        self.overrideAttr(sys, 'stderr', StringIO())
         # Set the log file to something that cannot exist
         self.overrideEnv('BRZ_LOG', '/no-such-dir/brz.log')
         self.overrideAttr(trace, '_brz_log_filename')
@@ -378,33 +374,43 @@
         self.assertEqual(u"   DEBUG  \xa7\n", self.get_log())
 
     def test_log_utf8_msg(self):
-        logging.getLogger("brz").debug("\xc2\xa7")
+        logging.getLogger("brz").debug(b"\xc2\xa7")
         self.assertEqual(u"   DEBUG  \xa7\n", self.get_log())
 
     def test_log_utf8_arg(self):
-        logging.getLogger("brz").debug("%s", "\xc2\xa7")
-        self.assertEqual(u"   DEBUG  \xa7\n", self.get_log())
+        logging.getLogger("brz").debug(b"%s", b"\xc2\xa7")
+        if PY3:
+            expected = u"   DEBUG  b'\\xc2\\xa7'\n"
+        else:
+            expected = u"   DEBUG  \xa7\n"
+        self.assertEqual(expected, self.get_log())
 
     def test_log_bytes_msg(self):
-        logging.getLogger("brz").debug("\xa7")
+        logging.getLogger("brz").debug(b"\xa7")
         log = self.get_log()
         self.assertContainsString(log, "UnicodeDecodeError: ")
-        self.assertContainsString(log,
-            "Logging record unformattable: '\\xa7' % ()\n")
+        self.assertContainsRe(log,
+            "Logging record unformattable: b?'\\\\xa7' % \\(\\)\n")
 
     def test_log_bytes_arg(self):
-        logging.getLogger("brz").debug("%s", "\xa7")
+        logging.getLogger("brz").debug(b"%s", b"\xa7")
         log = self.get_log()
-        self.assertContainsString(log, "UnicodeDecodeError: ")
-        self.assertContainsString(log,
-            "Logging record unformattable: '%s' % ('\\xa7',)\n")
+        if PY3:
+            self.assertEqual(u"   DEBUG  b'\\xa7'\n", self.get_log())
+        else:
+            self.assertContainsString(log, "UnicodeDecodeError: ")
+            self.assertContainsRe(log,
+                "Logging record unformattable: ?'%s' % \\(b?'\\\\xa7',\\)\n")
 
     def test_log_mixed_strings(self):
-        logging.getLogger("brz").debug(u"%s", "\xa7")
+        logging.getLogger("brz").debug(u"%s", b"\xa7")
         log = self.get_log()
-        self.assertContainsString(log, "UnicodeDecodeError: ")
-        self.assertContainsString(log,
-            "Logging record unformattable: u'%s' % ('\\xa7',)\n")
+        if PY3:
+            self.assertEqual(u"   DEBUG  b'\\xa7'\n", self.get_log())
+        else:
+            self.assertContainsString(log, "UnicodeDecodeError: ")
+            self.assertContainsRe(log,
+                "Logging record unformattable: u'%s' % \\('\\\\xa7',\\)\n")
 
     def test_log_repr_broken(self):
         class BadRepr(object):

=== modified file 'breezy/trace.py'
--- breezy/trace.py	2017-05-22 00:56:52 +0000
+++ breezy/trace.py	2017-06-10 22:21:19 +0000
@@ -82,6 +82,8 @@
 
 from .sixish import (
     BytesIO,
+    PY3,
+    StringIO,
     text_type,
     )
 
@@ -173,7 +175,7 @@
     :param fmt: The format string to pass to mutter.
     :param args: A list of substitution variables.
     """
-    outf = BytesIO()
+    outf = StringIO()
     if stacklevel is None:
         limit = None
     else:
@@ -252,9 +254,9 @@
         brz_log_file = _open_or_create_log_file(_brz_log_filename)
         brz_log_file.write(b'\n')
         if brz_log_file.tell() <= 2:
-            brz_log_file.write("this is a debug log for diagnosing/reporting problems in brz\n")
-            brz_log_file.write("you can delete or truncate this file, or include sections in\n")
-            brz_log_file.write("bug reports to https://bugs.launchpad.net/brz/+filebug\n\n")
+            brz_log_file.write(b"this is a debug log for diagnosing/reporting problems in brz\n")
+            brz_log_file.write(b"you can delete or truncate this file, or include sections in\n")
+            brz_log_file.write(b"bug reports to https://bugs.launchpad.net/brz/+filebug\n\n")
 
         return brz_log_file
 
@@ -469,7 +471,7 @@
     """
     class_name = eclass.__name__
     module_name = eclass.__module__
-    if module_name in ("exceptions", "__main__") or (
+    if module_name in ("builtins", "exceptions", "__main__") or (
             unqualified_breezy_errors and module_name == "breezy.errors"):
         return class_name
     return "%s.%s" % (module_name, class_name)
@@ -521,8 +523,8 @@
 
 def print_exception(exc_info, err_file):
     exc_type, exc_object, exc_tb = exc_info
-    err_file.write("brz: ERROR: %s.%s: %s\n" % (
-        exc_type.__module__, exc_type.__name__, exc_object))
+    err_file.write("brz: ERROR: %s: %s\n" % (
+        _qualified_exception_name(exc_type), exc_object))
     err_file.write('\n')
     traceback.print_exception(exc_type, exc_object, exc_tb, file=err_file)
 
@@ -539,7 +541,7 @@
     """
     err_file.write("brz: ERROR: %s\n" % (exc_info[1],))
     if advice:
-        err_file.write("%s\n" % (advice,))
+        err_file.write("%s\n" % advice)
 
 
 def report_bug(exc_info, err_file):
@@ -597,6 +599,10 @@
 
     def emit(self, record):
         try:
+            if not isinstance(record.msg, text_type):
+                msg = record.msg.decode("utf-8")
+                if PY3:
+                    record.msg = msg
             line = self.format(record)
             if not isinstance(line, text_type):
                 line = line.decode("utf-8")
@@ -606,8 +612,8 @@
             # Try saving the details that would have been logged in some form
             msg = args = "<Unformattable>"
             try:
-                msg = repr(record.msg).encode("ascii")
-                args = repr(record.args).encode("ascii")
+                msg = repr(record.msg).encode("ascii", "backslashescape")
+                args = repr(record.args).encode("ascii", "backslashescape")
             except Exception:
                 pass
             # Using mutter() bypasses the logging module and writes directly