Project

General

Profile

Actions

Misc #20968

open

`Array#fetch_values` unexpected method name in stack trace

Added by koic (Koichi ITO) 3 months ago. Updated 12 days ago.

Status:
Open
Assignee:
-
[ruby-core:120315]

Description

It seems that the current Ruby implementation is displaying unexpected method name in stack trace.

Expected

Similar to Hash#fetch_values, the method name Array#fetch_values is expected to be displayed in the stack trace.

$ ruby -e '{k: 42}.fetch_values(:unknown)'
-e:1:in 'Hash#fetch_values': key not found: :unknown (KeyError)
        from -e:1:in '<main>'

$ ruby -e '[1].fetch_values(42)'
-e:1:in 'Array#fetch_values': index 42 outside of array bounds: -1...1 (IndexError)
        from -e:1:in '<main>'

Actual

The stack trace displays the Array#fetch method, which user is not aware of, along with the <internal.array> stack trace.

$ ruby -e '[1].fetch_values(42)'
<internal:array>:211:in 'Array#fetch': index 42 outside of array bounds: -1...1 (IndexError)
        from <internal:array>:211:in 'block in Array#fetch_values'
        from <internal:array>:211:in 'Array#map!'
        from <internal:array>:211:in 'Array#fetch_values'
        from -e:1:in '<main>'

It likely requires an approach such as implementing it in C, as suggested in https://github.com/ruby/ruby/pull/11555.

Updated by jeremyevans0 (Jeremy Evans) 3 months ago

This doesn't seem like a bug to me. Array#fetch_values is in the backtrace, just not the top frame.

This isn't the only core method with the behavior:

1.ceildiv(0)
# <internal:numeric>:304:in 'Integer#div': divided by 0 (ZeroDivisionError)
#         from <internal:numeric>:304:in 'Integer#ceildiv'

As more core methods are implemented in Ruby, this situation will occur more frequently. Can you explain why you think this is a bug? This is the expected behavior for most methods in the standard library, as well as most methods in gems. Any method written in Ruby that calls other methods will have this behavior, so I think it is OK that core methods are allowed to have this behavior.

Updated by byroot (Jean Boussier) 3 months ago

I agree with @jeremyevans0 (Jeremy Evans) that it's not a bug.

But if it's decided than it is, then there's no need to rewrite it all in C, you can just set the c_trace attribute:

Primitive.attr! :c_trace

Updated by koic (Koichi ITO) 3 months ago

Thank you for your prompt response.
I hadn’t realized that the same issue occurs with 1.ceildiv(0) as well.

This is not a bug, but my concern arises from the asymmetry in how exceptions are displayed for Array#fetch_values. Even though Array#fetch_values was used incorrectly, the backtrace displays Array#fetch at the top, which was not explicitly called, and this caused some confusion.

This is just a personal opinion, but it seems more natural for exception related to Array#fetch_values to show Array#fetch_values itself instead of the internal implementation of Array#fetch. This is not specific to Array#fetch_values, as the same can be said for cases like 1.ceildiv(0).

Updated by Eregon (Benoit Daloze) about 1 month ago

I agree with Jeremy and Jean, this is not a bug.
There are more and more methods implemented in Ruby, and that's a good thing: https://gist.github.com/eregon/912e6359e83781c5fa1c638d3768c526
That means these methods can look slightly different in backtraces, but it doesn't matter, from <internal:array>:211:in 'Array#fetch_values' is still in the backtrace above.
It's a bit like Hash#[], if there is an error during calling key.hash you will see #hash in the backtrace, it's natural.

Updated by mame (Yusuke Endoh) about 1 month ago

This issue was discussed briefly at the dev meeting and Matz agreed with koic's expectation.

https://github.com/ruby/dev-meeting-log/blob/47882270bd90fb0027e8fe62e421b398d6b3195b/2025/DevMeeting-2025-01-09.md?plain=1#L454


The following is my opinion.

