Castrated traceback in sys.exc_info()

[Vinay Sajip]

On Mar 23, 6:12 am, "Gabriel Genellina" <gagsl-... at yahoo.com.ar>
wrote:
> En Mon, 22 Mar 2010 15:20:39 -0300, Pascal Chambon  
> <chambon.pas... 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  
> theloggingmodule 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>
> importlogging
> 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 theloggingmodulelogging.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  loggingmodule, 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-hie...
>
> --
> Gabriel Genellina

Good catch, Gabriel.

There should be no need to monkey-patch the logging module - it's
better if I include the change in the module itself. The only
remaining question is that of backward compatibility, but I can do
this for Python 2.7/3.2 only so that won't be an issue. It's probably
a good idea to log an issue on the bug tracker, though, so we have
some history for the change - do you want to do that, or shall I?

Regards,

Vinay Sajip