splitwise/super_diff

RSpec hanging when matching on http response

tomchipchase opened this issue · 14 comments

tomchipchase commented

We've seen an issue where in a rails request spec we have something like this:

it "returns a failure" do
  post some_path(**args)
  expect(response).to be_created
end

In cases where the spec would fail, it seems to hang forever (I'm not sure if it would eventually complete if I left it, but it hits our CI pipeline timeout limit of 15 minutes).

I've managed to trace it to a method within super_diff when its trying to report the failure, but I've not found the root cause.

We're using version super_diff 0.9.0, with rspec 3.11.0 (and rails 7.0.4). (I can provide our Gemfile.lock if that would be useful).

If anyone else comes across this with the same problem, we've worked around this by using have_http_status(:created) instead.

jsugarman commented

Exactly the same problem and solution. the use of be_ predicates seems to be the trigger but only when the test would fail

expect(response).to be_successful
=> passes

expect(response).not_to be_successful
=> hangs
tradiff commented

We are experiencing this as well. It appears to be a problem with trying to inspect the ActionDispatch::TestResponse. It goes into infinite recursions which the RecursionGuard doesn't seem to detect. Another way to reproduce the infinite recursion, in a request spec:

SuperDiff.inspect_object(response, as_lines: false)

If it helps any, I found that rspec had the same issue with this object, and they fixed it with this rails PR.

There's another bit of a hacky fix by changing the RecursionGuard. In this method, if I keep a counter, and guard against that counter hitting too high of a value, we can break out of the infinite loop. Proof of concept code:

def self.guarding_recursion_of(*objects, &block)
  Thread.current["recursion_counter"] ||= 0 
  Thread.current["recursion_counter"] = Thread.current["recursion_counter"] + 1

  already_seen_objects, first_seen_objects = objects.partition do |object|
    !SuperDiff.primitive?(object) && (Thread.current["recursion_counter"] > 1000 || already_seen?(object))
  end

# rest of the method is unchanged
mcmire commented

Ah, thanks @travatomic, that's helpful. I'll take a look at the Rails fix — maybe inspect_object can look for a ActionDispatch::TestResponse and monkeypatch it on the fly so that to_a returns something else. It would be educational to start by tracing it and finding which method it keeps recursing on, though. As for your recursion counter idea, that would be good in general as well, in case we run into any other situations like this in the future. In any case I'm a bit busy at the moment but will hopefully have time to look at this shortly.

  • 👀1
tradiff commented

For anyone else having this problem: I have two solutions. Both solutions work in the user code and don't need a change to the gem. My company is probably going with option 1.

Solution 1:

Monkey patch the TestResponse. Add this to the bottom of spec/rails_helper.rb.

class ActionDispatch::TestResponse
  def attributes_for_super_diff
    {
      status: status,
      # you could also add headers or body here if those are meaningful to you.
    }
  end
end

Solution 2:

Create a new inspection tree builder. Make the following new file at spec/support/super_diff/action_dispatch_test_response_inspection_tree_builder.rb

class ActionDispatchTestResponseInspectionTreeBuilder < SuperDiff::ObjectInspection::InspectionTreeBuilders::Base
  def self.applies_to?(value)
    value.is_a?(ActionDispatch::TestResponse)
  end

  def call
    SuperDiff::ObjectInspection::InspectionTree.new do
      as_lines_when_rendering_to_lines(collection_bookend: :open) do
        add_text { |object| "#<#{object.class} " }

        when_rendering_to_lines { add_text "{" }
      end

      nested do |object|
        response_hash = {
          status: object.status,
        }
        insert_hash_inspection_of(response_hash)
      end

      as_lines_when_rendering_to_lines(collection_bookend: :close) do
        when_rendering_to_lines { add_text "}" }

        add_text ">"
      end
    end
  end
end

Then change your SuperDiff configuration to use the new inspection tree builder:

SuperDiff.configure do |config|
  config.add_extra_inspection_tree_builder_classes(
    ActionDispatchTestResponseInspectionTreeBuilder
  )
end

Output

With either option, the output looks something like this:

Failures:

  1) Api::UsersController GET /api/user/settings returns not found
     Failure/Error: expect(response).to be_not_found

                            Expected #<ActionDispatch::TestResponse status: 200>
       to return a truthy result for not_found? or not_founds?
     # ./spec/requests/api/users_spec.rb:25:in `block (3 levels) in <top (required)>'

@mcmire do you think either one of these is suitable to add to the gem?

  • 👍2
panozzaj commented