I agree that this is not a bug, but I think koic's expectations are clearly better than the current from a user benefit perspective, not from a consistency perspective.
I think it is significantly unlikely that <internal:array>:211 is valuable information for user to debug a bug.
It would be more convenient to combine <internal> backtraces into one and substitute the name of the calling Ruby source file and line number, as in the current C-implemented method.

Updated by Eregon (Benoit Daloze) about 1 month ago · Edited

TLDR: I think this is mostly a matter of getting used to <internal: backtrace entries, and so I think we should not do anything about this now but reevaluate in some time.
We already all agree this is not a bug.
As more methods are defined in Ruby, users are getting more used to this and won't find it surprising or unusual.
In fact these backtraces are more accurate and can help the user understand better what is going on.

As an example, I think semantically it is very nice to be able to see Array#fetch_values calls Array#fetch here.
I believe it is what users would expect (that fetch_values uses fetch), hiding that seems not good.

mame (Yusuke Endoh) wrote in #note-5:

I agree that this is not a bug, but I think koic's expectations are clearly better than the current from a user benefit perspective, not from a consistency perspective.
I think it is significantly unlikely that <internal:array>:211 is valuable information for user to debug a bug.
It would be more convenient to combine <internal> backtraces into one and substitute the name of the calling Ruby source file and line number, as in the current C-implemented method.

FWIW we considered this (combine internal entries into one, or hiding internal entries, or attribute all entries to the caller, etc) in TruffleRuby (it was discussed a few times on the truffleruby issue tracker, since truffleruby has many more methods defined in Ruby) but rejected this idea as it is clearly suboptimal for multiple reasons:

  • Debugging an issue with a partial backtrace is always worse and more confusing (for both VM developers and users).
  • Imagine that someone redefines Array#fetch. And when used from fetch_values it raises some unexpected exception. With the full backtrace like currently the user can easily understand what's going on. Without it, it's very hard. We might see the file which redefines Array#fetch, but not if it's redefined in C. And it would be weird for fetch_values to have a different number of backtraces entries based on which fetch method ends up being called.
  • As an example for Hash#[]=, if that hides the key.hash call, and some hash method implementation raises, it's way more confusing if the hash is not shown in the backtrace.
    Current:
$ ruby -e 'k=Object.new; def k.hash; raise "foo"; end; {}[k] = 1'
-e:1:in 'hash': foo (RuntimeError)
	from -e:1:in '<main>'

vs

$ ruby -e 'k=Object.new; def k.hash; raise "foo"; end; {}[k] = 1'
-e:1:in '<main>': foo (RuntimeError)

