Add test to reproduce bug with Warden test helper #930

toddmazierski · 2015-02-17T22:10:18Z

When using the login_as Warden test helper, it depends whether or not the API class under test is evaluated before or after the tests.

Given that this bug first appeared in v0.10.0, my current theory is the use of deep_dup is responsible. Warden persists registered hooks in instance variables. When an API class is evaluated before the tests, the hooks are registered after duplication takes place, so the original object is left with an empty array of hooks.

Any help or suggestions are most appreciated. Thanks for this great library! 😄

When using the `login_as` Warden test helper, it depends whether or not the API class under test is evaluated *before* or *after* the tests. Given that this bug first appeared in v0.10.0, my current theory is the use of `deep_dup` is responsible. Warden persists registered hooks in instance variables (ex. http://git.io/NhKG). When an API class is evaluated *before* the tests, the hooks are registered *after* duplication takes place, so the original object is left with an empty array of hooks.

toddmazierski · 2015-02-17T22:39:37Z

Unfortunately, this test only fails when run in isolation. My apologies!

bundle exec rspec spec/grape/warden_test_helpers_spec.rb

Below is the expected output:

Warden::Test::Helpers
  #login_as
    API evaluated before tests
      logs in (FAILED - 1)
    API evaluated after tests
      logs in

Failures:

  1) Warden::Test::Helpers#login_as API evaluated before tests logs in
     Failure/Error: expect(last_response).to be_ok
       expected `#<Rack::MockResponse:0x007fad7c762b28 @original_headers={}, @errors="", @body_string=nil, @status=401, @header={"Content-Length"=>"0"}, @chunked=false, @writer=#<Proc:0x007fad7c7629e8@/Users/todd/code/grape/vendor/bundle/gems/rack-1.6.0/lib/rack/response.rb:30 (lambda)>, @block=nil, @length=0, @body=[""]>.ok?` to return true, got false
     # ./spec/grape/warden_test_helpers_spec.rb:26:in `block (4 levels) in <top (required)>'

Finished in 0.06702 seconds (files took 0.54087 seconds to load)
2 examples, 1 failure

Failed examples:

rspec ./spec/grape/warden_test_helpers_spec.rb:24 # Warden::Test::Helpers#login_as API evaluated before tests logs in

dblock · 2015-02-20T17:55:30Z

I would dig into Warden next to find out what causes the 401 and what's different at that place when it fails vs. succeeds.

toddmazierski · 2015-02-20T18:09:52Z

Hi, @dblock! Thanks for looking into this.

I believe it's related to the state of the @_on_request instance variable in Warden::Hooks and duplication, but I'm not entirely sure I understand what's going on. If you add this monkey-patch immediately below require 'spec_helper' in the attached file:

# spec/grape/warden_test_helpers_spec.rb
require 'spec_helper'

module Warden
  module Hooks
    def dup
      _on_request # before duplicating, initialize @_on_request 
      super
    end
  end
end

…both tests pass:

bundle exec rspec spec/grape/warden_test_helpers_spec.rb

Warden::Test::Helpers
  #login_as
    API evaluated before tests
      logs in
    API evaluated after tests
      logs in

Finished in 0.12192 seconds (files took 0.57675 seconds to load)
2 examples, 0 failures

dblock · 2015-02-20T18:16:06Z

I see. Generally using locals there is assuming that the scope used for the request is the same one after initialization, but that's no longer the case in Grape. I would change this to an attr_accessible or something like that in the Warden test helper - if anything a PR into Warden that gets rid of it would be a start, we can see if they would take it (code would be cleaner so I don't see why not).

toddmazierski · 2015-02-20T18:25:21Z

a PR into Warden that gets rid of it would be a start

Cool! Happy to try to fix this upstream in Warden, but I'm having trouble understanding the root cause (or the suggested solution), my apologies. Is this the attr_accessible you're referring to, and is the suggested change in Warden::Hooks? Any code examples you can provide would be most appreciated.

toddmazierski · 2015-02-23T19:33:10Z

Just wanted to share a one-liner alternative to the monkey-patch mentioned above:

# spec/grape/warden_test_helpers_spec.rb
require 'spec_helper'

Warden::Manager._on_request

I'm still a little confused about what to try to merge upstream in Warden. Any assistance would be most appreciated! Thanks in advance.

dblock · 2015-03-01T16:22:47Z

I think something that doesn't rely on instance variables. Ultimately the issue is that after a deep_dup those don't survive, right? Or the scope of instance variables changes when you manipulate the dup?

toddmazierski · 2015-03-01T22:26:36Z

Hi @dblock, I think there are two distinct "bugs" at work here related to deep_dup. Here are my findings:

Bug 1: why the first test fails

Summary

The hook is registered on Warden::Manager, but the callbacks are executed on a deep_dup of it.

Example

Warden::Manager is duplicated to object_id 24661960
The test hook login_as is registered on the original Warden::Manager (object_id 33780040)
However, the callbacks are executed on the duplicate (object_id 24661960), so nothing happens—401 Unauthorized is returned

[TEST] Evaluating APIEvaluatedBeforeTests
[WARDEN] Warden::Manager(33780040).deep_dup => Warden::Manager(24661960) / @_on_request(4)

Warden::Test::Helpers
  #login_as
    API evaluated before tests
[TEST] Warden::Manager(33780040) login_as(:user) / @_on_request(31354740)
[WARDEN] Warden::Manager(33780040).deep_dup => Warden::Manager(23554060) / @_on_request(31354740)
[WARDEN] Warden::Manager(33780040).deep_dup => Warden::Manager(23575960) / @_on_request(31354740)
[WARDEN] Warden::Manager(24661960).run_callbacks / @_on_request(4)
      logs in (FAILED - 1)

