search

anthony-tuininga / cx_PyGenLib

Other
3 stars 5 forks source link

Fake Cython tracebacks cause _FormatException() in cx_Exceptions to produce unuseful stack traces #2

Open nhaugrud opened 11 months ago

nhaugrud commented 11 months ago

Problem

I've run into an issue where _FormatException() in cx_Exceptions is giving unhelpful stack traces when there are fake Cython tracebacks around. In my case, the fake Cython tracebacks are coming from oracledb.

Example

Here is small example to reproduce the issue using oracledb:

import sys

import cx_Exceptions
import oracledb

class DatabaseException(cx_Exceptions.BaseException):
    def __init__(self, excType, excValue, excTraceback):
        cx_Exceptions.BaseException.__init__(self)
        self._FormatException(excType, excValue, excTraceback)
        self.message = str(excValue)

sys.excepthook = cx_Exceptions.ExceptionHandler
oracledb.init_oracle_client()
with oracledb.connect(input("Connect string: ")) as conn:
    with conn.cursor() as cursor:
        try:
            cursor.execute("select 'foo' + 'bar' from dual")
        except Exception:
            raise DatabaseException(*sys.exc_info())

Python 3.11.4 oracledb 1.4.0 cx_PyGenLib 3.2

My output from the example:

Exception encountered: ORA-01722: invalid number
Template Id: 0
Arguments:
Traceback:
file src\\oracledb\\impl/thick/utils.pyx, line 421, in oracledb.thick_impl._raise_from_info
Details:
Exception type: <class 'oracledb.exceptions.DatabaseError'>
Exception value: ORA-01722: invalid number
Local Variables:
file src\\oracledb\\impl/thick/utils.pyx, line 421, in oracledb.thick_impl._raise_from_info

In my output, the traceback does not include my file as I would have expected.

Notes

When looking into the issue, it appears that the loop here is iterating the linked list of tracebacks past the one including my Python into the fake Cython tracebacks, resulting in the output in my example. It may or may not be helpful in resolving this issue that the Cython tracebacks "can’t fill in co_code".

nhaugrud commented 11 months ago

Have you had a chance to look into this @anthony-tuininga ?

anthony-tuininga commented 11 months ago

I took a look and just pushed a change that should address this for you. Effectively I modernized the code a bit to make use of capabilities added in Python 3.5.

nhaugrud commented 10 months ago

Thanks for looking into this!

The changes you made worked for adding more info to the stack (i.e. the Python file making use of oracledb), but a chunk of info I previously had when using cx_Oracle was still missing. However, I found that making the following adjustment appeared to fully replicate the stacks I would get previously:

diff --git a/cx_Exceptions.py b/cx_Exceptions.py
index c845d5d..5e29971 100644
--- a/cx_Exceptions.py
+++ b/cx_Exceptions.py
@@ -47,7 +47,7 @@ class BaseException(Exception):

     def __AddLocalVariables(self, tb, frames_to_skip = 0):
         self.details.append("Local Variables:")
-        for frame, line_no in traceback.walk_tb(tb):
+        for frame, line_no in traceback.walk_stack(tb.tb_frame):
             if frames_to_skip > 0:
                 frames_to_skip -= 1
             else:

I'm not incredibly familiar with Python tracebacks; would this be an acceptable change?

anthony-tuininga commented 10 months ago

I just looked at this and I get different results. With the original change in place:

Exception encountered: ORA-01722: invalid number
Template Id: 0
Arguments:
Traceback:
file /home/anthony/dev/tmp/cx-pygenlib-issue-2.py, line 20, in <module>
file /home/anthony/git/py-oracledb-oh/build/lib.linux-x86_64-cpython-312/oracledb/cursor.py, line 743, in execute
file src/oracledb/impl/thick/cursor.pyx, line 263, in oracledb.thick_impl.ThickCursorImpl.execute
file src/oracledb/impl/thick/utils.pyx, line 427, in oracledb.thick_impl._raise_from_odpi
file src/oracledb/impl/thick/utils.pyx, line 417, in oracledb.thick_impl._raise_from_info
Details:
Exception type: <class 'oracledb.exceptions.DatabaseError'>
Exception value: ORA-01722: invalid number
Local Variables:
file /home/anthony/dev/tmp/cx-pygenlib-issue-2.py, line 20, in <module>
  DSN -> 'python/dev@localhost/DB21PDB1'
  DatabaseException -> <class '__main__.DatabaseException'>
  conn -> <oracledb.Connection to python@localhost/DB21PDB1>
  cursor -> <oracledb.Cursor on <oracledb.Connection to python@localhost/DB21PDB1>>
  cx_Exceptions -> <module 'cx_Exceptions' from '/home/anthony/git/cx_PyGenLib/cx_Exceptions.py'>
  oracledb -> <module 'oracledb' from '/home/anthony/git/py-oracledb-oh/build/lib.linux-x86_64-cpython-312/oracledb/__init__.py'>
  sys -> <module 'sys' (built-in)>