I ran into this today using gem version 0.10.0.

Will add one more workaround:

      expect(response.successful?).to be true

It's a little less fancy, but seems to not have issues when the test fails.

By the way, I am not getting "hanging" behavior. For the code below:

      expect(response).to be_successful?

I just get an error like:

     NoMethodError:
       undefined method `keys' for nil:NilClass
     # /Users/anthony/.rvm/gems/ruby-3.2.2@my-project/gems/super_diff-0.10.0/lib/super_diff/object_inspection/inspection_tree.rb:72:in `insert_hash_inspection_of'
panozzaj commented

Also please note that #159 (comment) seems to reference the same issue, in case that is helpful.

serogers commented

This just bit me and took some time to debug. This issue has been around a while. @mcmire do you have any thoughts about applying a fix to the gem?

nnat425 commented

Bumping this as well, my company is facing this issue as well. A fix to the gem would be great.

mcmire commented

I agree this has been around a while — sorry for the delay on this. I'll try to look at this soon!

jas14 commented

@panozzaj , sorry for the delay. The NoMethodError issue you're describing was also described in #199 and should be solved by #202, which was included in v0.11.0. Feel free to comment on that issue if you're still encountering the problem!

Re: hanging on the HTTP response – as mentioned in #204, it would be good to find a way to avoid prematurely calculating the actual text when it's not used. But that won't solve the problem when it is used.

Since this gem is designed to support Rails and rspec-rails, and already supports active_support and active_record, I would accept a PR that added an abbreviated ActionDispatch::TestResponse inspection tree builder. To support as wide a range as possible, we should default to including the full HTTP response triplet (status, headers, body) in the inspection – folks can always abbreviate further with a custom inspector if desired.

b-loyola commented

The issue seems to be because of circular references in the object in question, so it seems like we could just wrap the compare in Base with a circular reference protection?

E.g.:

# in SuperDiff::OperationTreeBuilders::Base

def compare(expected, actual)
  RecursionGuard.guarding_recursion_of(expected, actual) do |already_seen|
    next if already_seen

    OperationTreeBuilders::Main.call(
      expected: expected,
      actual: actual,
      all_or_nothing: false
    )
  end
end
b-loyola commented

Actually the problem here seems to be in SuperDiff::ObjectInspection::InspectionTreeBuilders::DefaultObject when building the InspectionTree. This is stack trace I'm seeing when it goes into recursion there:

