Python3.8 changes how decorators are traced

[nedbat]

BPO	34876
Nosy	@birkenfeld, @terryjreedy, @tiran, @nedbat, @serhiy-storchaka, @ammaraskar
PRs	bpo-34876: Change the lineno of the AST for decorated function and class. #9731

^{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 2018-10-30.11:16:43.246>
created_at = <Date 2018-10-02.23:06:44.490>
labels = ['interpreter-core', '3.8']
title = 'Python3.8 changes how decorators are traced'
updated_at = <Date 2018-10-30.11:16:43.245>
user = 'https://github.com/nedbat'

bugs.python.org fields:

activity = <Date 2018-10-30.11:16:43.245>
actor = 'serhiy.storchaka'
assignee = 'none'
closed = True
closed_date = <Date 2018-10-30.11:16:43.246>
closer = 'serhiy.storchaka'
components = ['Interpreter Core']
creation = <Date 2018-10-02.23:06:44.490>
creator = 'nedbat'
dependencies = []
files = []
hgrepos = []
issue_num = 34876
keywords = ['patch']
message_count = 15.0
messages = ['326921', '326924', '326935', '326936', '326952', '326956', '326958', '326963', '327185', '327186', '327194', '327241', '327877', '328214', '328894']
nosy_count = 6.0
nosy_names = ['georg.brandl', 'terry.reedy', 'christian.heimes', 'nedbat', 'serhiy.storchaka', 'ammar2']
pr_nums = ['9731']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue34876'
versions = ['Python 3.8']

[nedbat]

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.

[ammaraskar]

It looks like this is caused by da8d72c

Adding Serhiy to the nosy list.

[serhiy-storchaka]

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

[serhiy-storchaka]

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.

[nedbat]

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.

[serhiy-storchaka]

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 = [

[nedbat]

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.

[serhiy-storchaka]

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 bpo-12458). 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.

[terryjreedy]

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

[nedbat]

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.

[serhiy-storchaka]

Seems PR 9731 fixes this issue. I'll add tests later.

[serhiy-storchaka]

See 09aaa88. 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.

[serhiy-storchaka]

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?

[nedbat]

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 ¯\(ツ)/¯ :)

[serhiy-storchaka]

New changeset 95b6acf by Serhiy Storchaka in branch 'master':
bpo-34876: Change the lineno of the AST for decorated function and class. (GH-9731)
95b6acf