Job finished, but lock is not cleared

[olegantonyan]

sidekiq-unique-jobs 7.1.12
sidekiq 6.3.1

Job:

module Job
  class TestJob
    include ::Sidekiq::Worker
    sidekiq_options lock: :until_executed, on_conflict: { client: :log }

    def perform
      puts "STARTING"
      sleep 15
      puts "FINISHING"
    end
  end
end

Config:

SidekiqUniqueJobs.configure do |config|
  config.enabled = !Rails.env.test?
  config.lock_ttl = 20.minutes.to_i
  config.lock_info = true
  #config.reaper = :ruby
  #config.reaper_count = 1000
  #config.reaper_interval = 10
  #config.reaper_timeout = 150
end

After upgrading sidekiq and sidekiq-unique-jobs I run 100.times { Job::TestJob.perform_async } in rails console and check /sidekiq/locks. The problem is, when the job has finished the lock stays there and I cannot enqueue more jobs:

2022-01-14T06:23:50.669Z pid=13423 tid=lej uniquejobs=client until_executed=uniquejobs:182d12d729164fb2ca154c1fcfad8ac3 INFO: Skipping job with id (a161966c1809de8f1543ed59) because lock_digest: (uniquejobs:182d12d729164fb2ca154c1fcfad8ac3) already exists

It will eventually expire after lock_ttl, but I want lock_ttl to be high enough for additional safety. Or I can set config.reaper_interval = 10 and this seems to work, but it doesn't look like a proper way of cleaning up locks after successful job runs.

From readme "it is either unlocked when lock_ttl is hit or when Sidekiq has called the perform method on your worker" but in my case sidekiq has successfully called perform, but lock remains active.

It works on sidekiq 5.2.9 and sidekiq-unique-jobs 6.0.22

[olegantonyan]

Here's more info after I did a bit of debugging.

1. in rails console:

[1] pry(main)> Job::TestJob.perform_async
=> "f8425f0ad00c164ac0daab4c"

2. look at http://localhost:3000/sidekiq/locks - one lock "uniquejobs:182d12d729164fb2ca154c1fcfad8ac3" with locked JIDs "f8425f0ad00c164ac0daab4c"
3. the job has finished
4. Locksmith#unlock! called twice.
5. First time argument key.to_a:

09:16:10 sidekiq.1 | [
09:16:10 sidekiq.1 |     [0] "uniquejobs:dbdf4aaf819baaeec4d73d26001195a2",
09:16:10 sidekiq.1 |     [1] "uniquejobs:dbdf4aaf819baaeec4d73d26001195a2:QUEUED",
09:16:10 sidekiq.1 |     [2] "uniquejobs:dbdf4aaf819baaeec4d73d26001195a2:PRIMED",
09:16:10 sidekiq.1 |     [3] "uniquejobs:dbdf4aaf819baaeec4d73d26001195a2:LOCKED",
09:16:10 sidekiq.1 |     [4] "uniquejobs:dbdf4aaf819baaeec4d73d26001195a2:INFO",
09:16:10 sidekiq.1 |     [5] "uniquejobs:changelog",
09:16:10 sidekiq.1 |     [6] "uniquejobs:digests"

argument job_id:
d10585f2dfe7bb0f2433d0ac
6. Second call argument key.to_a:

09:16:11 sidekiq.1 |     [0] "uniquejobs:8e02507d663f97a98cce50821573860f",
09:16:11 sidekiq.1 |     [1] "uniquejobs:8e02507d663f97a98cce50821573860f:QUEUED",
09:16:11 sidekiq.1 |     [2] "uniquejobs:8e02507d663f97a98cce50821573860f:PRIMED",
09:16:11 sidekiq.1 |     [3] "uniquejobs:8e02507d663f97a98cce50821573860f:LOCKED",
09:16:11 sidekiq.1 |     [4] "uniquejobs:8e02507d663f97a98cce50821573860f:INFO",
09:16:11 sidekiq.1 |     [5] "uniquejobs:changelog",
09:16:11 sidekiq.1 |     [6] "uniquejobs:digests"

argument job_id:
2c20db2e70d6b1a788a84c81

None of this makes any sense to me. Where is the real job id? Where those digests came from? They aren't shown in web ui

btw, also this:

SidekiqUniqueJobs.reflect do |on|
  on.unlocked do |job_hash|
    # never called
  end

  on.unlock_failed do |job_hash|
    # never called
  end
end

module Job
  class TestJob
    ....

    def after_unlock
      # never called
    end
  end
end

[olegantonyan]

Nevermind
I messed up client and server midlewares