classification
Title: Another strange Tracebacks with importlib
Type: behavior Stage: resolved
Components: Versions: Python 3.3
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: Arfrever, amaury.forgeotdarc, brett.cannon, chris.jerdonek, eric.snow, georg.brandl, jcea, ncoghlan, pitrou, python-dev
Priority: release blocker Keywords: patch

Created on 2012-07-22 20:07 by amaury.forgeotdarc, last changed 2012-08-03 15:40 by jcea. This issue is now closed.

Files
File name Uploaded Description Edit
ImportError_is_king.diff eric.snow, 2012-07-29 01:41 review
issue15425_test_cases.diff ncoghlan, 2012-07-29 08:28 review
issue15425_handle_syntax_error.diff ncoghlan, 2012-07-29 09:26 Test cases + fix for the syntax error case review
Messages (23)
msg166163 - (view) Author: Amaury Forgeot d'Arc (amaury.forgeotdarc) * (Python committer) Date: 2012-07-22 20:07
Two "easy" ways to get tracebacks which contain useless importlib._bootstrap rows:
- When there is a syntax error in the imported module
- On "import package.module", when top-level package cannot be imported


$ ./python -c "import foo"
Traceback (most recent call last):
  File "<string>", line 1, in <module>
  File "<frozen importlib._bootstrap>", line 1421, in _find_and_load
  File "<frozen importlib._bootstrap>", line 1388, in _find_and_load_unlocked
  File "<frozen importlib._bootstrap>", line 527, in _check_name_wrapper
  File "<frozen importlib._bootstrap>", line 899, in load_module
  File "<frozen importlib._bootstrap>", line 880, in load_module
  File "<frozen importlib._bootstrap>", line 503, in module_for_loader_wrapper
  File "<frozen importlib._bootstrap>", line 744, in _load_module
  File "<frozen importlib._bootstrap>", line 857, in get_code
  File "./foo.py", line 1
    invalid syntax
                 ^
SyntaxError: invalid syntax


$ ./python
Python 3.3.0b1 (default:afdb0e1a9dac+, Jul 19 2012, 23:55:02) 
[GCC 4.4.3] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import _sqlite3
>>> del _sqlite3.register_converter
>>> import sqlite3.dump
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "<frozen importlib._bootstrap>", line 1421, in _find_and_load
  File "<frozen importlib._bootstrap>", line 1372, in _find_and_load_unlocked
  File "/home/amauryfa/python/cpython3.x/Lib/sqlite3/__init__.py", line 23, in <module>
    from sqlite3.dbapi2 import *
  File "/home/amauryfa/python/cpython3.x/Lib/sqlite3/dbapi2.py", line 83, in <module>
    register_adapters_and_converters()
  File "/home/amauryfa/python/cpython3.x/Lib/sqlite3/dbapi2.py", line 80, in register_adapters_and_converters
    register_converter("date", convert_date)
NameError: global name 'register_converter' is not defined
msg166666 - (view) Author: Amaury Forgeot d'Arc (amaury.forgeotdarc) * (Python committer) Date: 2012-07-28 17:12
IMO we should not ship 3.3 without a fix for this.
msg166682 - (view) Author: Eric Snow (eric.snow) * (Python committer) Date: 2012-07-28 19:51
Perhaps this should be split into two issues, as the fix will likely be different for the two.

For the first part (SyntaxError), my initial impression is that this will require a similar fix, or extension of it, to the one in issue15110.  That fix was limited just to the execution of the module, while this problem happens earlier (during the compilation step in SourceLoader.get_code()).  

For the second part, it is all about failures during the execution of an import that was initiated during the import of another module.  That traceback is definitely less than helpful.  A better traceback would is doable.

