Tracing report events leak on trace function failures for doctest-implemented functions in 3.11 #94381

scoder · 2022-06-28T12:33:24Z

Bug report

In Py3.11, one of our tracing tests in Cython is reporting trace events at different times than before. The difference is for Python functions that we implement inside of doctests (so that they remain uncompiled). We use a C trace function to collect the events.

https://github.com/cython/cython/blob/7ab11ec473a604792bae454305adece55cd8ab37/tests/run/line_trace.pyx

The failing test is fail_on_call_trace, where an exception is raised from the trace function. This seems to leak the last trace event into the next trace execution.

We can apparently resolve the issue by moving the functions into Python sections using exec()

https://github.com/cython/cython/pull/4851/files

so this looks like a strictly doctest related issue.

Here is the difference from our test output. Note how some trace events arbitrarily leak into later test runs.

----------------------------------------------------------------------
File "/home/runner/work/cython/cython/TEST_TMP/1/run/c/line_trace/line_trace.cpython-311-x86_64-linux-gnu.so", line ?, in line_trace.fail_on_line_trace
Failed example:
    len(result)
Expected:
    17
Got:
    16
----------------------------------------------------------------------
File "/home/runner/work/cython/cython/TEST_TMP/1/run/c/line_trace/line_trace.cpython-311-x86_64-linux-gnu.so", line ?, in line_trace.fail_on_line_trace
Failed example:
    result[:5]  # py
Expected:
    ['NO ERROR', ('call', 0), ('line', 1), ('line', 2), ('return', 2)]
Got:
    ['NO ERROR', ('call', 2), ('line', 2), ('return', 2), ('call', 0)]
----------------------------------------------------------------------
File "/home/runner/work/cython/cython/TEST_TMP/1/run/c/line_trace/line_trace.cpython-311-x86_64-linux-gnu.so", line ?, in line_trace.fail_on_line_trace
Failed example:
    result[5:10]  # py
Expected:
    [('call', 0), ('line', 1), ('line', 2), ('line', 3), ('line', 4)]
Got:
    [('line', 1), ('line', 2), ('line', 3), ('line', 4), ('call', 0)]
----------------------------------------------------------------------
File "/home/runner/work/cython/cython/TEST_TMP/1/run/c/line_trace/line_trace.cpython-311-x86_64-linux-gnu.so", line ?, in line_trace.fail_on_line_trace
Failed example:
    result[10:14]  # py
Expected:
    [('call', 0), ('line', 1), ('line', 2), ('return', 2)]
Got:
    [('line', 1), ('line', 2), ('return', 2), ('line', 2)]
----------------------------------------------------------------------
File "/home/runner/work/cython/cython/TEST_TMP/1/run/c/line_trace/line_trace.cpython-311-x86_64-linux-gnu.so", line ?, in line_trace.fail_on_line_trace
Failed example:
    result[14:]  # py
Expected:
    [('line', 2), ('line', 5), ('return', 5)]
Got:
    [('line', 5), ('return', 5)]

Only the plain Python comparison tests are failing, while the tests for the C compiled functions continue to work as expected, as do the Python functions when not implemented in doctests.

Your environment

CPython versions tested on: 3.11 latest
Operating system and architecture: GHA

The text was updated successfully, but these errors were encountered:

da-woods · 2022-06-28T21:42:48Z

I don't fully know understand the details but it seems like fail_on_call_trace is essential to the failure - get rid of that and it seems to work fine.

da-woods · 2022-06-29T06:31:03Z

Here is a much reduced version that demonstrates the issue:

# cython: linetrace=True
# distutils: define_macros=CYTHON_TRACE_NOGIL=1

__tests__ = {}

import sys

py_ = {}
exec("""
import sys

def _create_trace_func(trace):
    local_names = {}

    def _trace_func(frame, event, arg):
        trace.append((event, frame.f_lineno - frame.f_code.co_firstlineno))

        lnames = frame.f_code.co_varnames
        if frame.f_code.co_name in local_names:
            assert lnames == local_names[frame.f_code.co_name]
        else:
            local_names[frame.f_code.co_name] = lnames

        # Currently, the locals dict is empty for Cython code, but not for Python code.
        if frame.f_code.co_name.startswith('py_'):
            # Change this when we start providing proper access to locals.
            assert frame.f_locals, frame.f_code.co_name
        else:
            assert not frame.f_locals, frame.f_code.co_name

        return _trace_func
    return _trace_func


def _create_failing_call_trace_func(trace):
    func = _create_trace_func(trace)
    def _trace_func(frame, event, arg):
        if event or event == "call":
            raise ValueError("failing call trace!")

        func(frame, event, arg)
        return _trace_func

    return _trace_func
""", py_)
_create_trace_func_py = py_["_create_trace_func"]
_create_failing_call_trace_func_py = py_["_create_failing_call_trace_func"]


def cy_add(a,b):
    x = a + b     # 1
    return x      # 2


