Skip to content
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

JRuby 9.0.1.0 #to_ary should return Array #3338

Closed
tandibar opened this issue Sep 18, 2015 · 11 comments
Closed

JRuby 9.0.1.0 #to_ary should return Array #3338

tandibar opened this issue Sep 18, 2015 · 11 comments

Comments

@tandibar
Copy link

We are currently trying to migrate from jruby 1.7.16 to jruby 9.0.1.0. We are using ActiveJob with DelayedJob and are getting the following error in the worker:

Delayed::Backend::ActiveRecord::Job#to_ary should return Array

It seems to be unimportant what the job does or how it is implmented. In the Rails-App we are calling SomeJob.perform_later(params) which works perfectly. But when the worker (executed via rake jobs:work) catches the job the error happens immediately. The Class SomeJob is of type ActiveJob::Base. We have another job of type Struct.new which also does not work.

Here is the whole backtrace:

Delayed::Backend::ActiveRecord::Job#to_ary should return Array
org/jruby/RubyProc.java:306:in `call'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/lifecycle.rb:79:in `block in add'
org/jruby/RubyProc.java:308:in `call'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/lifecycle.rb:61:in `block in initialize'
org/jruby/RubyProc.java:308:in `call'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/lifecycle.rb:79:in `block in add'
org/jruby/RubyProc.java:308:in `call'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/lifecycle.rb:66:in `execute'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/lifecycle.rb:40:in `run_callbacks'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/backend/base.rb:91:in `invoke_job'
(eval):3:in `block in invoke_job_with_newrelic_transaction_trace'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/newrelic_rpm-3.13.0.299/lib/new_relic/agent/instrumentation/controller_instrumentation.rb:362:in `perform_action_with_newrelic_trace'
(eval):2:in `invoke_job_with_newrelic_transaction_trace'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/worker.rb:204:in `block in run'
org/jruby/ext/timeout/Timeout.java:147:in `timeout'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/worker.rb:204:in `block in run'
/Users/andreasbade/.rvm/rubies/jruby-9.0.1.0/lib/ruby/stdlib/benchmark.rb:303:in `realtime'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/worker.rb:203:in `run'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/worker.rb:280:in `block in reserve_and_run_one_job'
org/jruby/RubyProc.java:308:in `call'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/lifecycle.rb:61:in `block in initialize'
org/jruby/RubyProc.java:308:in `call'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/lifecycle.rb:66:in `execute'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/lifecycle.rb:40:in `run_callbacks'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/worker.rb:280:in `reserve_and_run_one_job'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/worker.rb:187:in `block in work_off'
org/jruby/RubyFixnum.java:299:in `times'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/worker.rb:186:in `work_off'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/worker.rb:150:in `block in start'
/Users/andreasbade/.rvm/rubies/jruby-9.0.1.0/lib/ruby/stdlib/benchmark.rb:303:in `realtime'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/worker.rb:149:in `block in start'
org/jruby/RubyProc.java:308:in `call'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/lifecycle.rb:61:in `block in initialize'
org/jruby/RubyProc.java:308:in `call'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/lifecycle.rb:66:in `execute'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/lifecycle.rb:40:in `run_callbacks'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/worker.rb:148:in `block in start'
org/jruby/RubyKernel.java:1291:in `loop'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/worker.rb:147:in `block in start'
org/jruby/RubyProc.java:308:in `call'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/plugins/clear_locks.rb:7:in `block in ClearLocks'
org/jruby/RubyProc.java:308:in `call'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/lifecycle.rb:79:in `block in add'
org/jruby/RubyProc.java:308:in `call'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/lifecycle.rb:61:in `block in initialize'
org/jruby/RubyProc.java:308:in `call'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/lifecycle.rb:79:in `block in add'
org/jruby/RubyProc.java:308:in `call'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/lifecycle.rb:66:in `execute'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/lifecycle.rb:40:in `run_callbacks'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/worker.rb:146:in `start'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/delayed_job-4.0.6/lib/delayed/tasks.rb:9:in `block in (root)'
org/jruby/RubyProc.java:308:in `call'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/rake-10.4.2/lib/rake/task.rb:240:in `block in execute'
org/jruby/RubyArray.java:1560:in `each'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/rake-10.4.2/lib/rake/task.rb:235:in `execute'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/rake-10.4.2/lib/rake/task.rb:179:in `block in invoke_with_call_chain'
/Users/andreasbade/.rvm/rubies/jruby-9.0.1.0/lib/ruby/stdlib/monitor.rb:211:in `mon_synchronize'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/rake-10.4.2/lib/rake/task.rb:172:in `invoke_with_call_chain'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/rake-10.4.2/lib/rake/task.rb:165:in `invoke'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/rake-10.4.2/lib/rake/application.rb:150:in `invoke_task'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/rake-10.4.2/lib/rake/application.rb:106:in `block in top_level'
org/jruby/RubyArray.java:1560:in `each'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/rake-10.4.2/lib/rake/application.rb:106:in `block in top_level'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/rake-10.4.2/lib/rake/application.rb:115:in `run_with_threads'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/rake-10.4.2/lib/rake/application.rb:100:in `top_level'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/rake-10.4.2/lib/rake/application.rb:78:in `block in run'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/rake-10.4.2/lib/rake/application.rb:176:in `standard_exception_handling'
/Users/andreasbade/.rvm/gems/jruby-9.0.1.0/gems/rake-10.4.2/lib/rake/application.rb:75:in `run'
bin/rake:4:in `<top>'
@rtyler
Copy link

