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

Wrong trace with multiple decorators (linenumber wrong in frame) #82152

Closed
jorants mannequin opened this issue Aug 28, 2019 · 10 comments
Closed

Wrong trace with multiple decorators (linenumber wrong in frame) #82152

jorants mannequin opened this issue Aug 28, 2019 · 10 comments
Labels
3.8 only security fixes 3.9 only security fixes interpreter-core (Objects, Python, Grammar, and Parser dirs) type-bug An unexpected behavior, bug, or error

Comments

@jorants
Copy link
Mannequin

jorants mannequin commented Aug 28, 2019

BPO 37971
Nosy @cfbolz, @nedbat, @ambv, @serhiy-storchaka, @jorants
PRs
  • bpo-37971: fix the position of decorator application #30027
  • Files
  • decolinenumbers.patch
  • 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 = None
    created_at = <Date 2019-08-28.18:32:52.219>
    labels = ['interpreter-core', 'type-bug', '3.8', '3.9']
    title = 'Wrong trace with multiple decorators (linenumber wrong in frame)'
    updated_at = <Date 2021-12-10.23:45:06.848>
    user = 'https://github.com/jorants'

    bugs.python.org fields:

    activity = <Date 2021-12-10.23:45:06.848>
    actor = 'lukasz.langa'
    assignee = 'none'
    closed = False
    closed_date = None
    closer = None
    components = ['Interpreter Core']
    creation = <Date 2019-08-28.18:32:52.219>
    creator = 'control-k'
    dependencies = []
    files = ['48567']
    hgrepos = []
    issue_num = 37971
    keywords = ['patch']
    message_count = 8.0
    messages = ['350686', '350691', '350762', '350769', '350782', '350792', '408203', '408271']
    nosy_count = 5.0
    nosy_names = ['Carl.Friedrich.Bolz', 'nedbat', 'lukasz.langa', 'serhiy.storchaka', 'control-k']
    pr_nums = ['30027']
    priority = 'normal'
    resolution = None
    stage = 'patch review'
    status = 'open'
    superseder = None
    type = 'behavior'
    url = 'https://bugs.python.org/issue37971'
    versions = ['Python 3.8', 'Python 3.9']

    @jorants
    Copy link
    Mannequin Author

    jorants mannequin commented Aug 28, 2019

    When applying multiple decorators to a function, a traceback from the top generator shows the bottom generator instead.
    For example

    ----------------

    def printingdec(f):
        raise Exception()
        return f
    
    def dummydec(f):
        return f
    
    @printingdec
    @dummydec
    def foo():
        pass

    gives
    Traceback (most recent call last):
      File "bug.py", line 9, in <module>
        @dummydec
      File "bug.py", line 2, in printingdec
        raise Exception()
    Exception
    
    instead of
    Traceback (most recent call last):
      File "bug.py", line 8, in <module>
        @printingdec
      File "bug.py", line 2, in printingdec
        raise Exception()
    Exception

    Digging around with sys._getframe() it seems that the frame's linenumber is set wrong internally, leading to the wrong line being displayed.
    The ast does display the correct linenumber.

    @jorants jorants mannequin added the type-bug An unexpected behavior, bug, or error label Aug 28, 2019
    @serhiy-storchaka
    Copy link
    Member

    In Python 3.8+ I got:

    Traceback (most recent call last):
      File "/home/serhiy/py/cpython/issue37971.py", line 10, in <module>
        def foo():
      File "/home/serhiy/py/cpython/issue37971.py", line 2, in printingdec
        raise Exception()
    Exception

    The traceback refers to the line where the function is defined.

    @jorants
    Copy link
    Mannequin Author

    jorants mannequin commented Aug 29, 2019

    Digging around with the disassembler shows that this originates in the bytecode.
    Code:
    --------

    import dis
    src = """
    def printingdec(f):
        raise Exception()
        return f
    
    def dummydec(f):
        return f
    
    @printingdec
    @dummydec
    def foo():
        pass
    """
    code = compile(src,filename="bug.py",mode='exec')
    print(dis.dis(code))
    --------- 

    gives on 3.6:
    2 0 LOAD_CONST 0 (<code object printingdec at 0x7f86c87171e0, file "bug.py", line 2>)
    2 LOAD_CONST 1 ('printingdec')
    4 MAKE_FUNCTION 0
    6 STORE_NAME 0 (printingdec)

    6 8 LOAD_CONST 2 (<code object dummydec at 0x7f86c84b8660, file "bug.py", line 6>)
    10 LOAD_CONST 3 ('dummydec')
    12 MAKE_FUNCTION 0
    14 STORE_NAME 1 (dummydec)

    9 16 LOAD_NAME 0 (printingdec)

    10 18 LOAD_NAME 1 (dummydec)
    20 LOAD_CONST 4 (<code object foo at 0x7f86c84b8540, file "bug.py", line 9>)
    22 LOAD_CONST 5 ('foo')
    24 MAKE_FUNCTION 0
    26 CALL_FUNCTION 1
    28 CALL_FUNCTION 1
    30 STORE_NAME 2 (foo)
    32 LOAD_CONST 6 (None)
    34 RETURN_VALUE
    None

    and on 3.9:
    2 0 LOAD_CONST 0 (<code object printingdec at 0x7f5e13aaca80, file "bug.py", line 2>)
    2 LOAD_CONST 1 ('printingdec')
    4 MAKE_FUNCTION 0
    6 STORE_NAME 0 (printingdec)

    6 8 LOAD_CONST 2 (<code object dummydec at 0x7f5e13aacb30, file "bug.py", line 6>)
    10 LOAD_CONST 3 ('dummydec')
    12 MAKE_FUNCTION 0
    14 STORE_NAME 1 (dummydec)

    9 16 LOAD_NAME 0 (printingdec)

    10 18 LOAD_NAME 1 (dummydec)

    11 20 LOAD_CONST 4 (<code object foo at 0x7f5e13aacbe0, file "bug.py", line 9>)
    22 LOAD_CONST 5 ('foo')
    24 MAKE_FUNCTION 0
    26 CALL_FUNCTION 1
    28 CALL_FUNCTION 1
    30 STORE_NAME 2 (foo)
    32 LOAD_CONST 6 (None)
    34 RETURN_VALUE

    Disassembly of <code object printingdec at 0x7f5e13aaca80, file "bug.py", line 2>:
    3 0 LOAD_GLOBAL 0 (Exception)
    2 CALL_FUNCTION 0
    4 RAISE_VARARGS 1

    4 6 LOAD_FAST 0 (f)
    8 RETURN_VALUE

    Disassembly of <code object dummydec at 0x7f5e13aacb30, file "bug.py", line 6>:
    7 0 LOAD_FAST 0 (f)
    2 RETURN_VALUE

    Disassembly of <code object foo at 0x7f5e13aacbe0, file "bug.py", line 9>:
    12 0 LOAD_CONST 0 (None)
    2 RETURN_VALUE
    None

    The change from 3.6 seems to be that a new line number is introduced for instruction 20, loading the function code, which seems reasonable.
    It would feel natural if the line number of the decorator would be used for instructions 26 & 28, the decorator call.

    @serhiy-storchaka
    Copy link
    Member

    It makes sense. If write decorators as explicit function calls:

    decorated = (
        deco1(
            deco2(
                original
            )
        )
    )

    The line number of decorator itself will be used for CALL_FUNCTION:

    2 0 LOAD_NAME 0 (deco1)

    3 2 LOAD_NAME 1 (deco2)

    4 4 LOAD_NAME 2 (original)

    3 6 CALL_FUNCTION 1

    2 8 CALL_FUNCTION 1

    1 10 STORE_NAME 3 (decorated)
    12 LOAD_CONST 0 (None)
    14 RETURN_VALUE

    But I suppose this will add more headache for coverage.py.

    @jorants
    Copy link
    Mannequin Author

    jorants mannequin commented Aug 29, 2019

    After compiling 3.7 and 3.8 as well it seems that the change happened between those versions.

    I was a able to patch compiler.c for 3.9 to make it work (first time changing cpython internals, so no guarantees).
    Patch is attached.

    This trips up one of the tests in test_trace however, since both the LOAD_NAME before the function def and the CALL_FUNCTION after are counted as a visit to the decorator line.

    However, this is also the case for your example with the decorators written out, running:
    def deco1(f):
    return f

    def deco2(f):
        return f
    
    def go():
        f = 5
        f = (
            deco1(
                deco2(
                    f
                )
            )
        )
    
    
    import trace
    tracer = trace.Trace(count=1,trace=0,countfuncs=0, countcallers=0)
    tracer.run('go()')
    for k,v in  tracer.results().counts.items():
        print(k,v)

    gives

    ('<string>', 1) 1
    ('/home/user/projects/ShortUse/tracebug/cpython3.9clean/mytracetest.py', 8) 1
    ('/home/user/projects/ShortUse/tracebug/cpython3.9clean/mytracetest.py', 10) 2
    ('/home/user/projects/ShortUse/tracebug/cpython3.9clean/mytracetest.py', 11) 2
    ('/home/user/projects/ShortUse/tracebug/cpython3.9clean/mytracetest.py', 12) 1
    ('/home/user/projects/ShortUse/tracebug/cpython3.9clean/mytracetest.py', 5) 1
    ('/home/user/projects/ShortUse/tracebug/cpython3.9clean/mytracetest.py', 2) 1
    ('/home/user/projects/ShortUse/tracebug/cpython3.9clean/mytracetest.py', 9) 1

    while clearly each function is only called ones.

    In addition, to get back to the 3.6/3.7 problem as well, on 3.6 the slight modification
    def deco1(f):
    raise Exception()
    return f

    def deco2(f):
        return f
    
    f = 5
    f = (
         deco1(
             deco2(
                 f
             )
         )
    )
    gives 
    Traceback (most recent call last):
      File "sixtest.py", line 12, in <module>
        f
      File "sixtest.py", line 2, in deco1
        raise Exception()
    Exception

    So the problem is not only with decorators, it is with function calls on multiple lines, in all versions.
    It seems that:

    1. The problem with tracebacks for function calls on multiple lines has been fixed in going from 3.7 to 3.8 (should this fix be merged down as well?)
    2. The same problem for decorators has not been fixed (patch attached for 3.9)
    3. The fix in 3.8 introduced a bug in the trace module which seems hard to fix.

    @serhiy-storchaka
    Copy link
    Member

    Thank you for your patch Joran. We now use GitHub, do you mind to create a pull request?

    You need to use 4-spaces indentation instead of tabs.

    Would be nice if you have signed the PSF contributor agreement
    https://www.python.org/psf/contrib/contrib-form/ .

    @serhiy-storchaka serhiy-storchaka added interpreter-core (Objects, Python, Grammar, and Parser dirs) 3.8 only security fixes 3.9 only security fixes labels Aug 29, 2019
    @cfbolz
    Copy link
    Mannequin

    cfbolz mannequin commented Dec 10, 2021

    I ran into this problem in PyPy today, preparing a patch for CPython too (without looking at the old one).

    @ambv
    Copy link
    Contributor

    ambv commented Dec 10, 2021

    New changeset b593bdc by Carl Friedrich Bolz-Tereick in branch 'main':
    bpo-37971: fix the position of decorator application (GH-30027)
    b593bdc

    @ezio-melotti ezio-melotti transferred this issue from another repository Apr 10, 2022
    @iritkatriel
    Copy link
    Member

    @ambv did you want to backport this to 3.10 or can we close it?

    @ambv
    Copy link
    Contributor

    ambv commented May 30, 2022

    Ah, I got stuck here on the conflicts between versions and discussing with Pablo it seemed they weren't trivial. Let me take one last look tomorrow, maybe I can still patch 3.10.

    Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
    Labels
    3.8 only security fixes 3.9 only security fixes interpreter-core (Objects, Python, Grammar, and Parser dirs) type-bug An unexpected behavior, bug, or error
    Projects
    None yet
    Development

    No branches or pull requests

    3 participants