BigBinary Blog

Ruby 2.5 prints backtrace & error message in reverse

Stack trace or backtrace is a sequential representation of the stack of method calls in a program which gets printed when an exception is raised. It is often used to find out the exact location in a program from where the exception was raised.

Before Ruby 2.5

Before Ruby 2.5, the printed backtrace contained the exception class and the error message at the top. Next line contained where in the program the exception was raised. Next we got more lines which contained cascaded method calls.

Consider a simple Ruby program.

1class DivisionService
2  attr_reader :a, :b
3
4  def initialize(a, b)
5    @a, @b = a.to_i, b.to_i
6  end
7
8  def divide
9    puts a / b
10  end
11end
12
13DivisionService.new(ARGV[0], ARGV[1]).divide

Let's execute it using Ruby 2.4.

1$ RBENV_VERSION=2.4.0 ruby division_service.rb 5 0
2
3division_service.rb:9:in `/': divided by 0 (ZeroDivisionError)
4	from division_service.rb:9:in `divide'
5	from division_service.rb:13:in `<main>'

In the printed backtrace above, the first line shows the location, error message and the exception class name; whereas the subsequent lines shows the caller method names and their locations. Each line in the backtrace above is often considered as a stack frame placed on the call stack.

Most of the times, a backtrace has so many lines that it makes it very difficult to fit the whole backtrace in the visible viewport of the terminal.

Since the backtrace is printed in top to bottom order the meaningful information like error message, exception class and the exact location where the exception was raised is displayed at top of the backtrace. It means developers often need to scroll to the top in the terminal window to find out what went wrong.

After Ruby 2.5

Over 4 years ago an issue was created to make printing of backtrace in reverse order configurable.

After much discussion Nobuyoshi Nakada made the commit to print backtrace and error message in reverse order only when the error output device (STDERR) is a TTY (i.e. a terminal). Message will not be printed in reverse order if the original STDERR is attached to something like a File object.

Look at the code here where the check happens if STDERR is a TTY and is unchanged.

Let's execute the same program using Ruby 2.5.

1$ RBENV_VERSION=2.5.0 ruby division_service.rb 5 0
2
3Traceback (most recent call last):
4	2: from division_service.rb:13:in `<main>'
5	1: from division_service.rb:9:in `divide'
6division_service.rb:9:in `/': divided by 0 (ZeroDivisionError)
7
8$

We can notice two new changes in the above backtrace.

1. The error message and exception class is printed last (i.e. at the bottom).
2. The stack also adds frame number when printing in reverse order.

This feature makes the debugging convenient when the backtrace size is a quite big and cannot fit in the terminal window. We can easily see the error message without scrolling up now.

Note that, the Exception#backtrace attribute still holds an array of stack frames like before in the top to bottom order.

So if we rescue the caught exception and print the backtrace manually

1class DivisionService
2  attr_reader :a, :b
3
4  def initialize(a, b)
5    @a, @b = a.to_i, b.to_i
6  end
7
8  def divide
9    puts a / b
10  end
11end
12
13begin
14  DivisionService.new(ARGV[0], ARGV[1]).divide
15rescue Exception => e
16  puts "#{e.class}: #{e.message}"
17  puts e.backtrace.join("\n")
18end

we will get the old behavior.

1$ RBENV_VERSION=2.5.0 ruby division_service.rb 5 0
2
3ZeroDivisionError: divided by 0
4division_service.rb:9:in `/'
5division_service.rb:9:in `divide'
6division_service.rb:16:in `<main>'
7
8$

Also, note that if we assign STDERR with a File object, thus making it a non-TTY

1puts "STDERR is a TTY? [before]: #{$stderr.tty?}"
2$stderr = File.new("stderr.log", "w")
3$stderr.sync = true
4puts "STDERR is a TTY? [after]: #{$stderr.tty?}"
5
6class DivisionService
7  attr_reader :a, :b
8
9  def initialize(a, b)
10    @a, @b = a.to_i, b.to_i
11  end
12
13  def divide
14    puts a / b
15  end
16end
17
18DivisionService.new(ARGV[0], ARGV[1]).divide

we can get the old behavior but the backtrace would be written to the specified file and not to STDERR.

1$ RBENV_VERSION=2.5.0 ruby division_service.rb 5 0
2
3STDERR is a TTY? [before]: true
4STDERR is a TTY? [after]: false
5
6$ cat stderr.log
7
8division_service.rb:14:in `/': divided by 0 (ZeroDivisionError)
9	from division_service.rb:14:in `divide'
10	from division_service.rb:18:in `<main>'
11
12$

This feature has been tagged as experimental feature. What it means is that Ruby team is gathering feedback on this feature.