Project

General

Profile

Feature #8661

Add option to print backstrace in reverse order(stack frames first & error last)

Added by gary4gar (Gaurish Sharma) about 5 years ago. Updated about 1 month ago.

Status:
Closed
Priority:
Normal
Target version:
-
[ruby-core:56096]

Description

Currently the way ruby prints the backtrace is that the error comes first & then the stack frames. like this

  Main Error Message
stack frame 1
stack frame 2
stack frame 3
.....

this is perfectly fine provided

  1. Backstraces are short, so fits in terminal.hence, no need to scroll.
  2. you read it from top to bottom.

But, I am a rails developer where

  1. Backstraces are always HUGE, therefore seldom don't fit in terminal. Means LOTS of scrolling to do everytime we get an error.
  2. in terminal we tend to read backstraces from bottom to top, especially when tailing(tail -f) the production logs.
  3. people, who practice Test-driven development literally spend most of their time scrolling to read backstraces to the point most end up buying a larger display.

Proposed Solution:
Please add a way so we can configure backstraces to be printed in reverse order. so if you are reading from bottom, say from terminal, you can get the main error message without need to scroll. like this

stack frame 3
stack frame 2
stack frame 1
 Main Error Message
..... 

this would save lot of time because when the error message is print at the bottom, no need to scroll for reading it. Not sure if this can be done today. I tried Overriding Exception#backtrace but it caused stack level too deep & illegal hardware instruction Error.

Attached are currently what backstrace currently looks like & how there be an option to make it look for comparison.

current.log (5.13 KB) current.log here is currently backtraces are printed gary4gar (Gaurish Sharma), 07/21/2013 05:20 AM
proposed.log (4.9 KB) proposed.log here is how I wish they could printed, so its easier read in terminal gary4gar (Gaurish Sharma), 07/21/2013 05:20 AM

Associated revisions

Revision 5318154f
Added by nobu (Nobuyoshi Nakada) over 1 year ago

