classification
Title: Wrong trace with multiple decorators (linenumber wrong in frame)
Type: behavior Stage:
Components: Interpreter Core Versions: Python 3.9, Python 3.8
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: control-k, nedbat, serhiy.storchaka
Priority: normal Keywords: patch

Created on 2019-08-28 18:32 by control-k, last changed 2019-08-29 15:43 by serhiy.storchaka.

Files
File name Uploaded Description Edit
decolinenumbers.patch control-k, 2019-08-29 14:36
Messages (6)
msg350686 - (view) Author: Joran van Apeldoorn (control-k) * Date: 2019-08-28 18:32
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.
msg350691 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2019-08-28 22:01
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.
msg350762 - (view) Author: Joran van Apeldoorn (control-k) * Date: 2019-08-29 10:19
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.
msg350769 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2019-08-29 12:43
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.
msg350782 - (view) Author: Joran van Apeldoorn (control-k) * Date: 2019-08-29 14:36
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.
msg350792 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2019-08-29 15:43
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/ .
History
Date User Action Args
2019-08-29 15:43:56serhiy.storchakasetmessages: + msg350792
components: + Interpreter Core
versions: + Python 3.8, Python 3.9, - Python 3.6
2019-08-29 14:36:27control-ksetfiles: + decolinenumbers.patch
keywords: + patch
messages: + msg350782
2019-08-29 12:43:12serhiy.storchakasetnosy: + nedbat
messages: + msg350769
2019-08-29 10:19:18control-ksetmessages: + msg350762
2019-08-28 22:01:27serhiy.storchakasetnosy: + serhiy.storchaka
messages: + msg350691
2019-08-28 18:32:52control-kcreate