classification
Title: strange Tracebacks with importlib
Type: behavior Stage: resolved
Components: Library (Lib) Versions: Python 3.3
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: pitrou Nosy List: Arfrever, amaury.forgeotdarc, brett.cannon, dmalcolm, eric.snow, georg.brandl, gvanrossum, pitrou, python-dev, r.david.murray
Priority: release blocker Keywords: patch

Created on 2012-06-20 00:11 by amaury.forgeotdarc, last changed 2012-07-28 19:53 by eric.snow. This issue is now closed.

Files
File name Uploaded Description Edit
importlib-frames.patch amaury.forgeotdarc, 2012-06-25 20:16 review
trim_tb.patch pitrou, 2012-07-07 19:16 review
trim_tb2.patch pitrou, 2012-07-07 22:18 review
Messages (27)
msg163233 - (view) Author: Amaury Forgeot d'Arc (amaury.forgeotdarc) * (Python committer) Date: 2012-06-20 00:11
Exceptions during import now display huge tracebacks across importlib._bootstrap, this adds a lot of noise to the error:

For example, I added some syntax error in distutils/spawn.py, then:

~/python/cpython3.x$ ./python -c "from distutils import ccompiler"
Traceback (most recent call last):
  File "<string>", line 1, in <module>
  File "<frozen importlib._bootstrap>", line 1335, in _handle_fromlist
  File "<frozen importlib._bootstrap>", line 1288, in _find_and_load
  File "<frozen importlib._bootstrap>", line 1255, in _find_and_load_unlocked
  File "<frozen importlib._bootstrap>", line 432, in _check_name_wrapper
  File "<frozen importlib._bootstrap>", line 778, in load_module
  File "<frozen importlib._bootstrap>", line 759, in load_module
  File "<frozen importlib._bootstrap>", line 408, in module_for_loader_wrapper
  File "<frozen importlib._bootstrap>", line 647, in _load_module
  File "/home/amauryfa/python/cpython3.x/Lib/distutils/ccompiler.py", line 8, in <module>
    from distutils.spawn import spawn
  File "<frozen importlib._bootstrap>", line 1288, in _find_and_load
  File "<frozen importlib._bootstrap>", line 1255, in _find_and_load_unlocked
  File "<frozen importlib._bootstrap>", line 432, in _check_name_wrapper
  File "<frozen importlib._bootstrap>", line 778, in load_module
  File "<frozen importlib._bootstrap>", line 759, in load_module
  File "<frozen importlib._bootstrap>", line 408, in module_for_loader_wrapper
  File "<frozen importlib._bootstrap>", line 635, in _load_module
  File "<frozen importlib._bootstrap>", line 736, in get_code
  File "/home/amauryfa/python/cpython3.x/Lib/distutils/spawn.py", line 14
    does not compile
                   ^