rtyler commented Sep 21, 2015

@tandibar since I am without a DelayedJob project handy, would it be possible to isolate this behavior into a more simple reproduction case? Perhaps something that is creating the same type of object that is having #to_ary called on it?

It's not entirely clear to me whether this is a DelayedJob or a JRuby bug at this point

@tandibar
Copy link
Author

Hi, i am currently not able to isolate it out of DelayedJob. But i found a very short path to reproduce it:

  1. Create a rails 4.2.4 App via rails new
  2. add gem 'delayed_job_active_record' to your Gemfile and execute bundle install
  3. call rails generate delayed_job:active_record and rails db:migrate for basic DelayedJob setup
  4. execute the following code in rails c
Delayed::Worker.lifecycle.run_callbacks(:invoke_job, Delayed::Backend::ActiveRecord::Job.new) { |a| puts a }

this will work perfectly but id you add an around callback like

Delayed::Worker.lifecycle.around(:invoke_job) do |job, *args, &block|
  block.call(job, *args)
end

and execute again

Delayed::Worker.lifecycle.run_callbacks(:invoke_job, Delayed::Backend::ActiveRecord::Job.new) { |a| puts a }

you'll get the error

TypeError: Delayed::Backend::ActiveRecord::Job#to_ary should return Array

So i think it has something to do with the callback chain which get's build up, but i was not able to track it down. My guess is that the problem is somewhere in this line: https://github.com/collectiveidea/delayed_job/blob/master/lib/delayed/lifecycle.rb#L79

Hope, that helps.

@film42
Copy link

film42 commented Sep 26, 2015

I can reproduce the error on Jruby 9.0.0.0, but everything works on Jruby 1.7.20.1.

Jruby 1.7.20.1

irb(main):001:0> Delayed::Worker.lifecycle.run_callbacks(:invoke_job, Delayed::Backend::ActiveRecord::Job.new) { |a| puts a }
   (0.0ms)  SELECT name FROM sqlite_master WHERE type = 'table' AND NOT name = 'sqlite_sequence'
#<Delayed::Backend::ActiveRecord::Job:0x51f18e31>
=> nil
irb(main):002:0> Delayed::Worker.lifecycle.around(:invoke_job) do |job, *args, &block|
irb(main):003:1*   block.call(job, *args)
irb(main):004:1> end
=> #<Proc:0x60ed12e8@/Users/film42/.rbenv/versions/jruby-1.7.20.1/lib/ruby/gems/shared/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:79 (lambda)>
irb(main):005:0> Delayed::Worker.lifecycle.run_callbacks(:invoke_job, Delayed::Backend::ActiveRecord::Job.new) { |a| puts a }
#<Delayed::Backend::ActiveRecord::Job:0x24c8d8be>
=> nil
irb(main):006:0>

Jruby 9.0.0.0

irb(main):001:0> Delayed::Worker.lifecycle.run_callbacks(:invoke_job, Delayed::Backend::ActiveRecord::Job.new) { |a| puts a }
   (1.0ms)  SELECT name FROM sqlite_master WHERE type = 'table' AND NOT name = 'sqlite_sequence'