(both of these hide the []= call, that's not great but due to having a special instruction for this, hard to fix without hurting performance)

  • Another example could be inject calling some core method, if we replace the two entries by one it would be very confusing, leading to think that inject is raising when it's the core method being called which is raising an exception.
  • <internal:...> is now a well-established format for this for some time already.
  • The line information could be useful for users too, especially if the editor/IDE would support viewing the source file in such a case.
  • It is important for reasoning that one Ruby call/frame = one backtrace entry.
  • In some specific use cases it may make sense to skip <internal: entries (e.g. already done for Kernel#warn) or present them differently. That's fine, but in general we should not hide crucial information like that.

Also while Rubyists are used to backtraces like:

def foo = [0].fetch(42)
foo

Giving:

fetch.rb:1:in 'Array#fetch': index 42 outside of array bounds: -1...1 (IndexError)
	from fetch.rb:1:in 'Object#foo'
	from fetch.rb:2:in '<main>'

They are actually "wrong" because Array#fetch is not defined in fetch.rb:1, it is defined in the core library.
I think that has BTW caused some confusion because people might not realize the location on the left should be the definition of the method mentioned on the right (since it doesn't hold for C methods).

Actions #7

Updated by Eregon (Benoit Daloze) about 1 month ago

  • Tracker changed from Bug to Misc
  • ruby -v deleted (ruby 3.4.0dev (2024-12-19T04:44:56Z master 2783868de2) +PRISM [x86_64-darwin23])
  • Backport deleted (3.1: UNKNOWN, 3.2: UNKNOWN, 3.3: UNKNOWN)

Updated by jeremyevans0 (Jeremy Evans) about 1 month ago

My thinking is inline with @Eregon (Benoit Daloze) 's. It's significantly more work to try to modify the backtraces to omit <internal: entries. Ultimately, I think that hiding such entries results in less helpful information.

If we could show the file and line for C functions, that would be useful for debugging. I assume the only reason we don't is that doing so is not feasible.

Note that even if we hide the <internal: methods, you still have the same issue for any method that is defined in C and calls another C or Ruby method in a way that pushes a VM frame:

$ ruby -e "Class.new.new(1)"
-e:1:in `initialize': wrong number of arguments (given 1, expected 0) (ArgumentError)

Class.new.new(1)
              ^
        from -e:1:in `new'
        from -e:1:in `<main>'

Note that I never overrode initialize. I am calling new, but initialize is showing up in the backtrace even though both new and initialize are defined in C. The internal reason for this is because Class.new uses rb_funcallv_kw to call Obejct#initialize, which pushes a VM frame.

That being said, if we do want to change behavior of this only for <internal: entries, the Primitive.attr! :c_trace approach mentioned by @byroot (Jean Boussier) seems preferable to modifying the backtrace internals. Should we just add that to all <internal: methods that call other methods?

Updated by Eregon (Benoit Daloze) about 1 month ago · Edited

Another way to look at it is if Array#fetch_values was defined by a gem (e.g. by activesupport), then everyone would expect:

/path/to/activesupport/some/file.rb:211:in 'Array#fetch': index 42 outside of array bounds: -1...1 (IndexError)
        from /path/to/activesupport/some/file.rb:211:in 'block in Array#fetch_values'
        from /path/to/activesupport/some/file.rb:211:in 'Array#map!'
        from /path/to/activesupport/some/file.rb:211:in 'Array#fetch_values'
        from -e:1:in '<main>'

So the fact it's <internal:array>:211 instead of /path/to/activesupport/some/file.rb:211 in the description seems a very small expected difference, it's just defined "in a core library Ruby file" vs "in a gem Ruby file".

I think this argument is strong enough on its own to not change stacktraces until a concrete problem is reported with the current core library stacktraces.


Maybe the core library Ruby paths could be a bit nicer like <internal:/path/to/array.rb>:211 then potentially editors could just open that.
It would be pretty cool if users could just see the implementation of some core library methods defined in Ruby.
FWIW TruffleRuby uses <internal:core> core/array.rb:211 which I think is nice and clear:

$ ruby -e '1.tap { raise "foo" }'
-e:1:in `block in <main>': foo (RuntimeError)
	from <internal:core> core/kernel.rb:520:in `tap'
	from -e:1:in `<main>'

We could ship these core files with CRuby to make it easier to understand what's going on.
We'd add a comment at the top of the file explaining modifying the file would have no effect as the source is not used, only its bytecode.

Updated by ioquatix (Samuel Williams) 23 days ago · Edited

I also agree this is not a bug and the expanded stack trace is good. But let me talk about my experience with Objective-C.

A long time ago, I created Objective-C applications with Apple's Cocoa framework. It uses "delegate" pattern extensively which are essentially callbacks wrapped in objects with a well defined interface.

In particular, Apple's frameworks were sometimes buggy, but using a debugger, all the intermediate stack entries are hidden. So a stack trace (or thread backtrace) would show something like:

<your delegate implementation>
<hidden internal function call>
<hidden internal function call>
<hidden internal function call>
<possibly user code>

This made debugging EXTREMELY difficult because it was impossible to figure out what the expectations of the <hidden internal function call> were - no way to correlate it back to code or even inspect what was going on.

Now, back to Ruby. I greatly prefer visibility in the stack trace. If something goes wrong (usual cause of exception with backtrace), even if it was the user code that made a mistake (e.g. the implementation of hash or something invoked by the internal code), it can be extremely helpful if the user can easily find that code in order to read it and debug their own code.

This difficulty with Objective-C was one of the reasons I eventually stopped using it - the frameworks were too opaque and it made debugging extremely painful.

Updated by mame (Yusuke Endoh) 13 days ago

I reconfirmed this with @matz (Yukihiro Matsumoto) during the dev meeting. He reiterated that <internal: should not be displayed.

To address this issue, the following approach is proposed:

  1. Merge the consecutive <internal: frames into a single frame.
  2. Use the method name of the bottom-most (closest to the root) frame for the merged frame.
  3. Set the location (filename:lineno) of the merged frame to that of the first Ruby frame below the consecutive <internal: frames.

For example, consider the following frames:

...
        from bar.rb:1:in 'Bar#bar'
        from <internal:array>:111:in '...'
        from <internal:array>:111:in '...'
        from <internal:array>:111:in '...'
        from <internal:array>:111:in 'Array#fetch_values'
        from foo.rb:1:in 'Foo#foo'
...

When creating a backtrace object (such as when creating an exception object, calling Kernel#caller_locations, etc.), this should be condensed to:

...
        from bar.rb:1:in 'Bar#bar'
        from foo.rb:1:in 'Array#fetch_values'
        from foo.rb:1:in 'Foo#foo'
...

(Array#fetch_values is just an example; other built-in methods should be handled in the same way.)

Updated by byroot (Jean Boussier) 13 days ago

He reiterated that <internal: should not be displayed.

Should it even exist then? Because a "simple" solution would be simply make Primitive.attr! :c_trace the default rather than a opt-in thing.

Updated by matz (Yukihiro Matsumoto) 13 days ago

It should not be displayed. I don't care much if it exists. It should be decided according to the demand and implementation easiness.

Matz.

Updated by Eregon (Benoit Daloze) 13 days ago

matz (Yukihiro Matsumoto) wrote in #note-13:

It should not be displayed. I don't care much if it exists. It should be decided according to the demand and implementation easiness.

FWIW, I am pretty sure TruffleRuby will never do that change.
It would hide crucial information for both users and implementation developers, as I detailed above.
We tried it in TruffleRuby, it was bad for both users and devs, we learned from it.
It's like hiding crucial debugging information from segfault reports, who would want that?

To be frank, I think it's shortsighted to do anything about this now.
The problem of hiding will naturally become more evident as more of the Ruby core library is defined in Ruby.

Primitive.attr! :c_trace can be used on Array#fetch_values, I don't really care about that specific one (except obviously we wouldn't hide it on TruffleRuby).
But in general I think it's clearly a mistake to hide those backtrace entries which are helpful to understand behavior.
It's like silently swallowing exceptions, it wastes tons of time in debugging for little value.

It's also not the Ruby VM's job to hide frames, it should show all of them to ease debugging.
Test frameworks might choose to filter stacktraces or display them differently, that's fine, and it's easy.
All the test frameworks that I know and filter also provide an option to opt out of that filtering, proving that it's sometimes necessary to have the full stacktrace.

There are no practical problems with it (just people learning about it/getting used to it because it was less common).
In fact <internal exists since at least Ruby 2.3, probably even before.
A common example, from Ruby 3.0 is Kernel#tap (AFAIK nobody ever complained or got confused about it):

$ ruby -e 'tap { raise "oops" }'  
-e:1:in `block in <main>': oops (RuntimeError)
	from <internal:kernel>:90:in `tap'
	from -e:1:in `<main>'

The suggested change would result in:

$ ruby -e 'tap { raise "oops" }'
-e:1:in `block in <main>': oops (RuntimeError)
	from -e:1:in `tap'
	from -e:1:in `<main>'

which is no better and would make debugging far worse if there are multiple <internal frames.


I'll give another example where the proposed change hurts understandability:
Suppose Method#call is defined in Ruby code, then this change proposes to go from:

...
        from bar.rb:1:in 'Bar#bar'
        from foo.rb:1:in 'block in Foo#foo'
        from <internal:kernel>:90:in 'Kernel#tap'
        from <internal:method>:111:in 'Method#call'
        from foo.rb:1:in 'Foo#foo'
...

to

...
        from bar.rb:1:in 'Bar#bar'
        from foo.rb:1:in 'block in Foo#foo'
        from <internal:method>:111:in 'Method#call'
        from foo.rb:1:in 'Foo#foo'
...

So now Method#call can call a block directly?
No, it's just the stacktrace betraying you by hiding crucial information.
(there are more examples which don't even need methods to move from C to Ruby in previous comment https://bugs.ruby-lang.org/issues/20968#note-6)

Updated by mame (Yusuke Endoh) 12 days ago · Edited

So now Method#call can directly invoke a block?
No, it's just the stack trace deceiving you by hiding crucial details.

At the dev meeting, @ko1 (Koichi Sasada) also raised this issue. He suggested that, for this reason, we should stop writing in Ruby and revert to C. However, I expect @k0kubun (Takashi Kokubun) to oppose this change due to YJIT’s performance benefits.

The root of the problem lies in the distinction between different types of function calls: standard C function calls do not appear in the Ruby backtrace, whereas calls made via rb_funcall, etc., do.

I proposed that the Ruby method should maintain this distinction: normal method calls should not appear in the backtrace, and if a Ruby method is invoked explicitly using Primitive.rb_funcall or something, it should be included in the backtrace.
However, a decision on my proposal was postponed until we could confirm whether there are sufficient real-world cases where naive hiding would cause issues.

In any case, it was reaffirmed that matz strongly prefers that <internal: not be displayed. Given this, implementation costs and some runtime overhead are considered acceptable. If no one else takes it on, I will implement it myself (probably after RubyKaigi).

Updated by Eregon (Benoit Daloze) 12 days ago

mame (Yusuke Endoh) wrote in #note-15:

In any case, it was reaffirmed that matz strongly prefers that <internal: not be displayed.

@matz (Yukihiro Matsumoto) Is that because there is the word "internal" in there and so it sounds like exposing internals?
How about <core: or <core-library: then? That would make it clear those are core library methods.

As I explained in my previous reply <internal: has been there since many years (since gem_prelude.rb/prelude.rb exist) and has caused no real issues (just a few incorrect assumptions in gems which have been fixed since).
If it wasn't for this issue, we would probably not even discuss this, and most (all I think) people on this issue already agreed it is not a bug and not a problem in practice.

If it's about consistency of C-defined vs Ruby-defined core methods in the backtrace, we could maybe go the other way around, @jeremyevans0 (Jeremy Evans) said earlier in the thread:

If we could show the file and line for C functions, that would be useful for debugging. I assume the only reason we don't is that doing so is not feasible.

It should be feasible with a C preprocessor macro using __FILE__ and __LINE__.
In fact, I think it's confusing and misleading that methods defined in C report that they are defined in the caller Ruby file (which is obviously incorrect, they are not defined there).
Detailed in the 2nd part of this comment after the horizontal line.

I think that illustrates clearly that people got used to this "confusing/misleading way to report the stacktrace for C-defined methods", and so they are surprised to see something else for Ruby-defined core methods.
But I believe it is just a matter of getting used to it. Passed the initial "surprise" it makes total sense because it's no different than a regular method defined in Ruby code (except the file prefix).

This comment demonstrates that the current stacktrace for Array#fetch_values is very consistent as if the method was defined in a Ruby file in some gem or so.
And on the contrary, changing stacktraces as proposed would introduce a 3rd kind of entry in the backtrace, which I think is evident it will cause more confusion, due to hiding crucial information in at least some cases.


BTW <internal: is used for filtering in Kernel#warn and in https://github.com/rubygems/rubygems/blob/7ab9c82b1b01614b052a57ccb49370cea9be17e9/lib/rubygems.rb#L1404-L1407
It's also intentional that Kernel#warn filters out core methods, since those should definitely not emit warnings (or if they do the cause is probably the caller, if not then it's a CRuby bug).
So <internal: is a useful concept besides just the core library.
In fact a quick search shows it's used in various gem, a well-known example is Sinatra.
So removing <internal: in CRuby would likely cause some incompatibility.

Actions

Also available in: Atom PDF

Like0
Like1Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0Like0