SyntaxError: invalid syntax
msg163236 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2012-06-20 00:52
importlib is written in python.  So you get a python traceback of its execution stack.  Yes it is noisy, but I'm not sure that this should be changed, or we'd lose some of the benefit of having importlib written in python.  (It also might be really complicated to change...I'm sure Brett will tell us :)
msg163258 - (view) Author: Georg Brandl (georg.brandl) * (Python committer) Date: 2012-06-20 06:41
I agree that this is not helpful at all in the usual case, i.e. when you *don't* want to debug importlib.  The one frame in actual user code (distutils in this case) in the middle is kind of hard to spot, but it is what you want to know.  Note that Amaury's example is quite small; in other projects the import chains may go on for 10-20 modules until the ImportError is raised.  Good luck finding out where the bad module was imported without cursing.

This is different from the normal case in user code calling stdlib code, which raises an exception: the user code frames will be near the top, and the stdlib code near the bottom.

I see several options here, in no particular order of preference:

1. special-case importlib._bootstrap when printing tracebacks
2. rewrite the traceback object when raising ImportErrors from importlib
5. (is there more?)
msg164010 - (view) Author: Amaury Forgeot d'Arc (amaury.forgeotdarc) * (Python committer) Date: 2012-06-25 20:16
Here is a patch which removes "<frozen importlib._bootstrap>" frames from tracebacks.  Tests are missing, but this gives good result on the few samples I tried.
"python -v" does not suppress importlib frames.
msg164013 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2012-06-25 20:21
Wouldn't it be better to do it in pure Python in importlib itself?
msg164014 - (view) Author: Amaury Forgeot d'Arc (amaury.forgeotdarc) * (Python committer) Date: 2012-06-25 20:26
I tried to do it in importlib, with code like 
    raise original_exception.with_traceback(trimmed_traceback)
but the function containing this very line would always be part of the displayed stack trace.
msg164015 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2012-06-25 20:30
Perhaps at least the trimming should only be done for ImportErrors, then?
msg164016 - (view) Author: Amaury Forgeot d'Arc (amaury.forgeotdarc) * (Python committer) Date: 2012-06-25 20:35
No, the example above is a SyntaxError, and I claim the importlib frames should be removed as well.
msg164017 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2012-06-25 20:40
Ah, you're right. But it could become confusing if some error is raised inside of importlib itself (not an ImportError, something else - perhaps a bug).

So I would suggest the following:
- trim ImportErrors
- trim errors raised when executing the code of an imported module (i.e. in _LoaderBasics._load_module())
- don't trim other errors, since they can be importlib programming errors
msg164018 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2012-06-25 20:49
About this proposal:

> - trim errors raised when executing the code of an imported module (i.e. in _LoaderBasics._load_module())

The exec() could be isolated in a distinctly-named submethod (e.g. _exec_module()), so that it is easy to detect it in a traceback.
msg164456 - (view) Author: Georg Brandl (georg.brandl) * (Python committer) Date: 2012-07-01 08:16
Setting to blocker for b2.
msg164922 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2012-07-07 19:16
Here is a patch with tests. Brett, what do you think?
msg164923 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2012-07-07 19:18
By the way, it has to be done in C since tb_next can't be modified from Python code.
msg164936 - (view) Author: Amaury Forgeot d'Arc (amaury.forgeotdarc) * (Python committer) Date: 2012-07-07 21:00
Does it work for extension modules?
msg164938 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2012-07-07 21:06
> Does it work for extension modules?

What do you mean?
msg164939 - (view) Author: Amaury Forgeot d'Arc (amaury.forgeotdarc) * (Python committer) Date: 2012-07-07 21:15
I added to _ssl.c:

    PyErr_SetString(PyExc_ValueError, "Just a test");
    return NULL;

Then I tried to import the module:

~/python/cpython3.x$ ./python -c "import ssl"
Traceback (most recent call last):
  File "<string>", line 1, in <module>
  File "/home/amauryfa/python/cpython3.x/Lib/ssl.py", line 60, in <module>
    import _ssl             # if we can't import it, let the error propagate
  File "<frozen importlib._bootstrap>", line 1300, in _find_and_load
  File "<frozen importlib._bootstrap>", line 1267, in _find_and_load_unlocked
  File "<frozen importlib._bootstrap>", line 432, in _check_name_wrapper
  File "<frozen importlib._bootstrap>", line 347, in set_package_wrapper
  File "<frozen importlib._bootstrap>", line 360, in set_loader_wrapper
  File "<frozen importlib._bootstrap>", line 878, in load_module
ValueError: Just a test
msg164940 - (view) Author: Amaury Forgeot d'Arc (amaury.forgeotdarc) * (Python committer) Date: 2012-07-07 21:17
See also msg164937
msg164950 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2012-07-07 22:18
Ah, right, here is an updated patch which also handles extension modules and frozen ones.
msg164961 - (view) Author: Brett Cannon (brett.cannon) * (Python committer) Date: 2012-07-08 01:48
Looks good to me. Go ahead and commit it.
msg164987 - (view) Author: Roundup Robot (python-dev) Date: 2012-07-08 10:02
New changeset 8c877ad00bc4 by Antoine Pitrou in branch 'default':
Issue #15110: Fix the tracebacks generated by "import xxx" to not show the importlib stack frames.
http://hg.python.org/cpython/rev/8c877ad00bc4
msg164995 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2012-07-08 10:27
Thanks, Brett!
msg165012 - (view) Author: Amaury Forgeot d'Arc (amaury.forgeotdarc) * (Python committer) Date: 2012-07-08 13:07
I really like the "_exec_module" trick, but it should be applied to builtin modules as well. I hacked _sre.c and got:

~/python/cpython3.x$ ./python 
Traceback (most recent call last):
  File "/home/amauryfa/python/cpython3.x/Lib/site.py", line 70, in <module>
    import re
  File "/home/amauryfa/python/cpython3.x/Lib/re.py", line 122, in <module>
    import sre_compile
  File "/home/amauryfa/python/cpython3.x/Lib/sre_compile.py", line 13, in <module>
    import _sre, sys
  File "<frozen importlib._bootstrap>", line 1318, in _find_and_load
  File "<frozen importlib._bootstrap>", line 1285, in _find_and_load_unlocked
  File "<frozen importlib._bootstrap>", line 347, in set_package_wrapper
  File "<frozen importlib._bootstrap>", line 360, in set_loader_wrapper
  File "<frozen importlib._bootstrap>", line 443, in _requires_builtin_wrapper
  File "<frozen importlib._bootstrap>", line 493, in load_module
ValueError: Just a test


This change correctly hides importlib frames:


diff -r 9afdd8c25bf2 Lib/importlib/_bootstrap.py
--- a/Lib/importlib/_bootstrap.py	Sun Jul 08 14:00:06 2012 +0200
+++ b/Lib/importlib/_bootstrap.py	Sun Jul 08 15:03:27 2012 +0200
@@ -490,12 +490,15 @@
         """Load a built-in module."""
         is_reload = fullname in sys.modules
         try:
-            return _imp.init_builtin(fullname)
+            return self._exec_module(fullname)
         except:
             if not is_reload and fullname in sys.modules:
                 del sys.modules[fullname]
             raise
 
+    def _exec_module(self, fullname):
+        return _imp.init_builtin(fullname)
+
     @classmethod
     @_requires_builtin
     def get_code(cls, fullname):
msg165016 - (view) Author: Brett Cannon (brett.cannon) * (Python committer) Date: 2012-07-08 13:42
Re-opening so Antoine can look at Amaury's proposed fix for builtin modules.
msg165021 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2012-07-08 15:31
> I really like the "_exec_module" trick, but it should be applied to
> builtin modules as well. I hacked _sre.c and got:

I hadn't thought about this one. Can you apply your patch?
msg165032 - (view) Author: Roundup Robot (python-dev) Date: 2012-07-08 18:59
New changeset 37e68da59047 by Amaury Forgeot d'Arc in branch 'default':
Issue #15110: Also hide importlib frames when importing a builtin module fails.
http://hg.python.org/cpython/rev/37e68da59047
msg165033 - (view) Author: Roundup Robot (python-dev) Date: 2012-07-08 19:03
New changeset 5d43154d68a8 by Amaury Forgeot d'Arc in branch 'default':
Issue #15110: Copy same docstring as other '_exec_module' methods.
http://hg.python.org/cpython/rev/5d43154d68a8
msg166683 - (view) Author: Eric Snow (eric.snow) * (Python committer) Date: 2012-07-28 19:53
Issue15425 is related.  I'm looking into an exception chaining approach that could be applied for this issue too.
History
Date User Action Args
2012-07-28 19:53:03eric.snowsetnosy: + eric.snow
messages: + msg166683
2012-07-08 19:03:33amaury.forgeotdarcsetstatus: open -> closed
2012-07-08 19:03:11python-devsetmessages: + msg165033
2012-07-08 18:59:30python-devsetmessages: + msg165032
2012-07-08 15:31:10pitrousetmessages: + msg165021
2012-07-08 13:42:07brett.cannonsetstatus: closed -> open

messages: + msg165016
2012-07-08 13:07:16amaury.forgeotdarcsetmessages: + msg165012
2012-07-08 10:27:08pitrousetstatus: open -> closed
resolution: fixed
messages: + msg164995

stage: commit review -> resolved
2012-07-08 10:02:54python-devsetnosy: + python-dev
messages: + msg164987
2012-07-08 01:48:59brett.cannonsetstage: patch review -> commit review
2012-07-08 01:48:52brett.cannonsetassignee: brett.cannon -> pitrou
messages: + msg164961
2012-07-07 22:18:01pitrousetfiles: + trim_tb2.patch

messages: + msg164950
2012-07-07 21:17:04amaury.forgeotdarcsetmessages: + msg164940
2012-07-07 21:15:12amaury.forgeotdarcsetmessages: + msg164939
2012-07-07 21:06:03pitrousetmessages: + msg164938
2012-07-07 21:00:22amaury.forgeotdarcsetmessages: + msg164936
2012-07-07 19:18:41pitrousetmessages: + msg164923
2012-07-07 19:16:00pitrousetfiles: + trim_tb.patch

messages: + msg164922
stage: patch review
2012-07-01 08:16:09georg.brandlsetpriority: critical -> release blocker

messages: + msg164456
2012-06-25 20:49:12pitrousetmessages: + msg164018
2012-06-25 20:42:11dmalcolmsetnosy: + dmalcolm
2012-06-25 20:40:27pitrousetmessages: + msg164017
2012-06-25 20:35:52amaury.forgeotdarcsetmessages: + msg164016
2012-06-25 20:30:54pitrousetmessages: + msg164015
2012-06-25 20:26:01amaury.forgeotdarcsetmessages: + msg164014
2012-06-25 20:23:29Arfreversetnosy: + Arfrever
2012-06-25 20:21:16pitrousetnosy: + pitrou
messages: + msg164013
2012-06-25 20:16:50amaury.forgeotdarcsetfiles: + importlib-frames.patch
keywords: + patch
messages: + msg164010
2012-06-20 06:53:03georg.brandlsetnosy: + gvanrossum
2012-06-20 06:41:44georg.brandlsetpriority: normal -> critical

nosy: + georg.brandl
messages: + msg163258

assignee: brett.cannon
2012-06-20 00:52:58r.david.murraysetnosy: + r.david.murray, brett.cannon

messages: + msg163236
versions: + Python 3.3
2012-06-20 00:11:42amaury.forgeotdarccreate