Asp Forum - Castrated traceback in sys.exc_info

Pakal

3/17/2010 10:43:00 AM

Hello

I've just realized recently that sys.exc_info() didn't return a full
traceback for exception concerned : it actually only contains the
frame below the point of exception catching.

That's very annoying to me, because I planned to log such tracebacks
with logging.critical(*****, exc_info=True), and these partial
tracebacks, like the one below, are clearly unsufficient to determine
where the problem comes from. A whole traceback, from program entry
point to exception raising point, would be much better.

2010-03-17 09:28:59,184 - pims - CRITICAL - This is just a test to
ensure critical emails are properly sent
Traceback (most recent call last):
<< HERE, lots of frames missing >>
File "test_common.py", line 34, in test_email_sending
os.open("qsdsdqsdsdqsd", "r")
TypeError: an integer is required

Is there any workaround for this ? I've thought about a custom logging
formatter, which would take both the exc_info traceback AND its own
full backtrace, and to connect them together on their relevant part,
but it's awkward and error prone... why can't we just have all the
precious traceback info under the hand there (an additional attribute
might have pointed the precise frame in which the exception was
caught).

Tanks for the attention,
Regards,
Pascal

9 Answers

Michael Ricordeau

3/17/2010 11:40:00 AM

Hi,

to log tracebacks, you can probably try traceback module.

I use it like this :

import traceback
..... # your code

for line in traceback.format_exc().splitlines():
log.trace(line)

Le Wed, 17 Mar 2010 03:42:44 -0700 (PDT),
Pakal <chambon.pascal@gmail.com> a écrit :

> Hello
>
> I've just realized recently that sys.exc_info() didn't return a full
> traceback for exception concerned : it actually only contains the
> frame below the point of exception catching.
>
> That's very annoying to me, because I planned to log such tracebacks
> with logging.critical(*****, exc_info=True), and these partial
> tracebacks, like the one below, are clearly unsufficient to determine
> where the problem comes from. A whole traceback, from program entry
> point to exception raising point, would be much better.
>
> 2010-03-17 09:28:59,184 - pims - CRITICAL - This is just a test to
> ensure critical emails are properly sent
> Traceback (most recent call last):
> << HERE, lots of frames missing >>
> File "test_common.py", line 34, in test_email_sending
> os.open("qsdsdqsdsdqsd", "r")
> TypeError: an integer is required
>
> Is there any workaround for this ? I've thought about a custom logging
> formatter, which would take both the exc_info traceback AND its own
> full backtrace, and to connect them together on their relevant part,
> but it's awkward and error prone... why can't we just have all the
> precious traceback info under the hand there (an additional attribute
> might have pointed the precise frame in which the exception was
> caught).
>
> Tanks for the attention,
> Regards,
> Pascal

Vinay Sajip

3/17/2010 1:25:00 PM

On Mar 17, 10:42 am, Pakal <chambon.pas...@gmail.com> wrote:
> Hello
>
> I've just realized recently that sys.exc_info() didn't return a full
> traceback for exception concerned : it actually only contains the
> frame below the point of exception catching.
>
> That's very annoying to me, because I planned to log such tracebacks
> withlogging.critical(*****, exc_info=True), and these partial
> tracebacks, like the one below, are clearly unsufficient to determine
> where the problem comes from. A whole traceback, from program entry
> point to exception raising point, would be much better.
>
> 2010-03-17 09:28:59,184 - pims - CRITICAL - This is just a test to
> ensure critical emails are properly sent
> Traceback (most recent call last):
> << HERE, lots of frames missing >>
> File "test_common.py", line 34, in test_email_sending
> os.open("qsdsdqsdsdqsd", "r")
> TypeError: an integer is required
>
> Is there any workaround for this ? I've thought about a customlogging
> formatter, which would take both the exc_info traceback AND its own
> full backtrace, and to connect them together on their relevant part,
> but it's awkward and error prone... why can't we just have all the
> precious traceback info under the hand there (an additional attribute
> might have pointed the precise frame in which the exception was
> caught).
>
> Tanks for the attention,
> Regards,
> Pascal

Do you have a short script which demonstrates the problem? Some more
context is needed. For example, if you have multiple threads of
execution, the traceback will only go up to the top-level function in
the thread.

Regards,

Vinay Sajip

Gabriel Genellina

3/20/2010 1:55:00 AM

En Wed, 17 Mar 2010 09:42:06 -0300, Pascal Chambon
<chambon.pascal@gmail.com> escribió:

> traceback functions indeed allow the manipulation of exception
> tracebacks,
> but the root problem is that anyway, since that traceback is incomplete,
> your "traceback.format_exc().splitlines()" will only provide frames for
> callee (downward) functions, not caller (upward) ones, starting from the
> exception catching frame.