file /home/anthony/git/py-oracledb-oh/build/lib.linux-x86_64-cpython-312/oracledb/cursor.py, line 743, in execute
  impl -> <oracledb.thick_impl.ThickCursorImpl object at 0x7f1f37828580>
  keyword_parameters -> {}
  parameters -> None
  self -> <oracledb.Cursor on <oracledb.Connection to python@localhost/DB21PDB1>>
  statement -> "select 'foo' + 'bar' from dual"
file src/oracledb/impl/thick/cursor.pyx, line 263, in oracledb.thick_impl.ThickCursorImpl.execute
file src/oracledb/impl/thick/utils.pyx, line 427, in oracledb.thick_impl._raise_from_odpi
file src/oracledb/impl/thick/utils.pyx, line 417, in oracledb.thick_impl._raise_from_info

but with your suggested change I get this:

Exception encountered: ORA-01722: invalid number
Template Id: 0
Arguments:
Traceback:
file /home/anthony/dev/tmp/cx-pygenlib-issue-2.py, line 22, in <module>
Details:
Exception type: <class 'oracledb.exceptions.DatabaseError'>
Exception value: ORA-01722: invalid number
Local Variables:
file /home/anthony/dev/tmp/cx-pygenlib-issue-2.py, line 22, in <module>
  DSN -> 'python/dev@localhost/DB21PDB1'
  DatabaseException -> <class '__main__.DatabaseException'>
  conn -> <oracledb.Connection to python@localhost/DB21PDB1>
  cursor -> <oracledb.Cursor on <oracledb.Connection to python@localhost/DB21PDB1>>
  cx_Exceptions -> <module 'cx_Exceptions' from '/home/anthony/git/cx_PyGenLib/cx_Exceptions.py'>
  oracledb -> <module 'oracledb' from '/home/anthony/git/py-oracledb-oh/build/lib.linux-x86_64-cpython-312/oracledb/__init__.py'>
  sys -> <module 'sys' (built-in)>

The original change looks better! Can you clarify what was missing before and provide a sample that demonstrates that?

nhaugrud commented 9 months ago

@anthony-tuininga I should have been more specific in my previous comment, sorry!

Here are two modified examples, one using oracledb, and one using cx_Oracle:

oracledb Example

import sys

import cx_Exceptions
import oracledb

class DatabaseException(cx_Exceptions.BaseException):
    def __init__(self, excType, excValue, excTraceback):
        cx_Exceptions.BaseException.__init__(self)
        self._FormatException(excType, excValue, excTraceback)
        self.message = str(excValue)

sys.excepthook = cx_Exceptions.ExceptionHandler
oracledb.init_oracle_client()

def TestC():
    with oracledb.connect(input("Connect string: ")) as conn:
        with conn.cursor() as cursor:
            try:
                cursor.execute("select 'foo' + 'bar' from dual")
            except Exception:
                raise DatabaseException(*sys.exc_info())

def TestB():
    TestC()

def TestA():
    TestB()

TestA()

cx_Oracle Example

import sys

import cx_Exceptions
import cx_Oracle

class DatabaseException(cx_Exceptions.BaseException):
    def __init__(self, excType, excValue, excTraceback):
        cx_Exceptions.BaseException.__init__(self)
        self._FormatException(excType, excValue, excTraceback)
        self.message = str(excValue)

sys.excepthook = cx_Exceptions.ExceptionHandler

def TestC():
    with cx_Oracle.connect(input("Connect string: ")) as conn:
        with conn.cursor() as cursor:
            try:
                cursor.execute("select 'foo' + 'bar' from dual")
            except Exception:
                raise DatabaseException(*sys.exc_info())

