sidekiq-unique-jobs: Similar but unique keys are being treated as non-unique and conflicting with lock

Describe the bug

Similar, but different, unique keys are being marked as the same and skipping the job altogether

Expected behavior The job will run because it is unique

Current behavior A job that should run is getting skipped

Worker class

class MyWorker
  include Sidekiq::Worker
  sidekiq_options lock: :while_executing, queue: :undefault
  def perform(id, table_name, file_key); end
end

Additional context Sets of args

3269, app_safts, app_safts0000_part_00
3275, app_safts, app_safts0001_part_00
3276, app_safts, app_safts0002_part_00
3281, app_safts, app_safts0003_part_00

The set 3275, app_safts, app_safts0001_part_00 got skipped. I have ~25 tables and their accompanying file sets that get queued around the same time and randomly a few of them will get skipped. I’ve logged where the jobs get queued to ensure the same job is not getting queued more than once

On version 7.1.2

I have also done a version with

  def self.lock_args(args)
     [args.last]
  end

which led to more jobs getting skipped

About this issue

Original URL
State: open
Created 3 years ago
Comments: 17 (6 by maintainers)

Most upvoted comments

I have a similar case and it reproduces stably on versions 7.1.5, 7.1.3 and 7.1.1. Worker:

class TestWorker
  include Sidekiq::Worker

  sidekiq_options retry: false,
                  lock: :until_and_while_executing,
                  lock_args_method: ->(args) { [args.first] },
                  # lock_timeout: 2,
                  on_conflict: :raise,
                  queue: :default

  def perform(id); end
end

When pushing a lot of tasks, sometimes collisions occur:

