classification
Title: Python3.8 changes how decorators are traced
Type: Stage: resolved
Components: Interpreter Core Versions: Python 3.8
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: ammar2, christian.heimes, georg.brandl, nedbat, serhiy.storchaka, terry.reedy
Priority: normal Keywords: patch

Created on 2018-10-02 23:06 by nedbat, last changed 2018-10-30 11:16 by serhiy.storchaka. This issue is now closed.

Pull Requests
URL Status Linked Edit
PR 9731 merged serhiy.storchaka, 2018-10-05 22:29
Messages (15)
msg326921 - (view) Author: Ned Batchelder (nedbat) * (Python triager) Date: 2018-10-02 23:06
When decorating a function, the sequence of lines reported to the trace function is different in Python3.8 than with previous versions

$ cat -n decorator.py
     1	def decorator(f):
     2	    return f
     3
     4	def f():
     5	    @decorator
     6	    @decorator
     7	    @decorator
     8	    def func():
     9	        pass
    10
    11	import sys
    12	def trace(frame, event, args):
    13	    print(frame.f_lineno, event)
    14	    return trace
    15
    16	sys.settrace(trace)
    17	f()

$ python3.7 decorator.py
4 call
5 line
6 line
7 line
1 call
2 line
2 return
1 call
2 line
2 return
1 call
2 line
2 return
7 return

$ python3.8 decorator.py
4 call
5 line
6 line
7 line
5 line
1 call
2 line
2 return
1 call
2 line
2 return
1 call
2 line
2 return
5 return

Is this intentional? Will it be changed back before 3.8 ships?

People are testing their projects against 3.8-dev, and reporting problems with coverage.  The problems are due to these sorts of changes.
msg326924 - (view) Author: Ammar Askar (ammar2) * (Python triager) Date: 2018-10-02 23:30
It looks like this is caused by https://github.com/python/cpython/commit/da8d72c953369b872a12c13f136ada77a786714a

Adding Serhiy to the nosy list.
msg326935 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2018-10-03 05:45
This is because the first line of the function definition was the line of the last decorator in 3.7, and it is the line of the first decorator in 3.8.

$ rlwrap ./python -m dis

@decorator
@decorator
@decorator
def func():
    pass

In 3.7:

  2           0 LOAD_NAME                0 (decorator)

  3           2 LOAD_NAME                0 (decorator)

  4           4 LOAD_NAME                0 (decorator)
              6 LOAD_CONST               0 (<code object func at 0x7f53a8281c40, file "<stdin>", line 2>)
              8 LOAD_CONST               1 ('func')
             10 MAKE_FUNCTION            0
             12 CALL_FUNCTION            1
             14 CALL_FUNCTION            1
             16 CALL_FUNCTION            1
             18 STORE_NAME               1 (func)
             20 LOAD_CONST               2 (None)
             22 RETURN_VALUE

In 3.8:

  2           0 LOAD_NAME                0 (decorator)

  3           2 LOAD_NAME                0 (decorator)

  4           4 LOAD_NAME                0 (decorator)

  2           6 LOAD_CONST               0 (<code object func at 0x7f7045a80100, file "<stdin>", line 2>)
              8 LOAD_CONST               1 ('func')
             10 MAKE_FUNCTION            0
             12 CALL_FUNCTION            1
             14 CALL_FUNCTION            1
             16 CALL_FUNCTION            1
             18 STORE_NAME               1 (func)
             20 LOAD_CONST               2 (None)
             22 RETURN_VALUE
msg326936 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2018-10-03 05:51
On other hand, consider the following example of multiline assignment:

$ rlwrap ./python -m dis
a = [
    x,
    y,
]

In 3.7:

  2           0 LOAD_NAME                0 (x)

  3           2 LOAD_NAME                1 (y)
              4 BUILD_LIST               2
              6 STORE_NAME               2 (a)
              8 LOAD_CONST               0 (None)
             10 RETURN_VALUE

In 3.8:

  2           0 LOAD_NAME                0 (x)

  3           2 LOAD_NAME                1 (y)

  1           4 BUILD_LIST               2
              6 STORE_NAME               2 (a)
              8 LOAD_CONST               0 (None)
             10 RETURN_VALUE

In 3.7 the line of the assignment "a = [" is not traced. In 3.8 it is traced.

These all are a consequences of the same change.
msg326952 - (view) Author: Ned Batchelder (nedbat) * (Python triager) Date: 2018-10-03 09:35
Are we sure this is the behavior we want? Now when I step through your code in the debugger, it will show me line 2, then 3, then 4, then 2 again.