Bug 2: why the second test passes

Summary

The hook is registered on Warden::Manager, and the callbacks are executed on a deep_dup of it, but the original and the duplicates share state

Example

Warden::Manager is duplicated to object_id 25832060
The test hook login_as is registered on the original Warden::Manager (object_id 28428300)
The callbacks are executed on the duplicate (object_id 25832060), but surprisingly—200 OK is returned

Warden::Test::Helpers
  #login_as
    API evaluated after tests
[TEST] Warden::Manager(28428300) login_as(:user) / @_on_request(25796340)
[TEST] Evaluating :api_evaluated_after_tests
[WARDEN] Warden::Manager(28428300).deep_dup => Warden::Manager(25832060) / @_on_request(25796340)
[WARDEN] Warden::Manager(28428300).deep_dup => Warden::Manager(20576700) / @_on_request(25796340)
[WARDEN] Warden::Manager(28428300).deep_dup => Warden::Manager(20581980) / @_on_request(25796340)
[WARDEN] Warden::Manager(25832060).run_callbacks / @_on_request(25796340)
      logs in

Sharing state

I was surprised by some "spooky action at a distance" behavior of Object#deep_dup, a cause of bug №2:

require 'active_support'
require 'active_support/core_ext'

class Atom
  attr_accessor :electrons
end

hydrogen = Atom.new
hydrogen.electrons = ['-']
hydrogen.electrons.count
# => 1

helium = hydrogen.deep_dup
helium.electrons << '-'
helium.electrons.count
# => 2

hydrogen.electrons.count
# => 2                        <-- ಠ_ಠ

Solutions

Not `duplicable?`

One solution seems simple enough—flag Warden::Manager as a class that cannot be duplicated:

manager = Warden::Manager
def manager.duplicable?; false; end

I'm uncertain as to why Grape needs to deep_dup, so I'm not sure what the implications are of this.

Patch Warden

Another solution may be to patch Warden to not persist its test hooks in instance variables, but I'm not sure:

What would be preferable
How this could be justified to Warden's maintainers

Thanks for your help!

dblock · 2015-03-02T17:15:10Z

This is some very good research!

I think we should fix this in Grape, but white-listing things that need to be deep_dup'ed, which is really about settings and stacks of things in Grape. I would start by defaulting things to not be actually dup-ed, and then white-listing those that do by examining spec failures. I would merge anything that has all the existing grape tests passing along these lines.

dblock · 2015-03-04T11:30:56Z

@toddmazierski You should give my suggestion a try, I'll do my best to help.

toddmazierski · 2015-03-04T15:48:08Z

Sounds good, @dblock! I'll give it a go. Thanks!

@dblock

@dblock's suggestion (http://git.io/vvmJj) was instead of `deep_dup`ing _all_ settings by default, to only `deep_dup` settings on a whitelist. However, after implementing this, at least according to the tests, there doesn't appear to be **any** settings need to be `deep_dup`ed. Instead, a shallow clone (a `dup`) looks to be sufficient. I've confirmed that with this change, the test `warden_test_helpers_spec.rb` passes in the suite and in isolation (i.e. the bug described is fixed).

toddmazierski · 2015-04-12T22:01:16Z

Hi @dblock, please let me know what you think about 009be00! Thank you.

dblock · 2015-04-12T23:35:05Z

The code looks ok, if no tests break you can PR it.

dblock · 2015-04-12T23:35:41Z

So for this one to be merged, build needs to be fixed, commits squashed, readme/changelogs updated.

toddmazierski · 2015-06-15T20:51:38Z

Moved to #1034!

dblock added the bug? label Feb 20, 2015

Todd Mazierski added 2 commits April 12, 2015 15:22

Merge branch 'master' into warden-test-helper-bug

abcc1f1

toddmazierski pushed a commit to generalassembly/grape that referenced this pull request Jun 15, 2015

Fix ruby-grape#930: only dup StackableValues.

75abad0

toddmazierski mentioned this pull request Jun 15, 2015

Only dup StackableValues #1034

Merged

toddmazierski closed this Jun 15, 2015

Uh oh!

Add test to reproduce bug with Warden test helper #930

Add test to reproduce bug with Warden test helper #930

Uh oh!

Conversation

toddmazierski commented Feb 17, 2015

Uh oh!

toddmazierski commented Feb 17, 2015

Uh oh!

dblock commented Feb 20, 2015

Uh oh!

toddmazierski commented Feb 20, 2015

Uh oh!

dblock commented Feb 20, 2015

Uh oh!

toddmazierski commented Feb 20, 2015

Uh oh!

toddmazierski commented Feb 23, 2015

Uh oh!

dblock commented Mar 1, 2015

Uh oh!

toddmazierski commented Mar 1, 2015

Bug 1: why the first test fails

Summary

Example

Bug 2: why the second test passes

Summary

Example

Sharing state

Solutions

Not duplicable?

Patch Warden

Uh oh!

dblock commented Mar 2, 2015

Uh oh!

dblock commented Mar 4, 2015

Uh oh!

toddmazierski commented Mar 4, 2015

Uh oh!

toddmazierski commented Apr 12, 2015

Uh oh!

dblock commented Apr 12, 2015

Uh oh!

dblock commented Apr 12, 2015

Uh oh!

toddmazierski commented Jun 15, 2015

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

Not `duplicable?`