New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

http.rb gem specs fail on JRuby 9.0.0.0.pre2 and greater #3151

Closed
sferik opened this Issue Jul 19, 2015 · 11 comments

Comments

Projects
None yet
3 participants
@sferik
Contributor

sferik commented Jul 19, 2015

I wasn’t able to create a reduced version, so here are the full reproduction steps:

  1. git clone https://github.com/sferik/twitter.git
  2. cd twitter
  3. gem install bundler
  4. bundle install
  5. bundle exec rake spec

468 specs will fail with an error message similar to:

NoMethodError:
  protected method `params' called for #<HTTP::Options:0x8badf00d>

On all supported versions of CRuby, these specs all pass. These specs also pass on JRuby 1.7.21 and JRuby 9.0.0.0 up to the pre2 release, so this regression must have been introduced some time between pre1 and pre2, which narrows it down to just 2,852 commits. 😉

I hope helps you to identify and fix this issue before the JRuby 9.0.0.0 final release. Sorry for not testing sooner.

FWIW, most of the other gems I’ve tests pass with flying colors on JRuby 9.0.0.0.rc2.

@sferik

This comment has been minimized.

Show comment
Hide comment
@sferik

sferik Jul 19, 2015

Contributor

It’s probably worth noting that this issue can also be reproduced by cloning the http.rb repo directly and running the specs there. Doing that might make it easier to debug this issue.

Contributor

sferik commented Jul 19, 2015

It’s probably worth noting that this issue can also be reproduced by cloning the http.rb repo directly and running the specs there. Doing that might make it easier to debug this issue.

@enebo enebo added this to the JRuby 9.0.0.0 milestone Jul 20, 2015

@enebo

This comment has been minimized.

Show comment
Hide comment
@enebo

enebo Jul 20, 2015

Member

@sferik I see 3 failures in http.rb:

       undefined method `headers' for #<HTTP::Request::Caching:0x6e88c81e>

but I see no errors on HEAD:

system ~/work/twitter master 1166% jruby -S bundle exec rake spec
uri:classloader:/jruby/kernel/kernel.rb:28: warning: unsupported exec option: close_others
/Users/enebo/work/jruby/bin/jruby -I/Users/enebo/work/jruby/lib/ruby/gems/shared/gems/rspec-core-3.3.2/lib:/Users/enebo/work/jruby/lib/ruby/gems/shared/gems/rspec-support-3.3.0/lib /Users/enebo/work/jruby/lib/ruby/gems/shared/gems/rspec-core-3.3.2/exe/rspec --pattern spec/\*\*\{,/\*/\*\*\}/\*_spec.rb
Coverage may be inaccurate; Try setting JRUBY_OPTS="-Xcli.debug=true --debug"
/Users/enebo/work/jruby/lib/ruby/gems/shared/gems/simplecov-0.10.0/lib/simplecov.rb:43: warning: tracing (e.g. set_trace_func) will not capture all events without --debug flag

Randomized with seed 23430
....................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................

Finished in 12.34 seconds (files took 6.35 seconds to load)
996 examples, 0 failures

Randomized with seed 23430

Coverage report generated for RSpec to /Users/enebo/work/twitter/coverage. 0 / 1828 LOC (0.0%) covered.
[Coveralls] Outside the CI environment, not sending data.
Coverage (0.00%) is below the expected minimum coverage (99.62%).
/Users/enebo/work/jruby/bin/jruby -I/Users/enebo/work/jruby/lib/ruby/gems/shared/gems/rspec-core-3.3.2/lib:/Users/enebo/work/jruby/lib/ruby/gems/shared/gems/rspec-support-3.3.0/lib /Users/enebo/work/jruby/lib/ruby/gems/shared/gems/rspec-core-3.3.2/exe/rspec --pattern spec/\*\*\{,/\*/\*\*\}/\*_spec.rb failed