I can see the appeal for a multiline assignment statement, but for stacked decorators it just seems wrong.
msg326956 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2018-10-03 09:53
I think this is a correct behavior.

$ cat -n multiline_assignment.py 
     1  x = 1
     2  y = 2
     3  z = [
     4      x,
     5      y,
     6  ]

$ ./python -m trace --trace multiline_assignment.py

In 3.7 the line with the assignment is missed:

 --- modulename: multiline_assignment, funcname: <module>
multiline_assignment.py(1): x = 1
multiline_assignment.py(2): y = 2
multiline_assignment.py(4):     x,
multiline_assignment.py(5):     y,

In 3.8:

 --- modulename: multiline_assignment, funcname: <module>
multiline_assignment.py(1): x = 1
multiline_assignment.py(2): y = 2
multiline_assignment.py(4):     x,
multiline_assignment.py(5):     y,
multiline_assignment.py(3): z = [
msg326958 - (view) Author: Ned Batchelder (nedbat) * (Python triager) Date: 2018-10-03 10:08
Yes, I agree that the assignment statement behavior is fine.  The stacked decorator behavior is not.

I understand that under the hood the two cases are very similar, but the syntax is different.  Jumping back to the first decorator makes it look like the decorators are executed in order and then the first decorator runs again.  There is nothing in the syntax that makes revisting the first decorator line reasonable.
msg326963 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2018-10-03 10:56
First the decorator itself is loaded. Then the function is created, decorators are called and the result is bound to the name.

There is similar situation in the case of multiline call.

$ cat -n multiline_call.py 
     1  def f(a, b):
     2      return [
     3          a,
     4          b,
     5      ]
     6
     7  x = f(
     8      1,
     9      2,
    10  )

$ ./python -m trace --trace multiline_call.py

In 3.7:

 --- modulename: multiline_call, funcname: <module>
multiline_call.py(1): def f(a, b):
multiline_call.py(7): x = f(
multiline_call.py(8):     1,
multiline_call.py(9):     2,
 --- modulename: multiline_call, funcname: f
multiline_call.py(3):         a,
multiline_call.py(4):         b,

In 3.8:

 --- modulename: multiline_call, funcname: <module>
multiline_call.py(1): def f(a, b):
multiline_call.py(7): x = f(
multiline_call.py(8):     1,
multiline_call.py(9):     2,
multiline_call.py(7): x = f(
 --- modulename: multiline_call, funcname: f
multiline_call.py(3):         a,
multiline_call.py(4):         b,
multiline_call.py(2):     return [

Line 7 started the execution with loading the function f. Then arguments are evaluated on lines 1 and 2. Then line 7 continue the execution with calling the function and consuming its result.

Maybe using a range of lines instead of a single line will help (as was discussed in issue12458). First time the single line with a decorator is executed, second time the multiline expression that starts with the same line is executed. But this may require a significant change of AST and bytecode format.
msg327185 - (view) Author: Terry J. Reedy (terry.reedy) * (Python committer) Date: 2018-10-05 20:36
I have never looked at the trace of a decorated object before.  The 3.7 behavior treating the inner decorator line as the first line of the decorated function definition looks wrong to me.  I actually expected the line pointer to move down to the def line, analogously to the following, at least until after MAKE_FUNCTION, but moving to the beginning of the statement for the rest would seem proper.

>>> dis.dis("""a = f(
f(
f(
3)))""")
  1           0 LOAD_NAME                0 (f)

  2           2 LOAD_NAME                0 (f)

  3           4 LOAD_NAME                0 (f)

  4           6 LOAD_CONST               0 (3)
              8 CALL_FUNCTION            1
             10 CALL_FUNCTION            1
             12 CALL_FUNCTION            1
             14 STORE_NAME               1 (a)
             16 LOAD_CONST               1 (None)
             18 RETURN_VALUE
msg327186 - (view) Author: Ned Batchelder (nedbat) * (Python triager) Date: 2018-10-05 20:55
This is the --trace output for some stacked decorators:

$ cat -n /tmp/decdec.py
     1	def decorator1(f):
     2	    return f
     3
     4	def decorator2(f):
     5	    return f
     6
     7	def decorator3(f):
     8	    return f
     9
    10	@decorator1
    11	@decorator2
    12	@decorator3
    13	def func():
    14	    print("hello")
    15
    16	func()

$ python3.7 -m trace --trace /tmp/decdec.py
 --- modulename: decdec, funcname: <module>
decdec.py(1): def decorator1(f):
decdec.py(4): def decorator2(f):
decdec.py(7): def decorator3(f):
decdec.py(10): @decorator1
decdec.py(11): @decorator2
decdec.py(12): @decorator3
 --- modulename: decdec, funcname: decorator3
decdec.py(8):     return f
 --- modulename: decdec, funcname: decorator2
decdec.py(5):     return f
 --- modulename: decdec, funcname: decorator1
decdec.py(2):     return f
decdec.py(16): func()
 --- modulename: decdec, funcname: func
decdec.py(14):     print("hello")
hello

$ python3.8 -m trace --trace /tmp/decdec.py
 --- modulename: decdec, funcname: <module>
decdec.py(1): def decorator1(f):
decdec.py(4): def decorator2(f):
decdec.py(7): def decorator3(f):
decdec.py(10): @decorator1
decdec.py(11): @decorator2
decdec.py(12): @decorator3
decdec.py(10): @decorator1
 --- modulename: decdec, funcname: decorator3
decdec.py(8):     return f
 --- modulename: decdec, funcname: decorator2
decdec.py(5):     return f
 --- modulename: decdec, funcname: decorator1
decdec.py(2):     return f
decdec.py(16): func()
 --- modulename: decdec, funcname: func
decdec.py(14):     print("hello")
hello


In Python3.8, "@decorator1" appears twice, as both the first and the last decorator line traced.  There's no conceptual reason to show that line twice.

I'd like to consider the stacked decorator case separately from the multi-line function call case.  Yes, they are consequences of the same change.  One change can have good effects and bad effects.  We can do further work to eliminate the bad effects.
msg327194 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2018-10-05 22:30
Seems PR 9731 fixes this issue. I'll add tests later.
msg327241 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2018-10-06 11:25
See 09aaa88328a5083469b2682230c7f3c62942afab. The position of the AST node for decorated function and class was changed to the position of the first decorator. It was made to help inspect.getsource() for functions to include decorator lines in the result. But the position of `def` and `class` lines was lost.
msg327877 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2018-10-17 09:06
Ned, please look at PR 9731. Does it fixes the issue to you?

Georg, you had added the original code for patching the lineno of decorated function. Are your good to remove this patch and to move updating the first line number at the code generation stage?
msg328214 - (view) Author: Ned Batchelder (nedbat) * (Python triager) Date: 2018-10-21 14:04
Thanks, the fix looks good to me.

I made a comparison of some decorator tracing to check it out:  https://gist.github.com/nedbat/d603a34136299f0c0b8e442fccadeb7d

TBH, the first time I tried it, something seemed wrong, but I can't see it now, so ¯\_(ツ)_/¯  :)
msg328894 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2018-10-30 11:16
New changeset 95b6acf951fa7f503a3cc5ce7d969d7bcf2f95c9 by Serhiy Storchaka in branch 'master':
bpo-34876: Change the lineno of the AST for decorated function and class. (GH-9731)
https://github.com/python/cpython/commit/95b6acf951fa7f503a3cc5ce7d969d7bcf2f95c9
History
Date User Action Args
2018-10-30 11:16:43serhiy.storchakasetstatus: open -> closed
resolution: fixed
stage: patch review -> resolved
2018-10-30 11:16:06serhiy.storchakasetmessages: + msg328894
2018-10-21 14:04:22nedbatsetmessages: + msg328214
2018-10-17 09:06:19serhiy.storchakasetmessages: + msg327877
2018-10-06 11:25:28serhiy.storchakasetnosy: + georg.brandl, christian.heimes
messages: + msg327241
2018-10-05 22:30:35serhiy.storchakasetmessages: + msg327194
2018-10-05 22:29:00serhiy.storchakasetkeywords: + patch
stage: patch review
pull_requests: + pull_request9117
2018-10-05 20:55:27nedbatsetmessages: + msg327186
2018-10-05 20:36:17terry.reedysetnosy: + terry.reedy
messages: + msg327185
2018-10-03 10:56:08serhiy.storchakasetmessages: + msg326963
2018-10-03 10:08:21nedbatsetmessages: + msg326958
2018-10-03 09:53:03serhiy.storchakasetmessages: + msg326956
2018-10-03 09:35:05nedbatsetmessages: + msg326952
2018-10-03 05:51:27serhiy.storchakasetmessages: + msg326936
2018-10-03 05:45:55serhiy.storchakasetmessages: + msg326935
2018-10-02 23:30:14ammar2setnosy: + serhiy.storchaka, ammar2
messages: + msg326924
2018-10-02 23:06:44nedbatcreate