Either I don't understand what you mean, or I can't reproduce it:

<code>
import logging

def a(): return b()
def b(): return c()
def c(): return d()
def d(): raise ValueError

def main():
logging.basicConfig(level=logging.DEBUG)
try: a()
except: logging.exception("An error")

main()
</code>

Output:

D:\temp>python test_logging.py
ERROR:root:An error
Traceback (most recent call last):
File "test_logging.py", line 10, in main
try: a()
File "test_logging.py", line 3, in a
def a(): return b()
File "test_logging.py", line 4, in b
def b(): return c()
File "test_logging.py", line 5, in c
def c(): return d()
File "test_logging.py", line 6, in d
def d(): raise ValueError
ValueError

--
Gabriel Genellina

Pascal Chambon

3/22/2010 6:21:00 PM

Gabriel Genellina a écrit :
>
> En Wed, 17 Mar 2010 09:42:06 -0300, Pascal Chambon
> <chambon.pascal@gmail.com> escribió:
>
>> traceback functions indeed allow the manipulation of exception
>> tracebacks,
>> but the root problem is that anyway, since that traceback is incomplete,
>> your "traceback.format_exc().splitlines()" will only provide frames for
>> callee (downward) functions, not caller (upward) ones, starting from the
>> exception catching frame.
>
> Either I don't understand what you mean, or I can't reproduce it:
>
>

Allright, here is more concretely the problem :

<code>
import logging

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

def d(): raise ValueError

def main():
logging.basicConfig(level=logging.DEBUG)
a()

main()
</code>

OUTPUT:
>>>
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 ?

Thank you for your help,
regards,

Pascal

Gabriel Genellina

3/23/2010 6:13:00 AM

En Mon, 22 Mar 2010 15:20:39 -0300, Pascal Chambon
<chambon.pascal@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#sy...
[2]
http://docs.python.org/reference/datamodel.html#the-standard-type...

--
Gabriel Genellina

Vinay Sajip

3/23/2010 5:07:00 PM

On Mar 23, 6:12 am, "Gabriel Genellina" <gagsl-...@yahoo.com.ar>
wrote:
> En Mon, 22 Mar 2010 15:20:39 -0300, Pascal Chambon
> <chambon.pas...@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#sy...
> [2] http://docs.python.org/reference/datamodel.html#the-standar......
>
> --
> 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

Pascal Chambon

3/23/2010 8:49:00 PM

Gabriel Genellina a écrit :
>
> En Mon, 22 Mar 2010 15:20:39 -0300, Pascal Chambon
> <chambon.pascal@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):
Good point, there is clearly a distinction between "stack trace" and
"exception traceback" that I didn't know (actually, it seems no one
makes it in computer literature).

> 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
>
Well having it fixed in logging would be great, but that kind of
information is good to have in other circumstances, so shouldn't we
rather advocate the availability of this "stack trace part" in exc_info
too ?
This way, people like me who consider frames as black magic wouldn't
need to meet complex stuffs as
"traceback.format_stack(ei[2].tb_frame.f_back" :p

Should I open an issue for this evolution of exceptiuon handling, or
should we content ourselves of this "hacking" of frame stck ?

Regards,
Pascal

Vinay Sajip

3/23/2010 10:44:00 PM

On Mar 23, 8:49 pm, Pascal Chambon <chambon.pas...@wanadoo.fr> wrote:
>
> Should I open an issue for this evolution of exceptiuon handling, or
> should we content ourselves of this "hacking" of frame stck ?
>

Possibly worth raising an issue (not logging-related), but perhaps
it's worth seeing if this has come up before creating the issue.

Regards,

Vinay Sajip

Gabriel Genellina

3/24/2010 8:04:00 AM

En Tue, 23 Mar 2010 19:43:40 -0300, Vinay Sajip <vinay_sajip@yahoo.co.uk>
escribió:
> On Mar 23, 8:49 pm, Pascal Chambon <chambon.pas...@wanadoo.fr> wrote:
>>
>> Should I open an issue for this evolution of exceptiuon handling, or
>> should we content ourselves of this "hacking" of frame stck ?
>
> Possibly worth raising an issue (not logging-related), but perhaps
> it's worth seeing if this has come up before creating the issue.

There is, from 2006: http://bugs.python.org/is...
I'll add a patch+tests to this issue.

--
Gabriel Genellina

comp.lang.python

Castrated traceback in sys.exc_info

Pakal

Michael Ricordeau

Vinay Sajip

Gabriel Genellina

Pascal Chambon

Gabriel Genellina

Vinay Sajip

Pascal Chambon

Vinay Sajip

Gabriel Genellina

x Login to ForumsZone