Exception when using alongside websocket-rails: RuntimeError: eventmachine not initialized: evma_connect_to_unix_server

synthead commented 8 years ago

In config/application.rb, as suggested by README.md...

module MyRailsProject
  class Application < Rails::Application
    ...
    config.active_job.locks.redis = [Rails.application.config_for(:redis)["url"]]
  end
end

...(where config/redis.yml contains):

default: &default
  url: unix:/var/run/redis/redis.sock

development:
  <<: *default
  namespace: my_rails_project_development

test:
  <<: *default
  namespace: my_rails_project_test

production:
  <<: *default
  namespace: my_rails_project_production

...if I have this job:

class HelloWorldJob < ActiveJob::Base
  lock_by :payload

  def perform
    puts "Hello World!"
  end
end

...and I queue it up in Sidekiq via the vanilla ActiveJob implementation, I get this in my logs:

2016-05-23T23:26:14.771Z 27761 TID-grijk HelloWorldJob JID-aa9e0533737b38b1bbe780f5 INFO: start
2016-05-23T23:26:14.795Z 27761 TID-grijk HelloWorldJob JID-aa9e0533737b38b1bbe780f5 INFO: fail: 0.024 sec
2016-05-23T23:26:14.795Z 27761 TID-grijk WARN: {"class"=>"ActiveJob::QueueAdapters::SidekiqAdapter::JobWrapper", "wrapped"=>"HelloWorldJob", "queue"=>"default", "args"=>[{"job_class"=>"HelloWorldJob", "job_id"=>"83a48f12-b32e-4bae-9de0-e05046bae80a", "queue_name"=>"default", "arguments"=>[{"_aj_globalid"=>"gid://my_rails_project/Job/199"}], "locale"=>"en"}], "retry"=>true, "jid"=>"aa9e0533737b38b1bbe780f5", "created_at"=>1464045974.7657638, "enqueued_at"=>1464045974.7658272, "error_message"=>"eventmachine not initialized: evma_connect_to_unix_server", "error_class"=>"RuntimeError", "failed_at"=>1464045974.773907, "retry_count"=>0}
2016-05-23T23:26:14.795Z 27761 TID-grijk WARN: RuntimeError: eventmachine not initialized: evma_connect_to_unix_server
2016-05-23T23:26:14.795Z 27761 TID-grijk WARN: /home/fred/.gem/ruby/2.3.0/gems/eventmachine-1.2.0.1/lib/eventmachine.rb:680:in `connect_unix_server'
/home/fred/.gem/ruby/2.3.0/gems/eventmachine-1.2.0.1/lib/eventmachine.rb:680:in `bind_connect'
/home/fred/.gem/ruby/2.3.0/gems/eventmachine-1.2.0.1/lib/eventmachine.rb:653:in `connect'
/home/fred/.gem/ruby/2.3.0/gems/eventmachine-1.2.0.1/lib/eventmachine.rb:813:in `connect_unix_domain'
/home/fred/.gem/ruby/2.3.0/gems/redis-3.3.0/lib/redis/connection/synchrony.rb:75:in `connect'
/home/fred/.gem/ruby/2.3.0/gems/redis-3.3.0/lib/redis/client.rb:336:in `establish_connection'
/home/fred/.gem/ruby/2.3.0/gems/redis-3.3.0/lib/redis/client.rb:101:in `block in connect'
/home/fred/.gem/ruby/2.3.0/gems/redis-3.3.0/lib/redis/client.rb:293:in `with_reconnect'
/home/fred/.gem/ruby/2.3.0/gems/redis-3.3.0/lib/redis/client.rb:100:in `connect'
/home/fred/.gem/ruby/2.3.0/gems/redis-3.3.0/lib/redis/client.rb:364:in `ensure_connected'
/home/fred/.gem/ruby/2.3.0/gems/redis-3.3.0/lib/redis/client.rb:221:in `block in process'
/home/fred/.gem/ruby/2.3.0/gems/redis-3.3.0/lib/redis/client.rb:306:in `logging'
/home/fred/.gem/ruby/2.3.0/gems/redis-3.3.0/lib/redis/client.rb:220:in `process'
/home/fred/.gem/ruby/2.3.0/gems/redis-3.3.0/lib/redis/client.rb:120:in `call'
/home/fred/.gem/ruby/2.3.0/gems/redis-3.3.0/lib/redis.rb:2380:in `block in script'
/home/fred/.gem/ruby/2.3.0/gems/redis-3.3.0/lib/redis.rb:58:in `block in synchronize'
/usr/lib/ruby/2.3.0/monitor.rb:214:in `mon_synchronize'
/home/fred/.gem/ruby/2.3.0/gems/redis-3.3.0/lib/redis.rb:58:in `synchronize'
/home/fred/.gem/ruby/2.3.0/gems/redis-3.3.0/lib/redis.rb:2379:in `script'
/home/fred/.gem/ruby/2.3.0/gems/redlock-0.1.6/lib/redlock/client.rb:121:in `load_scripts'
/home/fred/.gem/ruby/2.3.0/gems/redlock-0.1.6/lib/redlock/client.rb:101:in `initialize'
/home/fred/.gem/ruby/2.3.0/gems/redlock-0.1.6/lib/redlock/client.rb:23:in `new'
/home/fred/.gem/ruby/2.3.0/gems/redlock-0.1.6/lib/redlock/client.rb:23:in `block in initialize'
/home/fred/.gem/ruby/2.3.0/gems/redlock-0.1.6/lib/redlock/client.rb:21:in `map'
/home/fred/.gem/ruby/2.3.0/gems/redlock-0.1.6/lib/redlock/client.rb:21:in `initialize'
/home/fred/.gem/ruby/2.3.0/gems/activejob-locks-0.0.4/lib/active_job/locks/callbacks.rb:10:in `new'
/home/fred/.gem/ruby/2.3.0/gems/activejob-locks-0.0.4/lib/active_job/locks/callbacks.rb:10:in `redis_lock'
/home/fred/.gem/ruby/2.3.0/gems/activejob-locks-0.0.4/lib/active_job/locks/callbacks.rb:30:in `block (2 levels) in <module:Callbacks>'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:441:in `instance_exec'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:441:in `block in make_lambda'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:328:in `block in conditional'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:497:in `block in around'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:505:in `call'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:498:in `block (2 levels) in around'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:343:in `block (2 levels) in simple'
/home/fred/.gem/ruby/2.3.0/gems/i18n-0.7.0/lib/i18n.rb:257:in `with_locale'
/home/fred/.gem/ruby/2.3.0/gems/activejob-4.2.6/lib/active_job/translation.rb:7:in `block (2 levels) in <module:Translation>'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:441:in `instance_exec'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:441:in `block in make_lambda'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:342:in `block in simple'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:497:in `block in around'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:505:in `call'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:498:in `block (2 levels) in around'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:343:in `block (2 levels) in simple'
/home/fred/.gem/ruby/2.3.0/gems/activejob-4.2.6/lib/active_job/logging.rb:23:in `block (4 levels) in <module:Logging>'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/notifications.rb:164:in `block in instrument'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/notifications.rb:164:in `instrument'
/home/fred/.gem/ruby/2.3.0/gems/activejob-4.2.6/lib/active_job/logging.rb:22:in `block (3 levels) in <module:Logging>'
/home/fred/.gem/ruby/2.3.0/gems/activejob-4.2.6/lib/active_job/logging.rb:43:in `block in tag_logger'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/tagged_logging.rb:68:in `block in tagged'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/tagged_logging.rb:26:in `tagged'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/tagged_logging.rb:68:in `tagged'
/home/fred/.gem/ruby/2.3.0/gems/activejob-4.2.6/lib/active_job/logging.rb:43:in `tag_logger'
/home/fred/.gem/ruby/2.3.0/gems/activejob-4.2.6/lib/active_job/logging.rb:19:in `block (2 levels) in <module:Logging>'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:441:in `instance_exec'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:441:in `block in make_lambda'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:342:in `block in simple'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:497:in `block in around'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:505:in `call'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:92:in `__run_callbacks__'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:778:in `_run_perform_callbacks'
/home/fred/.gem/ruby/2.3.0/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:81:in `run_callbacks'
/home/fred/.gem/ruby/2.3.0/gems/activejob-4.2.6/lib/active_job/execution.rb:31:in `perform_now'
/home/fred/.gem/ruby/2.3.0/gems/activejob-4.2.6/lib/active_job/execution.rb:21:in `execute'
/home/fred/.gem/ruby/2.3.0/gems/activejob-4.2.6/lib/active_job/queue_adapters/sidekiq_adapter.rb:42:in `perform'
/home/fred/.gem/ruby/2.3.0/gems/sidekiq-4.1.1/lib/sidekiq/processor.rb:151:in `execute_job'
/home/fred/.gem/ruby/2.3.0/gems/sidekiq-4.1.1/lib/sidekiq/processor.rb:133:in `block (2 levels) in process'
/home/fred/.gem/ruby/2.3.0/gems/sidekiq-4.1.1/lib/sidekiq/middleware/chain.rb:127:in `block in invoke'
/home/fred/.gem/ruby/2.3.0/gems/sidekiq-4.1.1/lib/sidekiq/middleware/server/active_record.rb:6:in `call'
/home/fred/.gem/ruby/2.3.0/gems/sidekiq-4.1.1/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/home/fred/.gem/ruby/2.3.0/gems/sidekiq-4.1.1/lib/sidekiq/middleware/server/retry_jobs.rb:74:in `call'
/home/fred/.gem/ruby/2.3.0/gems/sidekiq-4.1.1/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/home/fred/.gem/ruby/2.3.0/gems/sidekiq-4.1.1/lib/sidekiq/middleware/server/logging.rb:11:in `block in call'
/home/fred/.gem/ruby/2.3.0/gems/sidekiq-4.1.1/lib/sidekiq/logging.rb:31:in `with_context'
/home/fred/.gem/ruby/2.3.0/gems/sidekiq-4.1.1/lib/sidekiq/middleware/server/logging.rb:7:in `call'
/home/fred/.gem/ruby/2.3.0/gems/sidekiq-4.1.1/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/home/fred/.gem/ruby/2.3.0/gems/sidekiq-4.1.1/lib/sidekiq/middleware/chain.rb:132:in `invoke'
/home/fred/.gem/ruby/2.3.0/gems/sidekiq-4.1.1/lib/sidekiq/processor.rb:128:in `block in process'
/home/fred/.gem/ruby/2.3.0/gems/sidekiq-4.1.1/lib/sidekiq/processor.rb:167:in `stats'
/home/fred/.gem/ruby/2.3.0/gems/sidekiq-4.1.1/lib/sidekiq/processor.rb:127:in `process'
/home/fred/.gem/ruby/2.3.0/gems/sidekiq-4.1.1/lib/sidekiq/processor.rb:79:in `process_one'
/home/fred/.gem/ruby/2.3.0/gems/sidekiq-4.1.1/lib/sidekiq/processor.rb:67:in `run'
/home/fred/.gem/ruby/2.3.0/gems/sidekiq-4.1.1/lib/sidekiq/util.rb:16:in `watchdog'
/home/fred/.gem/ruby/2.3.0/gems/sidekiq-4.1.1/lib/sidekiq/util.rb:24:in `block in safe_thread'