For both (and maybe for issue15110) we should explore using exception chaining to separate the import portion from the rest.  I see about working on a patch later this evening.
msg166702 - (view) Author: Eric Snow (eric.snow) * (Python committer) Date: 2012-07-29 01:41
Here's a trivial patch that demonstrates what I mean.  Yet, in light of exception chaining, I wonder if we should consider actually making ImportError supercede the inner exception.  I'll still try coming up with something similar, but propagates the inside exception.
msg166723 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2012-07-29 08:19
Added patch with test cases for the situations Amaury picked up, as well another I noticed (when the from clause refers to a module that fails)
msg166724 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2012-07-29 08:20
I actually did start refactoring a lot of this when I was working on the pkgutil changes, but stopped because that patch was already hairy enough.

Maybe I should have kept going...
msg166725 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2012-07-29 08:25
I think tuning the "what frames to hide" heuristic is a better bet - I remember know that the real reason I stopped messing with which exceptions were thrown was that I ended up confusing pkgutil.
msg166726 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2012-07-29 08:28
Fixed test case patch - previous one included a comment from when my test was buggy.
msg166727 - (view) Author: Amaury Forgeot d'Arc (amaury.forgeotdarc) * (Python committer) Date: 2012-07-29 08:49
I like the concept of "exit points" that Antoine introduced with a special method name. Maybe we coule generalize this and have a "execute_and_hide_frames(func, *args, **kwargs)" that is recognized by the caller in import.c.
msg166730 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2012-07-29 09:07
OK, to investigate the failures a bit further, I turned off the traceback suppression altogether by sticking an immediate return at the start of remove_importlib_frames. For the three failing tests, this is what I got when adding a traceback.print_tb call:

test_broken_from (test.test_import.ImportTracebackTests) ...   File "/home/ncoghlan/devel/py3k/Lib/test/test_import.py", line 890, in test_broken_from
    from _parent_foo import bar
  File "<frozen importlib._bootstrap>", line 1572, in _handle_fromlist
  File "<frozen importlib._bootstrap>", line 1524, in _find_and_load
  File "<frozen importlib._bootstrap>", line 1491, in _find_and_load_unlocked
  File "<frozen importlib._bootstrap>", line 571, in _check_name_wrapper
  File "<frozen importlib._bootstrap>", line 1002, in load_module
  File "<frozen importlib._bootstrap>", line 983, in load_module
  File "<frozen importlib._bootstrap>", line 547, in module_for_loader_wrapper
  File "<frozen importlib._bootstrap>", line 853, in _load_module
  File "<frozen importlib._bootstrap>", line 860, in _exec_module
  File "./_parent_foo/bar.py", line 1, in <module>
    1/0
FAIL
test_broken_parent (test.test_import.ImportTracebackTests) ...   File "/home/ncoghlan/devel/py3k/Lib/test/test_import.py", line 902, in test_broken_parent
    import _parent_foo.bar
  File "<frozen importlib._bootstrap>", line 1524, in _find_and_load
  File "<frozen importlib._bootstrap>", line 1475, in _find_and_load_unlocked
  File "<frozen importlib._bootstrap>", line 1524, in _find_and_load
  File "<frozen importlib._bootstrap>", line 1491, in _find_and_load_unlocked
  File "<frozen importlib._bootstrap>", line 571, in _check_name_wrapper
  File "<frozen importlib._bootstrap>", line 1002, in load_module
  File "<frozen importlib._bootstrap>", line 983, in load_module
  File "<frozen importlib._bootstrap>", line 547, in module_for_loader_wrapper
  File "<frozen importlib._bootstrap>", line 853, in _load_module
  File "<frozen importlib._bootstrap>", line 860, in _exec_module
  File "./_parent_foo/__init__.py", line 1, in <module>
    1/0
FAIL
test_syntax_error (test.test_import.ImportTracebackTests) ...   File "/home/ncoghlan/devel/py3k/Lib/test/test_import.py", line 851, in test_syntax_error
    import foo
  File "<frozen importlib._bootstrap>", line 1524, in _find_and_load
  File "<frozen importlib._bootstrap>", line 1491, in _find_and_load_unlocked
  File "<frozen importlib._bootstrap>", line 571, in _check_name_wrapper
  File "<frozen importlib._bootstrap>", line 1002, in load_module
  File "<frozen importlib._bootstrap>", line 983, in load_module
  File "<frozen importlib._bootstrap>", line 547, in module_for_loader_wrapper
  File "<frozen importlib._bootstrap>", line 838, in _load_module
  File "<frozen importlib._bootstrap>", line 960, in get_code
