Skip to content

Duplicate frame in traceback of exception raised inside trace function #102818

Closed
Closed
Duplicate frame in traceback of exception raised inside trace function#102818
Assignees
markshannon
Labels
type-bugAn unexpected behavior, bug, or error

Description

@chgnrdv
chgnrdv
opened on Mar 18, 2023

First appeared in e028ae9.
Reproducer:

import sys

def f():
    pass

def trace(frame, event, arg):
    raise ValueError()

sys.settrace(trace)
f()

Before 'bad' commit (3e43fac):

Traceback (most recent call last):
  File "/home/.../trace_tb_bug.py", line 10, in <module>
    f()
    ^^^
  File "/home/.../trace_tb_bug.py", line 3, in f
    def f():
  File "/home/.../trace_tb_bug.py", line 7, in trace
    raise ValueError()
    ^^^^^^^^^^^^^^^^^^
ValueError

After 'bad' commit (e028ae9):

Traceback (most recent call last):
  File "/home/.../trace_tb_bug.py", line 10, in <module>
    f()
    ^^^
  File "/home/.../trace_tb_bug.py", line 3, in f
    def f():
    
  File "/home/.../trace_tb_bug.py", line 3, in f
    def f():
    
  File "/home/.../trace_tb_bug.py", line 7, in trace
    raise ValueError()
    ^^^^^^^^^^^^^^^^^^
ValueError

3.11.0 release and main (039714d) also lack pointers to error locations, but this probably needs a different issue:

Traceback (most recent call last):
  File "/home/.../trace_tb_bug.py", line 10, in <module>
    f()
  File "/home/.../trace_tb_bug.py", line 3, in f
    def f():
    
  File "/home/.../trace_tb_bug.py", line 3, in f
    def f():
    
  File "/home/.../trace_tb_bug.py", line 7, in trace
    raise ValueError()
ValueError

Linked PRs

Activity

  1. chgnrdv
    added
    type-bugAn unexpected behavior, bug, or error
    on Mar 18, 2023

  2. Eclips4 commented on Mar 18, 2023

    @Eclips4
    Eclips4
    on Mar 18, 2023
    Member

    cc @markshannon

  3. chgnrdv
    changed the title [-]Duplicate frame in traceback if exception is raised inside trace function[/-] [+]Duplicate frame in traceback of exception raised inside trace function[/+] on Mar 18, 2023

  4. gaogaotiantian commented on Mar 20, 2023

    @gaogaotiantian
    gaogaotiantian
    on Mar 20, 2023
    Member

    This actually will reproduce before the commit given. The reason the example code was working was because the trace function happens to raise an exception on "call" event, which happened in start_frame label and is directed to exit_unwind. If you change the code of trace to:

    def trace(frame, event, arg):
    if event == "line":
        raise ValueError()
    return trace

    It will reproduce this issue even on e028ae9. The fundamental issue here is - who is responsible to set the traceback when the trace function raises an exception.

    Currently, call_trampoline has the code to set traceback, but on the frame the trace function is being called. In the meantime, error label in _PyEval_EvalFrameDefault also has the code to set the traceback. If both code executes, two identical entries will be added to the traceback.

    In this specific case, TRACE_FUNCTION_ENTRY in RESUME went to error label when failed, which caused the duplicate frames (It used to goto exit_unwind which hides this issue).

    The solution is not trivial here - multiple functions are relying on call_trampoline to set the traceback. A clear way to fix this is to always do traceback at the same place, preferably in _PyEval_EvalFrameDefault where the tracebacks are set for normal functions. However, to achieve that, all the trace function failures need to go through error lable, rather than some going through exit_unwind on failure as of now.

    I'm not familiar with the structure enough to make the call, but I guess this would be a good question to @markshannon - can we do that? There is definitely performance hit(on a very rare case), but is that even valid? To go through error lable when the frame got an error from the tracing function?

    I can help implementing this if needed, just need to confirm the solution.

  5. chgnrdv commented on Mar 20, 2023

    @chgnrdv
    chgnrdv
    on Mar 20, 2023
    ContributorAuthor

    @gaogaotiantian Yes, I overlooked the case on 3e43fac when trace function raises during line event.

    My first rough attempt to fix this issue was to make goto in TRACE_FUNCTION_ENTRY point to exception_unwind label, but tests were failing and I was not familiar enough with code in _PyEval_EvalFrameDefault to make other attempts.

    This draft patch works as expected and passes all tests. It's not a final fix but something that can prove the concept.

    diff --git a/Python/ceval.c b/Python/ceval.c
