incorrect :until_and_while_executing behavior

[roman-melnyk]

Describe the bug
enqueue the job with until_and_while_executing lock policy 2 times with interval 1 second

Expected behavior
second job should be performed right after first job finished

Current behavior
second job is not performed

Worker class

class TestJob
  include Sidekiq::Worker

  sidekiq_options(
    queue: 'test_queue',
    unique: :until_and_while_executing
  )

  def perform(*arguments)
    Rails.logger.info "!!!!!! start"
    sleep 10
    Rails.logger.info "!!!!!! finish"
  end
end

Additional context
here is a log from 'sidekiq', '5.2.5' and 'sidekiq-unique-jobs', '5.0.10', second job has been performed

>> TestJob.perform_async 'foo'
[Newrelic::CustomMetricService] record Custom/Sidekiq::Queue::TestQueue/size, 0
[Newrelic::CustomMetricService] record Custom/Sidekiq::Queue::TestQueue/latency, 0
=> "e25789130a376a14942e7009"
>> TestJob.perform_async 'foo'
[Newrelic::CustomMetricService] record Custom/Sidekiq::Queue::TestQueue/size, 0
[Newrelic::CustomMetricService] record Custom/Sidekiq::Queue::TestQueue/latency, 0
=> "58a290f384405a89087cb162"

2019-09-27T12:35:14.948Z 9748 TID-gt8pzi1ao TestJob JID-e25789130a376a14942e7009 INFO: start
2019-09-27T12:35:14.949Z 9748 TID-gt8pzi1ao TestJob JID-e25789130a376a14942e7009 SidekiqUniqueJobs::UniqueArgs DEBUG: unique_args : unique arguments disabled
2019-09-27T12:35:14.949Z 9748 TID-gt8pzi1ao TestJob JID-e25789130a376a14942e7009 SidekiqUniqueJobs::UniqueArgs DEBUG: unique_digest : {"class"=>"TestJob", "queue"=>"test_queue", "unique_args"=>["foo"]} into uniquejobs:c3bd986d71c5f4ff21ed14cbafae3b28
2019-09-27T12:35:14.949Z 9748 TID-gt8pzi1ao TestJob JID-e25789130a376a14942e7009 DEBUG: successfully unlocked uniquejobs:c3bd986d71c5f4ff21ed14cbafae3b28
2019-09-27T12:35:14.950Z 9748 TID-gt8pzi1ao TestJob JID-e25789130a376a14942e7009 INFO: !!!!!! start
2019-09-27T12:35:16.390Z 9748 TID-gt8pzi1ic TestJob JID-58a290f384405a89087cb162 INFO: start
2019-09-27T12:35:24.950Z 9748 TID-gt8pzi1ao TestJob JID-e25789130a376a14942e7009 INFO: !!!!!! finish
2019-09-27T12:35:24.951Z 9748 TID-gt8pzi1ao TestJob JID-e25789130a376a14942e7009 INFO: done: 10.003 sec
2019-09-27T12:35:24.970Z 9748 TID-gt8pzi1ic TestJob JID-58a290f384405a89087cb162 SidekiqUniqueJobs::UniqueArgs DEBUG: unique_args : unique arguments disabled
2019-09-27T12:35:24.970Z 9748 TID-gt8pzi1ic TestJob JID-58a290f384405a89087cb162 SidekiqUniqueJobs::UniqueArgs DEBUG: unique_digest : {"class"=>"TestJob", "queue"=>"test_queue", "unique_args"=>["foo"]} into uniquejobs:c3bd986d71c5f4ff21ed14cbafae3b28
2019-09-27T12:35:24.971Z 9748 TID-gt8pzi1ic TestJob JID-58a290f384405a89087cb162 DEBUG: successfully unlocked uniquejobs:c3bd986d71c5f4ff21ed14cbafae3b28
2019-09-27T12:35:24.972Z 9748 TID-gt8pzi1ic TestJob JID-58a290f384405a89087cb162 INFO: !!!!!! start
2019-09-27T12:35:34.972Z 9748 TID-gt8pzi1ic TestJob JID-58a290f384405a89087cb162 INFO: !!!!!! finish
2019-09-27T12:35:34.973Z 9748 TID-gt8pzi1ic TestJob JID-58a290f384405a89087cb162 INFO: done: 18.583 sec

and this is from 'sidekiq', '6.0.0', 'sidekiq-unique-jobs', '6.0.13', only first job has been actually performed

>> TestJob.perform_async 'foo'
[Newrelic::CustomMetricService] record Custom/Sidekiq::Queue::TestQueue/size, 0
[Newrelic::CustomMetricService] record Custom/Sidekiq::Queue::TestQueue/latency, 0
=> "6d0682cac6dc7801ba56c444"
>> TestJob.perform_async 'foo'
[Newrelic::CustomMetricService] record Custom/Sidekiq::Queue::TestQueue/size, 0
[Newrelic::CustomMetricService] record Custom/Sidekiq::Queue::TestQueue/latency, 0
=> "4b52f07568118778e9cf1a51"

