Re: Castrated traceback in sys.exc_info()
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()). This results in the way the tb is created. If an exception occours, and there is no one who handles it in the current function, a traceback object is created. Because the the calling function could have a try-except clause, the function returns with NULL and an set exception. Now if there is no one to handle the exception, a traceback object is created and linked with the existing one. In your case does the traceback start from the function c, because no exception occoured in main() etc. You catched it. If you want to determine the calling path, you can take a look at the encapsuled frame in the tb. Best -- http://mail.python.org/mailman/listinfo/python-list
Re: Castrated traceback in sys.exc_info()
En Tue, 23 Mar 2010 19:43:40 -0300, Vinay Sajip vinay_sa...@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/issue1553375 I'll add a patch+tests to this issue. -- Gabriel Genellina -- http://mail.python.org/mailman/listinfo/python-list
Re: Castrated traceback in sys.exc_info()
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 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 -- http://mail.python.org/mailman/listinfo/python-list
Re: Castrated traceback in sys.exc_info()
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#sys.exc_info [2]
Re: Castrated traceback in sys.exc_info()
Gabriel Genellina a écrit : 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 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 -- http://mail.python.org/mailman/listinfo/python-list
Re: Castrated traceback in sys.exc_info()
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 -- http://mail.python.org/mailman/listinfo/python-list
Re: Castrated traceback in sys.exc_info()
Gabriel Genellina a écrit : En Wed, 17 Mar 2010 09:42:06 -0300, Pascal Chambon chambon.pas...@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 -- http://mail.python.org/mailman/listinfo/python-list
Re: Castrated traceback in sys.exc_info()
En Wed, 17 Mar 2010 09:42:06 -0300, Pascal Chambon chambon.pas...@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:\temppython 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 -- http://mail.python.org/mailman/listinfo/python-list
Castrated traceback in sys.exc_info()
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 -- http://mail.python.org/mailman/listinfo/python-list
Re: Castrated traceback in sys.exc_info()
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.pas...@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 -- http://mail.python.org/mailman/listinfo/python-list
Re: Castrated traceback in sys.exc_info()
Hello, 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. Regards, Pascal 2010/3/17 Michael Ricordeau michael.ricord...@gmail.com 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.pas...@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 -- http://mail.python.org/mailman/listinfo/python-list
Re: Castrated traceback in sys.exc_info()
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 -- http://mail.python.org/mailman/listinfo/python-list