index 7d60cf987e..0b70c7dc8b 100644
--- a/Python/ceval.c
+++ b/Python/ceval.c
@@ -835,6 +835,8 @@ _PyEval_EvalFrameDefault(PyThreadState *tstate, _PyInterpreterFrame *frame, int
     }
     DISPATCH();
 
+    bool tracing_error = false;
+
     {
     /* Start instructions */
 #if !USE_COMPUTED_GOTOS
@@ -896,6 +898,7 @@ _PyEval_EvalFrameDefault(PyThreadState *tstate, _PyInterpreterFrame *frame, int
                         // instruction. Increment it before handling the error,
                         // so that it looks the same as a "normal" instruction:
                         next_instr++;
+                        tracing_error = true;
                         goto error;
                     }
                     // Reload next_instr. Don't increment it, though, since
@@ -982,13 +985,15 @@ _PyEval_EvalFrameDefault(PyThreadState *tstate, _PyInterpreterFrame *frame, int
 
         /* Log traceback info. */
         assert(frame != &entry_frame);
-        if (!_PyFrame_IsIncomplete(frame)) {
+        if (!_PyFrame_IsIncomplete(frame) && !tracing_error) {
             PyFrameObject *f = _PyFrame_GetFrameObject(frame);
             if (f != NULL) {
                 PyTraceBack_Here(f);
             }
         }
 
+        tracing_error = false;
+
         if (tstate->c_tracefunc != NULL) {
             /* Make sure state is set to FRAME_UNWINDING for tracing */
             call_exc_trace(tstate->c_tracefunc, tstate->c_traceobj,
@@ -996,6 +1001,7 @@ _PyEval_EvalFrameDefault(PyThreadState *tstate, _PyInterpreterFrame *frame, int
         }
 
 exception_unwind:
+
         {
             /* We can't use frame->f_lasti here, as RERAISE may have set it */
             int offset = INSTR_OFFSET()-1;
diff --git a/Python/ceval_macros.h b/Python/ceval_macros.h
index c2257515a3..107a5724e0 100644
--- a/Python/ceval_macros.h
+++ b/Python/ceval_macros.h
@@ -312,6 +312,7 @@ GETITEM(PyObject *v, Py_ssize_t i) {
         stack_pointer = _PyFrame_GetStackPointer(frame); \
         frame->stacktop = -1; \
         if (err) { \
+            tracing_error = true; \
             goto error; \
         } \
     }

  6. gaogaotiantian commented on Mar 20, 2023

    @gaogaotiantian
    gaogaotiantian
    on Mar 20, 2023
    Member

    Well, even though the fix is easy to understand, I'm not sure if it's elegant enough. Introducing a state variable makes the code less robust and harder to maintain in the future. But I agree that it proves the logic of the problem. I guess we still need to wait for @markshannon for the actual path to fix this.

  7. chgnrdv commented on Mar 20, 2023

    @chgnrdv
    chgnrdv
    on Mar 20, 2023
    ContributorAuthor

    I think we can get rid of variable by placing the code that sets traceback just after error label, since, as far as I see, this code cannot clear the current exception set on tstate and obviously can't change kwnames variable. But yes, let's wait and see what markshannon say about it.

    diff --git a/Python/ceval.c b/Python/ceval.c
index 7d60cf987e..9d4f25a58b 100644
--- a/Python/ceval.c
+++ b/Python/ceval.c
@@ -896,7 +896,7 @@ _PyEval_EvalFrameDefault(PyThreadState *tstate, _PyInterpreterFrame *frame, int
                         // instruction. Increment it before handling the error,
                         // so that it looks the same as a "normal" instruction:
                         next_instr++;
-                        goto error;
+                        goto trace_error;
                     }
                     // Reload next_instr. Don't increment it, though, since
                     // we're going to re-dispatch to the "true" instruction now:
@@ -969,6 +969,16 @@ _PyEval_EvalFrameDefault(PyThreadState *tstate, _PyInterpreterFrame *frame, int
 pop_1_error:
     STACK_SHRINK(1);
 error:
+        /* Log traceback info. */
+        assert(frame != &entry_frame);
+        if (!_PyFrame_IsIncomplete(frame)) {
+            PyFrameObject *f = _PyFrame_GetFrameObject(frame);
+            if (f != NULL) {
+                PyTraceBack_Here(f);
+            }
+        }
+
+trace_error:
         kwnames = NULL;
         /* Double-check exception status. */
 #ifdef NDEBUG
@@ -980,15 +990,6 @@ _PyEval_EvalFrameDefault(PyThreadState *tstate, _PyInterpreterFrame *frame, int
         assert(_PyErr_Occurred(tstate));
 #endif
 
-        /* Log traceback info. */
-        assert(frame != &entry_frame);
-        if (!_PyFrame_IsIncomplete(frame)) {
-            PyFrameObject *f = _PyFrame_GetFrameObject(frame);
-            if (f != NULL) {
-                PyTraceBack_Here(f);
-            }
-        }
-
         if (tstate->c_tracefunc != NULL) {
             /* Make sure state is set to FRAME_UNWINDING for tracing */
             call_exc_trace(tstate->c_tracefunc, tstate->c_traceobj,
diff --git a/Python/ceval_macros.h b/Python/ceval_macros.h
index c2257515a3..c8a077a9a6 100644
--- a/Python/ceval_macros.h
+++ b/Python/ceval_macros.h
@@ -312,7 +312,7 @@ GETITEM(PyObject *v, Py_ssize_t i) {
         stack_pointer = _PyFrame_GetStackPointer(frame); \
         frame->stacktop = -1; \
         if (err) { \
-            goto error; \
+            goto trace_error; \
         } \
     }

  8. markshannon commented on May 17, 2023

    @markshannon
    markshannon
    on May 17, 2023
    Member

    It is a bit strange that call_trampoline is setting the traceback.
    I'll see if we can do something more sensible.

  9. markshannon
    self-assigned this
    on May 17, 2023

  10. markshannon commented on May 17, 2023

    @markshannon
    markshannon
    on May 17, 2023
    Member

    The documentation for PyEval_SetTrace doesn't say anything about adding the caller's frame to the traceback.
    It would a strange API design if it did.

    So, call_trampoline should not be adding the frame. It is the job of the interpreter to add the frame.
    There are no tests for PyEval_SetTrace set trace functions raising exceptions, and it is a very rare use case.

  11. markshannon
    added 2 commits that reference this issue on May 19, 2023

    GH-102818: Do not call `PyTraceBack_Here` in sys.settrace trampoline. (…

    c26d03d

    [3.11] GH-102818: Do not call PyTraceBack_Here in sys.settrace trampo…

    7b3bc95
  12. carljm
    added a commit that references this issue on May 20, 2023

    Merge branch 'main' into gsallam/main

    ea5965a

  13. chgnrdv commented on May 29, 2023

    @chgnrdv
    chgnrdv
    on May 29, 2023
    ContributorAuthor

    I'm closing this one as it is fixed and the fix is backported.

  14. chgnrdv
    closed this as completedon May 29, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

type-bugAn unexpected behavior, bug, or error

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions