Sidekiq: Rails says job was enqueued but it's not appearing in redis in development?

[NielsKSchjoedt]

In development ENV I have noticed a strange behaviour. When I enqueue a sidekiq job, it does not appear in the queue and hence no job gets executed when I try to start sidekiq. This only seems to happen in development.

[2] pry(main)> Rails.env
=> "development"
[3] pry(main)> AuRatingRefreshJob.perform_later(735)
Enqueued AuRatingRefreshJob (Job ID: a0fc6cc9-2e58-49fb-b573-403da1f6824e) to Sidekiq(default) with arguments: 735
=> #<AuRatingRefreshJob:0x007fc23c74be80 @arguments=[735], @job_id="a0fc6cc9-2e58-49fb-b573-403da1f6824e", @priority=nil, @provider_job_id="4068eaa08afd9ab7820bb0a0", @queue_name="default">
[4] pry(main)> Sidekiq::Queue.new('default').count
=> 0

As you can see, no sidekiq processes are running on my computer, so it's not because the job get's consumed:

Nielsk@my-car-data: $ ps aux | grep sidekiq
Nielsk          41523   0,0  0,0  2442020    884 s006  S+    3:23pm   0:00.00 grep sidekiq

And no other redis instances are running neither:

Nielsk@my-car-data: $ ps aux | grep redis
Nielsk           1142   0,0  0,0  2506960   2872   ??  S    Tor10pm   0:20.12 /usr/local/opt/redis/bin/redis-server 127.0.0.1:6379 
Nielsk          41663   0,0  0,0  2432804    872 s006  S+    3:26pm   0:00.00 grep redis

This is my job class:

class AuRatingRefreshJob < ApplicationJob
  queue_as :default

  def perform(car_id)
    car = Car.find(car_id)
    car.refresh_au_valuation
    car.save!
  end
end

And here is my initializers/sidekiq.rb

Sidekiq.configure_server do |config|
  config.redis = {url: 'redis://localhost:6379/0', network_timeout: 5}
end

Sidekiq.configure_client do |config|
  config.redis = {url: 'redis://localhost:6379/0', network_timeout: 5}
end

Ruby version: 2.3

Rails 5.0.0.1
Sidekiq: 4.2.6

[mperham]

Run redis-cli monitor and do it again. It'll give you the clue necessary to solve the mystery.

[NielsKSchjoedt]

Thanks, did that now - enqueueing the job with: AuRatingRefreshJob.perform_later(735) is not showing anything, where as the the queue lookup Sidekiq::Queue.new('default').count shows:

1481565368.016131 [0 127.0.0.1:53569] "llen" "queue:default"
1481565368.017356 [0 127.0.0.1:53569] "lrange" "queue:default" "0" "49"

So apparently nothing get's send to redis - strange - any idea what could cause that, and how I can further debug it?

[mperham]

I'd guess that ActiveJob is not configured to use Sidekiq correctly? Try creating a job with a native Sidekiq::Worker and see if that works?

[mperham]

Possible you have Sidekiq::Testing.fake! or something like that activated?

[NielsKSchjoedt]

I now tried sidekiq directly, same thing...

[3] pry(main)> class HardWorker
[3] pry(main)*   include Sidekiq::Worker  
[3] pry(main)*   def perform(name, count)  
[3] pry(main)*     # do something    
[3] pry(main)*   end    
[3] pry(main)* end  
=> :perform
[4] pry(main)> HardWorker.perform_async(1,2)
=> "48e61bfd4ec6112af32b3a24"
[5] pry(main)> Sidekiq::Queue.new('default').count
=> 0

[NielsKSchjoedt]

I searched for anything sidekiq related in the project, which is not supposed to be there (like Sidekiq::Testing.fake!), nothing came up.

My gem file looks like this:

source 'https://rubygems.org'
ruby '2.3.1'

gem 'rails', '5.0.0.1'

gem 'pg', '0.18.4'
gem 'puma', '3.4.0'
gem 'storext', '~> 2.2.0'
gem 'pundit', '1.1.0'
gem 'honeybadger', '~> 2.0'
gem 'paperclip', '~> 5.0.0'
gem 'aws-sdk'
gem 'active_model_serializers'
gem 'apipie-rails'

gem 'scoped_search'
gem 'kaminari'
gem 'newrelic_rpm'

# View layer
gem 'jquery-rails'
gem 'coffee-rails'
gem 'js_cookie_rails'
gem 'sass-rails'
gem 'uglifier'
gem 'haml-rails'
gem 'simple_form'
gem 'bootstrap-sass'
gem 'dropzonejs-rails', git: 'https://github.com/radubogdan/dropzonejs-rails.git'
gem 'bourbon', '~> 4.2.1'
gem 'selectize-rails', '~> 0.12'
gem 'clipboard-rails', '~> 1.5'

gem 'dalli'

# Model
gem 'draper', '> 3.x'
gem 'exonio'
gem 'ranked-model'

gem 'sidekiq'
gem 'delayed_paperclip'
gem "sinatra", ">= 2.0.0.beta2", require: false # https://github.com/mperham/sidekiq/issues/2839
gem 'slim'
gem 'httparty'