def TestB():
    TestC()

def TestA():
    TestB()

TestA()

Output

Here is the output I'm getting for both examples before and after the changes in 96f8a5b7618217fd8af31324cf68e23524842daa

oracledb Example - Before

Exception encountered: ORA-01722: invalid number
Template Id: 0
Arguments:
Traceback:
file src\\oracledb\\impl/thick/utils.pyx, line 421, in oracledb.thick_impl._raise_from_info
Details:
Exception type: <class 'oracledb.exceptions.DatabaseError'>
Exception value: ORA-01722: invalid number
Local Variables:
file src\\oracledb\\impl/thick/utils.pyx, line 421, in oracledb.thick_impl._raise_from_info

oracledb Example - After

Exception encountered: ORA-01722: invalid number
Template Id: 0
Arguments:
Traceback:
file C:\cx_PyGenLib-issue\oracledb_issue.py, line 22, in TestC
file C:\cx_PyGenLib-issue\Python-new\Lib\site-packages\oracledb\cursor.py, line 383, in execute
file src\\oracledb\\impl/thick/cursor.pyx, line 243, in oracledb.thick_impl.ThickCursorImpl.execute
file src\\oracledb\\impl/thick/utils.pyx, line 431, in oracledb.thick_impl._raise_from_odpi
file src\\oracledb\\impl/thick/utils.pyx, line 421, in oracledb.thick_impl._raise_from_info
Details:
Exception type: <class 'oracledb.exceptions.DatabaseError'>
Exception value: ORA-01722: invalid number
Local Variables:
file C:\cx_PyGenLib-issue\oracledb_issue.py, line 22, in TestC
  conn -> <oracledb.Connection to possedba@devd>
  cursor -> <oracledb.Cursor on <oracledb.Connection to possedba@devd>>
file C:\cx_PyGenLib-issue\Python-new\Lib\site-packages\oracledb\cursor.py, line 383, in execute
  bind_style -> None
  bind_vars -> None
  impl -> <oracledb.thick_impl.ThickCursorImpl object at 0x000001A9F4DCA880>
  keyword_parameters -> {}
  parameters -> None
  prepare_needed -> True
  self -> <oracledb.Cursor on <oracledb.Connection to possedba@devd>>
  statement -> "select 'foo' + 'bar' from dual"
file src\\oracledb\\impl/thick/cursor.pyx, line 243, in oracledb.thick_impl.ThickCursorImpl.execute
file src\\oracledb\\impl/thick/utils.pyx, line 431, in oracledb.thick_impl._raise_from_odpi
file src\\oracledb\\impl/thick/utils.pyx, line 421, in oracledb.thick_impl._raise_from_info

cx_Oracle Example - Before

Exception encountered: ORA-01722: invalid number
Template Id: 0
Arguments:
Traceback:
file C:\cx_PyGenLib-issue\oracledb_issue2.py, line 21, in TestC
file C:\cx_PyGenLib-issue\oracledb_issue2.py, line 27, in TestB
file C:\cx_PyGenLib-issue\oracledb_issue2.py, line 31, in TestA
file C:\cx_PyGenLib-issue\oracledb_issue2.py, line 34, in <module>
Details:
Exception type: <class 'cx_Oracle.DatabaseError'>
Exception value: ORA-01722: invalid number
Local Variables:
file C:\cx_PyGenLib-issue\oracledb_issue2.py, line 21, in TestC
  conn -> <cx_Oracle.Connection to possedba@devd>
  cursor -> <cx_Oracle.Cursor on <cx_Oracle.Connection to possedba@devd>>
file C:\cx_PyGenLib-issue\oracledb_issue2.py, line 27, in TestB
file C:\cx_PyGenLib-issue\oracledb_issue2.py, line 31, in TestA
file C:\cx_PyGenLib-issue\oracledb_issue2.py, line 34, in <module>
  DatabaseException -> <class '__main__.DatabaseException'>
  TestA -> <function TestA at 0x000001B846480D60>
  TestB -> <function TestB at 0x000001B84697D800>
  TestC -> <function TestC at 0x000001B8464FA160>
  cx_Exceptions -> <module 'cx_Exceptions' from 'C:\\repos\\data-mart-tools\\oracledb-issue\\PythonCXO\\Lib\\site-packages\\cx_Exceptions.py'>
  cx_Oracle -> <module 'cx_Oracle' from 'C:\\repos\\data-mart-tools\\oracledb-issue\\PythonCXO\\Lib\\site-packages\\cx_Oracle.cp311-win_amd64.pyd'>
  sys -> <module 'sys' (built-in)>

