classification
Title: Add traceback.print_full_exception()
Type: enhancement Stage: patch review
Components: Library (Lib) Versions: Python 3.5
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: asvetlov, flox, ggenellina, guettli, hoffman, ncoghlan, news1234, pakal, piotr.dobrogost, pitrou, r.david.murray, rbcollins, stutzbach, vinay.sajip, vstinner, ysj.ray
Priority: normal Keywords: patch

Created on 2006-09-06 12:48 by hoffman, last changed 2019-02-24 22:08 by BreamoreBoy.

Files
File name Uploaded Description Edit
full_traceback.patch r.david.murray, 2010-08-02 13:27
full_traceback.patch r.david.murray, 2010-08-04 02:32 complete patch
full_traceback2.patch r.david.murray, 2010-10-09 03:06 review
full_traceback3.patch r.david.murray, 2010-10-09 14:56 review
full_traceback4.patch r.david.murray, 2010-10-09 18:37 review
full_traceback5.patch vinay.sajip, 2010-10-09 20:12 Mod to David's patch using communicate() review
full_traceback6.patch r.david.murray, 2010-11-12 03:04 review
Messages (39)
msg61256 - (view) 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.
msg61257 - (view) 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. :)
msg61258 - (view) 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()
msg102476 - (view) 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 ?
msg112062 - (view) 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.
msg112065 - (view) Author: Thomas Guettler (guettli) Date: 2010-07-30 11:27
Related #9427
msg112421 - (view) Author: R. David Murray (r.david.murray) * (Python committer) 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.
msg112444 - (view) Author: ysj.ray (ysj.ray) Date: 2010-08-02 11:30
David Murray, where is the patch?
msg112463 - (view) Author: R. David Murray (r.david.murray) * (Python committer) 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...)
msg112738 - (view) Author: R. David Murray (r.david.murray) * (Python committer) 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?
msg114975 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) 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".
msg118210 - (view) 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.
msg118222 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2010-10-08 19:26
No, that would be a bug, thanks.

Also thanks for reminding me about this issue.
msg118242 - (view) Author: R. David Murray (r.david.murray) * (Python committer) 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.
msg118265 - (view) 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 foo
+                    bar()
+                  File "testmod.py", line 11, in bar
+                    raise Exception
+                Exception

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 ?
msg118266 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2010-10-09 11:36
The regression tests are failing for me, see

http://gist.github.com/618117
msg118267 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2010-10-09 11:39
Also, "fullstack" remains in one place in the docs. Should now say "allframes".
msg118275 - (view) Author: R. David Murray (r.david.murray) * (Python committer) 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.
msg118284 - (view) Author: R. David Murray (r.david.murray) * (Python committer) 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.
msg118285 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2010-10-09 18:40
It's still failing - the existing gist has been updated with the output from the new run:

http://gist.github.com/618117
msg118286 - (view) Author: R. David Murray (r.david.murray) * (Python committer) 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...
msg118287 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) 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 :-(
msg118288 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2010-10-09 19:05
Also, the use of literal 'testmod.py' in _do_test should probably be replaced by self.testfn.
msg118289 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) 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?
msg118290 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2010-10-09 20:12
Attached a patch which works on my machine.
msg121014 - (view) Author: R. David Murray (r.david.murray) * (Python committer) 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.)
msg121189 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) 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.
msg121190 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) 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).
msg121192 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) 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).
msg121209 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) 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.
msg121210 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2010-11-14 21:40
Re. the change in r86467, you can test using this simple script:

http://pastebin.com/ZXs3sXDW
msg121238 - (view) 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 ?
msg121239 - (view) Author: R. David Murray (r.david.murray) * (Python committer) 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 :)
msg121282 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) 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.__traceback__.tb_frame.f_back
>>> ex.__context__.__traceback__.tb_frame.f_back
<frame object at 0x2118ff0>
>>> ex.__context__.__context__.__traceback__.tb_frame.f_back
<frame object at 0x2115b80>

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.
msg167476 - (view) Author: Florent Xicluna (flox) * (Python committer) Date: 2012-08-05 08:38
Changeset ba014543ed2c (3.2a4) references this issue.
msg174220 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) 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 <module>
    upper()
> File "testmod.py", line 11, in upper
    foo()
  File "testmod.py", line 6, in foo
    raise Exception
Exception
msg237910 - (view) 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?
msg238287 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) 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.
msg238335 - (view) Author: Robert Collins (rbcollins) * (Python committer) 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
2019-02-24 22:08:57BreamoreBoysetnosy: - BreamoreBoy
2017-11-02 11:17:48piotr.dobrogostsetnosy: + piotr.dobrogost
2015-03-17 20:31:54rbcollinssetmessages: + msg238335
2015-03-17 12:28:54ncoghlansetnosy: + rbcollins
messages: + msg238287
2015-03-12 02:18:26BreamoreBoysetnosy: + BreamoreBoy