FAIL

And here's what I get with my patched version enabled (which also ignores chunks ending with get_code when the failure is a syntax error):

test_broken_from (test.test_import.ImportTracebackTests) ...   File "/home/ncoghlan/devel/py3k/Lib/test/test_import.py", line 890, in test_broken_from
    from _parent_foo import bar
  File "<frozen importlib._bootstrap>", line 1572, in _handle_fromlist
  File "./_parent_foo/bar.py", line 1, in <module>
    1/0
FAIL
test_broken_parent (test.test_import.ImportTracebackTests) ...   File "/home/ncoghlan/devel/py3k/Lib/test/test_import.py", line 902, in test_broken_parent
    import _parent_foo.bar
  File "<frozen importlib._bootstrap>", line 1524, in _find_and_load
  File "<frozen importlib._bootstrap>", line 1475, in _find_and_load_unlocked
  File "./_parent_foo/__init__.py", line 1, in <module>
    1/0
FAIL
test_syntax_error (test.test_import.ImportTracebackTests) ...   File "/home/ncoghlan/devel/py3k/Lib/test/test_import.py", line 851, in test_syntax_error
    import foo
FAIL
msg166731 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2012-07-29 09:26
I realised that it is my test that was wrong in the syntax error case. Attached patch includes the test cases, and the fix for that case.

The weird thing that still requires an explanation is why the chunks in the first two cases are only being partially stripped. Those blocks end with _exec_module, yet a couple of frames are being left in the traceback.

Current patch includes my debugging output from those tests.
msg166735 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2012-07-29 09:46
Ah, it turns out the three problem children are those which accept an "import_" callback, which is set to builtins.__import__ when accessed via the import statement. This means we end up making a *recursive* call to PyImport_ImportModuleLevelObject, which calls remove_importlib_frames. The inner section of the trace gets stripped away, thus the "_exec_module" frame is already gone by the time the outer frames get added to the traceback.

For the moment, I'm just going to adopt the blunt instrument approach and special case those three functions (including them in the "always strip" category). If anyone else comes up with a more elegant mechanism to deal with the recursion, we can switch to it later.
msg166739 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2012-07-29 10:03
I'll at least introduce a "_recursive_import" exit point to simplify handling of those three cases. For those, if there isn't another importlib frame on the stack below them, odds are pretty good that it has been stripped already.
msg166742 - (view) Author: Roundup Robot (python-dev) Date: 2012-07-29 10:30
New changeset 75a30a478dc7 by Nick Coghlan in branch 'default':
Close #15425: Eliminate more importlib related traceback noise
http://hg.python.org/cpython/rev/75a30a478dc7
msg166743 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2012-07-29 10:36
I think the implementation I just checked in is close to being as simple as we can get:

Blocks ending in _exec_module and _recursive_import are trimmed unconditionally
For SyntaxError, it also trims blocks ending in get_code
For ImportError, it trims everything involving importlib

Because the latter two are conditional on the kind of exception thrown, it's only the first two that could be unified and I think keeping the two distinct checks is actually clearer in that case.
msg166744 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2012-07-29 10:39
On second thought, I realised having a general purpose "hide this" hook means that any future unconditional cases can easily be hidden just by changing from the normal call to a stripped call. I'll implement that now.
msg166746 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2012-07-29 10:47
Seeing as the blocker is dealt with for beta2, see #15486 for the proposed refactoring.
msg166757 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2012-07-29 13:30
The unit tests added here are another candidate for the refactoring in issue 15403 ("Refactor package creation support code into a common location").  I'll note this in that issue.
msg166888 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2012-07-30 12:05
For some reason the new tests fail on the XP buildbots.
msg166962 - (view) Author: Eric Snow (eric.snow) * (Python committer) Date: 2012-07-31 06:09
For instance, http://buildbot.python.org/all/builders/x86%20XP-4%203.x/builds/7214/steps/test/logs/stdio

4 cases of "ImportError: No module named '_parent_foo'".  Failing on "import _parent_foo.bar" and "from _parent_foo import bar".

Unfortunately I don't have an XP system set up on which to debug this.
msg166989 - (view) Author: Roundup Robot (python-dev) Date: 2012-07-31 11:39
New changeset 8a0eb395e725 by Nick Coghlan in branch 'default':
Issue #15425: Don't rely on the assumption that the current working directory is on sys.path (this will hopefully appease the XP buildbots)
http://hg.python.org/cpython/rev/8a0eb395e725
msg167013 - (view) Author: Eric Snow (eric.snow) * (Python committer) Date: 2012-07-31 16:12
Looks like both XP buildbots are happy now.  (one is failing, but not for test_import).
msg167124 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2012-08-01 13:07
Indeed, there are still a couple of Windows failures, but they aren't related to this.
History
Date User Action Args
2012-08-03 15:40:30jceasetnosy: + jcea
2012-08-01 13:07:59ncoghlansetstatus: pending -> closed

messages: + msg167124
2012-07-31 16:13:10eric.snowsetstatus: open -> pending
2012-07-31 16:12:27eric.snowsetstatus: pending -> open

messages: + msg167013
2012-07-31 11:40:25ncoghlansetstatus: open -> pending
2012-07-31 11:39:57python-devsetmessages: + msg166989
2012-07-31 06:09:00eric.snowsetmessages: + msg166962
2012-07-30 12:05:15pitrousetstatus: closed -> open

messages: + msg166888
2012-07-29 13:30:33chris.jerdoneksetnosy: + chris.jerdonek
messages: + msg166757
2012-07-29 11:53:56Arfreversetnosy: + Arfrever
2012-07-29 10:47:22ncoghlansetmessages: + msg166746
2012-07-29 10:39:59ncoghlansetmessages: + msg166744
2012-07-29 10:36:50ncoghlansetmessages: + msg166743
2012-07-29 10:30:51python-devsetstatus: open -> closed

nosy: + python-dev
messages: + msg166742

resolution: fixed
stage: resolved
2012-07-29 10:03:42ncoghlansetmessages: + msg166739
2012-07-29 09:46:16ncoghlansetmessages: + msg166735
2012-07-29 09:26:09ncoghlansetfiles: + issue15425_handle_syntax_error.diff

messages: + msg166731
2012-07-29 09:07:31ncoghlansetmessages: + msg166730
2012-07-29 08:49:49amaury.forgeotdarcsetmessages: + msg166727
2012-07-29 08:28:45ncoghlansetfiles: - issue15425_test_cases.diff
2012-07-29 08:28:32ncoghlansetfiles: + issue15425_test_cases.diff

messages: + msg166726
2012-07-29 08:25:44ncoghlansetmessages: + msg166725
2012-07-29 08:20:44ncoghlansetmessages: + msg166724
2012-07-29 08:19:09ncoghlansetfiles: + issue15425_test_cases.diff

messages: + msg166723
2012-07-29 07:19:33ncoghlansetnosy: + ncoghlan
2012-07-29 01:41:24eric.snowsetfiles: + ImportError_is_king.diff
keywords: + patch
messages: + msg166702
2012-07-28 19:51:45eric.snowsetnosy: + eric.snow
messages: + msg166682
2012-07-28 17:45:08eric.snowsetversions: + Python 3.3
2012-07-28 17:21:36georg.brandlsetpriority: high -> release blocker
2012-07-28 17:15:33ezio.melottisetnosy: + georg.brandl
2012-07-28 17:12:32amaury.forgeotdarcsetpriority: normal -> high

messages: + msg166666
2012-07-22 20:07:01amaury.forgeotdarccreate