classification
Title: Shrink recursive tracebacks
Type: behavior Stage: resolved
Components: Interpreter Core Versions: Python 3.6
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: ncoghlan Nosy List: Decorater, Rosuav, berker.peksag, ebarry, ethan.furman, georg.brandl, ncoghlan, python-dev, serhiy.storchaka, xiang.zhang
Priority: normal Keywords: patch

Created on 2016-04-22 02:36 by ebarry, last changed 2016-08-20 01:06 by python-dev. This issue is now closed.

Files
File name Uploaded Description Edit
short_tracebacks.patch ebarry, 2016-04-22 02:36 review
short_tracebacks_2.patch ebarry, 2016-04-22 04:25 review
short_tracebacks_3.patch ebarry, 2016-04-22 15:11 review
short_tracebacks_4.patch ebarry, 2016-07-06 21:31 review
short_tracebacks_5.patch ebarry, 2016-07-23 15:50 review
short_tracebacks_6.patch ebarry, 2016-07-24 13:50 review
short_tracebacks_7.patch ebarry, 2016-07-24 15:00 review
short_tracebacks_doc_1.patch ebarry, 2016-08-15 16:47 review
Messages (33)
msg263948 - (view) Author: Emanuel Barry (ebarry) * Date: 2016-04-22 02:36
I recently suggested on Python-ideas ( https://mail.python.org/pipermail/python-ideas/2016-April/039899.html ) to shrink long tracebacks if they were all the same noise (recursive calls). Seeing as the idea had a good reception, I went ahead and implemented a small patch for this.

It doesn't keep track of call chains, and I'm not sure if we want to implement that, as the performance decrease needed to store all of that might not be worth it. But then again, if an error happened performance is probably not a concern in this case.

I've never really coded in C before, so feedback is very much welcome.
msg263949 - (view) Author: Chris Angelico (Rosuav) * Date: 2016-04-22 02:44
By "doesn't keep track of call chains", you mean that it can't handle mutually-recursive functions, right?

Still useful.
msg263950 - (view) Author: Emanuel Barry (ebarry) * Date: 2016-04-22 02:47
Yes, can't handle mutually recursive functions. I could maybe check for the last two or three functions, but that seems like unnecessary work for something that might not happen as often (I can see it being the case with e.g. __getattr__ though).

If enough people think it should keep track of all or most functions being called, I can do it.
msg263951 - (view) Author: Ethan Furman (ethan.furman) * (Python committer) Date: 2016-04-22 02:48
If you can, give it a go.  Make it a new patch, though -- don't delete the existing one.
msg263952 - (view) Author: Xiang Zhang (xiang.zhang) * (Python committer) Date: 2016-04-22 02:59
With the current patch, a simple test gives the traceback:

Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "<stdin>", line 2, in test
  File "<stdin>", line 2, in test
  File "<stdin>", line 2, in test
  [Previous message repeated 995 more times]
RecursionError: maximum recursion depth exceeded

I think the message [Previous message repeated 995 more times] is vague. Does it refer to the previous line or the whole previous messages? Hmm, at least it is vague for me, a non-native English speaker.
msg263953 - (view) Author: Emanuel Barry (ebarry) * Date: 2016-04-22 03:02
The message is mostly a placeholder, but "message" is singular so I figured it would be obvious. But alas, if you are confused, others might be too. Propositions for a better message are welcome :)

I'll attempt to make it track chained calls (or mutually recursive functions) tomorrow, my sleep-deprived brain is unable to find a clean way to do this right now :)
msg263954 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2016-04-22 03:46
+1 for the simple approach, and deferring the mutual recursion support - it's desirable to keep traceback printing simple in order to minimise the chance for failures during the display process.

In addition to the C implementation of traceback printing, the standard library's traceback module would also need updating.

Regarding the ambiguity of "Previous message", I'd suggest using "Previous line" instead - that way it's accurate regardless of whether people read it as "previous line of the traceback" or "previous line of quoted source code".
msg263955 - (view) Author: Emanuel Barry (ebarry) * Date: 2016-04-22 04:25
Attached patch also modifies Lib/traceback.py to present identical behaviour, and changes "Previous message" to "Previous line". I'll postpone the more complex implementation of that, and might just not do it as it's indeed better to avoid bugs where we're meant to handle bugs =)

