Merge lp:~mbp/bzr/406113-extension-warnings into lp:bzr

[Martin Pool]

[Martin Pool (mbp)]

Here's an update for the bug 406113 taking into account John's comments in the previous review.

We now give just one warning, at the end of running bzr, describing all modules that failed to load.

[John A Meinel (jameinel)]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Martin Pool wrote:
> Martin Pool has proposed merging lp:~mbp/bzr/406113-extension-warnings into lp:bzr.
>
> Requested reviews:
> bzr-core (bzr-core)
>
> Here's an update for the bug 406113 taking into account John's comments in the previous review.
>
> We now give just one warning, at the end of running bzr, describing all modules that failed to load.
>

I like it, though I'm a little concerned about:
+ warnings.warn(
+ "bzr: warning: Failed to load compiled extensions:\n"
+ " %s\n"
+ " Bazaar can run, but performance may be reduced.\n"
+ " Check Bazaar is correctly installed or set
ignore_missing_extensions"
+ % '\n '.join(_extension_load_failures,))

^- "Bazaar can run" is being issued after Bazaar finishes running. I
can't think off-hand of a better way to write it, though. So

  review: approve
  merge: approve

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Cygwin)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAkqqPGUACgkQJdeBCYSNAANLRwCgs6UGupgQYRLX1QA/lE88U9Vk
hugAn2dcrgFkwauP1wHQIbTme3f2RH9m
=7yI0
-----END PGP SIGNATURE-----

review: Approve

[John A Meinel (jameinel)]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Martin Pool wrote:
> Martin Pool has proposed merging lp:~mbp/bzr/406113-extension-warnings into lp:bzr.
>
> Requested reviews:
> bzr-core (bzr-core)
>
> Here's an update for the bug 406113 taking into account John's comments in the previous review.
>
> We now give just one warning, at the end of running bzr, describing all modules that failed to load.
>

So with this new version, I just started getting the failure on
Kerguelen. So I went to investigate, but I can't get any real info. This
is what is in .bzr.log:

Tue 2009-09-22 14:18:26 +1000
0.266 bzr arguments: [u'--version']
0.406 encoding stdout as sys.stdout encoding 'cp437'
0.641 failed to load compiled extension: DLL load failed: Access is denied.
0.844 opening working tree 'C:/home/shared/bzr/bzr.dev'
6.344 return code 0
[58364] 2009-09-22 14:18:33.082 WARNING: bzr: warning: some compiled
extensions could not be loaded; see
<https://answers.launchpad.net/bzr/+faq/703>

So it says "I can't load" but it doesn't say *what* fails to load, and
with the shorter error, you don't show the summary of what failed to
load either.

- -Derror doesn't seem to help.

So I would recommend and least dropping the list of failures into the
log file.

John
=:->

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Cygwin)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAkq4UOoACgkQJdeBCYSNAAPh2QCeOoJIYy3Xie8UHG5u0fJtYrvK
rFQAoJhwF6fepodbW2uI3PUO7YVvDq3S
=l3m6
-----END PGP SIGNATURE-----

[John A Meinel (jameinel)]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

John A Meinel wrote:
> Martin Pool wrote:
>> Martin Pool has proposed merging lp:~mbp/bzr/406113-extension-warnings into lp:bzr.
>
>> Requested reviews:
>> bzr-core (bzr-core)
>
>> Here's an update for the bug 406113 taking into account John's comments in the previous review.
>
>> We now give just one warning, at the end of running bzr, describing all modules that failed to load.
>
>
> So with this new version, I just started getting the failure on
> Kerguelen. So I went to investigate, but I can't get any real info. This
> is what is in .bzr.log:
>
> Tue 2009-09-22 14:18:26 +1000
> 0.266 bzr arguments: [u'--version']
> 0.406 encoding stdout as sys.stdout encoding 'cp437'
> 0.641 failed to load compiled extension: DLL load failed: Access is denied.
> 0.844 opening working tree 'C:/home/shared/bzr/bzr.dev'
> 6.344 return code 0
> [58364] 2009-09-22 14:18:33.082 WARNING: bzr: warning: some compiled
> extensions could not be loaded; see
> <https://answers.launchpad.net/bzr/+faq/703>
>
>
> So it says "I can't load" but it doesn't say *what* fails to load, and
> with the shorter error, you don't show the summary of what failed to
> load either.
>
> -Derror doesn't seem to help.
>
> So I would recommend and least dropping the list of failures into the
> log file.

