3.11: Tracing of decorators now visits the decorator line before the decorator function

[nedbat]

BPO	46234
Nosy	@nedbat, @markshannon

^{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 2022-01-02.23:14:57.596>
labels = ['interpreter-core', 'type-bug', '3.11']
title = '3.11: Tracing of decorators now visits the decorator line before the decorator function'
updated_at = <Date 2022-01-02.23:14:57.596>
user = 'https://github.com/nedbat'

bugs.python.org fields:

activity = <Date 2022-01-02.23:14:57.596>
actor = 'nedbat'
assignee = 'none'
closed = False
closed_date = None
closer = None
components = ['Interpreter Core']
creation = <Date 2022-01-02.23:14:57.596>
creator = 'nedbat'
dependencies = []
files = []
hgrepos = []
issue_num = 46234
keywords = ['3.11regression']
message_count = 1.0
messages = ['409539']
nosy_count = 2.0
nosy_names = ['nedbat', 'Mark.Shannon']
pr_nums = []
priority = 'normal'
resolution = None
stage = None
status = 'open'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue46234'
versions = ['Python 3.11']

[nedbat]

Sometime after 3.11.0a3, tracing of decorators changed so that each decorator
line is revisited as the decorator is invoked. Is this intentional?

---< dectrace.py >-----------------------------------

import linecache, sys

def trace(frame, event, arg):
    # The weird globals here is to avoid a NameError on shutdown...
    if frame.f_code.co_filename == globals().get("__file__"):
        lineno = frame.f_lineno
        print("{} {}: {}".format(event[:4], lineno, linecache.getline(__file__, lineno).rstrip()))
    return trace

print(sys.version)
sys.settrace(trace)

def decorator(func):
    return func

def doit():
    @decorator
    @decorator
    @decorator
    def func(x):
        return x + 1

    print(func(1))

doit()

---

Running it on 3.10, 3.11.0a3, and latest 3.11. The last run has the new line
hightlighted with <<<<<:

$ python3.10 dectrace.py
3.10.1 (main, Dec 14 2021, 08:30:13) [Clang 12.0.0 (clang-1200.0.32.29)]
call 16: def doit():
line 17:     @decorator
line 18:     @decorator
line 19:     @decorator
line 20:     def func(x):
call 13: def decorator(func):
line 14:     return func
retu 14:     return func
call 13: def decorator(func):
line 14:     return func
retu 14:     return func
call 13: def decorator(func):
line 14:     return func
retu 14:     return func
line 23:     print(func(1))
call 17:     @decorator
line 21:         return x + 1
retu 21:         return x + 1
2
retu 23:     print(func(1))

$ python3.11 dectrace.py
3.11.0a3 (main, Dec  9 2021, 12:22:18) [Clang 12.0.0 (clang-1200.0.32.29)]
call 16: def doit():
line 17:     @decorator
line 18:     @decorator
line 19:     @decorator
line 20:     def func(x):
call 13: def decorator(func):
line 14:     return func
retu 14:     return func
call 13: def decorator(func):
line 14:     return func
retu 14:     return func
call 13: def decorator(func):
line 14:     return func
retu 14:     return func
line 23:     print(func(1))
call 17:     @decorator
line 21:         return x + 1
retu 21:         return x + 1
2
retu 23:     print(func(1))

$ /usr/local/cpython/bin/python3.11 dectrace.py
3.11.0a3+ (heads/main:a82baed0e9, Jan  2 2022, 08:12:01) [Clang 12.0.0 (clang-1200.0.32.29)]
call 16: def doit():
line 17:     @decorator
line 18:     @decorator
line 19:     @decorator
line 20:     def func(x):
line 19:     @decorator             <<<<<
call 13: def decorator(func):
line 14:     return func
retu 14:     return func
line 18:     @decorator             <<<<<
call 13: def decorator(func):
line 14:     return func
retu 14:     return func
line 17:     @decorator             <<<<<
call 13: def decorator(func):
line 14:     return func
retu 14:     return func
line 20:     def func(x):
line 23:     print(func(1))
call 17:     @decorator
line 21:         return x + 1
retu 21:         return x + 1
2
retu 23:     print(func(1))

(this might or might not be related to https://bugs.python.org/issue37971)

[sweeneyde]

I verified that the change is from #30027. It looks like that could still be backported to 3.10?

I think the tracing behavior here is a natural consequence of wanting tracebacks to include the decorator line: in order for that to happen, the call instruction has be associated to that line, and so some line trace event has to be generated. Unless we wanted to add a special case to the line-tracing logic in ceval.c, which I'm not sure we want.

cc @ambv

[ambv]

The change is intentional, yes.

I changed my mind since #30027 about whether this should be backported. It's a somewhat of an edge case to call the change there a bug fix. It's an improvement but also a change that Ned noticed. It's much easier to work around it in third-party software is the check required is simply >= 3.11.0. So we won't be bringing this to Python 3.10.