Should there be unit tests for that? I'm really not sure how to write tests for that particular case...
msg263959 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2016-04-22 05:23
For testing, you can create a recursive scenario that terminates with an exception after a defined number of iterations:

>>> def f(counter):
...     if counter:
...         f(counter-1)
...     else:
...         raise RuntimeError
... 
>>> f(3)
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "<stdin>", line 3, in f
  File "<stdin>", line 3, in f
  File "<stdin>", line 3, in f
  File "<stdin>", line 5, in f
RuntimeError

It's probably also worth checking the handling of two distinct frame repetitions by having another recursion counter that terminates itself by calling the one that terminates by raising an exception

Beyond that, https://hg.python.org/cpython/file/tip/Lib/test/test_traceback.py covers both traceback formatting implementations, so a new test case in TracebackFormatTests seems appropriate.
msg264022 - (view) Author: Emanuel Barry (ebarry) * Date: 2016-04-22 15:11
New version with tests now, I test both the C and Python implementations.
msg265750 - (view) Author: Emanuel Barry (ebarry) * Date: 2016-05-17 02:55
I realize that I haven't given any update on this since my last patch. I figured that trying to detect when an arbitrary number of functions call each other in a convoluted call chain isn't a very good idea.

Not only is it way beyond my abilities, but I think it'll overcomplicate the code too much. Furthermore, the way Python/traceback.c (and, coincidentally, Lib/traceback.py) is done - print each frame as they come and then throw it away - means that remembering more than the last frame needs a refactor of both files. This is way out of the scope of this issue, which aims to solve the common cases (a typo when messing around in the REPL, __getattribute__ and __getattr__ are what get me the most).

I think that if the idea of keeping a track of multiple frames still flies, it should be a separate issue - probably after yet another issue proposing to refactor the files for that, but I'm dropping the idea.

Except for the ambigous message, I haven't seen any comments on any of my patches, which I take as a very good thing. Is there anything else preventing this from being merged?

TL;DR - Ping
msg269909 - (view) Author: Emanuel Barry (ebarry) * Date: 2016-07-06 21:31
Sorry for the delay, but here's a patch with updated tests after Nick's suggestions. It should be ready to merge now.