10000.times { |x| TestWorker.perform_async(x) }
...
2021-08-12T08:15:54.976Z pid=820626 tid=gmy6e7f06 class=TestWorker jid=d526805cc4c31f1faa404328 elapsed=0.073 INFO: fail
2021-08-12T08:15:54.981Z pid=820626 tid=gmy6e7f06 class=TestWorker jid=d526805cc4c31f1faa404328 INFO: delete_by_digest(uniquejobs:1c223f9177e709981b84b02450a5fdc3) completed in 5ms
2021-08-12T08:15:54.981Z pid=820626 tid=gmy6e7f06 WARN: {"context":"Job raised exception","job":{"retry":false,"queue":"default","lock":"until_and_while_executing","lock_args_method":"#<Proc:0x00007fa75ee74ca0@/home/yura/test/app/workers/test_worker.rb:6 (lambda)>","on_conflict":"raise","class":"TestWorker","args":[15101],"jid":"d526805cc4c31f1faa404328","created_at":1628756137.2082617,"locale":"ru","lock_timeout":0,"lock_ttl":null,"lock_prefix":"uniquejobs","lock_args":[15101],"lock_digest":"uniquejobs:1c223f9177e709981b84b02450a5fdc3","enqueued_at":1628756137.2092724},"jobstr":"{\"retry\":false,\"queue\":\"default\",\"lock\":\"until_and_while_executing\",\"lock_args_method\":\"#<Proc:0x00007fa75ee74ca0@/home/yura/test/app/workers/test_worker.rb:6 (lambda)>\",\"on_conflict\":\"raise\",\"class\":\"TestWorker\",\"args\":[15101],\"jid\":\"d526805cc4c31f1faa404328\",\"created_at\":1628756137.2082617,\"locale\":\"ru\",\"lock_timeout\":0,\"lock_ttl\":null,\"lock_prefix\":\"uniquejobs\",\"lock_args\":[15101],\"lock_digest\":\"uniquejobs:1c223f9177e709981b84b02450a5fdc3\",\"enqueued_at\":1628756137.2092724}"}
2021-08-12T08:15:54.982Z pid=820626 tid=gmy6e7f06 WARN: SidekiqUniqueJobs::Conflict: Item with the key: uniquejobs:1c223f9177e709981b84b02450a5fdc3:RUN is already scheduled or processing
2021-08-12T08:15:54.982Z pid=820626 tid=gmy6e7f06 WARN: /home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-unique-jobs-7.1.5/lib/sidekiq_unique_jobs/on_conflict/raise.rb:13:in `call'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-unique-jobs-7.1.5/lib/sidekiq_unique_jobs/lock/base_lock.rb:121:in `call_strategy'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-unique-jobs-7.1.5/lib/sidekiq_unique_jobs/lock/while_executing.rb:43:in `block in execute'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-unique-jobs-7.1.5/lib/sidekiq_unique_jobs/logging.rb:123:in `block in with_logging_context'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-6.2.1/lib/sidekiq/logger.rb:11:in `with'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-unique-jobs-7.1.5/lib/sidekiq_unique_jobs/logging.rb:138:in `call'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-unique-jobs-7.1.5/lib/sidekiq_unique_jobs/logging.rb:138:in `with_configured_loggers_context'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-unique-jobs-7.1.5/lib/sidekiq_unique_jobs/logging.rb:122:in `with_logging_context'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-unique-jobs-7.1.5/lib/sidekiq_unique_jobs/lock/while_executing.rb:42:in `execute'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-unique-jobs-7.1.5/lib/sidekiq_unique_jobs/lock/until_and_while_executing.rb:37:in `execute'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-unique-jobs-7.1.5/lib/sidekiq_unique_jobs/middleware/server.rb:25:in `call'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-unique-jobs-7.1.5/lib/sidekiq_unique_jobs/middleware.rb:41:in `block in call'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-unique-jobs-7.1.5/lib/sidekiq_unique_jobs/logging.rb:123:in `block in with_logging_context'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-6.2.1/lib/sidekiq/logger.rb:11:in `with'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-unique-jobs-7.1.5/lib/sidekiq_unique_jobs/logging.rb:138:in `call'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-unique-jobs-7.1.5/lib/sidekiq_unique_jobs/logging.rb:138:in `with_configured_loggers_context'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-unique-jobs-7.1.5/lib/sidekiq_unique_jobs/logging.rb:122:in `with_logging_context'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-unique-jobs-7.1.5/lib/sidekiq_unique_jobs/middleware.rb:40:in `call'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-6.2.1/lib/sidekiq/middleware/chain.rb:140:in `block in invoke'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/i18n-1.8.10/lib/i18n.rb:314:in `with_locale'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-6.2.1/lib/sidekiq/middleware/i18n.rb:22:in `call'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-6.2.1/lib/sidekiq/middleware/chain.rb:140:in `block in invoke'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-6.2.1/lib/sidekiq/middleware/chain.rb:143:in `invoke'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-6.2.1/lib/sidekiq/processor.rb:163:in `block in process'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-6.2.1/lib/sidekiq/processor.rb:136:in `block (6 levels) in dispatch'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-6.2.1/lib/sidekiq/job_retry.rb:112:in `local'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-6.2.1/lib/sidekiq/processor.rb:135:in `block (5 levels) in dispatch'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-6.2.1/lib/sidekiq/rails.rb:14:in `block in call'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-5.2.6/lib/active_support/execution_wrapper.rb:87:in `wrap'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-5.2.6/lib/active_support/reloader.rb:73:in `block in wrap'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-5.2.6/lib/active_support/execution_wrapper.rb:87:in `wrap'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-5.2.6/lib/active_support/reloader.rb:72:in `wrap'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-6.2.1/lib/sidekiq/rails.rb:13:in `call'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-6.2.1/lib/sidekiq/processor.rb:131:in `block (4 levels) in dispatch'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-6.2.1/lib/sidekiq/processor.rb:257:in `stats'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-6.2.1/lib/sidekiq/processor.rb:126:in `block (3 levels) in dispatch'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-6.2.1/lib/sidekiq/job_logger.rb:13:in `call'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-6.2.1/lib/sidekiq/processor.rb:125:in `block (2 levels) in dispatch'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-6.2.1/lib/sidekiq/job_retry.rb:79:in `global'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-6.2.1/lib/sidekiq/processor.rb:124:in `block in dispatch'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-6.2.1/lib/sidekiq/logger.rb:11:in `with'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-6.2.1/lib/sidekiq/job_logger.rb:33:in `prepare'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-6.2.1/lib/sidekiq/processor.rb:123:in `dispatch'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-6.2.1/lib/sidekiq/processor.rb:162:in `process'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-6.2.1/lib/sidekiq/processor.rb:78:in `process_one'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-6.2.1/lib/sidekiq/processor.rb:68:in `run'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-6.2.1/lib/sidekiq/util.rb:43:in `watchdog'
/home/yura/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/sidekiq-6.2.1/lib/sidekiq/util.rb:52:in `block in safe_thread'

Maybe this will help find the reason.

yoreek on Aug 12, 2021

LMK if want to hop on a zoom call to look at it

ryanbjones on Jul 28, 2021

deleted the old one as some time had passed. tag me and I’ll post a new link 😃

ryanbjones on Jul 30, 2021

@mhenrixon just saw this, but tomorrow I can do tomorrow morning. I’ll look to get on around 7 am MDT

ryanbjones on Jul 29, 2021

I’m in MDT (Utah) and could do either day. If I need to wake up early let me know 😃

ryanbjones on Jul 28, 2021