group :development, :test do
  gem 'byebug', '9.0.5', platform: :mri
  gem 'rspec-rails'
  gem 'rails-controller-testing'
  gem 'factory_girl_rails'
  gem 'database_cleaner'
  gem 'pry-rails'
  gem 'pry-rescue'
  gem 'pry-stack_explorer'
  gem 'rspec-sidekiq'
  gem 'rubocop'
end

group :development do
  gem 'listen', '3.0.8'
  gem 'spring'
  gem 'spring-watcher-listen', '2.0.0'
  gem 'web-console'
end

group :test do
  gem 'timecop'
  gem 'vcr'
  gem 'webmock'
  gem 'simplecov', :require => false
  gem 'simplecov-badge', git: "https://github.com/radubogdan/simplecov-badge", :require => false
end

[mperham]

You can get rid of sinatra and slim in your Gemfile, those aren't used by Sidekiq anymore.

Your problem is that you have rspec-sidekiq in the development group.

https://github.com/philostler/rspec-sidekiq#installation

[cshupp1]

@NielsKSchjoedt
@mperham

Did you ever get this issue resolved?

I am having the same issue.

my version from Gemfile.lock:

    sidekiq (5.0.4)
      concurrent-ruby (~> 1.0)
      connection_pool (~> 2.2, >= 2.2.0)
      rack-protection (>= 1.5.0)
      redis (~> 3.3, >= 3.3.3)
    sidekiq-scheduler (2.1.7)
      redis (~> 3)
      rufus-scheduler (~> 3.2)
      sidekiq (>= 3)
      tilt (>= 1.4.0)

After reading this I did move rspec-sidekiq to a test only group (it was in dev and test like yours) but I am skeptical it was part of my issue.

Consider the following class:

class HardWorker
  include Sidekiq::Worker
  def perform
    puts "Howdy ho neighbor!"
  end
end

in irb:

[13] pry(main)> HardWorker.new.perform
Howdy ho neighbor!

As expected, but asynchronously... No luck:

```
[15] pry(main)> HardWorker.perform_async
=> "4508bdfa4813e50abd0c742c"

I never see the stdout, but c:\utilities\Redis\redis-cli.exe monitor) yields:

1510099744.685941 [0 127.0.0.1:54352] "multi"
1510099744.685992 [0 127.0.0.1:54352] "sadd" "queues" "default"
1510099744.685999 [0 127.0.0.1:54352] "lpush" "queue:default" "{\"class\":\"HardWorker\",\"args\":[],\"retry\":true,\"queue\":\"default\",\"jid\":\"4508bdfa4813e50abd0c742c\",\"created_at\":1510099744.68
5287,\"enqueued_at\":1510099744.685287}"
1510099744.686029 [0 127.0.0.1:54352] "exec"
````

I am skeptical testing is hurting me:

[16] pry(main)> Sidekiq::Testing
NameError: uninitialized constant Sidekiq::Testing

Ultimately I need ActiveJob to be responsive, but my results are similar:

Consider:

class LazyWorker < ActiveJob::Base
  def perform
    puts "Not gonna happen!"
  end
end

in my rails console:

[18] pry(main)> LazyWorker.perform_later
Enqueued LazyWorker (Job ID: c2757070-a907-4ef7-8468-ee85b90899ac) to Sidekiq(default)
=> #<LazyWorker:0x0000000d8f15d0 @arguments=[], @job_id="c2757070-a907-4ef7-8468-ee85b90899ac", @queue_name="default">

The log shows:

[ActiveJob] Enqueued LazyWorker (Job ID: c2757070-a907-4ef7-8468-ee85b90899ac) to Sidekiq(default)
````

Reddis:

1510100047.250671 [0 127.0.0.1:54352] "multi"
1510100047.251028 [0 127.0.0.1:54352] "sadd" "queues" "default"
1510100047.251042 [0 127.0.0.1:54352] "lpush" "queue:default" "{\"class\":\"ActiveJob::QueueAdapters::SidekiqAdapter::JobWrapper\",\"wrapped\":\"LazyWorker\",\"queue\":\"default\",\"args\":[{\"job_class\
":\"LazyWorker\",\"job_id\":\"c2757070-a907-4ef7-8468-ee85b90899ac\",\"queue_name\":\"default\",\"arguments\":[]}],\"retry\":true,\"jid\":\"aeec98cfb9ab931930b50444\",\"created_at\":1510100047.249631,\"e
nqueued_at\":1510100047.249631}"
1510100047.251109 [0 127.0.0.1:54352] "exec"
```

Alas, no STDOUT!

[cshupp1]

Forgot to give my ruby version:

[19] pry(main)> RUBY_VERSION
=> "2.3.3"

[mperham]

@cshupp1 Please don't hijack someone else's issue. Open your own.

[cshupp1]

opened:
https://github.com/mperham/sidekiq/issues/3660

[imi56]

You can get rid of sinatra and slim in your Gemfile, those aren't used by Sidekiq anymore.

Your problem is that you have rspec-sidekiq in the development group.

https://github.com/philostler/rspec-sidekiq#installation

In which version?