(I'm having some failures in test_traceback, but they fail even without my patch)
msg271085 - (view) Author: Emanuel Barry (ebarry) * Date: 2016-07-23 15:16
After discussing with someone, I realized that the tests actually test the Python implementation twice, and never the C implementation (since I use traceback.print_exc() to "test" the C implementation).

I don't think it's possible to both catch the output from the C implementation and prevent it from exiting out of the function prematurely, but if anyone knows how to do that, be my guest! In the meantime, I'm going to mess about with _testcapi and see if I can add something there to help with this.
msg271089 - (view) Author: Emanuel Barry (ebarry) * Date: 2016-07-23 15:50
Turns out there's already some functions in _testcapi that do this, great! Here's an updated patch actually testing the C implementation (and the tests pass, obviously :)
msg271140 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2016-07-24 09:01
Thanks Emanuel, and sorry for the long delay in getting a review!

My main substantive comment is that the approach of hardcoding the recursion count won't work cross platform, as the default recursion limit is set differently depending on how the platform's C runtime behaves. Fortunately, sys.getrecursionlimit() and len(inspect.stack()) should make it possible to tweak the tests to avoid the hardcoded assumption.

I also have some additional readability suggestions, which can be found in Rietveld.
msg271152 - (view) Author: Emanuel Barry (ebarry) * Date: 2016-07-24 13:50
Thank you Nick for the comments! Updated patch attached.

The new patch uses inspect.stack() to calculate the total stack size, but I'm unable to get the exact number needed, and I found that I'm either 19 or 20 above (depending on whether I run it with -m or manually). The test now "just works" with it, but I'm quite sure it's going to break at some point. Any idea?

The other alternative would be to use traceback.walk_tb(exc.__traceback__), but the Python implementation uses that, so it'd be comparing itself; and that's about as useful as not caring about the size at all. (On the other hand, the C and Python implementations get the exact same number, so it can confirm it's fine)
msg271156 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2016-07-24 14:35
Since you're ultimately comparing a list of lines, it may be useful to split the checks into two parts:

1. Check the deterministic lines
2. Check the variable line (which should always be at index -2 in the splitlines() result)

For the recursion error, we're not too worried about the *exact* repetition count, we're mostly interested in checking that it abbreviated the traceback. Once you've pulled that line out of the main "Are they the same?" comparison, you can use a regex (or just string operations) to extract the repetition count, convert it to an integer and check that it gives the right answer to within (say) +/- 50 repetitions.
msg271162 - (view) Author: Emanuel Barry (ebarry) * Date: 2016-07-24 15:00
Alright, I think this works now. No more magic number, just some regex as well as checking that the number is in range(sys.getrecursionlimit()-50, sys.getrecursionlimit()) :)
msg272642 - (view) Author: Emanuel Barry (ebarry) * Date: 2016-08-14 03:13
Is it possible to get this in in time for 3.6.0a4? The feature itself hasn't been touched in about 4 months, only tests have been tweaked since.
msg272703 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2016-08-15 01:08
I'm at the PyCon AU sprints today, and will take a look at getting this merged.
msg272705 - (view) Author: Roundup Robot (python-dev) Date: 2016-08-15 03:13
New changeset 5a2ff215e841 by Nick Coghlan in branch 'default':
Issue #26823: Abbreviate recursive tracebacks
https://hg.python.org/cpython/rev/5a2ff215e841
msg272706 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2016-08-15 03:15
Thanks for the patch, Emanuel!

The merged patch uses your implementation and the test cases you designed, with the following changes:

- I refactored the test cases so the traceback module gets tested on all implementations, with only the CPython builtin rendering tests being specific to CPython

- I added docs updates and a couple of What's New entries for the change
msg272707 - (view) Author: Emanuel Barry (ebarry) * Date: 2016-08-15 03:20
Awesome, thanks! The "What's new" entry is a bit confusing though; to a casual observer it might look like the `traceback` module was updated but the normal behaviour wasn't changed.
msg272708 - (view) Author: Decorater (Decorater) * Date: 2016-08-15 03:20
Be nice if 3.5 had this as well. As it can be very annoying at times. (Not to mention thread exceptions just cant be handled by anyone's code unless you modify threading.py
msg272709 - (view) Author: Emanuel Barry (ebarry) * Date: 2016-08-15 03:22
Pretty sure this falls under the "New features" category, and as such can't be applied on 3.5.
msg272710 - (view) Author: Decorater (Decorater) * Date: 2016-08-15 03:25
3.6 would make thread exceptions not print out to console or at least be configured to make them logged with the logging module in threading.py for 3.6? because I would like it to use the logger. Oh and how can I get the logs from the logging module from 2 different libs in 1 module?

Like I can get the logs from 1 module just fine.
However if I try to get from things (lets say from asyncio (then it would return nothing).
msg272711 - (view) Author: Emanuel Barry (ebarry) * Date: 2016-08-15 03:26
This is irrelevant to this issue.
msg272724 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2016-08-15 07:13
As Emanuel noted, this is a new feature, and hence won't be backported to any earlier versions.

For What's New, it turns out that didn't quite render the way I expected, since the "StackSummary" class reference is missing in addition to the "traceback" module reference.

So I'll tweak that, and also try to make it clearer that all tracebacks are affected, not just those printed via the traceback module (PyTraceback_Print is mentioned further down, but what I'll probably do is add an example of an infinite recursion being truncated at the interactive prompt)
msg272734 - (view) Author: Berker Peksag (berker.peksag) * (Python committer) Date: 2016-08-15 08:28
> So I'll tweak that [...]

Hi Nick, could you also tweak the usage of versionchanged directive? :)

+    .. versionchanged:: 3.6
+
+    Long sequences of repeated frames are now abbreviated.

Description line needs to be indented:

    .. versionchanged:: 3.6
       Long sequences of repeated frames are now abbreviated.
msg272780 - (view) Author: Emanuel Barry (ebarry) * Date: 2016-08-15 16:47
Doc patch.
msg272812 - (view) Author: Roundup Robot (python-dev) Date: 2016-08-16 00:58
New changeset 86d062edb6ab by Nick Coghlan in branch 'default':
Issue #26823: fix traceback abbreviation docs
https://hg.python.org/cpython/rev/86d062edb6ab
msg272814 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2016-08-16 00:59
Thanks again Emanuel - I incorporated your suggested changes along with some other ones I had already made locally.
msg273177 - (view) Author: Roundup Robot (python-dev) Date: 2016-08-20 01:06
New changeset a7f3678f9509 by Victor Stinner in branch 'default':
Fix reference leak in tb_printinternal()
https://hg.python.org/cpython/rev/a7f3678f9509
History
Date User Action Args
2016-08-20 01:06:53python-devsetmessages: + msg273177
2016-08-16 01:00:00ncoghlansetstatus: open -> closed
stage: patch review -> resolved
2016-08-16 00:59:43ncoghlansetmessages: + msg272814
2016-08-16 00:58:37python-devsetmessages: + msg272812
2016-08-15 16:47:29ebarrysetstatus: closed -> open
files: + short_tracebacks_doc_1.patch
messages: + msg272780

stage: resolved -> patch review
2016-08-15 08:28:29berker.peksagsetnosy: + berker.peksag
messages: + msg272734
2016-08-15 07:13:38ncoghlansetmessages: + msg272724
2016-08-15 03:26:46ebarrysetmessages: + msg272711
2016-08-15 03:25:55Decoratersetmessages: + msg272710
2016-08-15 03:22:50ebarrysetmessages: + msg272709
2016-08-15 03:20:59Decoratersetnosy: + Decorater
messages: + msg272708
2016-08-15 03:20:07ebarrysetmessages: + msg272707
2016-08-15 03:15:42ncoghlansetstatus: open -> closed
resolution: fixed
messages: + msg272706

stage: commit review -> resolved
2016-08-15 03:13:08python-devsetnosy: + python-dev
messages: + msg272705
2016-08-15 01:08:05ncoghlansetassignee: ebarry -> ncoghlan
messages: + msg272703
stage: patch review -> commit review
2016-08-14 03:55:51serhiy.storchakasetnosy: + serhiy.storchaka
2016-08-14 03:13:53ebarrysetmessages: + msg272642
2016-07-24 15:00:12ebarrysetfiles: + short_tracebacks_7.patch

messages: + msg271162
2016-07-24 14:35:11ncoghlansetmessages: + msg271156
2016-07-24 13:50:29ebarrysetfiles: + short_tracebacks_6.patch

messages: + msg271152
stage: commit review -> patch review
2016-07-24 09:01:57ncoghlansetassignee: ncoghlan -> ebarry
messages: + msg271140
2016-07-24 08:35:48ncoghlansetassignee: ebarry -> ncoghlan
stage: patch review -> commit review
2016-07-23 15:50:38ebarrysetfiles: + short_tracebacks_5.patch

messages: + msg271089
2016-07-23 15:16:36ebarrysetmessages: + msg271085
2016-07-06 21:31:14ebarrysetfiles: + short_tracebacks_4.patch

messages: + msg269909
2016-05-17 02:55:21ebarrysetmessages: + msg265750
2016-04-22 15:11:57ebarrysetfiles: + short_tracebacks_3.patch
assignee: ebarry
messages: + msg264022
2016-04-22 05:23:55ncoghlansetmessages: + msg263959
2016-04-22 04:25:51ebarrysetfiles: + short_tracebacks_2.patch

messages: + msg263955
2016-04-22 03:46:02ncoghlansetnosy: + ncoghlan
messages: + msg263954
2016-04-22 03:02:43ebarrysetmessages: + msg263953
2016-04-22 02:59:12xiang.zhangsetnosy: + xiang.zhang
messages: + msg263952
2016-04-22 02:49:28ethan.furmansetnosy: + georg.brandl
2016-04-22 02:49:09ethan.furmansettype: behavior
2016-04-22 02:48:54ethan.furmansetmessages: + msg263951
2016-04-22 02:47:18ebarrysetmessages: + msg263950
2016-04-22 02:44:41Rosuavsetnosy: + Rosuav
messages: + msg263949
2016-04-22 02:39:36ethan.furmansetnosy: + ethan.furman
2016-04-22 02:36:25ebarrycreate