Timebomb Exceptions: Hangs when getting NameError/NoMethodError and an expensive #inspect

[JoshCheek]

Example

class Something
  def inspect
    start = Time.now.strftime('%S').to_i
    sleep(5)
    seconds = Time.now.strftime('%S').to_i - start
    seconds += 60 if seconds < 0
    "#<Something that took #{seconds} seconds to inspect>"
  end
end

describe 'Example of how confusing this could be' do
  example 'tests chugging along happily before the issue' do
    expect(true).to be_truthy
  end

  it "Here, we raise a Name or NoMethodError, whose #message depends on Something#inspect... "\
     "but Ruby doesn't perform the inspect right now, it calls it later when the formatter "\
     "tries to print the error message as part of the failure. Making it very difficult to "\
     "figure out where it happened, and mak it look like an RSpec issue" do
    Something.new.notamethod
  end

  example 'tests keep going just fine past the source of the issue' do
    expect(true).to be_truthy
  end
end

Explanation of what is actually happening

Unlike if you or I were to create a NameError / NoMethodError, when the interpreter does it, it uses some sort of crazy ass black magic when it generates the "String" for the error's message (I think I can go into that in more detail if anyone actually cares). This "String" is lazy and doesn't get evaluated until you ask for it. Since it includes the inspection of the receiver that the method was called on (e.g. "zomg".notamethod # ~> NoMethodError: undefined methodnotamethod' for "zomg":String`), if the receiver's inspect method does anything crazy, it will trip up whatever code is looking at the message.

Crazy in this case is very common for certain use cases, e.g. the default inspect will show the inspection of the instance variables, so any object with a huge amount of data in an instance variable will have an incredibly expensive inspect method. If anything then calls a nonexistent method on that object, it will raise one of these Timebomb Exceptions.

When does the bomb finally go off? When RSpec tries to print the exception message out. It looks like the exception is stored on the Example (code) which is accessed by the FailedExampleNotification (code)This accessing doesn't happen until later in the :dump_failures event, which ultimately invokes failure_lines (code). And suddenly everything just halts.

In my example, it's due to a sleep statement, in the real-world, it's doing some unintentional big calculation, so the cpu is also pegged to 100%, and memory is ballooning.

What to do about it?

It's not too hard to check for (a timeout on exception.message), so it might be worth notifying the user that they have this issue.

At the very least, if the message was accessed as soon as it was raised, then the problem would occur near to the example that exposed the issue.

Why care?

This is the kind of thing that my students are hitting (I teach at @turingschool). They are not capable of this kind of debugging, it just shuts them down, turns them off to testing, and demotivates them. I need to be able to tell them what to do. And sure, I can narrow it down and figure out that they should override #inspect in 20 to 30 minutes, if it's early enough in the day, but that's a lot of time, I still can't tell them why, and I still have to do that every time an issue like this arises.

This debugging cost is spread out to anyone having this issue, not just me here and now. It's the sort of thing that I imagine many people have actually hit, but couldn't figure out why it was happening, wasted a lot of time, and ultimately just fixed the issue (temporarily via the NameError/NoMethodError or permanently via overriding inspect). Imagine if they hit it in a 4 hour test suite that only runs on CI, because their unit tests didn't uncover the issue. Now CI takes 6 hours, everyone goes home, running the failed integration test takes an hour (they're used to waiting, they don't realize something is wrong). The feedback cycle is slow enough already to mask that it has just ground to a halt. Something they could have fixed in an hour or two winds up taking over a day.

[JoshCheek]

Here's a short example that illustrates the problem independent of RSpec.

def self.inspect
  sleep 5
  'MAIN'
end

ex = notamethod rescue $!

print "The Exception was: " # immediately get to here
p ex.message # then suddenly nothing! In RSpec, this line happens way after the fact when printing failures

[myronmarston]

In 7+ years of doing ruby I've never seen inspect take any noticeable amount of time. What are your objects like that do so much calculation in inspect?

Anyhow, I can see this tripping up new users. The behavior depends on what formatter you use. The Fivemat formatter, for example, prints failures as they happen so you would get the stalling affect immediately after the example that caused this, before the next example begins.

I need to think some more about your suggested solutions.

It's not too hard to check for (a timeout on exception.message), so it might be worth notifying the user that they have this issue.

Do you mean that we should do something like this?

def exception_message_from(exception)
  Timeout.timeout do
    exception.message
  end
rescue Timeout::Error
  "(Timeout occurred while fetching the message from an #{exception.class.name} instance)"
end

A few concerns/issues I have with this approach:

• "Ruby's Thread#raise, Thread#kill, and the timeout.rb standard library based on them are inherently broken and should not be used for any purpose." (source)
• We try to avoid having RSpec load and use parts of the standard lib unless we really, really need them to minimize the chance of users forgetting to load parts of the standard lib they use but having green tests (due to RSpec internally loading that part of stdlib) and releasing a gem or deploying code that's broken due to the missing require.
• There are many, many other places RSpec calls method on user objects and it could hit this issue. Why treat Exception#message as special?

At the very least, if the message was accessed as soon as it was raised, then the problem would occur near to the example that exposed the issue.

I have fewer concerns about this. My thoughts here:

• Calling Exception#message, just to do nothing with it, feels wrong.
• If accessing Exception#message is slow, this only compounds the issue, as it adds the slowness to the test suite runtime twice.
• Again, there are many other places the RSpec calls into user code that could hit this issue. I don't really want to start down the road of whack-a-mole where we treat one place as special due to this issue, and then later we get asked to do it in another place, etc.

I wish there was a holistic way to solve this across the board but I can't think of one :(.

Overall, ruby gives you a lot of rope to hang yourself and I don't think it's RSpec's job to protect you from that -- so I'm leaning towards doing nothing, but I do empathize with the experience of your students and I could still be convinced otherwise.

[JonRowe]

I kinda feel like the objects inspect methods should be fixed here, as Myron says there are many other places where this sort of thing can happen and cause confusion, and I'm really keen to keep extra parts of the standard library out of our code.

Out of curiosity, what are the real world objects you've encountered this on?

One thing we could consider @myronmarston is to use custom inspect code in our default formatters so that the symptom doesn't happen here, but it wouldn't fix the problem just circumvent us being affected.

[myronmarston]

@tomstuart I wonder if you have some thoughts here? I seem to remember you commenting on other issues about teaching RSpec to new users -- has this tripped any of your students up before?

[myronmarston]

One thing we could consider @myronmarston is to use custom inspect code in our default formatters so that the symptom doesn't happen here, but it wouldn't fix the problem just circumvent us being affected.

Bypassing the inspect the user has written for their object would be extremely surprising behavior (even though ruby itself does this in some situations).

[JoshCheek]

In 7+ years of doing ruby I've never seen inspect take any noticeable amount of time. What are your objects like that do so much calculation in inspect?

Yeah, I don't know whether I've hit it or not, either (I wouldn't have known why it happened, so wouldn't have attributed it to that). The objects are essentially a large in-memory graph. They're basically building an in-memory ORM, with the intent of providing familiarity with the concepts and interfaces for when they get to ActiveRecord.

The inspect method was not considered at all, which means it gets Kernel#inspect, which inspects every instance variable: all the other items in the graph. Under these conditions, the inspect grows very rapidly (I think a factorial growth). Here is an example:

class HasOthers
  attr_accessor :others
end

a = HasOthers.new
b = HasOthers.new
a.others = [a, b]
b.others = [a, b]
a.inspect.size # => 183

a = HasOthers.new
b = HasOthers.new
c = HasOthers.new
a.others = [a, b, c]
b.others = [a, b, c]
c.others = [a, b, c]
a.inspect.size # => 583

a = HasOthers.new
b = HasOthers.new
c = HasOthers.new
d = HasOthers.new
a.others = [a, b, c, d]
b.others = [a, b, c, d]
c.others = [a, b, c, d]
d.others = [a, b, c, d]
a.inspect.size # => 2353

a = HasOthers.new
b = HasOthers.new
c = HasOthers.new
d = HasOthers.new
e = HasOthers.new
a.others = [a, b, c, d, e]
b.others = [a, b, c, d, e]
c.others = [a, b, c, d, e]
d.others = [a, b, c, d, e]
e.others = [a, b, c, d, e]
a.inspect.size # => 11733

• "Ruby's Thread#raise, Thread#kill, and the timeout.rb standard library based on them are inherently broken and should not be used for any purpose." (source)
• We try to avoid having RSpec load and use parts of the standard lib unless we really, really need them to minimize the chance of users forgetting to load parts of the standard lib they use but having green tests (due to RSpec internally loading that part of stdlib) and releasing a gem or deploying code that's broken due to the missing require.

Good points.

• There are many, many other places RSpec calls method on user objects and it could hit this issue. Why treat Exception#message as special?

I'm not sure what your other examples are, but this hides until after all all the tests have been run and the failures are printing out. RSpec just stops in the middle of printing the failure messages. The source of the problem happened way back somewhere in the middle of one of the tests. If it was any other type of exception, everything would be fine. But this one particular type of exception is does crazy magic that leaks out sometimes.

Because of where and how it shows up, a user has very little ability to reason about what the problem is or how to fix it. Because it's printing messages, they do, at least have a reasonable idea where to start looking at their code, but due to context, I would have assumed it was a problem with RSpec, except that I know RSpec is well written, tested, and maintained.

Calling Exception#message, just to do nothing with it, feels wrong.

Side effects, man :P

[tomstuart]

@myronmarston Sorry, I’ve never seen this happen before. As you say, I haven’t been in a situation where #inspect is expensive.

[JoshCheek]

One thing we could consider @myronmarston is to use custom inspect code in our default formatters so that the symptom doesn't happen here, but it wouldn't fix the problem just circumvent us being affected.

The formatter isn't at fault, it is a NameError/NoMethodError raised by the interpreter that does the inspect... but not until the message is asked for.

Bypassing the inspect the user has written for their object would be extremely surprising behavior (even though ruby itself does this in some situations).

I'd rather not have this fixed than get Kernel#inspect overridden. Some functionality somewhere surely depends on it, and it would surprise me a lot.

[JonRowe]

You're teaching your students to do something fairly non standard, actually building an in memory ORM with a large amount of coupled objects, given the edge case nature of this, perhaps it would be advisable to teach them about inspect.

[myronmarston]

I wonder if MRI's maintainers might be amenable to changing NameError so that it protects against this internally?

[JonRowe]

Anyone feel like opening a Ruby ticket?

[myronmarston]

BTW, @JoshCheek, thanks for the link to the article on NameError::message -- that's an interesting tidbit I never knew about!

[JoshCheek]

You're teaching your students to do something fairly non standard, actually building an in memory ORM with a large amount of coupled objects, given the edge case nature of this, perhaps it would be advisable to teach them about inspect.

Yeah, it's hard for me to know. I feel like moderately large object graphs can't be that non-standard. E.g. a static website builder would probably wind up doing something like this.

And knowing about inspect wouldn't inherently prevent this (I do, and it took me a long time to figure it out).

Anyone feel like opening a Ruby ticket?

I'll set aside a few hours next week and try to come up with something.

BTW, @JoshCheek, thanks for the link to the article on NameError::message -- that's an interesting tidbit I never knew about!

NP, that nuance has actually bitten me more than once now >.< 1, 2

[fables-tales]

Based on reading this I find myself struggling to see any correct action that RSpec could take to help with this problem. I don't think it's ideal to timeout on inspecting objects that are user provided. Some users may be happy to wait for a while for their long expects to run in weird circumstances (one might be a remote database and an activerecord object, for example).

I think maybe this should be a ruby issue, but I can't see any specific action that RSpec should take here.

@myronmarston @JonRowe do you think this should be closed?

[myronmarston]

@myronmarston @JonRowe do you think this should be closed?

Yep.