...with the key lines being:

2016-05-23T23:26:14.795Z 27761 TID-grijk WARN: RuntimeError: eventmachine not initialized: evma_connect_to_unix_server
2016-05-23T23:26:14.795Z 27761 TID-grijk WARN: /home/fred/.gem/ruby/2.3.0/gems/eventmachine-1.2.0.1/lib/eventmachine.rb:680:in `connect_unix_server'

erickrause commented 8 years ago

Seems odd. I haven't looked at the code in a year or so. I'll take a look.

synthead commented 8 years ago

Scratch that, it looks like it doesn't accept redis://127.0.0.1:6379 as well, so it's not limited to sockets.

erickrause commented 8 years ago

@synthead I couldn't replicate. So I created a demo app to test. I had never configured redis to use sockets before so I had to learn that. Thank you. You can find the demo app here. https://github.com/erickrause/activejob-locks-example

synthead commented 8 years ago

Wow, this is really great! Thank you! I'll dig into the repo tomorrow and compare it to my project piece-by-piece to see what's going on here.

synthead commented 8 years ago

Oh gross, you know what the issue is? I'm also using websocket-rails and it is throwing this exception regardless that these jobs have nothing to do with it. I added the websocket-rails gem to the project, and without even calling it at all, it breaks ActiveJob. Yikes!

I didn't mention it because I didn't think it had anything to do with this issue, but it totally does. Sorry to bother; you've been awesome.

synthead commented 8 years ago

Actually, now that I realize it, it looks like this only happens when lock_by is called in a job. This might be websocket-rails or activejob-locks; I'm not sure. Perhaps the logic for activejob-locks could be contained in a namespace in Redis or something?

Here, check out this branch (forked from your repository). Notice that LockedJob.perform_now("foo") from a rails console displays this output:

Performing LockedJob from Sidekiq(default) with arguments: "foof"
Performed LockedJob from Sidekiq(default) in 2.58ms
RuntimeError: eventmachine not initialized: evma_connect_to_server
from /home/fred/.gem/ruby/2.3.0/gems/eventmachine-1.2.0.1/lib/eventmachine.rb:677:in `connect_server'

...but when the lock_by line is commented-out, the job runs just fine:

Performing LockedJob from Sidekiq(default) with arguments: "foo"
awesome foo
Performed LockedJob from Sidekiq(default) in 15004.9ms
=> nil

erickrause / activejob-locks

Exception when using alongside websocket-rails: RuntimeError: eventmachine not initialized: evma_connect_to_unix_server #1