#<Delayed::Backend::ActiveRecord::Job:0x5261ec9>
=> nil
irb(main):002:0> Delayed::Worker.lifecycle.around(:invoke_job) do |job, *args, &block|
irb(main):003:1*   block.call(job, *args)
irb(main):004:1> end
=> #<Proc:0x64da6cbd@/Users/film42/.rbenv/versions/jruby-9.0.0.0/lib/ruby/gems/shared/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:79 (lambda)>
irb(main):005:0> Delayed::Worker.lifecycle.run_callbacks(:invoke_job, Delayed::Backend::ActiveRecord::Job.new) { |a| puts a }
TypeError: Delayed::Backend::ActiveRecord::Job#to_ary should return Array
    from org/jruby/RubyProc.java:306:in `call'
    from /Users/film42/.rbenv/versions/jruby-9.0.0.0/lib/ruby/gems/shared/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:79:in `block in add'
    from org/jruby/RubyProc.java:308:in `call'
    from /Users/film42/.rbenv/versions/jruby-9.0.0.0/lib/ruby/gems/shared/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:61:in `block in initialize'
    from org/jruby/RubyProc.java:308:in `call'
    from /Users/film42/.rbenv/versions/jruby-9.0.0.0/lib/ruby/gems/shared/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:79:in `block in add'
    from org/jruby/RubyProc.java:308:in `call'
    from /Users/film42/.rbenv/versions/jruby-9.0.0.0/lib/ruby/gems/shared/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:66:in `execute'
    from /Users/film42/.rbenv/versions/jruby-9.0.0.0/lib/ruby/gems/shared/gems/delayed_job-4.1.1/lib/delayed/lifecycle.rb:40:in `run_callbacks'
    from (irb):5:in `<eval>'
    from org/jruby/RubyKernel.java:979:in `eval'
    from org/jruby/RubyKernel.java:1292:in `loop'
    from org/jruby/RubyKernel.java:1099:in `catch'
    from org/jruby/RubyKernel.java:1099:in `catch'
    from /Users/film42/.rbenv/versions/jruby-9.0.0.0/lib/ruby/gems/shared/gems/railties-4.2.3/lib/rails/commands/console.rb:110:in `start'
    from /Users/film42/.rbenv/versions/jruby-9.0.0.0/lib/ruby/gems/shared/gems/railties-4.2.3/lib/rails/commands/console.rb:9:in `start'
    from /Users/film42/.rbenv/versions/jruby-9.0.0.0/lib/ruby/gems/shared/gems/railties-4.2.3/lib/rails/commands/commands_tasks.rb:68:in `console'
    from /Users/film42/.rbenv/versions/jruby-9.0.0.0/lib/ruby/gems/shared/gems/railties-4.2.3/lib/rails/commands/commands_tasks.rb:39:in `run_command!'
    from /Users/film42/.rbenv/versions/jruby-9.0.0.0/lib/ruby/gems/shared/gems/railties-4.2.3/lib/rails/commands.rb:17:in `<top>'
    from org/jruby/RubyKernel.java:940:in `require'
    from bin/rails:4:in `<top>'irb(main):006:0>

@asthasr
Copy link

asthasr commented Oct 8, 2015

I have run into this error while trying to debug an issue on JRuby 1.7.22. In that context, the "should return array" exception is not raised. Instead, it silently behaves pathologically. In MRI Ruby, when you iterate over an object it seems that #to_ary is called and, if it returns nil, is disregarded. This is a test that you can execute to see the behavior on different Rubies:

class Example
  def to_ary
    nil
  end
end

test = [Example.new].map { |x, _| x }

puts test == [nil] ? "fail" : "pass"

On MRI versions, this passes. On JRuby 1.7.22, it returns [nil] and thus fails. On JRuby 9.0.1.0, it raises an exception: TypeError: Example#to_ary should return Array. It seems that the behavior in this case should conform to the behavior on MRI, in order to avoid surprising behavior when attempting to use map, each and other enumerable methods.

@enebo
Copy link
Member

enebo commented Oct 8, 2015

@asthasr thanks for reducing a clear compat error. I am wondering if this is more general than map (we do special optimized bindings for some Java implemented Enumerable methods), but we will try and fix this on both versions.

With any luck this is the culprit for delayed_job.

@enebo enebo added this to the JRuby 9.0.2.0 milestone Oct 8, 2015
@asthasr
Copy link

asthasr commented Oct 8, 2015

@enebo No problem! It certainly seems to extend to each, and I would guess that it occurs in all contexts where to_ary is called.

@enebo
Copy link
Member

enebo commented Oct 8, 2015

Ok so I fixed the reported snippet for map and I think many general block dispatches in [master 25aa878] If value.to_ary in block dispatch returns nil then return original value. This did not fix the delayed_job issue but this might be us missing the equivalent logic in RubyProc somewhere...looking into that.

@asthasr Can I trouble you to open an issue for 1.7.x on it not behaving properly? The two codebases for handling blocks is quite a bit different and also it will be nice to have an issue in our release notes for it for 1.7.23. The fix will be similarly simple as the above commit.

@enebo
Copy link
Member

enebo commented Oct 8, 2015

Ok banking on this being the delayed_job problem since I can see this exploding setting up args in RubyProc.java:

class Example
  def to_ary
    nil
  end
end


proc { |x, _| p x }.call(Example.new)

puts test == [nil] ? "fail" : "pass"

@asthasr
Copy link

asthasr commented Oct 8, 2015

@enebo I have opened #3377 and #3378 to track this bug. I cannot assign milestones to the tickets, but that should allow for both milestones, right? (Unless there is a jruby 1.7.* repo I overlooked).

@enebo enebo modified the milestones: JRuby 1.7.23, JRuby 9.0.2.0 Oct 8, 2015
@enebo
Copy link
Member

enebo commented Oct 8, 2015

@asthasr github issues only allows selecting a single milestone per issue unfortunately.

@enebo
Copy link
Member

enebo commented Oct 8, 2015

heh...fixed another issue in proc.call {} for the same behavior in 5f11f7e. This did not fix delyed_job either but I added a spec for the fix so we can at least test against this in the future.

@enebo enebo closed this as completed in 55e2030 Oct 8, 2015
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

5 participants