Issue 1553375: Add traceback.print_full_exception() - Python tracker (original) (raw)
Created on 2006-09-06 12:48 by hoffman, last changed 2022-04-11 14:56 by admin.
Messages (39)
Author: Michael Hoffman (hoffman)
Date: 2006-09-06 12:48
The suggestion is to add something roughly like this:
def print_full_exception(type, value, traceback, file): . _print(sys.stderr, 'Traceback (most recent call last):') . print_stack(traceback.tb_frame.f_back, file=file) . print_tb(traceback, file=file) . . lines = format_exception_only(type, value) . for line in lines[:-1]: . _print(file, line, ' ') . _print(file, lines[-1], '')
to the traceback module, to print the exception not just downward from the calling point, but also upward all the way to the top of the stack. This would be useful in, e.g. logging, where exceptions are caught and printed, but right now no information is given as to where they occurred in user code.
Author: Michael Hoffman (hoffman)
Date: 2006-09-06 12:59
Logged In: YES user_id=987664
Hmmm, my indentation didn't work very well. Hopefully you should be able to figure it out though. :)
Author: Michael Hoffman (hoffman)
Date: 2006-09-06 13:04
Logged In: YES user_id=987664
Here's some test code that might indicate how this is useful:
def x(n=0): .....try: ..........y(n+1) .....except: ..........ei = sys.exc_info() ..........print_full_exception(ei[0], ei[1], ei[2], sys.stderr)
def y(n): .....if n > 10: ..........raise IOError, "test" ..... .....x(n+1)
x()
Author: Pascal Chambon (pakal) *
Date: 2010-04-06 17:12
What's the status of this (imo quite useful) new traceback function ? Shall I provide some help ?
Author: Thomas Guettler (guettli) *
Date: 2010-07-30 11:14
It would be very nice if logging.info('...', exc_info=True) shows the calling/upper frames, too.
Author: Thomas Guettler (guettli) *
Date: 2010-07-30 11:27
Related #9427
Author: R. David Murray (r.david.murray) * 
Date: 2010-08-02 04:03
Here's a proof of concept patch that adds a 'fullstack' option to print_exception. The problem with this concept is what happens when you use it on an exception caught at the top level of a module. I'm not entirely clear on why tracebacks work the way they do, so I don't know how to fix that case (it's also late, maybe in the morning I'll be able to figure it out :)
Writing unit tests for this may also be a bit tricky.
I'm raising the priority to normal because I think this would be really useful for logging, as pointed out by Thomas.
Author: ysj.ray (ysj.ray)
Date: 2010-08-02 11:30
David Murray, where is the patch?
Author: R. David Murray (r.david.murray) *
Date: 2010-08-02 13:27
Morning does make a difference. Revised patch that also works at the top level of a module. (Let's see if I can manage to actually attach it this time...)
Author: R. David Murray (r.david.murray) *
Date: 2010-08-04 02:32
Updated patch with unit tests and docs. I realized that I'd forgotten to test chained exceptions. It looks like when the Interpreter prints a traceback all the exceptions in the chain are printed fully, which makes sense. Adopting that strategy for this patch simplified it into three lines (the signature change and an if/print in the loop).
I'm pretty satisfied with this patch. I have two questions: should the 'fullstack' option really be implemented in print_tb instead? And is there a better name for the option? Would just 'full' be acceptable?
Author: Vinay Sajip (vinay.sajip) *
Date: 2010-08-26 13:38
This functionality would be useful in format_exception(), too.
I prefer "fullstack" to "full" as it's clearer what the 'full' pertains to. An alternative might be "upperframes" or "allframes".
Author: Pascal Chambon (pakal) *
Date: 2010-10-08 18:04
Is that normal to have two methods "test_full_traceback_is_full" at the same place, in full_traceback.patch / r.david.murray / 2010-08-04 02:32 ?
format_exception should have the same semantic as print_exception indeed.
Author: R. David Murray (r.david.murray) *
Date: 2010-10-08 19:26
No, that would be a bug, thanks.
Also thanks for reminding me about this issue.
Author: R. David Murray (r.david.murray) *
Date: 2010-10-09 03:06
I like 'allframes', so I changed to that. The updated patch also adds the allframes parameter to format_exception.
In going over the tests I realized that I'm not sure the output for the case of chain=True is correct. Opinions? If it is not correct it is not obvious to me how to fix it.
Author: Pascal Chambon (pakal) *
Date: 2010-10-09 11:05
Indeed I don't understand the following part :
Traceback (most recent call last):File "testmod.py", line 16, in <module>{exception_action}File "testmod.py", line 6, in foobar()File "testmod.py", line 11, in barraise ExceptionException
Why does the f_back of the first exception, when chain=True, leads back to the {exception_action} part, in the except: black, instead of the initial foo() call inside the try: block ?
Author: Vinay Sajip (vinay.sajip) *
Date: 2010-10-09 11:36
The regression tests are failing for me, see
Author: Vinay Sajip (vinay.sajip) *
Date: 2010-10-09 11:39
Also, "fullstack" remains in one place in the docs. Should now say "allframes".
Author: R. David Murray (r.david.murray) *
Date: 2010-10-09 14:56
Pascal: my question exactly. The question is whether the code is accurately reflecting the state of the python stack at exception time (which it seems like it ought to), in which case I don't understand how Python handles the chained exception, or it doesn't, in which case (more likely) I'm not understanding how the stack frame is put together.
Vinay: so in your run the subprocess call is not producing the final 'exception detail' line...it looks like the last line of the output from subprocess is getting lost. I've updated the patch to add a p.wait() before the assert...can you see if that fixes it? I also fixed the doc nit, thanks.
Author: R. David Murray (r.david.murray) *
Date: 2010-10-09 18:37
After giving this some thought, I'm sure that the observed results are not what we want, so I've changed the test to be the result that we want. I haven't been able to figure out what is causing it, and am starting to wonder if it represents an actual bug in exception handling.
Author: Vinay Sajip (vinay.sajip) *
Date: 2010-10-09 18:40
It's still failing - the existing gist has been updated with the output from the new run:
Author: R. David Murray (r.david.murray) *
Date: 2010-10-09 18:44
vinay: duh. I'm using a debug build and my test is slicing off the refount line. I think there's a helping in test.support for that...
Author: Vinay Sajip (vinay.sajip) *
Date: 2010-10-09 19:04
David, I don't think it's that - I think it's the subprocess comms. This works:
def _do_test(self, program, exc_text):
with open(self.testfn, 'w') as testmod:
testmod.writelines(program.format(
exception_action=self.exception_action))
p = subprocess.Popen([sys.executable, 'testmod.py'],
stderr=subprocess.PIPE)
streams = p.communicate()
v1 = streams[1].decode('utf-8') # this shouldn't be hardcoded!
v2 = exc_text.format(exception_action=self.exception_action)
self.assertEqual(v1, v2)But I don't think the 'utf-8' encoding should be hardcoded. Not sure what to use - sys.getfilesystemencoding()? locale.getpreferredencoding()?
Decisions, decisions :-(
Author: Vinay Sajip (vinay.sajip) *
Date: 2010-10-09 19:05
Also, the use of literal 'testmod.py' in _do_test should probably be replaced by self.testfn.
Author: Vinay Sajip (vinay.sajip) *
Date: 2010-10-09 19:12
On reflection, perhaps we should use sys.stdin.encoding to decode the value received from the subprocess. What do you think?
Author: Vinay Sajip (vinay.sajip) *
Date: 2010-10-09 20:12
Attached a patch which works on my machine.
Author: R. David Murray (r.david.murray) *
Date: 2010-11-12 03:04
Vinay, your example with communicate only works because you removed the [:-1]. If you run your version against a debug build, the tests will fail.
I'm updating the patch with a version that works with both a non-debug and a debug build, and adds an additional test that shows that the chained full traceback fails even if the exception handler is not at the top level. Tomorrow I'll post a request for help to python-dev, since I've nowhere near the knowledge of the CPython internals needed to figure out what is going on here. (It is possible the traceback is in fact correct, but if so it is certainly unexpected and makes allframes a bit less useful.)
Author: Alyssa Coghlan (ncoghlan) *
Date: 2010-11-14 12:04
As per my response to RDM on python-dev, I think the patch is misguided as it currently stands.
The traceback on an exception is built up as the stack unwinds. The stack above the frame containing the exception handler obviously hasn't been unwound yet, so it isn't included in the traceback object.
Since the frame containing the exception handler is live, it and the frame stack above it reflect the state of the exception handler, while the tracebacks on the chain of exceptions currently being handled reflect the parts of the stack that have already been unwound.
For explicit printing, a separate section printing the stack with print_stack() is a better option than trying to embed the information in the stack trace of the exception currently being handled.
For the logging use case, a separate "stack_trace" flag to request inclusion of stack trace details independent of the exception state seems like a preferable option.
Author: Alyssa Coghlan (ncoghlan) *
Date: 2010-11-14 12:09
If the allframes flag is pursued further, then the stack trace should be added (with an appropriate header clause) after the entire exception chain has been printed (including the exception currently being handled).
Author: Alyssa Coghlan (ncoghlan) *
Date: 2010-11-14 12:47
Note that after the loop over the values is complete, the final value of tb should correctly refer to the traceback for the exception currently being handled regardless of whether or not any chaining is involved.
So moving the stack printing code that is currently inside the loop after the loop should do the right thing.
With my suggested change in the display layout, I think this idea is still worthwhile (getting it right in handling code is tricky, especially if the exception is passed around before being displayed).
Author: Vinay Sajip (vinay.sajip) *
Date: 2010-11-14 21:38
I've implemented an optional keyword argument stack_info (defaulting to False) for all logging calls. If specified as True, a line
Stack (most recent call last):
is printed, followed by the output of traceback.print_stack(). This is output after any exception information.
Checked into py3k (r86467), please can interested parties check if it meets the logging use case mentioned when the ticket was created?
Regression tests pass OK, and docs updated in this checkin.
Author: Vinay Sajip (vinay.sajip) *
Date: 2010-11-14 21:40
Re. the change in r86467, you can test using this simple script:
Author: Pascal Chambon (pakal) *
Date: 2010-11-15 18:24
I dont understand, if we use traceback.print_stack(), it's the stack at the exception handling point which will be displayed.
In my view, the interesting think was not the stack trace at the point where the exception is being handled, but where the unwinding stopped (i.e, a snapshot of the stack at the moment the exception was caught).
I agree that most of the time these stacks are quite close, but if you happen to move the traceback object all around, in misc. treatment functions (or even, if it has been returned by functions to their caller - let's be fool), it can be handy to still be able to output a full exception stack, like if the exception had flowed up to the root of the program. At least that's what'd interest me for debugging.
try: myfunction() #<- that's the point of which I'd likle a stack trace except Exception, e: handle_my_exception(e) #<- not of that point, some recursion levels deeper
Am I the only one viewing it as this ?
Author: R. David Murray (r.david.murray) *
Date: 2010-11-15 19:23
I agree with you, Pascal, but I think Nick is saying that that information is not actually available. I don't fully understand why, but he knows vastly more about Python internals than I do so I'll take his word for it.
It might be interesting to try saving the traceback and printing out the allframes traceback elsewhere, since that should prove to you and I that it doesn't work :)
Author: Alyssa Coghlan (ncoghlan) *
Date: 2010-11-16 11:38
Note that my suggestion was to move the if statement out of the loop as-is: you would still be pulling the traceback to display from the caught exception rather than displaying the stack from the current point of execution. If you want the bottom most point to display where the actual exception occurred rather than the last line executed in the frame that caught it you need to be even smarter than that, though.
The information to construct the full stack trace properly is actually available, but it is necessary to be very careful as to how it is stitched together at the point where the traceback and the stack trace meet up.
For a full stack trace, this stitching actually needs to occur every time there is a jump from one exception to another. For finally clauses and reraised exceptions, the interpreter handles this internally so the traceback reflects the appropriate lines, but recreating a complete stack trace for the original exception in the face of PEP 3134 is going to require a bit of work in the traceback module.
Alternatively, you could just provide the full stack trace for the very last exception caught, leaving it to the reader to follow the traceback chain back down to the original exception.
Here's some useful code to explore this (I just spent some time playing with it to make sure I was giving the right answer here):
import sys from traceback import print_exc, print_stack, print_tb def f(n): this = "F%d" % n if n: try: f(n-1) except: print("*** Traceback in", this) print_exc(chain=False) print("*** Call stack in", this) print_stack() print("*** Replacing exception in", this) raise RuntimeError(this) print("*** Call stack in", this) print_stack() raise RuntimeError(this)
try: f(2) except: etype, ex, tb = sys.exc_info()
"raise ex" will then show you the native display of that exception.
You can then use the context attributes to see what state is available to you:
ex RuntimeError('F2',) ex.context RuntimeError('F1',) ex.context.context RuntimeError('F0',)
In particular, we can see that the two inner exceptions are attached to frame objects which were used to run the nested function calls and hence have a frame that called them:
>>> ex.__context__.__context__.__traceback__.tb_frame.f_backex.traceback.tb_frame.f_back ex.context.traceback.tb_frame.f_back
The issue we have is that landing in the exception handlers means the state of those frames has been altered by the stack unwinding process. Let's compare the traceback for each exception with the current state of the corresponding frame (we skip the first traceback entry for our outermost function - it is there courtesy of the interactive loop and irrelevant to the current exploration):
ex.traceback.tb_next.tb_lineno # Top level exception line 2 ex.traceback.tb_next.tb_frame.f_lineno # Last executed line 4 ex.context.traceback.tb_lineno # f(2) exception line 5 ex.context.traceback.tb_frame.f_lineno # Last executed line 12 ex.context.context.traceback.tb_lineno # f(1) exception line 5 ex.context.context.traceback.tb_frame.f_lineno # Last executed line 12
f(0) avoids triggering the exception handler and we can see that the traceback line and the last executed line match in that case:
ex.context.context.traceback.tb_next.tb_lineno 15 ex.context.context.traceback.tb_next.tb_frame.f_lineno 15
So yes, the idea proposed is possible, but no, a simple call to print_stack isn't going to do the right thing.
Author: Florent Xicluna (flox) *
Date: 2012-08-05 08:38
Changeset ba014543ed2c (3.2a4) references this issue.
Author: Antoine Pitrou (pitrou) *
Date: 2012-10-30 19:50
I recently re-wrote something like this, so I think this is useful. I wonder if it wouldn't be nice to add a caret or some similar marker indicating the frame where the exception was caught, e.g.:
Traceback (most recent call last, catch point highlighted): File "testmod.py", line 13, in upper()
File "testmod.py", line 11, in upper foo() File "testmod.py", line 6, in foo raise Exception Exception
Author: Mark Lawrence (BreamoreBoy) *
Date: 2015-03-12 02:18
The functionality described here certainly seems wanted and there's been some other work on the traceback module recently so could we get this into 3.5?
Author: Alyssa Coghlan (ncoghlan) *
Date: 2015-03-17 12:28
Adding Robert Collins to the nosy list to see if the recent traceback changes make it easier to implement this one correctly.
Robert, for context, the general idea here is to be able to stitch the traceback for a caught exception together with the stack trace for the current frame in order to give a full stack trace for the caught exception, rather than just the stack trace up to the frame where it was caught.
Author: Robert Collins (rbcollins) *
Date: 2015-03-17 20:31
That should be straightforward - its just sequence suffix/prefix overlap detection, and FrameSummary (unlike frames) can be compared with ==. So yes, I think it makes it easier. It's not on my immediate itch-scratching though, but if someone were to poke at it and need any feedback / thoughts I'd be delighted to do so.
History
Date
User
Action
Args
2022-04-11 14:56:20
admin
set
github: 43948
2019-02-24 22:08:57
BreamoreBoy
set
nosy: - BreamoreBoy
2017-11-02 11:17:48
piotr.dobrogost
set
nosy: + piotr.dobrogost
2015-03-17 20:31:54
rbcollins
set
messages: +
2015-03-17 12:28:54
ncoghlan
set
nosy: + rbcollins
messages: +
2015-03-12 02🔞26
BreamoreBoy
set
nosy: + BreamoreBoy
messages: +
versions: + Python 3.5, - Python 3.4
2012-10-30 20:07:03
asvetlov
set
nosy: + asvetlov
2012-10-30 19:50:42
pitrou
set
nosy: + pitrou
messages: +
versions: + Python 3.4, - Python 3.3
2012-08-05 08:38:01
flox
set
nosy: + flox
messages: +
2011-07-09 14:42:02
eric.araujo
set
nosy: + vstinner
2011-03-07 18:46:34
vinay.sajip
unlink
2011-03-04 17:41:47
stutzbach
link
2011-03-04 17:37:35
stutzbach
set
nosy: + stutzbach
versions: + Python 3.3, - Python 3.2
2010-11-16 11:38:05
ncoghlan
set
keywords: - needs review
messages: +
2010-11-15 19:23:25
r.david.murray
set
messages: +
2010-11-15 18:24:44
pakal
set
messages: +
2010-11-14 21:40:50
vinay.sajip
set
messages: +
2010-11-14 21:38:17
vinay.sajip
set
messages: +
2010-11-14 12:47:13
ncoghlan
set
keywords: - easy
messages: +
2010-11-14 12:09:47
ncoghlan
set
messages: +
2010-11-14 12:04:54
ncoghlan
set
nosy: + ncoghlan
messages: +
2010-11-12 03:04:24
r.david.murray
set
files: + full_traceback6.patch
messages: +
2010-10-09 20:12:58
vinay.sajip
set
files: + full_traceback5.patch
messages: +
2010-10-09 19:12:38
vinay.sajip
set
messages: +
2010-10-09 19:05:47
vinay.sajip
set
messages: +
2010-10-09 19:04:10
vinay.sajip
set
messages: +
2010-10-09 18:44:34
r.david.murray
set
messages: +
2010-10-09 18:40:28
vinay.sajip
set
messages: +
2010-10-09 18:37:47
r.david.murray
set
files: + full_traceback4.patch
messages: +
2010-10-09 14:56:10
r.david.murray
set
files: + full_traceback3.patch
messages: +
2010-10-09 11:39:52
vinay.sajip
set
messages: +
2010-10-09 11:36:24
vinay.sajip
set
messages: +
2010-10-09 11:05:45
pakal
set
messages: +
2010-10-09 03:06:35
r.david.murray
set
files: + full_traceback2.patch
messages: +
2010-10-08 19:26:13
r.david.murray
set
messages: +
2010-10-08 18:04:53
pakal
set
messages: +
2010-08-26 13:38:50
vinay.sajip
set
messages: +
2010-08-26 13:37:58
vinay.sajip
set
messages: -
2010-08-26 13:31:20
vinay.sajip
set
messages: +
2010-08-26 13:24:27
vinay.sajip
set
nosy: + vinay.sajip
2010-08-04 02:33:01
r.david.murray
set
keywords: + needs review
files: + full_traceback.patch
messages: +
stage: test needed -> patch review
2010-08-02 13:27:25
r.david.murray
set
files: + full_traceback.patch
keywords: + patch
messages: +
2010-08-02 11:30:55
ysj.ray
set
nosy: + ysj.ray
messages: +
2010-08-02 04:03:02
r.david.murray
set
priority: low -> normal
versions: + Python 3.2, - Python 3.1, Python 2.7
nosy: + r.david.murray
messages: +
2010-07-30 11:27:53
guettli
set
messages: +
2010-07-30 11:14:03
guettli
set
messages: +
2010-07-30 11:09:59
guettli
set
nosy: + guettli
2010-04-06 17:12:29
pakal
set
messages: +
2010-03-30 17:35:47
pakal
set
nosy: + pakal
2010-03-24 22:51:04
news1234
set
nosy: + news1234
2010-03-24 07:59:52
ggenellina
set
nosy: + ggenellina
2009-04-22 05:09:15
ajaksu2
set
keywords: + easy
2009-03-30 03:23:28
ajaksu2
set
priority: normal -> low
stage: test needed
versions: + Python 3.1, Python 2.7, - Python 2.6
2006-09-06 12:48:54
hoffmanm.historic
create