Castrated traceback in sys.exc_info()

[Gabriel Genellina]

En Mon, 22 Mar 2010 15:20:39 -0300, Pascal Chambon  
<chambon.pascal at wanadoo.fr> escribió:
>
> Allright, here is more concretely the problem :
>
> ERROR:root:An error
> Traceback (most recent call last):
>   File "C:/Users/Pakal/Desktop/aaa.py", line 7, in c
>     return d()
>   File "C:/Users/Pakal/Desktop/aaa.py", line 11, in d
>     def d(): raise ValueError
> ValueError
>  >>>
>
> As you see, the traceback only starts from function c, which handles the  
> exception.
> It doesn't show main(), a() and b(), which might however be (and are, in  
> my case) critical to diagnose the severity of the problem (since many  
> different paths would lead to calling c()).
>
> So the question is : is that possible to enforce, by a way or another,  
> the retrieval of the FULL traceback at exception raising point, instead  
> of that incomplete one ?

Thanks for bringing this topic! I learned a lot trying to understand what  
happens.

The exception traceback (what sys.exc_info()[2] returns) is *not* a  
complete stack trace. The sys module documentation is wrong [1] when it  
says "...encapsulates the call stack at the point where the exception  
originally occurred."

The Language Reference is more clear [2]: "Traceback objects represent a  
stack trace of an exception. A traceback object is created when an  
exception occurs. When the search for an exception handler unwinds the  
execution stack, at each unwound level a traceback object is inserted in  
front of the current traceback. When an exception handler is entered, the  
stack trace is made available to the program."

That is, a traceback holds only the *forward* part of the stack: the  
frames already exited when looking for an exception handler. Frames going  
 from the program starting point up to the current execution point are  
*not* included.

Conceptually, it's like having two lists: stack and traceback. The  
complete stack trace is always stack+traceback. At each step (when  
unwinding the stack, looking for a frame able to handle the current  
exception) an item is popped from the top of the stack (last item) and  
inserted at the head of the traceback.

The traceback holds the "forward" path (from the current execution point,  
to the frame where the exception was actually raised). It's a linked list,  
its tb_next attribute holds a reference to the next item; None marks the  
last one.

The "back" path (going from the current execution point to its caller and  
all the way to the program entry point) is a linked list of frames; the  
f_back attribute points to the previous one, or None.

In order to show a complete stack trace, one should combine both. The  
traceback module contains several useful functions: extract_stack() +  
extract_tb() are a starting point. The simplest way I could find to make  
the logging module report a complete stack is to monkey patch  
logging.Formatter.formatException so it uses format_exception() and  
format_stack() combined (in fact it is simpler than the current  
implementation using a StringIO object):

<code>
import logging
import traceback

def formatException(self, ei):
     """
     Format and return the specified exception information as a string.

     This implementation builds the complete stack trace, combining
     traceback.format_exception and traceback.format_stack.
     """
     lines = traceback.format_exception(*ei)
     if ei[2]:
         lines[1:1] = traceback.format_stack(ei[2].tb_frame.f_back)
     return ''.join(lines)

# monkey patch the logging module
logging.Formatter.formatException = formatException

def a(): return b()
def b(): return c()
def c():
     try:
       return d()
     except:
       logging.exception("An error")
       raise
def d(): raise ValueError

def main():
   a()

main()
</code>

Output:

ERROR:root:An error
Traceback (most recent call last):
   File "test_logging.py", line 32, in <module>
     main()
   File "test_logging.py", line 30, in main
     a()
   File "test_logging.py", line 19, in a
     def a(): return b()
   File "test_logging.py", line 20, in b
     def b(): return c()
   File "test_logging.py", line 23, in c
     return d()
   File "test_logging.py", line 27, in d
     def d(): raise ValueError
ValueError

Traceback (most recent call last):
   File "test_logging.py", line 32, in <module>
     main()
   File "test_logging.py", line 30, in main
     a()
   File "test_logging.py", line 19, in a
     def a(): return b()
   File "test_logging.py", line 20, in b
     def b(): return c()
   File "test_logging.py", line 23, in c
     return d()
   File "test_logging.py", line 27, in d
     def d(): raise ValueError
ValueError

Note that both tracebacks are identical: the first comes from the patched  
logging module, the second is the standard Python one.

[1] http://docs.python.org/library/sys.html#sys.exc_info
[2]  
http://docs.python.org/reference/datamodel.html#the-standard-type-hierarchy

-- 
Gabriel Genellina