well perhaps other than the coverage number. I think your private error was fixed via #3123 (commit 8ae5cb3), but we apparently still have an error in http.rb.

Member

enebo commented Jul 20, 2015

@sferik I see 3 failures in http.rb:

       undefined method `headers' for #<HTTP::Request::Caching:0x6e88c81e>

but I see no errors on HEAD:

system ~/work/twitter master 1166% jruby -S bundle exec rake spec
uri:classloader:/jruby/kernel/kernel.rb:28: warning: unsupported exec option: close_others
/Users/enebo/work/jruby/bin/jruby -I/Users/enebo/work/jruby/lib/ruby/gems/shared/gems/rspec-core-3.3.2/lib:/Users/enebo/work/jruby/lib/ruby/gems/shared/gems/rspec-support-3.3.0/lib /Users/enebo/work/jruby/lib/ruby/gems/shared/gems/rspec-core-3.3.2/exe/rspec --pattern spec/\*\*\{,/\*/\*\*\}/\*_spec.rb
Coverage may be inaccurate; Try setting JRUBY_OPTS="-Xcli.debug=true --debug"
/Users/enebo/work/jruby/lib/ruby/gems/shared/gems/simplecov-0.10.0/lib/simplecov.rb:43: warning: tracing (e.g. set_trace_func) will not capture all events without --debug flag

Randomized with seed 23430
....................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................

Finished in 12.34 seconds (files took 6.35 seconds to load)
996 examples, 0 failures

Randomized with seed 23430

Coverage report generated for RSpec to /Users/enebo/work/twitter/coverage. 0 / 1828 LOC (0.0%) covered.
[Coveralls] Outside the CI environment, not sending data.
Coverage (0.00%) is below the expected minimum coverage (99.62%).
/Users/enebo/work/jruby/bin/jruby -I/Users/enebo/work/jruby/lib/ruby/gems/shared/gems/rspec-core-3.3.2/lib:/Users/enebo/work/jruby/lib/ruby/gems/shared/gems/rspec-support-3.3.0/lib /Users/enebo/work/jruby/lib/ruby/gems/shared/gems/rspec-core-3.3.2/exe/rspec --pattern spec/\*\*\{,/\*/\*\*\}/\*_spec.rb failed

well perhaps other than the coverage number. I think your private error was fixed via #3123 (commit 8ae5cb3), but we apparently still have an error in http.rb.

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Jul 20, 2015

Member

Doubleteam! I'm looking into http.rb issues now too.

Member

headius commented Jul 20, 2015

Doubleteam! I'm looking into http.rb issues now too.

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Jul 20, 2015

Member

Well this is odd... I added some logging to delegate.rb where it uses method_missing to redispatch. The lines here are the method to dispatch, the list of public methods on the delegated object, and whether it respond_to? that method. Why is it false when headers is obviously there?

:headers
[:!, :!=, :!~, :<=>, :==, :===, :=~, :[], :[]=, :__getobj__, :__id__, :__send__, :__setobj__, :body, :cache_headers, :cacheable?, :caching, :class, :clone, :com, :conditional_on_changes_to, :connect_using_proxy, :define_singleton_method, :display, :dup, :enum_for, :env, :eql?, :equal?, :extend, :freeze, :frozen?, :handle_different_imports, :hash, :headers, :headline, :host, :include_class, :include_proxy_authorization_header, :inspect, :instance_eval, :instance_exec, :instance_of?, :instance_variable_defined?, :instance_variable_get, :instance_variable_set, :instance_variables, :invalidates_cache?, :is_a?, :itself, :java, :java_annotation, :java_field, :java_implements, :java_kind_of?, :java_name, :java_package, :java_require, :java_signature, :javafx, :javax, :kind_of?, :marshal_dump, :marshal_load, :method, :method_missing, :methods, :nil?, :object_id, :org, :private_methods, :protected_methods, :proxy, :proxy_authorization_header, :proxy_connect_header, :proxy_connect_headers, :public_method, :public_methods, :public_send, :redirect, :remove_instance_variable, :request_header, :respond_to?, :respond_to_missing?, :scheme, :send, :sent_at, :sent_at=, :singleton_class, :singleton_methods, :skips_cache?, :socket_host, :socket_port, :stream, :taint, :tainted?, :tap, :to_enum, :to_java, :to_json, :to_s, :trust, :untaint, :untrust, :untrusted?, :uri, :using_authenticated_proxy?, :using_proxy?, :verb, :version]
false
Member

headius commented Jul 20, 2015

Well this is odd... I added some logging to delegate.rb where it uses method_missing to redispatch. The lines here are the method to dispatch, the list of public methods on the delegated object, and whether it respond_to? that method. Why is it false when headers is obviously there?

:headers
[:!, :!=, :!~, :<=>, :==, :===, :=~, :[], :[]=, :__getobj__, :__id__, :__send__, :__setobj__, :body, :cache_headers, :cacheable?, :caching, :class, :clone, :com, :conditional_on_changes_to, :connect_using_proxy, :define_singleton_method, :display, :dup, :enum_for, :env, :eql?, :equal?, :extend, :freeze, :frozen?, :handle_different_imports, :hash, :headers, :headline, :host, :include_class, :include_proxy_authorization_header, :inspect, :instance_eval, :instance_exec, :instance_of?, :instance_variable_defined?, :instance_variable_get, :instance_variable_set, :instance_variables, :invalidates_cache?, :is_a?, :itself, :java, :java_annotation, :java_field, :java_implements, :java_kind_of?, :java_name, :java_package, :java_require, :java_signature, :javafx, :javax, :kind_of?, :marshal_dump, :marshal_load, :method, :method_missing, :methods, :nil?, :object_id, :org, :private_methods, :protected_methods, :proxy, :proxy_authorization_header, :proxy_connect_header, :proxy_connect_headers, :public_method, :public_methods, :public_send, :redirect, :remove_instance_variable, :request_header, :respond_to?, :respond_to_missing?, :scheme, :send, :sent_at, :sent_at=, :singleton_class, :singleton_methods, :skips_cache?, :socket_host, :socket_port, :stream, :taint, :tainted?, :tap, :to_enum, :to_java, :to_json, :to_s, :trust, :untaint, :untrust, :untrusted?, :uri, :using_authenticated_proxy?, :using_proxy?, :verb, :version]
false
@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Jul 20, 2015

Member

Ok, the problem seems to be related to http.rb double-delegating the request. This code delegates twice, wrapping the given HTTP::Request in a Caching wrapper in both the caching call and in the self.class.new call:

      def conditional_on_changes_to(cached_response)
        self.class.new HTTP::Request.new(
          verb, uri, headers.merge(conditional_headers_for(cached_response)),
          proxy, body, version).caching
      end

Why this is double-delegating is a separate question, but something about this setup seems to cause issues dispatching. When I remove one or the other delegate wrapper, the code works fine.

@sferik Is this code supposed to double-delegate?

Member

headius commented Jul 20, 2015

Ok, the problem seems to be related to http.rb double-delegating the request. This code delegates twice, wrapping the given HTTP::Request in a Caching wrapper in both the caching call and in the self.class.new call:

      def conditional_on_changes_to(cached_response)
        self.class.new HTTP::Request.new(
          verb, uri, headers.merge(conditional_headers_for(cached_response)),
          proxy, body, version).caching
      end

Why this is double-delegating is a separate question, but something about this setup seems to cause issues dispatching. When I remove one or the other delegate wrapper, the code works fine.

@sferik Is this code supposed to double-delegate?

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Jul 20, 2015

Member

Reduced repro at this point, fwiw:

require 'http.rb'
request = HTTP::Request.new(:get, "http://example.com/")
subject = HTTP::Request::Caching.new(request)
mod_date    = Time.now.httpdate
headers     = {"Etag" => "foo", "Last-Modified" => mod_date}
cached_resp = HTTP::Response.new(200, "http/1.1", headers, "")
cond_req    = subject.conditional_on_changes_to(cached_resp)

p cond_req.headers["If-None-Match"]
Member

headius commented Jul 20, 2015

Reduced repro at this point, fwiw:

require 'http.rb'
request = HTTP::Request.new(:get, "http://example.com/")
subject = HTTP::Request::Caching.new(request)
mod_date    = Time.now.httpdate
headers     = {"Etag" => "foo", "Last-Modified" => mod_date}
cached_resp = HTTP::Response.new(200, "http/1.1", headers, "")
cond_req    = subject.conditional_on_changes_to(cached_resp)

p cond_req.headers["If-None-Match"]
@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Jul 20, 2015

Member

Ok, there's a complicated set of issues at play here, but I have a repro and at least a basic understanding of the problem.

HTTP::Request::Caching is a DelegateClass around HTTP::Request.

When the DelegateClass(HTTP::Request) is created, it is before the full HTTP::Request class is loaded, meaning that most of its methods don't get direct delegation and instead go through method_missing.

The double delegation falls into the m_m logic, where it tries to respond_to? on the inner delegate. This fails to see the method, even though it should be there as a delegation.

I suspect this is ultimately a respond_to? + respond_to_missing? protocol problem.

Here's the repro isolated from http.rb:

class MyClass
end

class MyDel < DelegateClass(MyClass)
end

class MyClass
  include Enumerable
end

MyDel.new(MyDel.new(MyClass.new)).each_with_index # BOOM

@sferik I don't think you want to double-delegate and you probably should modify the creation of the HTTP::Request::Caching delegator so it happens after HTTP::Request is fully defined; the m_m logic will be significantly slower. These are not bugs, per se, but they will certainly impact performance.

Member

headius commented Jul 20, 2015

Ok, there's a complicated set of issues at play here, but I have a repro and at least a basic understanding of the problem.

HTTP::Request::Caching is a DelegateClass around HTTP::Request.

When the DelegateClass(HTTP::Request) is created, it is before the full HTTP::Request class is loaded, meaning that most of its methods don't get direct delegation and instead go through method_missing.

The double delegation falls into the m_m logic, where it tries to respond_to? on the inner delegate. This fails to see the method, even though it should be there as a delegation.

I suspect this is ultimately a respond_to? + respond_to_missing? protocol problem.

Here's the repro isolated from http.rb:

class MyClass
end

class MyDel < DelegateClass(MyClass)
end

class MyClass
  include Enumerable
end

MyDel.new(MyDel.new(MyClass.new)).each_with_index # BOOM

@sferik I don't think you want to double-delegate and you probably should modify the creation of the HTTP::Request::Caching delegator so it happens after HTTP::Request is fully defined; the m_m logic will be significantly slower. These are not bugs, per se, but they will certainly impact performance.

@headius headius changed the title from Twitter gem specs fail on JRuby 9.0.0.0.pre2 and greater to Twitter and http.rb gem specs fail on JRuby 9.0.0.0.pre2 and greater Jul 20, 2015

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Jul 20, 2015

Member

A slightly smaller repro that shows this is a respond_to? problem:

...
p MyDel.new(MyClass.new).respond_to? :each_with_index
Member

headius commented Jul 20, 2015

A slightly smaller repro that shows this is a respond_to? problem:

...
p MyDel.new(MyClass.new).respond_to? :each_with_index
@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Jul 20, 2015

Member

Bingo. I have it.

diff --git a/core/src/main/java/org/jruby/RubyKernel.java b/core/src/main/java/org/jruby/RubyKernel.java
index 63837f1..c33b3fe 100644
--- a/core/src/main/java/org/jruby/RubyKernel.java
+++ b/core/src/main/java/org/jruby/RubyKernel.java
@@ -600,12 +600,12 @@ public class RubyKernel {
         return RubyArgsFile.readlines(context, context.runtime.getArgsFile(), args);
     }

-    @JRubyMethod(name = "respond_to_missing?", module = true)
+    @JRubyMethod(name = "respond_to_missing?", module = true, visibility = PRIVATE)
     public static IRubyObject respond_to_missing_p(ThreadContext context, IRubyObject recv, IRubyObject symbol) {
         return context.runtime.getFalse();
     }

-    @JRubyMethod(name = "respond_to_missing?", module = true)
+    @JRubyMethod(name = "respond_to_missing?", module = true, visibility = PRIVATE)
     public static IRubyObject respond_to_missing_p(ThreadContext context, IRubyObject recv, IRubyObject symbol, IRubyObject isPrivate) {
         return context.runtime.getFalse();
     }

The problem goes like this:

  • DelegateClass uses the list of instance_methods from the target class minus the "public API" of Delegate to decide on a list of methods that should be directly delegated.
  • When defining respond_to_missing? in Ruby code, it is automatically made private by the runtime, since it is only used for internal logic.
  • Because our base definition of respond_to_missing? is public and the "public API" of Delegate has it private, it leaks through to the delegation logic.
  • DelegateClass proceeds to define a directly-delegating method, bypassing the respond_to_missing? defined in Delegate. As a result, the respond_to? protocol gets broken.

This only affects cases passing through Delegate's method_missing, which is probably why we didn't see it before. All tests I know of for Delegate define the target class completely before wrapping it. Since that doesn't happen here, the bug was triggered.

Fix and specs coming.

Member

headius commented Jul 20, 2015

Bingo. I have it.

diff --git a/core/src/main/java/org/jruby/RubyKernel.java b/core/src/main/java/org/jruby/RubyKernel.java
index 63837f1..c33b3fe 100644
--- a/core/src/main/java/org/jruby/RubyKernel.java
+++ b/core/src/main/java/org/jruby/RubyKernel.java
@@ -600,12 +600,12 @@ public class RubyKernel {
         return RubyArgsFile.readlines(context, context.runtime.getArgsFile(), args);
     }

-    @JRubyMethod(name = "respond_to_missing?", module = true)
+    @JRubyMethod(name = "respond_to_missing?", module = true, visibility = PRIVATE)
     public static IRubyObject respond_to_missing_p(ThreadContext context, IRubyObject recv, IRubyObject symbol) {
         return context.runtime.getFalse();
     }

-    @JRubyMethod(name = "respond_to_missing?", module = true)
+    @JRubyMethod(name = "respond_to_missing?", module = true, visibility = PRIVATE)
     public static IRubyObject respond_to_missing_p(ThreadContext context, IRubyObject recv, IRubyObject symbol, IRubyObject isPrivate) {
         return context.runtime.getFalse();
     }

The problem goes like this:

  • DelegateClass uses the list of instance_methods from the target class minus the "public API" of Delegate to decide on a list of methods that should be directly delegated.
  • When defining respond_to_missing? in Ruby code, it is automatically made private by the runtime, since it is only used for internal logic.
  • Because our base definition of respond_to_missing? is public and the "public API" of Delegate has it private, it leaks through to the delegation logic.
  • DelegateClass proceeds to define a directly-delegating method, bypassing the respond_to_missing? defined in Delegate. As a result, the respond_to? protocol gets broken.

This only affects cases passing through Delegate's method_missing, which is probably why we didn't see it before. All tests I know of for Delegate define the target class completely before wrapping it. Since that doesn't happen here, the bug was triggered.

Fix and specs coming.

@headius headius closed this in 9a8a41e Jul 20, 2015

@enebo enebo changed the title from Twitter and http.rb gem specs fail on JRuby 9.0.0.0.pre2 and greater to http.rb gem specs fail on JRuby 9.0.0.0.pre2 and greater Jul 20, 2015

@sferik

This comment has been minimized.

Show comment
Hide comment
@sferik

sferik Jul 21, 2015

Contributor

@headius Thanks for tracking down and fixing this issue!

@sferik Is this code supposed to double-delegate?

I don’t think that double-delegation is strictly necessary but I don’t know the full history behind that decision. Perhaps @tarcieri or @ixti could chime in with an answer?

Contributor

sferik commented Jul 21, 2015

@headius Thanks for tracking down and fixing this issue!

@sferik Is this code supposed to double-delegate?

I don’t think that double-delegation is strictly necessary but I don’t know the full history behind that decision. Perhaps @tarcieri or @ixti could chime in with an answer?

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Jul 21, 2015

Member

@sferik I'll file a bug on http.rb and perhaps it will magically get fixed!

Member

headius commented Jul 21, 2015

@sferik I'll file a bug on http.rb and perhaps it will magically get fixed!

eregon added a commit that referenced this issue Jul 27, 2015

Squashed 'spec/ruby/' changes from e3e7dd7..2792cbd
2792cbd Fix Thread#priority= spec to follow MRI behavior.
348ee7e Remove trailing spaces
6173510 Add additional spec for Thread#priority=.
e43dd4e Remove extra top-level constants markers.
500347b Add two specs for error cases of define_method with a Method.
62def58 Make sure threads are actually waiting in Mutex specs
baf2858 Time#now should return Time instance when called on non-descendant class
8eaf6fa add test for backtrace presence
b4ea34c Add specs to Hash#merge with small hashes
13f2187 Make sure threads are actually waiting in other ConditionVariable specs
ae7a36c Make sure the thread is actually waiting in ConditionVariable specs
5c3d18e Add specs to Hash#merge with empty hashes
0133591 Add specs for Date#{<<,prev_year,next_year} around calendar reforms.
f56a046 Kernel#respond_to? and Kernel#respond_to_missing? should only be instance methods.
adf8655 Spec for jruby/jruby#3151 DelegateClass + respond_to_missing?
0baee92 Deduplicate Kernel#puts and IO#puts, the former delegates to the latter
f46e649 Improve IO#puts specs to not rely on individual calls to #write
b3fc7ae Add spec for non-local return bubbling through lambda.
f74566e Added failing Range#bsearch specs
109c494 Add specs for passing strings to constant visibility methods
6f28f90 Smash another racey process spec.
c6d9f6a Merge pull request #100 from jannishuebl/master
57064f9 Merge pull request #101 from ruby/hash
2b58c26 restart travis
3833763 remove another filterable opal exeptions.
06ee233 remove filterable opal exeptions.
bc6c119 Add unsuppored for Opal
bf46caa Add more Hash inequality examples
8350bad fix Bignum tests for opal
a9e6eb7 fix Fixnum#* overflow to bignum for all kinds of fixnums
979cebe fix Bignum#div Bignum#divmod and Bignum#divide to run with opal bignum
dd95805 Mocks can mock #hash and #eql? now.
6f4f099 Do not make 2 builds on Travis for branch + PR
9365015 Merge pull request #99 from ruby/array-add-missing-examples
15077ea Use at_least(1) instead of any_number_of_times, add comment re `eql?`
11476a4 Port missing examples from Array#uniq to Array#uniq!
87af503 Add missing examples for identical item for Array#{&,|,uniq,uniq!}
11146c9 Merge pull request #95 from ruby/array
c8b9498 Use should_receive to test Array#& and Array#| instead of singleton methods
61eff71 Revert "Try the new Travis CI infrastructure"
82f22e7 Try the new Travis CI infrastructure
b7605dd Module#prepend is private before Ruby 2.1
08de395 Binding#local_variable_set is available from Ruby 2.1

git-subtree-dir: spec/ruby
git-subtree-split: 2792cbd1159705ecf68776fdac98d4e7096aec7e
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment