Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Another strange Tracebacks with importlib #59630

Closed
amauryfa opened this issue Jul 22, 2012 · 23 comments
Closed

Another strange Tracebacks with importlib #59630

amauryfa opened this issue Jul 22, 2012 · 23 comments
Labels
release-blocker type-bug An unexpected behavior, bug, or error

Comments

@amauryfa
Copy link
Member

BPO 15425
Nosy @brettcannon, @birkenfeld, @jcea, @amauryfa, @ncoghlan, @pitrou, @cjerdonek, @ericsnowcurrently
Files
  • ImportError_is_king.diff
  • issue15425_test_cases.diff
  • issue15425_handle_syntax_error.diff: Test cases + fix for the syntax error case
  • Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.

    Show more details

    GitHub fields:

    assignee = None
    closed_at = <Date 2012-08-01.13:07:59.273>
    created_at = <Date 2012-07-22.20:07:01.802>
    labels = ['type-bug', 'release-blocker']
    title = 'Another strange Tracebacks with importlib'
    updated_at = <Date 2012-08-03.15:40:30.319>
    user = 'https://github.com/amauryfa'

    bugs.python.org fields:

    activity = <Date 2012-08-03.15:40:30.319>
    actor = 'jcea'
    assignee = 'none'
    closed = True
    closed_date = <Date 2012-08-01.13:07:59.273>
    closer = 'ncoghlan'
    components = []
    creation = <Date 2012-07-22.20:07:01.802>
    creator = 'amaury.forgeotdarc'
    dependencies = []
    files = ['26557', '26565', '26566']
    hgrepos = []
    issue_num = 15425
    keywords = ['patch']
    message_count = 23.0
    messages = ['166163', '166666', '166682', '166702', '166723', '166724', '166725', '166726', '166727', '166730', '166731', '166735', '166739', '166742', '166743', '166744', '166746', '166757', '166888', '166962', '166989', '167013', '167124']
    nosy_count = 10.0
    nosy_names = ['brett.cannon', 'georg.brandl', 'jcea', 'amaury.forgeotdarc', 'ncoghlan', 'pitrou', 'Arfrever', 'chris.jerdonek', 'python-dev', 'eric.snow']
    pr_nums = []
    priority = 'release blocker'
    resolution = 'fixed'
    stage = 'resolved'
    status = 'closed'
    superseder = None
    type = 'behavior'
    url = 'https://bugs.python.org/issue15425'
    versions = ['Python 3.3']

    @amauryfa
    Copy link
    Member Author

    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

    @amauryfa amauryfa added the type-bug An unexpected behavior, bug, or error label Jul 22, 2012
    @amauryfa
    Copy link
    Member Author

    IMO we should not ship 3.3 without a fix for this.

    @ericsnowcurrently
    Copy link
    Member

    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 bpo-15110. 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 bpo-15110) we should explore using exception chaining to separate the import portion from the rest. I see about working on a patch later this evening.

    @ericsnowcurrently
    Copy link
    Member

    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.

    @ncoghlan
    Copy link
    Contributor

    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)

    @ncoghlan
    Copy link
    Contributor

    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...

    @ncoghlan
    Copy link
    Contributor

    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.

    @ncoghlan
    Copy link
    Contributor

    Fixed test case patch - previous one included a comment from when my test was buggy.

    @amauryfa
    Copy link
    Member Author

    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.

    @ncoghlan
    Copy link
    Contributor

    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

    @ncoghlan
    Copy link
    Contributor

    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.

    @ncoghlan
    Copy link
    Contributor

    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.

    @ncoghlan
    Copy link
    Contributor

    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.

    @python-dev
    Copy link
    Mannequin

    python-dev mannequin commented Jul 29, 2012

    New changeset 75a30a478dc7 by Nick Coghlan in branch 'default':
    Close bpo-15425: Eliminate more importlib related traceback noise
    http://hg.python.org/cpython/rev/75a30a478dc7

    @python-dev python-dev mannequin closed this as completed Jul 29, 2012
    @ncoghlan
    Copy link
    Contributor

    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.

    @ncoghlan
    Copy link
    Contributor

    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.

    @ncoghlan
    Copy link
    Contributor

    Seeing as the blocker is dealt with for beta2, see bpo-15486 for the proposed refactoring.

    @cjerdonek
    Copy link
    Member

    The unit tests added here are another candidate for the refactoring in bpo-15403 ("Refactor package creation support code into a common location"). I'll note this in that issue.

    @pitrou
    Copy link
    Member

    pitrou commented Jul 30, 2012

    For some reason the new tests fail on the XP buildbots.

    @pitrou pitrou reopened this Jul 30, 2012
    @ericsnowcurrently
    Copy link
    Member

    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.

    @python-dev
    Copy link
    Mannequin

    python-dev mannequin commented Jul 31, 2012

    New changeset 8a0eb395e725 by Nick Coghlan in branch 'default':
    Issue bpo-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

    @ericsnowcurrently
    Copy link
    Member

    Looks like both XP buildbots are happy now. (one is failing, but not for test_import).

    @ncoghlan
    Copy link
    Contributor

    ncoghlan commented Aug 1, 2012

    Indeed, there are still a couple of Windows failures, but they aren't related to this.

    @ncoghlan ncoghlan closed this as completed Aug 1, 2012
    @ezio-melotti ezio-melotti transferred this issue from another repository Apr 10, 2022
    Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
    Labels
    release-blocker type-bug An unexpected behavior, bug, or error
    Projects
    None yet
    Development

    No branches or pull requests

    6 participants