Project

General

Profile

Feature #8661

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

Added by gary4gar (Gaurish Sharma) almost 5 years ago. Updated 20 days 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) about 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) about 1 year ago

Add NEWS about [Feature #8661]

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

Add NEWS about [Feature #8661]

Revision 87023a1d
Added by nobu (Nobuyoshi Nakada) about 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) about 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) about 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) almost 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) almost 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) over 1 year 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) about 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) about 1 year ago

  • Assignee set to matz (Yukihiro Matsumoto)

#8 [ruby-core:81100] Updated by ko1 (Koichi Sasada) about 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) about 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) about 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) about 1 year ago

  • Status changed from Closed to Assigned

#12 Updated by nobu (Nobuyoshi Nakada) about 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) about 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) 10 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) 8 months ago

My enthusiastic -1.

#16 [ruby-core:84161] Updated by kou (Kouhei Sutou) 7 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) 7 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) 20 days 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.

Also available in: Atom PDF