This issue tracker has been migrated to GitHub, and is currently read-only.
For more information, see the GitHub FAQs in the Python's Developer Guide.

classification
Title: Incorrect frame.f_lineno when frame.f_trace is set
Type: Stage: resolved
Components: Versions:
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Mark.Shannon Nosy List: Mark.Shannon, nedbat
Priority: normal Keywords: patch

Created on 2021-01-04 16:32 by Mark.Shannon, last changed 2022-04-11 14:59 by admin. This issue is now closed.

Pull Requests
URL Status Linked Edit
PR 24099 merged Mark.Shannon, 2021-01-04 18:21
PR 24150 merged Mark.Shannon, 2021-01-07 10:54
Messages (6)
msg384331 - (view) Author: Mark Shannon (Mark.Shannon) * (Python committer) Date: 2021-01-04 16:32
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.
msg384387 - (view) Author: Mark Shannon (Mark.Shannon) * (Python committer) Date: 2021-01-05 12:04
New changeset ee9f98d9f4b881ee15868a836a2b99271df1bc0e by Mark Shannon in branch 'master':
bpo-42823: Fix frame lineno when frame.f_trace is set (GH-24099)
https://github.com/python/cpython/commit/ee9f98d9f4b881ee15868a836a2b99271df1bc0e
msg384500 - (view) Author: Ned Batchelder (nedbat) * (Python triager) Date: 2021-01-06 13:10
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 1a9f51ed12feb4d95ad6d0faf610a030c05b9f5e) 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
msg384502 - (view) Author: Mark Shannon (Mark.Shannon) * (Python committer) Date: 2021-01-06 13:29
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.
msg384505 - (view) Author: Ned Batchelder (nedbat) * (Python triager) Date: 2021-01-06 15:18
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.
msg389920 - (view) Author: Mark Shannon (Mark.Shannon) * (Python committer) Date: 2021-03-31 16:46
Ned, can I close this?
History
Date User Action Args
2022-04-11 14:59:39adminsetgithub: 86989
2021-04-04 11:46:53nedbatsetstatus: open -> closed
stage: patch review -> resolved
2021-03-31 16:46:22Mark.Shannonsetmessages: + msg389920
2021-01-07 10:54:48Mark.Shannonsetstage: resolved -> patch review
pull_requests: + pull_request22978
2021-01-06 15:18:30nedbatsetmessages: + msg384505
2021-01-06 13:29:41Mark.Shannonsetmessages: + msg384502
2021-01-06 13:10:28nedbatsetstatus: closed -> open
nosy: + nedbat
messages: + msg384500

2021-01-05 12:07:07Mark.Shannonsetstatus: open -> closed
resolution: fixed
stage: patch review -> resolved
2021-01-05 12:04:20Mark.Shannonsetmessages: + msg384387
2021-01-04 18:21:30Mark.Shannonsetkeywords: + patch
stage: patch review
pull_requests: + pull_request22930
2021-01-04 16:32:45Mark.Shannoncreate