attr_extras-7.1.0/lib/attr_extras/explicit.rb:73:in `public_send'
attr_extras-7.1.0/lib/attr_extras/explicit.rb:73:in `block (2 levels) in static_facade'
super_diff-0.11.0/lib/super_diff/object_inspection/inspection_tree_builders/main.rb:11:in `call'
attr_extras-7.1.0/lib/attr_extras/explicit.rb:73:in `public_send'
attr_extras-7.1.0/lib/attr_extras/explicit.rb:73:in `block (2 levels) in static_facade'
super_diff-0.11.0/lib/super_diff.rb:44:in `block in inspect_object'
super_diff-0.11.0/lib/super_diff/recursion_guard.rb:22:in `guarding_recursion_of'
super_diff-0.11.0/lib/super_diff.rb:42:in `inspect_object'
super_diff-0.11.0/lib/super_diff/object_inspection/nodes/inspection.rb:22:in `block in render_to_string'
super_diff-0.11.0/lib/super_diff/recursion_guard.rb:20:in `guarding_recursion_of'
super_diff-0.11.0/lib/super_diff/object_inspection/nodes/inspection.rb:16:in `render_to_string'
super_diff-0.11.0/lib/super_diff/object_inspection/inspection_tree.rb:29:in `block in render_to_string'
super_diff-0.11.0/lib/super_diff/object_inspection/inspection_tree.rb:28:in `each'
super_diff-0.11.0/lib/super_diff/object_inspection/inspection_tree.rb:28:in `reduce'
super_diff-0.11.0/lib/super_diff/object_inspection/inspection_tree.rb:28:in `render_to_string'
super_diff-0.11.0/lib/super_diff/object_inspection/nodes/base.rb:93:in `render_to_string_in_subtree'
super_diff-0.11.0/lib/super_diff/object_inspection/nodes/as_lines_when_rendering_to_lines.rb:30:in `render_to_string'
super_diff-0.11.0/lib/super_diff/object_inspection/inspection_tree.rb:29:in `block in render_to_string'
super_diff-0.11.0/lib/super_diff/object_inspection/inspection_tree.rb:28:in `each'
super_diff-0.11.0/lib/super_diff/object_inspection/inspection_tree.rb:28:in `reduce'
super_diff-0.11.0/lib/super_diff/object_inspection/inspection_tree.rb:28:in `render_to_string'
super_diff-0.11.0/lib/super_diff/object_inspection/nodes/base.rb:93:in `render_to_string_in_subtree'
super_diff-0.11.0/lib/super_diff/object_inspection/nodes/nesting.rb:14:in `render_to_string'
super_diff-0.11.0/lib/super_diff/object_inspection/inspection_tree.rb:29:in `block in render_to_string'
super_diff-0.11.0/lib/super_diff/object_inspection/inspection_tree.rb:28:in `each'
super_diff-0.11.0/lib/super_diff/object_inspection/inspection_tree.rb:28:in `reduce'
super_diff-0.11.0/lib/super_diff/object_inspection/inspection_tree.rb:28:in `render_to_string'
super_diff-0.11.0/lib/super_diff/object_inspection/nodes/base.rb:93:in `render_to_string_in_subtree'
super_diff-0.11.0/lib/super_diff/object_inspection/nodes/only_when.rb:21:in `render_to_string'
super_diff-0.11.0/lib/super_diff/object_inspection/inspection_tree.rb:29:in `block in render_to_string'
super_diff-0.11.0/lib/super_diff/object_inspection/inspection_tree.rb:28:in `each'
super_diff-0.11.0/lib/super_diff/object_inspection/inspection_tree.rb:28:in `reduce'
super_diff-0.11.0/lib/super_diff/object_inspection/inspection_tree.rb:28:in `render_to_string'
super_diff-0.11.0/lib/super_diff.rb:49:in `block in inspect_object'
super_diff-0.11.0/lib/super_diff/recursion_guard.rb:22:in `guarding_recursion_of'
super_diff-0.11.0/lib/super_diff.rb:42:in `inspect_object'
super_diff-0.11.0/lib/super_diff/rspec/monkey_patches.rb:298:in `format'
rspec-expectations-3.13.1/lib/rspec/matchers/composable.rb:83:in `description_of'
super_diff-0.11.0/lib/super_diff/rspec/augmented_matcher.rb:53:in `actual_for_matcher_text'
super_diff-0.11.0/lib/super_diff/rspec/augmented_matcher.rb:43:in `matcher_text_builder_args'
super_diff-0.11.0/lib/super_diff/rspec/augmented_matcher.rb:34:in `matcher_text_builder'
super_diff-0.11.0/lib/super_diff/rspec/augmented_matcher.rb:29:in `build_failure_message'
super_diff-0.11.0/lib/super_diff/rspec/augmented_matcher.rb:17:in `failure_message_when_negated'
super_diff-0.11.0/lib/super_diff/rspec/monkey_patches.rb:25:in `handle_failure'

The issue seems to disappear if the RecursionGuart is wrapped around this line from SuperDiff::ObjectInspection::InspectionTreeBuilders::DefaultObject

RecursionGuard.substituting_recursion_of(object) do
  t4.add_inspection_of object.instance_variable_get(name)
end
jas14 commented

Thanks for the investigation, @b-loyola ! I'm admittedly not 100% on inspection tree construction and rendering yet, but I believe the inspection tree builder is supposed to be lazy. The recursion guards should be more useful during rendering than during inspection tree construction.

I'll take a look at ActionDispatch::TestResponse more specifically. It would be great if we could boil that down to a minimal repro case.

jas14 commented

On further investigation with a couple production apps, I've come to the conclusion that this is not infinite recursion: it's deep-inspecting ActionDispatch::Routing::RouteSet, a structure with tons of references to other complex structures. This is nested in:

  • ActionDispatch::TestResponse
    • @request
      • @env['action_dispatch.routes']

The Rails code itself aliases ActionDispatch::Routing::RouteSet#inspect to #to_s, specifically citing the large tree.

I added an inspection tree builder for ActionDispatch::Routing::RouteSet to test this theory. SuperDiff.inspect_object(response, as_lines: false) terminated in a couple seconds instead of hanging indefinitely (though it still rendered a string over 233K characters long!)

Adding a custom inspection of ActionDispatch::Request objects would prune the inspection tree even more. Rails also customizes inspection for ActionDispatch::Request, showing only the request method, original URL, and originating IP, so I think this would still be pretty reasonable. (I tested this out again and it shortened the output to "only" ~55K characters, which is very close to the length of the direct #inspect output on the original ActionDispatch::TestResponse object.)