cx_Oracle Example - After

Exception encountered: ORA-01722: invalid number
Template Id: 0
Arguments:
Traceback:
file C:\cx_PyGenLib-issue\oracledb_issue2.py, line 21, in TestC
Details:
Exception type: <class 'cx_Oracle.DatabaseError'>
Exception value: ORA-01722: invalid number
Local Variables:
file C:\cx_PyGenLib-issue\oracledb_issue2.py, line 21, in TestC
  conn -> <cx_Oracle.Connection to possedba@devd>
  cursor -> <cx_Oracle.Cursor on <cx_Oracle.Connection to possedba@devd>>

Looking at the cx_Oracle example, before the changes, the traceback goes back to <module>, and after the changes the traceback is only going back to TestC. Similarly, for the oracledb example, the post-changes traceback does not include TestB, TestA, and <module>. Would it be possible to add in this information in both cases?

nhaugrud commented 8 months ago

@anthony-tuininga have you been able to look any further into this issue?

anthony-tuininga commented 8 months ago

Apologies for the delay! I took a look and I believe I have repaired it. Essentially I had to add a call to walk_stack() as well but ignore any duplicate frames that were seen. Both examples work for me, now, anyway!

nhaugrud commented 7 months ago

Thanks! It looks like everything is there, but I also noticed it does look like there is an ordering issue. Upon looking at it a bit, the order of traversal from traceback.walk_tb() is reversed from what I would expect, having the most recent frame information found last, unlike traceback.walk_stack(). In my previous comment under cx_Oracle Example - Before, the old/previous behaviour had the most recent call at the top, while your earlier comment shows how it now can have the oldest <module> frame info at the top now instead. Things appeared to return to the old ordering with the following change:

diff --git a/cx_Exceptions.py b/cx_Exceptions.py
index f3ca41c..ec68fec 100644
--- a/cx_Exceptions.py
+++ b/cx_Exceptions.py
@@ -48,7 +48,7 @@ class BaseException(Exception):
     def __AddLocalVariables(self, tb, frames_to_skip = 0):
         self.details.append("Local Variables:")
         frames_seen = set()
-        for frame, line_no in traceback.walk_tb(tb):
+        for frame, line_no in reversed(list(traceback.walk_tb(tb))):
             if frames_to_skip > 0:
                 frames_to_skip -= 1
             else:

Would that work?

nhaugrud commented 6 months ago

Also, it appears there are now issues with descendants of cx_Exceptions.BaseException. Example code:

import sys

import cx_Exceptions

sys.excepthook = cx_Exceptions.ExceptionHandler

class MyException(cx_Exceptions.BaseException):
    message = "This is my exception."

raise MyException()

Output:

Exception encountered: This is my exception.
Template Id: 0
Arguments:
Traceback:
Details:
Local Variables:

The following appears to work to fix this issue for me (this includes the change in my comment above):

diff --git a/cx_Exceptions.py b/cx_Exceptions.py
index f3ca41c..74a1cf9 100644
--- a/cx_Exceptions.py
+++ b/cx_Exceptions.py
@@ -47,16 +47,17 @@ class BaseException(Exception):

     def __AddLocalVariables(self, tb, frames_to_skip = 0):
         self.details.append("Local Variables:")
-        frames_seen = set()
-        for frame, line_no in traceback.walk_tb(tb):
+        frames_seen = []
+        for frame, line_no in reversed(list(traceback.walk_tb(tb))):
+            for frame, line_no in traceback.walk_stack(frame):      
+                if (frame, line_no) in frames_seen:
+                    continue
+                frames_seen.append((frame, line_no))
+        for frame, line_no in frames_seen:
             if frames_to_skip > 0:
                 frames_to_skip -= 1
             else:
-                for frame, line_no in traceback.walk_stack(frame):
-                    if frame in frames_seen:
-                        continue
-                    frames_seen.add(frame)
-                    self.__AddFrame(frame, line_no)
+                self.__AddFrame(frame, line_no)

     def _FormatException(self, excType, excValue, tb):
         """Format the traceback and put it in the traceback attribute."""