eval_error.c: backstrace in reverse order

  • eval_error.c (rb_threadptr_error_print): print backtrace and error message in reverse order if STDERR is unchanged and a tty. [Feature #8661]

git-svn-id: svn+ssh://ci.ruby-lang.org/ruby/trunk@57685 b2dd03c8-39d4-4d8f-98ff-823fe69b080e

Revision 57685
Added by nobu (Nobuyoshi Nakada) over 1 year ago

eval_error.c: backstrace in reverse order

  • eval_error.c (rb_threadptr_error_print): print backtrace and error message in reverse order if STDERR is unchanged and a tty. [Feature #8661]

Revision 57685
Added by nobu (Nobuyoshi Nakada) over 1 year ago

eval_error.c: backstrace in reverse order

  • eval_error.c (rb_threadptr_error_print): print backtrace and error message in reverse order if STDERR is unchanged and a tty. [Feature #8661]

Revision 5b58d8e6
Added by naruse (Yui NARUSE) over 1 year ago

Add NEWS about [Feature #8661]

git-svn-id: svn+ssh://ci.ruby-lang.org/ruby/trunk@58785 b2dd03c8-39d4-4d8f-98ff-823fe69b080e

Revision 58785
Added by naruse (Yui NARUSE) over 1 year ago

Add NEWS about [Feature #8661]

Revision 58785
Added by naruse (Yui NARUSE) over 1 year ago

Add NEWS about [Feature #8661]

Revision 87023a1d
Added by nobu (Nobuyoshi Nakada) over 1 year ago

eval_error.c: enrich backtrace

  • eval_error.c (print_backtrace): add frame number when printing in reverse order. [Feature #8661]

git-svn-id: svn+ssh://ci.ruby-lang.org/ruby/trunk@58786 b2dd03c8-39d4-4d8f-98ff-823fe69b080e

Revision 58786
Added by nobu (Nobuyoshi Nakada) over 1 year ago

eval_error.c: enrich backtrace

  • eval_error.c (print_backtrace): add frame number when printing in reverse order. [Feature #8661]

Revision 58786
Added by nobu (Nobuyoshi Nakada) over 1 year ago

eval_error.c: enrich backtrace

  • eval_error.c (print_backtrace): add frame number when printing in reverse order. [Feature #8661]

History

#1 [ruby-core:56109] Updated by jballanc (Joshua Ballanco) about 5 years ago

You can already accomplish something like this yourself:

begin
  raise "Hello!"
rescue Exception => e
  puts e.backtrace.reverse.join("\n")
  puts e.message
end

Simple!

#2 [ruby-core:56117] Updated by nobu (Nobuyoshi Nakada) about 5 years ago

(13/07/23 4:56), Joshua Ballanco wrote:

You can already accomplish something like this yourself:

begin
  raise "Hello!"
rescue Exception => e
  puts e.backtrace.reverse.join("\n")

You don't need to join.

  puts e.message
end

Simple!

#3 [ruby-core:78808] Updated by nofxx (Marcos Piccinini) almost 2 years ago

Already doing the rescue & reverse, but need to do it on every project...

Another use case is when using some monitor (e.g. guard) to run tests as you code:
When there's a fail one needs to switch to terminal and scroll up to see the lines that matter.

#4 [ruby-core:79669] Updated by nobu (Nobuyoshi Nakada) over 1 year ago

  • Description updated (diff)

#5 Updated by nobu (Nobuyoshi Nakada) over 1 year ago

  • Status changed from Open to Closed

Applied in changeset ruby-trunk:r57685.


eval_error.c: backstrace in reverse order

  • eval_error.c (rb_threadptr_error_print): print backtrace and error message in reverse order if STDERR is unchanged and a tty. [Feature #8661]

#6 [ruby-core:81087] Updated by Eregon (Benoit Daloze) over 1 year ago

Should matz give an opinion on this feature?

It's a pretty big change for the user, I got confused a couple times by it when running trunk.
Particularly, if a test framework prints a backtrace in the old order, but then some exception kills the test framework then there is a mix of backtrace in old and new order.

I see from the commit this is limited to top-level backtraces printed to stderr.
This is good to limit breaking compatibility but also inconsistent with the Exception#backtrace order for instance.
Even then, it might already break compatibility significantly if anyone depends on the output of the top-level exception handler.

Also, I am not sure this addresses the OP concern, since the display of the backtrace in Rails is rarely an exception going to the top-level (which would be affected by this change) but managed by some handler printing the exception in the log (managed by Rails and can only be changed there).

In any case, if this remains for 2.5 it should be mentioned in the NEWS file.

#7 [ruby-core:81088] Updated by Eregon (Benoit Daloze) over 1 year ago

  • Assignee set to matz (Yukihiro Matsumoto)

#8 [ruby-core:81100] Updated by ko1 (Koichi Sasada) over 1 year ago

  • Status changed from Closed to Assigned

Agreed. I got confusing too. (not sure it is a matter of experience or not...)

#9 Updated by naruse (Yui NARUSE) over 1 year ago

We expect some people may object this.
Therefore we're gathering feedback now (so thank you for your feedback).

To gather feedback wider, we'll give final decision after preview 1, including rspec and Rails will follow this change or not.

In any case, if this remains for 2.5 it should be mentioned in the NEWS file.

Yeah, NEWS should include this and note as EXPERIMENTAL.
I add it.

#10 Updated by naruse (Yui NARUSE) over 1 year ago

  • Status changed from Assigned to Closed

Applied in changeset ruby-trunk:trunk|r58785.


Add NEWS about [Feature #8661]

#11 Updated by naruse (Yui NARUSE) over 1 year ago

  • Status changed from Closed to Assigned

#12 Updated by nobu (Nobuyoshi Nakada) over 1 year ago

  • Status changed from Assigned to Closed

Applied in changeset ruby-trunk:trunk|r58786.


eval_error.c: enrich backtrace

  • eval_error.c (print_backtrace): add frame number when printing in reverse order. [Feature #8661]

#13 [ruby-core:81299] Updated by shyouhei (Shyouhei Urabe) over 1 year ago

FYI it is intentional for this feature being automatically enabled right now, instead of some configuration like the OP requests.

The reason behind this is that stderr is expected to be passed to other processes (like some logging infrastructure for instance). If the order of backtraces is configurable, it becoms impossible for such outer-process things to detect which. So configuration is a bad idea in this area. Either the backtrace is ascending or descending, that order should be static and should never be configurable.

P.S. I get confused too so I personally don't like the way it is.

#14 Updated by sonots (Naotoshi Seo) 12 months ago

I object the current behavior which prints backtrace in reverse order for STDERR. It is confusing.

#15 [ruby-core:83953] Updated by mame (Yusuke Endoh) 10 months ago

My enthusiastic -1.

#16 [ruby-core:84161] Updated by kou (Kouhei Sutou) 10 months ago

I like this change. It's unbelievable.

I thought that I don't like this feature because I was confused Python's backtrace behavior (most recent call last).

I used trunk in a few weeks but I was not confused the current behavior. Instead it was convenient.

I noticed that I confirm error message and then backtrace on error. It was convenient that error message is shown at the last. I could confirm backtrace from the bottom to the top naturally.

Python's backtrace behavior doesn't show index:

def a():
    x()

def b():
    a()

b()
% python /tmp/a.py
Traceback (most recent call last):
  File "/tmp/a.py", line 7, in <module>
    b()
  File "/tmp/a.py", line 5, in b
    a()
  File "/tmp/a.py", line 2, in a
    x()
NameError: global name 'x' is not defined

Ruby 2.5's one shows index:

def a
  x
end

def b
  a
end

b
% ruby /tmp/a.rb
Traceback (most recent call last):
    2: from /tmp/a.rb:9:in `<main>'
    1: from /tmp/a.rb:6:in `b'
/tmp/a.rb:2:in `a': undefined local variable or method `x' for main:Object (NameError)

It may be helpful to recognize backtrace order.

I've added the same behavior to test-unit and released a new version.

#17 [ruby-core:84428] Updated by aeroastro (Takumasa Ochi) 9 months ago

Although I am not a Ruby committer, IMHO, I do not think the current implementation
is the best way to fully address the reporter's concern.

As written in this issue's description section, reversing the backtrace is a
solution which only works in the environments where you read the log from bottom
to top like terminals.

Nowadays, it is becoming more and more common to read the log from top to bottom
in other environments like CI report (e.g. Jenkins, Travis, and so on),
web-based error dashboard (e.g. Stack Driver), interactive applications
(e.g. Jupyter). Current Ruby 2.5's behavior is to reverse backtrace when STDERR
is unchanged and a tty. Therefore we can still read the backtrace from top to
bottom in those situations. However, this conditional reversing lacks consistency
and is confusing. For example, just a redirection can change the behavior of output.

At the same time, I think we need to clarify what the problem actually is.
If a lot of people using Rails are suffering from huge backtraces, which can be assumed from
the word "every project" and "tailing the production logs", ActiveSupport::BacktraceCleaner
can solve the problem in a more sophisticated way. It convert the huge backtrace to
a very compact one by filtering out irrelevant lines which belong to Rails framework.
This solution works well regardless of the way how we read the log because the backtrace
is short and simple.

If people developing Rails itself are suffering from huge backtraces, although conditional
reversing could work to some extent, IMHO, we need to consider a solution with fewer
and minor side effects.

#18 [ruby-core:87647] Updated by ioquatix (Samuel Williams) 3 months ago

This is possibly one of the most irritating changes to Ruby recently. Now, every time I read back trace, I have to check it carefully.

Is it top to bottom or bottom to top?

How is this confusion made worse?

  • Using multiple versions of Ruby, or different interpreters that retain the old behaviour.
  • Using testing frameworks and logging frameworks that retain the old behaviour.

This is a case where I think the benefit was significantly overshadowed by the cost to end users. It's now very, very confusing.

#19 [ruby-core:88515] Updated by mame (Yusuke Endoh) about 1 month ago

Over one year has passed since the backtrace order was reversed. But I'm not still used to the new order.

I agree with Samuel's points. In addition, the old order was more useful because it shows the last debug output and the exception message in one place.

$ ruby24 test.rb
...
...
"debug print"
"debug print"
"the last debug print"
test.rb:X:in 'buggy_func': exception message
    from test.rb:X:in `foo'
    from test.rb:X:in `bar'
...
...

In the above output, "the last debug output" and test.rb:X:in 'buggy_func': exception message are placed in one place. It is easy to understand the situation and to start debugging.

However, the current behavior separates the two. This is very frastrating.

$ ruby25 test.rb
...
...
"debug print"
"debug print"
"the last debug print"
...
...
    from test.rb:X:in `bar'
    from test.rb:X:in `foo'
test.rb:X:in 'buggy_func': exception message

Is there any chance to revert the change?

#20 [ruby-core:88545] Updated by shevegen (Robert A. Heiler) about 1 month ago

I think I agree with mame - perhaps it should be reverted for now.

There was another ruby hacker from japan who wrote, some time ago
(a year or two?), that he was confused about it too; I don't remember
where it was but I think it was in a standalone proposal some time
ago.

In my opinion, the best would be to find a way to be able to
fully customize the behaviour/display that ruby uses for reporting
warnings/errors, with a default chosen that may be most appropriate
for the most common ways to display the issues at hand (I have no
preference to the default chosen here, but perhaps we should
revert to the behaviour ruby used to use; and then allow full
customization for people to adapt it to their own personal needs).

I assume that matz may not have a huge preference either, so
perhaps we should (lateron?) focus on some way to be able to
customize how ruby treats warnings/errors or rather, display
them. An obvious way may be to allow for environment variables.

An additional way may be to pick something at compile time (so
that people can customize it for their own host system, as a
default), and perhaps also a --user flag directive of some
sorts; and perhaps additionally something like $VERBOSE, but
through some core method call or something instead.

I should, however had, also note that while I think I prefer
the old behaviour, to me personally it is not a huge deal either
way - I just can understand everyone who may not like the
chosen default as-is. The only thing that I personally found hard
was when the filenames are very long and the error is somewhere
deep down in code that gets called by lots of other methods in
different files - then the error messages are "overflowing" to
the right of my screen display, so in this case, I would prefer
a shorter message, or perhaps split up onto several lines; I kind
of focus on the left hand side of my screen normally. But again,
it's not really something I personally am deeply invested - I am
personally am more looking as to how mjit is progressing. :)

Also available in: Atom PDF