2019-09-27T12:39:39.128Z pid=14503 tid=gn6hegfxn class=TestJob jid=6d0682cac6dc7801ba56c444 INFO: start
2019-09-27T12:39:39.136Z pid=14503 tid=gn6hegfxn class=TestJob jid=6d0682cac6dc7801ba56c444 middleware=SidekiqUniqueJobs::Server::Middleware unique_digest=uniquejobs:c3bd986d71c5f4ff21ed14cbafae3b28 INFO: !!!!!! start
2019-09-27T12:39:40.608Z pid=14503 tid=gn6hegdaz class=TestJob jid=4b52f07568118778e9cf1a51 INFO: start
2019-09-27T12:39:40.611Z pid=14503 tid=gn6hegdaz class=TestJob jid=4b52f07568118778e9cf1a51 elapsed=0.004 INFO: done
2019-09-27T12:39:49.136Z pid=14503 tid=gn6hegfxn class=TestJob jid=6d0682cac6dc7801ba56c444 middleware=SidekiqUniqueJobs::Server::Middleware unique_digest=uniquejobs:c3bd986d71c5f4ff21ed14cbafae3b28 INFO: !!!!!! finish
2019-09-27T12:39:49.140Z pid=14503 tid=gn6hegfxn class=TestJob jid=6d0682cac6dc7801ba56c444 elapsed=10.011 INFO: done

[robinsingh-bw]

I think the second job quits because the first job already has a lock on the 'running' key. I have the same issue, tried resolving it with the on_conflict: :reschedule strategy but ran into stack level too deep.

I have a job that should not be run simultaneously but if it gets scheduled while another instance of the same job is already running, it should wait for that instance to finish and then run again. Is this possible with sidekiq unique jobs?

[mhenrixon]

reschedule doesn't work with the first part @robinsingh-bw. If you want, give 7.0.0.beta1 a try and see if that gives you better results.

Please in that case do try out the worker validation. v7 will allow you to configure the client and server conflict resolutions separately.

[robinsingh-bw]

Tried the beta, the client/server conflict resolution doesnt seem to be fully implemented yet so had to create a hack:

module SidekiqUniqueJobs
  class Lock
    class UntilAndWhileExecuting
      def runtime_lock
        server_item = item.dup
        server_item.merge!(SidekiqUniqueJobs::ON_CONFLICT => item[SidekiqUniqueJobs::ON_CONFLICT]["server"]) if server_item[SidekiqUniqueJobs::ON_CONFLICT].is_a?(Hash)
        @runtime_lock ||= SidekiqUniqueJobs::Lock::WhileExecuting.new(server_item, callback, redis_pool)
      end

      def strategy
        client_item = item.dup
        client_item.merge!(SidekiqUniqueJobs::ON_CONFLICT => item[SidekiqUniqueJobs::ON_CONFLICT]["client"]) if client_item[SidekiqUniqueJobs::ON_CONFLICT].is_a?(Hash)
        @strategy ||= OnConflict.find_strategy(client_item[SidekiqUniqueJobs::ON_CONFLICT]).new(client_item, redis_pool)
      end
    end
  end
end

Btw which keys does v7 use? I need to check if a unique job is scheduled, I am doing this atm:

Sidekiq.redis{ |red| red.exists(uniq_id(user_id, ':RUN:EXISTS')) || red.exists(uniq_id(user_id, ':RUN')) }

Should I continue checking for both keys or can it be replaced with one of them - which one?

Thanks

[robinsingh-bw]

Redis::CommandError: ERR Error running script (call to f_1234): @user_script:33: @user_script: 33: This Redis command is not allowed from scripts

SidekiqUniqueJobs::ScriptError:
@user_script: 33: This Redis command is not allowed from scripts

    30: 
    31: --------  BEGIN local functions --------
    32: local function redis_version()
 => 33:   local serverinfo = redis.call("INFO", "SERVER")
    34:   local _, _, maj, min, pat = string.find(serverinfo, "redis_version%:(%d+)%.(%d+)%.(%d+)")
    35:   return {
    36:     ["version"] = maj .. "." .. min .. "." .. pat,

Reverted to v6 :p, might wanna update the readme for v7 btw as people running on heroku will likely run into the above error.

[mhenrixon]

What redis version are you on @robinsingh-bw? I've been testing with the latest redis and it works fine locally at least and also on travis.

[robinsingh-bw]

@mhenrixon I am using Redis Cloud on Heroku. Not sure which version it is, but the error has to do with permissions, user scripts are not allowed to run the redis.call("INFO", "SERVER") command.

[mhenrixon]

That is a real bummer but I can certainly work around that. Will create a PR to fix it and I will get back to you on the other questions.

The Sidekiq::Web has been extended and if you use config.lock_info = true you will get detailed information about all the keys.

[mhenrixon]

@robinsingh-bw #431 will fix the problem with scripts not being allowed to retrieve server info I hope. If not then you'll have to ask your provider nicely to enable such information for all the performance gains! :D