Can't schedule a job from another job

[heaven]

My code is the next:

class PhoneMessage < ActiveRecord::Base
  def queue
    if self.persisted? and not self.sent?
      Worker::SmsSender.perform_async(self.id)
    end
  end

  def queue_status_check
    if self.persisted? and self.sent?
      Worker::SmsStatusUpdater.perform_at(10.seconds, self.id)
      Worker::SmsStatusUpdater.perform_at(1.minute, self.id)
    end
  end
end

Worker 1:

class Worker::SmsSender
  include Sidekiq::Worker

  sidekiq_options :unique => :until_executed, :unique_expiration => 100.years

  def perform(message_id)
    message = PhoneMessage.where(:id => message_id).first
    return unless message and not message.sent?

    number = message.phone_number
    return unless number.present?

    twilio_message = Twilio::REST::Client.new.account.messages.create(
      :from => Settings.twilio.from_number,
      :to => message.phone_number,
      :body => message.text
    )

    message.sent!(twilio_message.sid)
    message.queue_status_check # This doesn't work
  end
end

Worker 2:

class Worker::SmsStatusUpdater
  include Sidekiq::Worker

  sidekiq_options :unique => :until_executing, :unique_expiration => 100.years

  def perform(message_id)
    message = PhoneMessage.where(:id => message_id).first
    return unless message and message.sent?

    twilio_message = Twilio::REST::Client.new.account.messages.get(message.message_sid)

    message.update_attribute(:status, twilio_message.status)
    message.queue_status_check if message[:status] < 4
  end
end

First worker has until_executed while the second one has until_executing (it also calls message.queue_status_check so by idea could re-schedule itself).

Without the sidekiq_options both workers work as expected:

2015-12-02T14:37:53.028Z 30357 TID-117r950 DEBUG: Middleware: Sidekiq::Middleware::Server::Logging, Sidekiq::Middleware::Server::RetryJobs, Sidekiq::Middleware::Server::ActiveRecord, SidekiqUniqueJobs::Server::Middleware, Sidekiq::Status::ServerMiddleware
2015-12-02T14:37:53.028Z 30357 TID-117r950 INFO: Starting processing, hit Ctrl-C to stop
2015-12-02T14:37:53.097Z 30357 TID-117r950 DEBUG: {:queues=>["default", "mailers", "import", "export"], :labels=>[], :concurrency=>4, :require=>".", :environment=>nil, :timeout=>15, :poll_interval_average=>nil, :average_scheduled_poll_interval=>15, :error_handlers=>[#<Sidekiq::ExceptionHandler::Logger:0x0000010dd160b0>], :lifecycle_events=>{:startup=>[], :quiet=>[], :shutdown=>[]}, :dead_max_jobs=>10000, :dead_timeout_in_seconds=>15552000, :pidfile=>"./tmp/pids/sidekiq.pid", :config_file=>"config/sidekiq-dev.yml", :strict=>true, :tag=>"crm"}
2015-12-02T14:38:42.239Z 30357 TID-130c7m0 Worker::SmsSender JID-06774f37f646e106df47cf89 INFO: start
2015-12-02T14:38:44.734Z 30357 TID-130c7m0 Worker::SmsSender JID-06774f37f646e106df47cf89 INFO: done: 2.495 sec
2015-12-02T14:39:07.201Z 30357 TID-130c7wk DEBUG: enqueued schedule: {"class":"Worker::SmsStatusUpdater","args":[20],"retry":true,"queue":"default","jid":"a9a46c2099ed3d0e96adca11","created_at":1449067124.732828}
2015-12-02T14:39:07.202Z 30357 TID-130c7m0 Worker::SmsStatusUpdater JID-a9a46c2099ed3d0e96adca11 INFO: start
2015-12-02T14:39:10.562Z 30357 TID-130c7m0 Worker::SmsStatusUpdater JID-a9a46c2099ed3d0e96adca11 INFO: done: 3.361 sec
2015-12-02T14:39:47.599Z 30357 TID-130ej5s Worker::SmsStatusUpdater JID-51a88bae95eea6af3331adc5 INFO: start
2015-12-02T14:39:47.599Z 30357 TID-130c7wk DEBUG: enqueued schedule: {"class":"Worker::SmsStatusUpdater","args":[20],"retry":true,"queue":"default","jid":"51a88bae95eea6af3331adc5","created_at":1449067124.733674}
2015-12-02T14:39:49.262Z 30357 TID-130ej5s Worker::SmsStatusUpdater JID-51a88bae95eea6af3331adc5 INFO: done: 1.663 sec

With these options the output is as follows:

2015-12-02T14:42:53.051Z 30776 TID-10vw8i0 DEBUG: Middleware: Sidekiq::Middleware::Server::Logging, Sidekiq::Middleware::Server::RetryJobs, Sidekiq::Middleware::Server::ActiveRecord, SidekiqUniqueJobs::Server::Middleware, Sidekiq::Status::ServerMiddleware
2015-12-02T14:42:53.051Z 30776 TID-10vw8i0 INFO: Starting processing, hit Ctrl-C to stop
2015-12-02T14:42:53.117Z 30776 TID-10vw8i0 DEBUG: {:queues=>["default", "mailers", "import", "export"], :labels=>[], :concurrency=>4, :require=>".", :environment=>nil, :timeout=>15, :poll_interval_average=>nil, :average_scheduled_poll_interval=>15, :error_handlers=>[#<Sidekiq::ExceptionHandler::Logger:0x00000109fad160>], :lifecycle_events=>{:startup=>[], :quiet=>[], :shutdown=>[]}, :dead_max_jobs=>10000, :dead_timeout_in_seconds=>15552000, :pidfile=>"./tmp/pids/sidekiq.pid", :config_file=>"config/sidekiq-dev.yml", :strict=>true, :tag=>"crm"}
2015-12-02T14:43:13.841Z 30776 TID-12jtv8k Worker::SmsSender JID-9e40a8a29caffc759b23017a INFO: start
2015-12-02T14:43:16.915Z 30776 TID-12jtv8k Worker::SmsSender JID-9e40a8a29caffc759b23017a SidekiqUniqueJobs::UniqueArgs DEBUG: unique_args : unique arguments disabled
2015-12-02T14:43:16.915Z 30776 TID-12jtv8k Worker::SmsSender JID-9e40a8a29caffc759b23017a SidekiqUniqueJobs::UniqueArgs DEBUG: unique_digest : {"class"=>"Worker::SmsStatusUpdater", "queue"=>"default", "unique_args"=>[21]} into uniquejobs:b5ff82d3abdda99f6ade1266ebf4e710
2015-12-02T14:43:16.916Z 30776 TID-12jtv8k Worker::SmsSender JID-9e40a8a29caffc759b23017a DEBUG: successfully locked uniquejobs:b5ff82d3abdda99f6ade1266ebf4e710 for 3155760009 seconds
2015-12-02T14:43:16.917Z 30776 TID-12jtv8k Worker::SmsSender JID-9e40a8a29caffc759b23017a SidekiqUniqueJobs::UniqueArgs DEBUG: unique_args : unique arguments disabled
2015-12-02T14:43:16.917Z 30776 TID-12jtv8k Worker::SmsSender JID-9e40a8a29caffc759b23017a SidekiqUniqueJobs::UniqueArgs DEBUG: unique_digest : {"class"=>"Worker::SmsStatusUpdater", "queue"=>"default", "unique_args"=>[21]} into uniquejobs:b5ff82d3abdda99f6ade1266ebf4e710
2015-12-02T14:43:16.918Z 30776 TID-12jtv8k Worker::SmsSender JID-9e40a8a29caffc759b23017a DEBUG: failed to aquire lock for uniquejobs:b5ff82d3abdda99f6ade1266ebf4e710
2015-12-02T14:43:16.918Z 30776 TID-12jtv8k Worker::SmsSender JID-9e40a8a29caffc759b23017a SidekiqUniqueJobs::UniqueArgs DEBUG: unique_args : unique arguments disabled
2015-12-02T14:43:16.918Z 30776 TID-12jtv8k Worker::SmsSender JID-9e40a8a29caffc759b23017a DEBUG: unique_digest : {"class"=>"Worker::SmsSender", "queue"=>"default", "unique_args"=>[21]} into uniquejobs:cd8993a7e26f7e392a67b813bed400a0
2015-12-02T14:43:16.920Z 30776 TID-12jtv8k Worker::SmsSender JID-9e40a8a29caffc759b23017a DEBUG: successfully unlocked uniquejobs:cd8993a7e26f7e392a67b813bed400a0
2015-12-02T14:43:16.920Z 30776 TID-12jtv8k Worker::SmsSender JID-9e40a8a29caffc759b23017a INFO: done: 3.079 sec
2015-12-02T14:43:34.794Z 30776 TID-12ju9v8 SidekiqUniqueJobs::UniqueArgs DEBUG: unique_args : unique arguments disabled
2015-12-02T14:43:34.795Z 30776 TID-12ju9v8 DEBUG: unique_digest : {"class"=>"Worker::SmsStatusUpdater", "queue"=>"default", "unique_args"=>[21]} into uniquejobs:b5ff82d3abdda99f6ade1266ebf4e710
2015-12-02T14:43:34.795Z 30776 TID-12ju9v8 DEBUG: failed to aquire lock for uniquejobs:b5ff82d3abdda99f6ade1266ebf4e710
2015-12-02T14:43:34.795Z 30776 TID-12ju9v8 DEBUG: enqueued schedule: {"class":"Worker::SmsStatusUpdater","args":[21],"retry":true,"queue":"default","unique":"until_executing","unique_expiration":"3155760000.0","jid":"86b88964eeea21e95325fec6","created_at":1449067396.914665,"unique_prefix":"uniquejobs","unique_args":[21],"unique_digest":"uniquejobs:b5ff82d3abdda99f6ade1266ebf4e710"}

[heaven]

You can see the last job status remains queued, the job is missing from the queue, but the lock persists:

[mhenrixon]

Roger that! Great tip with the Redis Desktop Manager 👍

[heaven]

Thanks a lot! 👍

[mathieujobin]

we are still having an issue very similar to this
we have 4 different workers, two of them having similar issue.
the two workers are using unique: :until_executing and they are rescheduling themselves recursively to run every 15 seconds in one case, and every 3 hours in the other one...

we just enabled that verbose debug option that is showing that it fails to aquire the lock.

the way I understand the difference between until_executed and until_executing is that the former does not allow scheduling during execution. while the latter allow it. but any special consideration to recursive jobs?

the weirdest thing, is that for one one server, we haven't experienced the issue yet.
and on the other server, it is happening all the time.
also, for the same worker, different different argument. it will work fine in one case but not in the other.

no errors in the logs except for the DEBUG: failed to aquire lock for uniquejobs:xyz

jobs also complete their execution, the last line is a log entry which gets called everytime.

any idea what could be happening ?

CC: @ecnalyr