expect and_call_original messing up with modules build as jruby extensions.

[purbon]

While doing some test to upgrade https://github.com/elastic/logstash to use the last rspec set of gems, I found out an issue with the way expectation with the and_call_orignal call work in the 3.x branch.

Situation

In logstash we're using the jruby wrapper of jrjackson [1] as a json lib, so we get a really fast json processing. So to build the test we use calls like:

 expect(JrJackson::Raw).to receive(:parse_raw).with(json_hash).and_call_original
 expect(LogStash::Json.load(json_hash)).to eql(hash)

during the upgrade to use rspec 3.x I discovered that this kind of expectation were not playing well anymore, as they did with versions < 2.99. There seems to be a regression with using the and_call_original in modules defined as jruby/java exceptions.

To make a bit more easy to reproduce this I made a simple example that you can find at https://github.com/purbon/playground/tree/master/call_origin_with_module, running the test in this dummy gem will:

• If using the last rspec 3.2.x:

CallOriginWithModule
  calls the generate once
  calls the generate twice (FAILED - 1)
  calls the dump once (FAILED - 2)
  calls the dump twice (FAILED - 3)
  without using call original
    calls the generate once
    calls the generate twice

Failures:

  1) CallOriginWithModule calls the generate twice
     Failure/Error: expect(AClass.bar(3)).to eq("{\"source\":3,\"target\":3}")
     NoMethodError:
       undefined method `generate' for JrJackson::Raw:Module
     # ./lib/call_origin_with_module.rb:8:in `bar'
     # ./spec/call_origin_with_module_spec.rb:12:in `(root)'

if using a version <= 2.99:

╰─$ bundle exec rspec

CallOriginWithModule
  calls the generate once
  calls the generate twice
  calls the dump once
  calls the dump twice
  without using call original
    calls the generate once
    calls the generate twice

Finished in 0.322 seconds
6 examples, 0 failures

[1] https://github.com/guyboertje/jrjackson

[JonRowe]

Can you try something for me? Can you run your build with:

 export JRUBY_OPTS='--server -Xcompile.invokedynamic=false'

[purbon]

Hi @JonRowe I tried to run https://github.com/purbon/playground/tree/master/call_origin_with_module with your proposed options and I see the same error:

╭─purbon@purbon-elastic  ~/work/purbon/playground/call_origin_with_module  ‹master› 
╰─$ echo $JRUBY_OPTS
--server -Xcompile.invokedynamic=false
╭─purbon@purbon-elastic  ~/work/purbon/playground/call_origin_with_module  ‹master› 
╰─$ bundle exec rspec

CallOriginWithModule
  calls the generate once
  calls the generate twice (FAILED - 1)
  calls the dump once (FAILED - 2)
  calls the dump twice (FAILED - 3)
  without using call original
    calls the generate once
    calls the generate twice

Failures:

  1) CallOriginWithModule calls the generate twice
     Failure/Error: expect(AClass.bar(3)).to eq("{\"source\":3,\"target\":3}")
     NoMethodError:
       undefined method `generate' for JrJackson::Raw:Module
     # ./lib/call_origin_with_module.rb:8:in `bar'
     # ./spec/call_origin_with_module_spec.rb:12:in `(root)'

I did several attempts to reproduce this error with code as the one in 6f1941b, however I was only able to reproduce this in situations as the one using https://github.com/guyboertje/jrjackson, the code checking here, and messing the stuff up is defined in https://github.com/guyboertje/jrjackson/blob/master/src/main/java/com/jrjackson/JrJacksonRaw.java#L27 .... might be we found also an issue in jruby?

[fables-tales]

Can reproduce this against my local dev setup.

[fables-tales]

This did not work against 2.14.0

[fables-tales]

trying to find bisect commits on master that work for this error.

[fables-tales]

green with this combo of gems:

Installing rspec-core 2.14.8 (was 2.14.0.rc1)
Installing rspec-expectations 2.14.5 (was 2.14.0.rc1)
Installing rspec-mocks 2.14.6 (was 2.14.0.rc1)
Installing rspec 2.14.1 (was 2.14.0.rc1)

going to try bisecting against the 2-14 branch.

[fables-tales]

This is green in master as of 3956221. Going to work out which commit cause the breaking a little later.

[fables-tales]

7a047e25cbed756bfe2724037aeafe393b738e5d is the first bad commit
commit 7a047e25cbed756bfe2724037aeafe393b738e5d

[fables-tales]

the problem is this line of code, where I'm getting:

[18] pry(#<RSpec::Mocks::InstanceMethodStasher>)> @klass
=> #<Class:JrJackson::Raw>
[19] pry(#<RSpec::Mocks::InstanceMethodStasher>)> owner
=> JrJackson::Raw
[20] pry(#<RSpec::Mocks::InstanceMethodStasher>)> @klass == owner
=> false
[21] pry(#<RSpec::Mocks::InstanceMethodStasher>)>

[fables-tales]

Consider the following example:

require "jrjackson"

m = Module.new do
  def self.a

  end
end

m_singleton_class = (class << m; self; end)
puts "Pure module singleton class owner #{m_singleton_class.instance_method(:a).owner.inspect}"
puts "Pure module singleton class owner equals singleton class? #{m_singleton_class.instance_method(:a).owner == m_singleton_class}"

j = JrJackson::Raw
j_singleton_class = (class << j; self; end)
puts "jrjackson singleton class owner #{j_singleton_class.instance_method(:generate).owner.inspect}"
puts "jrjackson singleton class owner equals singleton class? #{j_singleton_class.instance_method(:generate).owner == j_singleton_class}"

output:

Pure module singleton class owner #<Class:#<Module:0x650eab8>>
Pure module singleton class owner equals singleton class? true
jrjackson singleton class owner JrJackson::Raw
jrjackson singleton class owner equals singleton class? false

So, unless I'm reading this wrong, JRuby has a bug in the return values from the #owner method on the result of #instance_method when it's called on singleton class objects on native extension module objects.

This causes some of our internal method stashing and unstashing logic to behave incorrectly. I'd love a second opinion on this. @JonRowe do you think I've called it correctly?

[fables-tales]

I tested a hypothetical fix to this by swapping out the owner in this exact case, I got the following error:

  1) CallOriginWithModule calls the generate once
     Failure/Error: Unable to find matching line from backtrace
     TypeError:
       bind argument must be an instance of JrJackson::Raw
     # org/jruby/RubyModule.java:1521:in `define_method'
     # /Users/sam/dev/rspec/rspec-dev/repos/rspec-mocks/lib/rspec/mocks/instance_method_stasher.rb:79:in `restore'
     # /Users/sam/dev/rspec/rspec-dev/repos/rspec-mocks/lib/rspec/mocks/method_double.rb:74:in `restore_original_method'
     # /Users/sam/dev/rspec/rspec-dev/repos/rspec-mocks/lib/rspec/mocks/method_double.rb:97:in `reset'
     # /Users/sam/dev/rspec/rspec-dev/repos/rspec-mocks/lib/rspec/mocks/proxy.rb:123:in `reset'
     # org/jruby/RubyArray.java:1613:in `each'
     # /Users/sam/dev/rspec/rspec-dev/repos/rspec-mocks/lib/rspec/mocks/proxy.rb:123:in `reset'
     # /Users/sam/dev/rspec/rspec-dev/repos/rspec-mocks/lib/rspec/mocks/proxy.rb:118:in `verify'
     # /Users/sam/dev/rspec/rspec-dev/repos/rspec-mocks/lib/rspec/mocks/space.rb:14:in `verify_all'

[fables-tales]

I'm increasingly convinced this is a JRuby bug. If someone from @rspec/rspec agrees I think we should reach out to the JRuby team and see if they can help us out?

[xaviershay]

Yeah that looks like a bug to me ... is there an analogous case we could provide for MRI to show that there is a behavioural difference?

[fables-tales]

@xaviershay the behaviour difference is on a pure module versus a jruby extension one, and the behaviour of the pure module is the same in MRI and JRuby, obviously, we can't run a JRuby extension on MRI.

[fables-tales]

@purbon btw, as a work around, you could simply wrap JrJackson::Raw in a pure ruby module and this would work

[fables-tales]

@rspec/rspec I'm going to write a minimal reproduction case that creates it's own JRuby module to see if my understanding is correct and then ping the JRuby folks.

[purbon]

Thanks a lot for your debugging, is much a appreciate it! For now this is not a hard issue for us, but would be nice to have so we can use mocks as "expected". Happy to help rspec reporting issues :-), this is such a great thing for ruby 👍

[JonRowe]

@samphippen your explanation makes sense to me, as is what JRuby is doing when you "fixed" it :)

[fables-tales]

I'm not gonna be able to do the JRuby thing for a while because of sudden unexpected busyness but roughly I think the repro case we'd want to build is:

• A jruby extension module with a single class method
• A normal ruby module with a single class method
• A test that shows the singleton class of the normal ruby module correctly returns an instance method object with the correct owner (i.e. the owner is the singleton class)
• A failing test that shows the singleton class of the jruby extension module does not return an instance method object with the correct owner (i.e. the owner will incorrectly be the module itself and not the singleton class of the module).

@purbon could you build that for us? If not don't worry.

[purbon]

@samphippen I can, I will report here when done.

[JonRowe]

Hey @purbon did you ever get a chance to build those tests @samphippen was talking about?

[purbon]

@JonRowe I apologies, not jet! I hope to do by soon, probably by the end of the week.

[purbon]

sorry, for being really late to this, going to work on this today :P I update this as soon as I get something up and working 😸

[purbon]

Hi,
I've been the last couple of days trying to make my way throw the jruby extensions, however I failed more or less like a little child. My project where I tried to do what we spoke is at https://github.com/purbon/jruby-ext-experiments, I would like to know what I'm doing wrong, do you know?

Here: http://lists.ruby-lang.org/pipermail/jruby/2015-August/000082.html are more details of my error 😸

Thanks a lot,

hope to finally get this up and running! :-P

/pere

[purbon]

@JonRowe @samphippen I finally managed to make happy jruby with the extension, was the name of the service not being the one :P, anyway! now the code in the repo works, but I could not make the test fail using the test case described by @samphippen, is the anything wrong with my implementation?

/cheers

[purbon]

Hi again, I recall one slightly small thing in jrjackson that might be the situation that caused this test to fail, actually is this part of the code:

// serialize
    @JRubyMethod(module = true, name = {"generate", "dump"}, required = 1, optional = 1)
    public static IRubyObject generate(ThreadContext context, IRubyObject self, IRubyObject[] args)
            throws IOException, JsonProcessingException {

this is how methods are defined, so not using one name, but also two I guess with the idea of making aliases. Not sure if this is standard way to do it, but I updated the code in [1] and then if you use the module you can make the test to fail. I guess this looks to me like a jruby bug, but not sure about the details there, because to use the singleton class it pass perfect.

/cheers

[1] https://github.com/purbon/jruby-ext-experiments

[JonRowe]

/cc @samphippen

[fables-tales]

I've handed the repro case over to @headius who confirms this is real, see the linked JRuby issue for details.

[fables-tales]

This was fixed by jruby/jruby#3463

[fables-tales]

Thanks @headius