sidekiq-unique-jobs: Question about until_timeout with 6.0.0

Formerly with 5.0.10 I had a job that did this:

  unique: :until_timeout,
  lock_expiration: 1.minute.to_i,

It’s a little unclear but looking at the updated readme & pr’s, the correct options in 6.0.0 is:

  lock: :until_expired,
  lock_expiration: 1.minute.to_i,

The goal is to have a job that will execute not more often than once a minute, given identical args. Eg,

Whatever.perform_async id: 1, group: 'x' # => job executes
Whatever.perform_async id: 2, group: 'a' # => job executes 
Whatever.perform_async id: 1, group: 'x' # => discarded
Whatever.perform_async id: 1, group: 'x' # => discarded

# wait at least 1 minute
Whatever.perform_async id: 1, group: 'x' # => job executes

Is that correct?

About this issue

Original URL
State: closed
Created 6 years ago
Comments: 19 (11 by maintainers)

Commits related to this issue

Bug fixes (#310) * Allow keys to be expired After calling PERSIST in LUA expiring a key does not EXPIRE. This should close ##303 * Delete the right key from the unique keys set * Adds covera... — committed to zormandi/sidekiq-unique-jobs by mhenrixon 6 years ago

Most upvoted comments

Okay, I have a new example that does not use sleep, in case that was affecting the expiration logic.

Not using unique args:

# simple_until_expired_worker2.rb
class SimpleUntilExpiredWorker2
  include Sidekiq::Worker
  sidekiq_options lock: :until_expired,
                  queue: :default,
                  lock_expiration: 3,
                  on_conflict: :log

  def perform(some_args)
    warn "executed #{jid} with #{some_args}"
  end
end

In rails c I just hit up arrow and enter once per second for a few seconds to re-run the perform_async on a cadence:

[80] pry(main)> SimpleUntilExpiredWorker2.perform_async 1
=> "52111483a97dcde770218cdb"
[81] pry(main)> SimpleUntilExpiredWorker2.perform_async 1
2018-08-02T13:46:03.335Z 3296 TID-oxyof8w54 INFO: skipping job with id (1f68dd13af0c40784b893d20) because unique_digest: (uniquejobs:90f9b01ac21ca0bbfd9e0cb0e9b3a461) already exists
=> "1f68dd13af0c40784b893d20"
[82] pry(main)> SimpleUntilExpiredWorker2.perform_async 1
2018-08-02T13:46:04.493Z 3296 TID-oxyof8w54 INFO: skipping job with id (199b4fdf62930cbe24e70e58) because unique_digest: (uniquejobs:90f9b01ac21ca0bbfd9e0cb0e9b3a461) already exists
=> "199b4fdf62930cbe24e70e58"
[83] pry(main)> SimpleUntilExpiredWorker2.perform_async 1
2018-08-02T13:46:05.461Z 3296 TID-oxyof8w54 INFO: skipping job with id (bc97b1839d267fca19281279) because unique_digest: (uniquejobs:90f9b01ac21ca0bbfd9e0cb0e9b3a461) already exists
=> "bc97b1839d267fca19281279"
[84] pry(main)> SimpleUntilExpiredWorker2.perform_async 1
2018-08-02T13:46:06.484Z 3296 TID-oxyof8w54 INFO: skipping job with id (f9368d532405971e92b74e5c) because unique_digest: (uniquejobs:90f9b01ac21ca0bbfd9e0cb0e9b3a461) already exists
=> "f9368d532405971e92b74e5c"
[85] pry(main)> SimpleUntilExpiredWorker2.perform_async 1
2018-08-02T13:46:07.591Z 3296 TID-oxyof8w54 INFO: skipping job with id (15136b41cb19042e3a0bcd23) because unique_digest: (uniquejobs:90f9b01ac21ca0bbfd9e0cb0e9b3a461) already exists
=> "15136b41cb19042e3a0bcd23"

sidekiq:

2018-08-02T13:46:02.973Z 3328 TID-oxh5guemo SimpleUntilExpiredWorker2 JID-52111483a97dcde770218cdb INFO: start
executed 52111483a97dcde770218cdb with 1
2018-08-02T13:46:02.986Z 3328 TID-oxh5guemo SimpleUntilExpiredWorker2 JID-52111483a97dcde770218cdb INFO: done: 0.013 sec
2018-08-02T13:46:03.336Z 3328 TID-oxh5hiccw SimpleUntilExpiredWorker2 JID-1f68dd13af0c40784b893d20 INFO: start
2018-08-02T13:46:03.339Z 3328 TID-oxh5hiccw SimpleUntilExpiredWorker2 JID-1f68dd13af0c40784b893d20 INFO: done: 0.002 sec
2018-08-02T13:46:04.495Z 3328 TID-oxh5hiccw SimpleUntilExpiredWorker2 JID-199b4fdf62930cbe24e70e58 INFO: start
2018-08-02T13:46:04.499Z 3328 TID-oxh5hiccw SimpleUntilExpiredWorker2 JID-199b4fdf62930cbe24e70e58 INFO: done: 0.004 sec
2018-08-02T13:46:05.484Z 3328 TID-oxh5guemo SimpleUntilExpiredWorker2 JID-bc97b1839d267fca19281279 INFO: start
2018-08-02T13:46:05.486Z 3328 TID-oxh5guemo SimpleUntilExpiredWorker2 JID-bc97b1839d267fca19281279 INFO: done: 0.002 sec
2018-08-02T13:46:06.487Z 3328 TID-oxh5hiccw SimpleUntilExpiredWorker2 JID-f9368d532405971e92b74e5c INFO: start
2018-08-02T13:46:06.489Z 3328 TID-oxh5hiccw SimpleUntilExpiredWorker2 JID-f9368d532405971e92b74e5c INFO: done: 0.003 sec
2018-08-02T13:46:07.593Z 3328 TID-oxh5hiccw SimpleUntilExpiredWorker2 JID-15136b41cb19042e3a0bcd23 INFO: start
2018-08-02T13:46:07.596Z 3328 TID-oxh5hiccw SimpleUntilExpiredWorker2 JID-15136b41cb19042e3a0bcd23 INFO: done: 0.002 sec

The output is the same: execute, skip, skip, skip, skip, skip. I’m not super concerned about precise millisecond expirations, but hopefully you agree that at least job 15136b41cb19042e3a0bcd23 should have executed (the last one) since it’s much later than 3 seconds after the first job.

I can tell that it can unlock, so I recognize that. Here’s another test where I ran 3 jobs quickly, waited a few seconds, then ran it one more time. I expected: execute, skip, skip, execute and that is what happened.

[194] pry(main)> SimpleUntilExpiredWorker2.perform_async 1
=> "726317a6e1b42e058161a308"
[195] pry(main)> SimpleUntilExpiredWorker2.perform_async 1
2018-08-02T13:58:15.528Z 3296 TID-oxyof8w54 INFO: skipping job with id (3479da7c0db50f4e31576491) because unique_digest: (uniquejobs:90f9b01ac21ca0bbfd9e0cb0e9b3a461) already exists
=> "3479da7c0db50f4e31576491"
[196] pry(main)> SimpleUntilExpiredWorker2.perform_async 1
2018-08-02T13:58:15.874Z 3296 TID-oxyof8w54 INFO: skipping job with id (e72d0108a498486e6cf03c6a) because unique_digest: (uniquejobs:90f9b01ac21ca0bbfd9e0cb0e9b3a461) already exists
=> "e72d0108a498486e6cf03c6a"
[197] pry(main)> SimpleUntilExpiredWorker2.perform_async 1
=> "39c86641cd7d25f4c8eee815"

2018-08-02T13:58:15.158Z 3328 TID-oxh5guemo SimpleUntilExpiredWorker2 JID-726317a6e1b42e058161a308 INFO: start
executed 726317a6e1b42e058161a308 with 1
2018-08-02T13:58:15.161Z 3328 TID-oxh5guemo SimpleUntilExpiredWorker2 JID-726317a6e1b42e058161a308 INFO: done: 0.003 sec
2018-08-02T13:58:15.545Z 3328 TID-oxh5hiccw SimpleUntilExpiredWorker2 JID-3479da7c0db50f4e31576491 INFO: start
2018-08-02T13:58:15.547Z 3328 TID-oxh5hiccw SimpleUntilExpiredWorker2 JID-3479da7c0db50f4e31576491 INFO: done: 0.002 sec
2018-08-02T13:58:15.876Z 3328 TID-oxh5guemo SimpleUntilExpiredWorker2 JID-e72d0108a498486e6cf03c6a INFO: start
2018-08-02T13:58:15.878Z 3328 TID-oxh5guemo SimpleUntilExpiredWorker2 JID-e72d0108a498486e6cf03c6a INFO: done: 0.002 sec
2018-08-02T13:58:21.957Z 3328 TID-oxh5guemo SimpleUntilExpiredWorker2 JID-39c86641cd7d25f4c8eee815 INFO: start
executed 39c86641cd7d25f4c8eee815 with 1
2018-08-02T13:58:21.959Z 3328 TID-oxh5guemo SimpleUntilExpiredWorker2 JID-39c86641cd7d25f4c8eee815 INFO: done: 0.002 sec

It’s almost like the lock is being taken out even when a job is a duplicate, and then released on schedule. That could explain why a repeated cadence of once per second is continually skipping execution, whereas explicitly waiting until the expiration window has passed will successfully execute the job.

aharpervc on Aug 2, 2018

@aharpervc found the bug. The UntilExpired was missing some coverage unfortunately, I’ll have it fixed shortly.

mhenrixon on Jul 31, 2018