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.

Sign up for GitHub

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

Jump to bottom

Incorrect frame.f_lineno when frame.f_trace is set #86989

Closed
markshannon opened this issue Jan 4, 2021 · 6 comments
Closed

Incorrect frame.f_lineno when frame.f_trace is set #86989

markshannon opened this issue Jan 4, 2021 · 6 comments
Assignees
@markshannon

Comments

@markshannon
Copy link
Member

BPO 42823
Nosy @nedbat, @markshannon
PRs
  • bpo-42823: Fix frame lineno when frame.f_trace is set #24099
  • bpo-42823: Update frame.f_lineno before any call to the (C) tracing function. #24150
    		•

    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 = 'https://github.com/markshannon'
closed_at = <Date 2021-04-04.11:46:53.404>
created_at = <Date 2021-01-04.16:32:45.048>
labels = []
title = 'Incorrect frame.f_lineno when frame.f_trace is set'
updated_at = <Date 2021-04-04.11:46:53.404>
user = 'https://github.com/markshannon'

    bugs.python.org fields:

    activity = <Date 2021-04-04.11:46:53.404>
actor = 'nedbat'
assignee = 'Mark.Shannon'
closed = True
closed_date = <Date 2021-04-04.11:46:53.404>
closer = 'nedbat'
components = []
creation = <Date 2021-01-04.16:32:45.048>
creator = 'Mark.Shannon'
dependencies = []
files = []
hgrepos = []
issue_num = 42823
keywords = ['patch']
message_count = 6.0
messages = ['384331', '384387', '384500', '384502', '384505', '389920']
nosy_count = 2.0
nosy_names = ['nedbat', 'Mark.Shannon']
pr_nums = ['24099', '24150']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue42823'
versions = []
    @markshannon
    Copy link
    Member Author

    The logic for frame.f_lineno assumes that the internal C field will be updated when f_trace is set, but that is incorrect.
    Consequently, the following code

    import sys

def print_line():
    print(sys._getframe(1).f_lineno)

def test():
    print_line()
    sys._getframe(0).f_trace = True
    print_line()
    print_line()

test()

    prints
    7
    8
    8

    it should print
    7
    9
    10

    Fixing this is required by PEP-626, but it should be fixed anyway.

    @markshannon markshannon self-assigned this Jan 4, 2021
    @markshannon
    Copy link
    Member Author

    New changeset ee9f98d by Mark Shannon in branch 'master':
    bpo-42823: Fix frame lineno when frame.f_trace is set (GH-24099)
    ee9f98d

    @nedbat
    Copy link
    Member

    nedbat commented Jan 6, 2021

    This change seems like it has caused a problem. Python trace functions behave as they did in Python 3.9, but C trace functions no longer get line numbers for call or return events.

    Running this test code:

        def gen(inp):
        for n in inp:
            yield n

    list(gen([1,2,3]))

    With my C trace function logging what it is passed, in Python 3.9 I got this:

    trace: CALL @ coverage_test_2616437928787223.py 1
trace: LINE @ coverage_test_2616437928787223.py 1
trace: LINE @ coverage_test_2616437928787223.py 5
trace: CALL @ coverage_test_2616437928787223.py 1
trace: LINE @ coverage_test_2616437928787223.py 2
trace: LINE @ coverage_test_2616437928787223.py 3
trace: RET  @ coverage_test_2616437928787223.py 3
trace: CALL @ coverage_test_2616437928787223.py 3
trace: LINE @ coverage_test_2616437928787223.py 2
trace: LINE @ coverage_test_2616437928787223.py 3
trace: RET  @ coverage_test_2616437928787223.py 3
trace: CALL @ coverage_test_2616437928787223.py 3
trace: LINE @ coverage_test_2616437928787223.py 2
trace: LINE @ coverage_test_2616437928787223.py 3
trace: RET  @ coverage_test_2616437928787223.py 3
trace: CALL @ coverage_test_2616437928787223.py 3
trace: LINE @ coverage_test_2616437928787223.py 2
trace: RET  @ coverage_test_2616437928787223.py 2
trace: RET  @ coverage_test_2616437928787223.py 5

    With 3.10 (commit 1a9f51e) I get:

    trace: CALL @ coverage_test_40117094849631774.py 0
trace: LINE @ coverage_test_40117094849631774.py 1
trace: LINE @ coverage_test_40117094849631774.py 5
trace: CALL @ coverage_test_40117094849631774.py 0
trace: LINE @ coverage_test_40117094849631774.py 2
trace: LINE @ coverage_test_40117094849631774.py 3
trace: RET  @ coverage_test_40117094849631774.py 0
trace: CALL @ coverage_test_40117094849631774.py 0
trace: LINE @ coverage_test_40117094849631774.py 2
trace: LINE @ coverage_test_40117094849631774.py 3
trace: RET  @ coverage_test_40117094849631774.py 0
trace: CALL @ coverage_test_40117094849631774.py 0
trace: LINE @ coverage_test_40117094849631774.py 2
trace: LINE @ coverage_test_40117094849631774.py 3
trace: RET  @ coverage_test_40117094849631774.py 0
trace: CALL @ coverage_test_40117094849631774.py 0
trace: LINE @ coverage_test_40117094849631774.py 2
trace: RET  @ coverage_test_40117094849631774.py 0
trace: RET  @ coverage_test_40117094849631774.py 0

    All of the call and return events now get a frame with f_lineno == 0.

    Python trace functions seem unaffected.

    The C code producing this debug output is here: https://github.com/nedbat/coveragepy/blob/a498ebc28273fd21b6a047a173b2e4443b91f563/coverage/ctracer/tracer.c#L786-L813

    @nedbat nedbat reopened this Jan 6, 2021
    @markshannon
    Copy link
    Member Author

    It looks like you are accessing the c field "f_lineno" directly.
    That was never guaranteed to work, it just happened to.
    You should use PyFrame_GetLineNumber()
    If "f_lineno" is up to date, then it will be almost efficient as the direct field access (the overhead is a C call).
    If "f_lineno" is not up to date, PyFrame_GetLineNumber() will compute the correct value.

    In the interest of efficiency it makes sense that the internal f_line field is updated before CALL and RETURN trace events.
    I'll make that change, but you really ought to use the API rather than probing into the frame internals.

    @nedbat
    Copy link
    Member

    nedbat commented Jan 6, 2021

    OK, thanks. I guess the parallels between the Python frame object and the C frame object made it easy to think I could use the fields directly. I'm updating the coverage.py code.

    @markshannon
    Copy link
    Member Author

    Ned, can I close this?

    @nedbat nedbat closed this as completed Apr 4, 2021
    @ezio-melotti ezio-melotti transferred this issue from another repository Apr 10, 2022
    Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
    Assignees

    @markshannon markshannon

    Labels
    None yet
    Projects
    None yet
    Milestone
    No milestone
    Development

    No branches or pull requests
    2 participants
    @nedbat @markshannon