messages: + msg237910
versions: + Python 3.5, - Python 3.4
2012-10-30 20:07:03asvetlovsetnosy: + asvetlov
2012-10-30 19:50:42pitrousetnosy: + pitrou

messages: + msg174220
versions: + Python 3.4, - Python 3.3
2012-08-05 08:38:01floxsetnosy: + flox
messages: + msg167476
2011-07-09 14:42:02eric.araujosetnosy: + vstinner
2011-03-07 18:46:34vinay.sajipunlinkissue9427 dependencies
2011-03-04 17:41:47stutzbachlinkissue9427 dependencies
2011-03-04 17:37:35stutzbachsetnosy: + stutzbach

versions: + Python 3.3, - Python 3.2
2010-11-16 11:38:05ncoghlansetkeywords: - needs review

messages: + msg121282
2010-11-15 19:23:25r.david.murraysetmessages: + msg121239
2010-11-15 18:24:44pakalsetmessages: + msg121238
2010-11-14 21:40:50vinay.sajipsetmessages: + msg121210
2010-11-14 21:38:17vinay.sajipsetmessages: + msg121209
2010-11-14 12:47:13ncoghlansetkeywords: - easy

messages: + msg121192
2010-11-14 12:09:47ncoghlansetmessages: + msg121190
2010-11-14 12:04:54ncoghlansetnosy: + ncoghlan
messages: + msg121189
2010-11-12 03:04:24r.david.murraysetfiles: + full_traceback6.patch

messages: + msg121014
2010-10-09 20:12:58vinay.sajipsetfiles: + full_traceback5.patch

messages: + msg118290
2010-10-09 19:12:38vinay.sajipsetmessages: + msg118289
2010-10-09 19:05:47vinay.sajipsetmessages: + msg118288
2010-10-09 19:04:10vinay.sajipsetmessages: + msg118287
2010-10-09 18:44:34r.david.murraysetmessages: + msg118286
2010-10-09 18:40:28vinay.sajipsetmessages: + msg118285
2010-10-09 18:37:47r.david.murraysetfiles: + full_traceback4.patch

messages: + msg118284
2010-10-09 14:56:10r.david.murraysetfiles: + full_traceback3.patch

messages: + msg118275
2010-10-09 11:39:52vinay.sajipsetmessages: + msg118267
2010-10-09 11:36:24vinay.sajipsetmessages: + msg118266
2010-10-09 11:05:45pakalsetmessages: + msg118265
2010-10-09 03:06:35r.david.murraysetfiles: + full_traceback2.patch

messages: + msg118242
2010-10-08 19:26:13r.david.murraysetmessages: + msg118222
2010-10-08 18:04:53pakalsetmessages: + msg118210
2010-08-26 13:38:50vinay.sajipsetmessages: + msg114975
2010-08-26 13:37:58vinay.sajipsetmessages: - msg114972
2010-08-26 13:31:20vinay.sajipsetmessages: + msg114972
2010-08-26 13:24:27vinay.sajipsetnosy: + vinay.sajip
2010-08-04 02:33:01r.david.murraysetkeywords: + needs review
files: + full_traceback.patch
messages: + msg112738

stage: test needed -> patch review
2010-08-02 13:27:25r.david.murraysetfiles: + full_traceback.patch
keywords: + patch
messages: + msg112463
2010-08-02 11:30:55ysj.raysetnosy: + ysj.ray
messages: + msg112444
2010-08-02 04:03:02r.david.murraysetpriority: low -> normal
versions: + Python 3.2, - Python 3.1, Python 2.7
nosy: + r.david.murray

messages: + msg112421
2010-07-30 11:27:53guettlisetmessages: + msg112065
2010-07-30 11:14:03guettlisetmessages: + msg112062
2010-07-30 11:09:59guettlisetnosy: + guettli
2010-04-06 17:12:29pakalsetmessages: + msg102476
2010-03-30 17:35:47pakalsetnosy: + pakal
2010-03-24 22:51:04news1234setnosy: + news1234
2010-03-24 07:59:52ggenellinasetnosy: + ggenellina
2009-04-22 05:09:15ajaksu2setkeywords: + easy
2009-03-30 03:23:28ajaksu2setpriority: normal -> low
stage: test needed
versions: + Python 3.1, Python 2.7, - Python 2.6
2006-09-06 12:48:54hoffmanm.historiccreate