So I tried editing it myself, and that error message is all you get from
the exception. (ie, it doesn't tell you what plugin failed to load).

To get that info, we would have to actually add it to the api... :(

John
=:->
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Cygwin)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAkq4WfwACgkQJdeBCYSNAAO4agCfbmz3mRCWx722uX8IMmEBDCbt
XakAoIKkTQpW0whPZxvWpDXKbOAape5D
=S/ns
-----END PGP SIGNATURE-----

[Martin Pool (mbp)]

2009/9/22 John Arbash Meinel <email address hidden>:
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA1
>
> John A Meinel wrote:
>> Martin Pool wrote:
>>> Martin Pool has proposed merging lp:~mbp/bzr/406113-extension-warnings into lp:bzr.
>>
>>> Requested reviews:
>>>     bzr-core (bzr-core)
>>
>>> Here's an update for the bug 406113 taking into account John's comments in the previous review.
>>
>>> We now give just one warning, at the end of running bzr, describing all modules that failed to load.
>>
>>
>> So with this new version, I just started getting the failure on
>> Kerguelen. So I went to investigate, but I can't get any real info. This
>> is what is in .bzr.log:
>>
>> Tue 2009-09-22 14:18:26 +1000
>> 0.266  bzr arguments: [u'--version']
>> 0.406  encoding stdout as sys.stdout encoding 'cp437'
>> 0.641  failed to load compiled extension: DLL load failed: Access is denied.
>> 0.844  opening working tree 'C:/home/shared/bzr/bzr.dev'
>> 6.344  return code 0
>> [58364] 2009-09-22 14:18:33.082 WARNING: bzr: warning: some compiled
>> extensions could not be loaded; see
>> <https://answers.launchpad.net/bzr/+faq/703>
>>
>>
>> So it says "I can't load" but it doesn't say *what* fails to load, and
>> with the shorter error, you don't show the summary of what failed to
>> load either.
>>
>> -Derror doesn't seem to help.
>>
>> So I would recommend and least dropping the list of failures into the
>> log file.
>
> So I tried editing it myself, and that error message is all you get from
> the exception. (ie, it doesn't tell you what plugin failed to load).
>
> To get that info, we would have to actually add it to the api... :(

Do we even know which plugin is involved here?

It seems weird to me that a unix program would use the term "DLL", so
I suspect it's hardcoded in one of our plugins, and they're raising a
custom ImportError.

--
Martin <http://launchpad.net/~mbp/>

[John A Meinel (jameinel)]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

...

>>> So with this new version, I just started getting the failure on
>>> Kerguelen. So I went to investigate, but I can't get any real info. This
>>> is what is in .bzr.log:
>>>
>>> Tue 2009-09-22 14:18:26 +1000
>>> 0.266 bzr arguments: [u'--version']
>>> 0.406 encoding stdout as sys.stdout encoding 'cp437'
>>> 0.641 failed to load compiled extension: DLL load failed: Access is denied.
>>> 0.844 opening working tree 'C:/home/shared/bzr/bzr.dev'
>>> 6.344 return code 0
>>> [58364] 2009-09-22 14:18:33.082 WARNING: bzr: warning: some compiled
>>> extensions could not be loaded; see
>>> <https://answers.launchpad.net/bzr/+faq/703>
>>>
>>>
>>> So it says "I can't load" but it doesn't say *what* fails to load, and
>>> with the shorter error, you don't show the summary of what failed to
>>> load either.
>>>
>>> -Derror doesn't seem to help.
>>>
>>> So I would recommend and least dropping the list of failures into the
>>> log file.
>> So I tried editing it myself, and that error message is all you get from
>> the exception. (ie, it doesn't tell you what plugin failed to load).
>>
>> To get that info, we would have to actually add it to the api... :(
>
> Do we even know which plugin is involved here?
>
> It seems weird to me that a unix program would use the term "DLL", so
> I suspect it's hardcoded in one of our plugins, and they're raising a
> custom ImportError.

Well, this is on Windows, and it occurs even after I delete everything
and rebuild. I wonder if it is the _readdir_pyx issue, but I sort of
doubt it.

John
=:->
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Cygwin)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAkq4X+AACgkQJdeBCYSNAAO6YQCgix5Uw6p+EUh4+KMpALR15Qja
q/gAoL/CPIJuoeJ2OhzPxWJxie2JMiiy
=p4bA
-----END PGP SIGNATURE-----

[Martin Pool (mbp)]

2009/9/22 John Arbash Meinel <email address hidden>:
> Well, this is on Windows, and it occurs even after I delete everything
> and rebuild. I wonder if it is the _readdir_pyx issue, but I sort of
> doubt it.

My mistake.

I was assuming that the ImportError would always tell you what module
failed. Apparently not. If you file another bug, we can arrange for
the module name to be included in the message.

--
Martin <http://launchpad.net/~mbp/>

[John A Meinel (jameinel)]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Martin Pool wrote:
> 2009/9/22 John Arbash Meinel <email address hidden>:
>> Well, this is on Windows, and it occurs even after I delete everything
>> and rebuild. I wonder if it is the _readdir_pyx issue, but I sort of
>> doubt it.
>
> My mistake.
>
> I was assuming that the ImportError would always tell you what module
> failed. Apparently not. If you file another bug, we can arrange for
> the module name to be included in the message.
>
>

I managed to track it down to a failure to load _chk_map_pyx, and *that*
was actually because it was failing to import zlib1.dll.

By copying zlib1.dll into the bzrlib folder, and then changing the
permission bits, things worked again.

I did submit a bug request for making debugging extension failures
easier. On the plus side, this is exactly what your patch helps, since
before we just didn't know that things were failing.

John
=:->

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Cygwin)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAkq48psACgkQJdeBCYSNAAN11wCcD2hOqQRbs/gpVbnKUGGkpHWJ
++kAn2oGw3gxDXsfhNeA8UYEpgD+jSHY
=XpUz
-----END PGP SIGNATURE-----

=== modified file 'bzrlib/__init__.py'
--- bzrlib/__init__.py	2009-07-20 11:27:05 +0000
+++ bzrlib/__init__.py	2009-07-29 03:08:32 +0000
@@ -55,6 +55,7 @@
 # API compatibility version: bzrlib is currently API compatible with 1.15.
 api_minimum_version = (1, 17, 0)
 
+
 def _format_version_tuple(version_info):
     """Turn a version number 2, 3 or 5-tuple into a short string.
 

=== modified file 'bzrlib/annotate.py'
--- bzrlib/annotate.py	2009-07-08 17:09:03 +0000
+++ bzrlib/annotate.py	2009-09-11 06:36:50 +0000
@@ -454,5 +454,6 @@
 
 try:
     from bzrlib._annotator_pyx import Annotator
-except ImportError:
+except ImportError, e:
+    osutils.failed_to_load_extension(e)
     from bzrlib._annotator_py import Annotator

=== modified file 'bzrlib/bencode.py'
--- bzrlib/bencode.py	2009-06-03 14:14:31 +0000
+++ bzrlib/bencode.py	2009-09-11 06:36:50 +0000
@@ -16,7 +16,10 @@
 
 """Wrapper around the bencode pyrex and python implementation"""
 
+from bzrlib import osutils
+
 try:
     from bzrlib._bencode_pyx import bdecode, bdecode_as_tuple, bencode, Bencached
-except ImportError:
+except ImportError, e:
+    osutils.failed_to_load_extension(e)
     from bzrlib.util._bencode_py import bdecode, bdecode_as_tuple, bencode, Bencached

=== modified file 'bzrlib/btree_index.py'
--- bzrlib/btree_index.py	2009-07-01 10:51:47 +0000
+++ bzrlib/btree_index.py	2009-09-11 06:36:50 +0000
@@ -1385,5 +1385,6 @@
 
 try:
     from bzrlib import _btree_serializer_pyx as _btree_serializer
-except ImportError:
+except ImportError, e:
+    osutils.failed_to_load_extension(e)
     from bzrlib import _btree_serializer_py as _btree_serializer

=== modified file 'bzrlib/chk_map.py'
--- bzrlib/chk_map.py	2009-07-16 23:28:49 +0000
+++ bzrlib/chk_map.py	2009-09-11 06:36:50 +0000
@@ -1637,7 +1637,8 @@
         _deserialise_leaf_node,
         _deserialise_internal_node,
         )
-except ImportError:
+except ImportError, e:
+    osutils.failed_to_load_extension(e)
     from bzrlib._chk_map_py import (
         _search_key_16,
         _search_key_255,

=== modified file 'bzrlib/commands.py'
--- bzrlib/commands.py	2009-06-19 09:06:56 +0000
+++ bzrlib/commands.py	2009-09-11 06:42:23 +0000
@@ -1107,6 +1107,7 @@
         argv = new_argv
     ret = run_bzr_catch_errors(argv)
     trace.mutter("return code %d", ret)
+    osutils.report_extension_load_failures()
     return ret
 
 

=== modified file 'bzrlib/dirstate.py'
--- bzrlib/dirstate.py	2009-07-20 08:56:45 +0000
+++ bzrlib/dirstate.py	2009-09-11 06:36:50 +0000
@@ -3809,7 +3809,8 @@
         ProcessEntryC as _process_entry,
         update_entry as update_entry,
         )
-except ImportError:
+except ImportError, e:
+    osutils.failed_to_load_extension(e)
     from bzrlib._dirstate_helpers_py import (
         _read_dirblocks,
         bisect_dirblock,

=== modified file 'bzrlib/graph.py'
--- bzrlib/graph.py	2009-06-12 18:05:15 +0000
+++ bzrlib/graph.py	2009-09-11 06:36:50 +0000
@@ -19,6 +19,7 @@
 from bzrlib import (
     debug,
     errors,
+    osutils,
     revision,
     trace,
     tsort,
@@ -1660,5 +1661,6 @@
 _counters = [0,0,0,0,0,0,0]
 try:
     from bzrlib._known_graph_pyx import KnownGraph
-except ImportError:
+except ImportError, e:
+    osutils.failed_to_load_extension(e)
     from bzrlib._known_graph_py import KnownGraph

=== modified file 'bzrlib/groupcompress.py'
--- bzrlib/groupcompress.py	2009-07-06 20:21:34 +0000
+++ bzrlib/groupcompress.py	2009-09-11 06:36:50 +0000
@@ -1828,6 +1828,7 @@
         decode_base128_int,
         )
     GroupCompressor = PyrexGroupCompressor
-except ImportError:
+except ImportError, e:
+    osutils.failed_to_load_extension(e)
     GroupCompressor = PythonGroupCompressor
 

=== modified file 'bzrlib/knit.py'
--- bzrlib/knit.py	2009-07-28 08:09:13 +0000
+++ bzrlib/knit.py	2009-09-11 06:36:50 +0000
@@ -3622,5 +3622,6 @@
 
 try:
     from bzrlib._knit_load_data_pyx import _load_data_c as _load_data
-except ImportError:
+except ImportError, e:
+    osutils.failed_to_load_extension(e)
     from bzrlib._knit_load_data_py import _load_data_py as _load_data

=== modified file 'bzrlib/osutils.py'
--- bzrlib/osutils.py	2009-07-23 16:01:17 +0000
+++ bzrlib/osutils.py	2009-09-11 06:39:56 +0000
@@ -21,6 +21,7 @@
                   S_ISCHR, S_ISBLK, S_ISFIFO, S_ISSOCK)
 import sys
 import time
+import warnings
 
 from bzrlib.lazy_import import lazy_import
 lazy_import(globals(), """
@@ -881,9 +882,56 @@
     return parents
 
 
+_extension_load_failures = []
+
+
+def failed_to_load_extension(exception):
+    """Handle failing to load a binary extension.
+
+    This should be called from the ImportError block guarding the attempt to
+    import the native extension.  If this function returns, the pure-Python
+    implementation should be loaded instead::
+
+    >>> try:
+    >>>     import bzrlib._fictional_extension_pyx
+    >>> except ImportError, e:
+    >>>     bzrlib.osutils.failed_to_load_extension(e)
+    >>>     import bzrlib._fictional_extension_py
+    """
+    # NB: This docstring is just an example, not a doctest, because doctest
+    # currently can't cope with the use of lazy imports in this namespace --
+    # mbp 20090729
+    
+    # This currently doesn't report the failure at the time it occurs, because
+    # they tend to happen very early in startup when we can't check config
+    # files etc, and also we want to report all failures but not spam the user
+    # with 10 warnings.
+    from bzrlib import trace
+    exception_str = str(exception)
+    if exception_str not in _extension_load_failures:
+        trace.mutter("failed to load compiled extension: %s" % exception_str)
+        _extension_load_failures.append(exception_str)
+
+
+def report_extension_load_failures():
+    if not _extension_load_failures:
+        return
+    from bzrlib.config import GlobalConfig
+    if GlobalConfig().get_user_option_as_bool('ignore_missing_extensions'):
+        return
+    # the warnings framework should by default show this only once
+    warnings.warn(
+        "bzr: warning: Failed to load compiled extensions:\n"
+        "    %s\n" 
+        "    Bazaar can run, but performance may be reduced.\n"
+        "    Check Bazaar is correctly installed or set ignore_missing_extensions"
+        % '\n    '.join(_extension_load_failures,))
+
+
 try:
     from bzrlib._chunks_to_lines_pyx import chunks_to_lines
-except ImportError:
+except ImportError, e:
+    failed_to_load_extension(e)
     from bzrlib._chunks_to_lines_py import chunks_to_lines
 
 
@@ -1466,7 +1514,8 @@
             try:
                 from bzrlib._readdir_pyx import UTF8DirReader
                 _selected_dir_reader = UTF8DirReader()
-            except ImportError:
+            except ImportError, e:
+                failed_to_load_extension(e)
                 pass
 
     if _selected_dir_reader is None:
@@ -1778,7 +1827,8 @@
         try:
             from bzrlib._readdir_pyx import UTF8DirReader
             file_kind_from_stat_mode = UTF8DirReader().kind_from_mode
-        except ImportError:
+        except ImportError, e:
+            failed_to_load_extension(e)
             from bzrlib._readdir_py import (
                 _kind_from_mode as file_kind_from_stat_mode
                 )

=== modified file 'bzrlib/rio.py'
--- bzrlib/rio.py	2009-06-10 03:56:49 +0000
+++ bzrlib/rio.py	2009-09-11 06:36:50 +0000
@@ -32,6 +32,7 @@
 
 import re
 
+from bzrlib import osutils
 from bzrlib.iterablefile import IterableFile
 
 # XXX: some redundancy is allowing to write stanzas in isolation as well as
@@ -377,7 +378,8 @@
         _read_stanza_unicode,
         _valid_tag,
         )
-except ImportError:
+except ImportError, e:
+    osutils.failed_to_load_extension(e)
     from bzrlib._rio_py import (
        _read_stanza_utf8,
        _read_stanza_unicode,

=== modified file 'bzrlib/tests/test_osutils.py'
--- bzrlib/tests/test_osutils.py	2009-07-23 16:01:17 +0000
+++ bzrlib/tests/test_osutils.py	2009-09-11 06:36:50 +0000
@@ -1798,3 +1798,33 @@
     def test_local_concurrency(self):
         concurrency = osutils.local_concurrency()
         self.assertIsInstance(concurrency, int)
+
+
+class TestFailedToLoadExtension(tests.TestCase):
+
+    def _try_loading(self):
+        try:
+            import bzrlib._fictional_extension_py
+        except ImportError, e:
+            osutils.failed_to_load_extension(e)
+            return True
+
+    def setUp(self):
+        super(TestFailedToLoadExtension, self).setUp()
+        self.saved_failures = osutils._extension_load_failures[:]
+        del osutils._extension_load_failures[:]
+        self.addCleanup(self.restore_failures)
+
+    def restore_failures(self):
+        osutils._extension_load_failures = self.saved_failures
+
+    def test_failure_to_load(self):
+        self._try_loading()
+        self.assertLength(1, osutils._extension_load_failures)
+        self.assertEquals(osutils._extension_load_failures[0],
+            "No module named _fictional_extension_py")
+
+    def test_report_extension_load_failures(self):
+        self.assertTrue(self._try_loading())
+        warnings, result = self.callCatchWarnings(osutils.report_extension_load_failures)
+        self.assertLength(1, warnings)