def run_trace(func, *args):
    """
    >>> def py_add(a,b):
    ...     x = a+b
    ...     return x

    >>> run_trace(py_add, 1, 2)
    [('call', 0), ('line', 1), ('line', 2), ('return', 2)]
    """
    trace = []
    trace_func = _create_trace_func_py(trace)
    sys.settrace(trace_func)
    try:
        func(*args)
    finally:
        sys.settrace(None)
    return trace


def fail_on_call_trace(func, *args):
    """
    >>> def py_add(a,b):
    ...     x = a+b
    ...     return x

    >>> fail_on_call_trace(cy_add, 1, 2)
    Traceback (most recent call last):
    ValueError: failing call trace!
    """
    trace = []
    trace_func = _create_failing_call_trace_func_py(trace)
    sys.settrace(trace_func)
    try:
        func(*args)
    finally:
        sys.settrace(None)

It does need to be compiled in Cython which leads me to think it might not actually be a Python bug.

The tracing functions are all in exec just so they're Python code rather than Cython code. It runs fine on 3.10 and fails on 3.11. In order for the issue to happen it seems to require an exception to be raised while tracing a Cython call, and that messes up a subsequent attempt to trace a Python call.

Can be run with

python3.11 cythonize.py -if line_trace.pyx
python3.11 -c "import doctest; import line_trace; doctest.testmod(line_trace)"

…Py3.11 (GH-4851) Thus fixing linetracing tests in Python 3.11 when the trace function raises an exception. The issue we were seeing looked to be something to do with functions defined within doctest docstrings. It was fixed by moving the "defined-in-Python" functions into an exec call instead. See python/cpython#94381

scoder · 2022-06-29T07:15:14Z

I've updated title and description to make it clear that this is related to failing trace functions.

da-woods · 2022-06-29T17:49:13Z

A further simplified version that eliminates a little more Cython from it

import sys

py_ = {}
exec("""
import sys

def _create_trace_func(trace):
    local_names = {}

    def _trace_func(frame, event, arg):
        trace.append((event, frame.f_lineno - frame.f_code.co_firstlineno))

        lnames = frame.f_code.co_varnames
        if frame.f_code.co_name in local_names:
            assert lnames == local_names[frame.f_code.co_name]
        else:
            local_names[frame.f_code.co_name] = lnames

        # Currently, the locals dict is empty for Cython code, but not for Python code.
        if frame.f_code.co_name.startswith('py_'):
            # Change this when we start providing proper access to locals.
            assert frame.f_locals, frame.f_code.co_name
        else:
            assert not frame.f_locals, frame.f_code.co_name

        return _trace_func
    return _trace_func

""", py_)
_create_trace_func_py = py_["_create_trace_func"]

def run_trace(func, *args):
    """
    >>> def py_add(a,b):
    ...     x = a+b
    ...     return x

    >>> run_trace(max, 1, 2)
    []
    >>> run_trace(py_add, 1, 2)
    [('call', 0), ('line', 1), ('line', 2), ('return', 2)]
    """
    trace = []
    trace_func = _create_trace_func_py(trace)
    sys.settrace(trace_func)
    try:
        func(*args)
    finally:
        sys.settrace(None)
    return trace

This no longer uses Cython's line tracing code - the error is now triggered by a C_CALL to max now. However the function run_trace is still compiled in Cython. I haven't yet succeeded in making a pure Python version.

Note that Cython automatically populates a __test__ dictionary and doctest runs this in addition to the docstrings generated (so runs each test twice). If I suppress this by doing __test__ = {} then the error doesn't occur.

da-woods · 2022-07-12T11:55:12Z

This looks to be fixed on Python 3.11b4

scoder added the type-bug An unexpected behavior, bug, or error label Jun 28, 2022

scoder mentioned this issue Jun 28, 2022

Move linetracing functions into an "exec" cython/cython#4851

Merged

scoder changed the title ~~Tracing reports events differently for doctest-implemented functions in 3.11~~ Tracing report events leak on trace function failures for doctest-implemented functions in 3.11 Jun 29, 2022

Tracing report events leak on trace function failures for doctest-implemented functions in 3.11 #94381

Tracing report events leak on trace function failures for doctest-implemented functions in 3.11 #94381

scoder commented Jun 28, 2022 •

edited

da-woods commented Jun 28, 2022

da-woods commented Jun 29, 2022 •

edited

scoder commented Jun 29, 2022

da-woods commented Jun 29, 2022 •

edited

da-woods commented Jul 12, 2022

Tracing report events leak on trace function failures for doctest-implemented functions in 3.11 #94381

Tracing report events leak on trace function failures for doctest-implemented functions in 3.11 #94381

Comments

scoder commented Jun 28, 2022 • edited

da-woods commented Jun 28, 2022

da-woods commented Jun 29, 2022 • edited

scoder commented Jun 29, 2022

da-woods commented Jun 29, 2022 • edited

da-woods commented Jul 12, 2022

scoder commented Jun 28, 2022 •

edited

da-woods commented Jun 29, 2022 •

edited

da-woods commented Jun 29, 2022 •

edited