sidekiq-unique-jobs until_and_while_executing job timeout on the server

until_and_while_executing job timeout on the server

Open dsander opened this issue 2 years ago • 1 comments

Describe the bug

We have a couple of our until_and_while_executing job fail to run because the lock could not be acquired on the server side.

Worker configuration (the actual worker inherits the sidekiq unique configuration):

class BaseWorker
  include Sidekiq::Worker

  sidekiq_options queue: :remote_encode, retry: false, lock: :until_and_while_executing

  def self.lock_args(args)
    [args.first['asset_id'].to_s]
  end
end

Global sidekiq unique configuration:

SidekiqUniqueJobs.configure do |config|
  config.debug_lua       = false
  config.lock_ttl        = nil
  config.lock_timeout    = 0
  config.logger          = ENV["RACK_ENV"] == "test" ? Logger.new("/dev/null") : Sidekiq.logger
  config.max_history     = 10_000
  config.reaper          = :ruby
  config.reaper_count    = 100
  config.reaper_interval = 60
  config.reaper_timeout  = 5
  config.lock_info       = true
end

SidekiqUniqueJobs.reflect do |on|
  # This job is skipped because it is a duplicate
  on.duplicate do |job_hash|
    Sidekiq.logger.info(job_hash.merge(message: "Duplicate Job"))
  end

  # Failed to acquire lock in a timely fashion
  on.lock_failed do |job_hash|
    Sidekiq.logger.info(job_hash.merge(message: "Lock failed"))
  end

  on.timeout do |job_hash|
    Sidekiq.logger.error(job_hash.merge(message: "Oh no! Timeout!! Timeout!!"))
  end

  # Unlock failed! Not good
  on.unlock_failed do |job_hash|
    Sidekiq.logger.error(job_hash.merge(message: "Unlock failed"))
  end
end

The job is enqueued on a different machine running a different sidekiq process:

local4.log:2021-08-09T20:46:45.248Z pid=24148 tid=120w class=FolderIndexJob jid=e20f2662a1e660a80a768bdb uniquejobs=server until_and_while_executing=uniquejobs:2dcff163baa6f55dd11a609a2733d983:RUN INFO: Enqueued EncodeImageJob jid=a817e55ba2e6683b3842ee47: Asset id=8242835 `QCBN000A223H_24_seconds.gif`

It then fails to start:

2021-08-09T20:46:45.268Z pid=28830 tid=oyi class=EncodeImageJob jid=a817e55ba2e6683b3842ee47 INFO: start
2021-08-09T20:46:45.285Z pid=28830 tid=oyi class=EncodeImageJob jid=a817e55ba2e6683b3842ee47 uniquejobs=server until_and_while_executing=uniquejobs:0ed6f5c12952ebc2a61567295a62e6fd DEBUG: Executed unlock.lua in 0ms
2021-08-09T20:46:45.313Z pid=28830 tid=oyi class=EncodeImageJob jid=a817e55ba2e6683b3842ee47 uniquejobs=server until_and_while_executing=uniquejobs:0ed6f5c12952ebc2a61567295a62e6fd:RUN DEBUG: Executed queue.lua in 1ms
2021-08-09T20:46:45.341Z pid=28830 tid=oyi class=EncodeImageJob jid=a817e55ba2e6683b3842ee47 uniquejobs=server until_and_while_executing=uniquejobs:0ed6f5c12952ebc2a61567295a62e6fd:RUN ERROR: {"retry"=>false, "queue"=>"remote_encode_high", "lock"=>"until_and_while_executing", "class"=>"EncodeImageJob", "args"=>[{"asset_id"=>8242835, "destination"=>"test/QCBN000A223H_24_seconds.gif/585a32759dcc872fa16e67a9", "resolution"=>"same_as_source", "thumbnail_width"=>216, "thumbnail_height"=>122, "preview_width"=>640, "preview_height"=>360, "animation_width"=>216, "animation_height"=>122, "aspect_ratio"=>nil, "label_position"=>"bottom", "duration"=>nil, "labels"=>nil, "label_burnin"=>false, "timecode_burnin"=>false, "channels"=>0, "scan_type"=>nil, "create_editing_proxy"=>false, "framerate"=>nil, "source_resolution"=>":", "files"=>[{"path"=>" test/QCBN000A223H_24_seconds.gif", "video_track_count"=>0, "audio_track_count"=>0, "track_number"=>nil, "track_languages"=>nil}], "skip_mixdown"=>false, "ikegami"=>false}], "jid"=>"a817e55ba2e6683b3842ee47", "created_at"=>1628542005.246907, "lock_timeout"=>0, "lock_ttl"=>nil, "lock_prefix"=>"uniquejobs", "lock_args"=>["8242835"], "lock_digest"=>"uniquejobs:0ed6f5c12952ebc2a61567295a62e6fd:RUN", "enqueued_at"=>1628542005.2483728, :message=>"Oh no! Timeout!! Timeout!!"}
2021-08-09T20:46:45.342Z pid=28830 tid=oyi class=EncodeImageJob jid=a817e55ba2e6683b3842ee47 elapsed=0.074 INFO: done

Since a lot of jobs process successully on the server this seems to be a random bug. Sadly I don't have any more information currently because lock_info does not seem to create anything in sidekiq web. The locks that are shown there are valid and from jobs that are still running or enqueued.

We are running the master branch on this commit: https://github.com/mhenrixon/sidekiq-unique-jobs/commit/921aaa4efc998b102790d1f4ecce2ebac609e464

For now we will try to set lock_timeout to 1. Any additional pointers would be greatly appreciated.

Aug 10 '21 10:08 dsander

It looks like that this is some kind of race condition, with lock_timeout = 1 we have not seen the error happen again.

Not sure if it helps, here is the output of redis-cli MONITOR for a job that times out:

1628764099.309871 [0 172.19.0.10:36136] "hexists" "uniquejobs:611212fd5c8e11832e6474607118cbf3:LOCKED" "83c47235d3f9ee8c82492b3d"
1628764099.310672 [0 172.19.0.10:36136] "evalsha" "abfb0cdb69a6141c58e02b5b32eb398e6ec23327" "7" "uniquejobs:611212fd5c8e11832e6474607118cbf3" "uniquejobs:611212fd5c8e11832e6474607118cbf3:QUEUED" "uniquejobs:611212fd5c8e11832e6474607118cbf3:PRIMED" "uniquejobs:611212fd5c8e11832e6474607118cbf3:LOCKED" "uniquejobs:611212fd5c8e11832e6474607118cbf3:INFO" "uniquejobs:changelog" "uniquejobs:digests" "83c47235d3f9ee8c82492b3d" "0" "until_and_while_executing" "1" "1628764099.3105803" "false" "10000" "queue" "5.0.10"1628764099.310703 [0 lua] "LLEN" "uniquejobs:611212fd5c8e11832e6474607118cbf3:QUEUED"
1628764099.310708 [0 lua] "HLEN" "uniquejobs:611212fd5c8e11832e6474607118cbf3:LOCKED"
1628764099.310713 [0 lua] "HEXISTS" "uniquejobs:611212fd5c8e11832e6474607118cbf3:LOCKED" "83c47235d3f9ee8c82492b3d"
1628764099.310717 [0 lua] "GET" "uniquejobs:611212fd5c8e11832e6474607118cbf3"
1628764099.310720 [0 lua] "SET" "uniquejobs:611212fd5c8e11832e6474607118cbf3" "83c47235d3f9ee8c82492b3d"
1628764099.310726 [0 lua] "LPUSH" "uniquejobs:611212fd5c8e11832e6474607118cbf3:QUEUED" "83c47235d3f9ee8c82492b3d"
1628764099.310736 [0 lua] "ZADD" "uniquejobs:changelog" "1628764099.3105803" "{\"message\":\"Queued\",\"job_id\":\"83c47235d3f9ee8c82492b3d\",\"time\":1628764099.3106,\"script\":\"queue.lua\",\"digest\":\"uniquejobs:611212fd5c8e11832e6474607118cbf3\"}"
1628764099.310765 [0 lua] "PUBLISH" "uniquejobs:changelog" "{\"message\":\"Queued\",\"job_id\":\"83c47235d3f9ee8c82492b3d\",\"time\":1628764099.3106,\"script\":\"queue.lua\",\"digest\":\"uniquejobs:611212fd5c8e11832e6474607118cbf3\"}"
1628764099.311147 [0 172.19.0.10:36136] "set" "uniquejobs:611212fd5c8e11832e6474607118cbf3:INFO" "{\"worker\":\"FolderIndexJob\",\"queue\":\"local\",\"limit\":null,\"timeout\":0,\"ttl\":null,\"type\":\"until_and_while_executing\",\"lock_args\":[\"BigAssProject\",\"media_2\",\"Avid MediaFiles/MXF\"],\"time\":1628764099.3110871}"
1628764099.313133 [0 172.19.0.10:36136] "rpoplpush" "uniquejobs:611212fd5c8e11832e6474607118cbf3:QUEUED" "uniquejobs:611212fd5c8e11832e6474607118cbf3:PRIMED"
1628764099.318133 [0 172.19.0.10:36136] "evalsha" "6b19e074438c866811c5333789cb0956acb8c30f" "7" "uniquejobs:611212fd5c8e11832e6474607118cbf3" "uniquejobs:611212fd5c8e11832e6474607118cbf3:QUEUED" "uniquejobs:611212fd5c8e11832e6474607118cbf3:PRIMED" "uniquejobs:611212fd5c8e11832e6474607118cbf3:LOCKED" "uniquejobs:611212fd5c8e11832e6474607118cbf3:INFO" "uniquejobs:changelog" "uniquejobs:digests" "83c47235d3f9ee8c82492b3d" "0" "until_and_while_executing" "1" "1628764099.3180509" "false" "10000" "lock" "5.0.10"
1628764099.318168 [0 lua] "HEXISTS" "uniquejobs:611212fd5c8e11832e6474607118cbf3:LOCKED" "83c47235d3f9ee8c82492b3d"
1628764099.318174 [0 lua] "HLEN" "uniquejobs:611212fd5c8e11832e6474607118cbf3:LOCKED"
1628764099.318180 [0 lua] "ZADD" "uniquejobs:digests" "1628764099.3180509" "uniquejobs:611212fd5c8e11832e6474607118cbf3"
1628764099.318221 [0 lua] "HSET" "uniquejobs:611212fd5c8e11832e6474607118cbf3:LOCKED" "83c47235d3f9ee8c82492b3d" "1628764099.3180509"
1628764099.318228 [0 lua] "LREM" "uniquejobs:611212fd5c8e11832e6474607118cbf3:QUEUED" "-1" "83c47235d3f9ee8c82492b3d"
1628764099.318309 [0 lua] "LREM" "uniquejobs:611212fd5c8e11832e6474607118cbf3:PRIMED" "1" "83c47235d3f9ee8c82492b3d"
1628764099.318317 [0 lua] "PEXPIRE" "uniquejobs:611212fd5c8e11832e6474607118cbf3:QUEUED" "1000"
1628764099.318321 [0 lua] "PEXPIRE" "uniquejobs:611212fd5c8e11832e6474607118cbf3:PRIMED" "1000"
1628764099.318325 [0 lua] "PEXPIRE" "uniquejobs:611212fd5c8e11832e6474607118cbf3:INFO" "1000"
1628764099.318336 [0 lua] "ZADD" "uniquejobs:changelog" "1628764099.3180509" "{\"message\":\"Locked\",\"job_id\":\"83c47235d3f9ee8c82492b3d\",\"time\":1628764099.3181,\"script\":\"lock.lua\",\"digest\":\"uniquejobs:611212fd5c8e11832e6474607118cbf3\"}"
1628764099.318357 [0 lua] "PUBLISH" "uniquejobs:changelog" "{\"message\":\"Locked\",\"job_id\":\"83c47235d3f9ee8c82492b3d\",\"time\":1628764099.3181,\"script\":\"lock.lua\",\"digest\":\"uniquejobs:611212fd5c8e11832e6474607118cbf3\"}"
1628764099.319527 [0 172.19.0.10:36136] "lpush" "queue:local" "{\"retry\":false,\"queue\":\"local\",\"lock\":\"until_and_while_executing\",\"class\":\"FolderIndexJob\",\"args\":[\"BigAssProject\",{\"mode\":\"rescan\",\"storage\":\"media_2\",\"path\":\"Avid MediaFiles/MXF\",\"recursive\":true,\"priority\":\"normal\",\"delegator_jid\":\"ec6086cea254bdb8591f4b2c\",\"parent_folder_id\":3481}],\"jid\":\"83c47235d3f9ee8c82492b3d\",\"created_at\":1628764099.309691,\"lock_timeout\":0,\"lock_ttl\":null,\"lock_prefix\":\"uniquejobs\",\"lock_args\":[\"BigAssProject\",\"media_2\",\"Avid MediaFiles/MXF\"],\"lock_digest\":\"uniquejobs:611212fd5c8e11832e6474607118cbf3\",\"enqueued_at\":1628764099.3194392}"
1628764099.394887 [0 172.19.0.10:36128] "hexists" "uniquejobs:611212fd5c8e11832e6474607118cbf3:LOCKED" "83c47235d3f9ee8c82492b3d"
1628764099.400848 [0 172.19.0.10:36128] "evalsha" "d4094f5627c0fd5babfc2e1a7defe2e848d2ca1d" "7" "uniquejobs:611212fd5c8e11832e6474607118cbf3" "uniquejobs:611212fd5c8e11832e6474607118cbf3:QUEUED" "uniquejobs:611212fd5c8e11832e6474607118cbf3:PRIMED" "uniquejobs:611212fd5c8e11832e6474607118cbf3:LOCKED" "uniquejobs:611212fd5c8e11832e6474607118cbf3:INFO" "uniquejobs:changelog" "uniquejobs:digests" "83c47235d3f9ee8c82492b3d" "0" "until_and_while_executing" "1" "1628764099.4007509" "false" "10000" "unlock" "5.0.10"
1628764099.400905 [0 lua] "LLEN" "uniquejobs:611212fd5c8e11832e6474607118cbf3:QUEUED"
1628764099.400911 [0 lua] "LLEN" "uniquejobs:611212fd5c8e11832e6474607118cbf3:PRIMED"
1628764099.400915 [0 lua] "HLEN" "uniquejobs:611212fd5c8e11832e6474607118cbf3:LOCKED"
1628764099.400922 [0 lua] "HEXISTS" "uniquejobs:611212fd5c8e11832e6474607118cbf3:LOCKED" "83c47235d3f9ee8c82492b3d"
1628764099.400930 [0 lua] "LREM" "uniquejobs:611212fd5c8e11832e6474607118cbf3:QUEUED" "-1" "83c47235d3f9ee8c82492b3d"
1628764099.400935 [0 lua] "LREM" "uniquejobs:611212fd5c8e11832e6474607118cbf3:PRIMED" "-1" "83c47235d3f9ee8c82492b3d"
1628764099.400940 [0 lua] "ZREM" "uniquejobs:digests" "uniquejobs:611212fd5c8e11832e6474607118cbf3"
1628764099.400951 [0 lua] "UNLINK" "uniquejobs:611212fd5c8e11832e6474607118cbf3" "uniquejobs:611212fd5c8e11832e6474607118cbf3:INFO"
1628764099.400965 [0 lua] "HDEL" "uniquejobs:611212fd5c8e11832e6474607118cbf3:LOCKED" "83c47235d3f9ee8c82492b3d"
1628764099.400971 [0 lua] "LPUSH" "uniquejobs:611212fd5c8e11832e6474607118cbf3:QUEUED" "1"
1628764099.400977 [0 lua] "PEXPIRE" "uniquejobs:611212fd5c8e11832e6474607118cbf3:QUEUED" "5000"
1628764099.400988 [0 lua] "ZADD" "uniquejobs:changelog" "1628764099.4007509" "{\"message\":\"Unlocked\",\"job_id\":\"83c47235d3f9ee8c82492b3d\",\"time\":1628764099.4008,\"script\":\"unlock.lua\",\"digest\":\"uniquejobs:611212fd5c8e11832e6474607118cbf3\"}"
1628764099.401036 [0 lua] "PUBLISH" "uniquejobs:changelog" "{\"message\":\"Unlocked\",\"job_id\":\"83c47235d3f9ee8c82492b3d\",\"time\":1628764099.4008,\"script\":\"unlock.lua\",\"digest\":\"uniquejobs:611212fd5c8e11832e6474607118cbf3\"}"
1628764099.411550 [0 172.19.0.10:36128] "hexists" "uniquejobs:611212fd5c8e11832e6474607118cbf3:RUN:LOCKED" "83c47235d3f9ee8c82492b3d"
1628764099.471193 [0 172.19.0.10:36128] "evalsha" "abfb0cdb69a6141c58e02b5b32eb398e6ec23327" "7" "uniquejobs:611212fd5c8e11832e6474607118cbf3:RUN" "uniquejobs:611212fd5c8e11832e6474607118cbf3:RUN:QUEUED" "uniquejobs:611212fd5c8e11832e6474607118cbf3:RUN:PRIMED" "uniquejobs:611212fd5c8e11832e6474607118cbf3:RUN:LOCKED" "uniquejobs:611212fd5c8e11832e6474607118cbf3:RUN:INFO" "uniquejobs:changelog" "uniquejobs:digests" "83c47235d3f9ee8c82492b3d" "0" "until_and_while_executing" "1" "1628764099.4710343" "false" "10000" "queue" "5.0.10"
1628764099.471265 [0 lua] "LLEN" "uniquejobs:611212fd5c8e11832e6474607118cbf3:RUN:QUEUED"
1628764099.471273 [0 lua] "HLEN" "uniquejobs:611212fd5c8e11832e6474607118cbf3:RUN:LOCKED"
1628764099.471281 [0 lua] "HEXISTS" "uniquejobs:611212fd5c8e11832e6474607118cbf3:RUN:LOCKED" "83c47235d3f9ee8c82492b3d"
1628764099.471286 [0 lua] "GET" "uniquejobs:611212fd5c8e11832e6474607118cbf3:RUN"
1628764099.471292 [0 lua] "SET" "uniquejobs:611212fd5c8e11832e6474607118cbf3:RUN" "83c47235d3f9ee8c82492b3d"
1628764099.471300 [0 lua] "LPUSH" "uniquejobs:611212fd5c8e11832e6474607118cbf3:RUN:QUEUED" "83c47235d3f9ee8c82492b3d"
1628764099.471320 [0 lua] "ZADD" "uniquejobs:changelog" "1628764099.4710343" "{\"message\":\"Queued\",\"job_id\":\"83c47235d3f9ee8c82492b3d\",\"time\":1628764099.471,\"script\":\"queue.lua\",\"digest\":\"uniquejobs:611212fd5c8e11832e6474607118cbf3:RUN\"}"
1628764099.471349 [0 lua] "PUBLISH" "uniquejobs:changelog" "{\"message\":\"Queued\",\"job_id\":\"83c47235d3f9ee8c82492b3d\",\"time\":1628764099.471,\"script\":\"queue.lua\",\"digest\":\"uniquejobs:611212fd5c8e11832e6474607118cbf3:RUN\"}"
1628764099.471533 [0 172.19.0.10:36128] "set" "uniquejobs:611212fd5c8e11832e6474607118cbf3:RUN:INFO" "{\"worker\":\"FolderIndexJob\",\"queue\":\"local\",\"limit\":null,\"timeout\":0,\"ttl\":null,\"type\":\"until_and_while_executing\",\"lock_args\":[\"BigAssProject\",\"media_2\",\"Avid MediaFiles/MXF\"],\"time\":1628764099.4714677}"
1628764099.507180 [0 172.19.0.10:36128] "rpoplpush" "uniquejobs:611212fd5c8e11832e6474607118cbf3:RUN:QUEUED" "uniquejobs:611212fd5c8e11832e6474607118cbf3:RUN:PRIMED"

And a second one that works as expected:

1628764107.341229 [0 172.19.0.10:36138] "hexists" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:LOCKED" "960310791ed315596bf8322b"
1628764107.342144 [0 172.19.0.10:36138] "evalsha" "abfb0cdb69a6141c58e02b5b32eb398e6ec23327" "7" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:QUEUED" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:PRIMED" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:LOCKED" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:INFO" "uniquejobs:changelog" "uniquejobs:digests" "960310791ed315596bf8322b" "0" "until_and_while_executing" "1" "1628764107.3420732" "false" "10000" "queue" "5.0.10"1628764107.342184 [0 lua] "LLEN" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:QUEUED"
1628764107.342188 [0 lua] "HLEN" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:LOCKED"
1628764107.342194 [0 lua] "HEXISTS" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:LOCKED" "960310791ed315596bf8322b"
1628764107.342198 [0 lua] "GET" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1"
1628764107.342202 [0 lua] "SET" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1" "960310791ed315596bf8322b"
1628764107.342208 [0 lua] "LPUSH" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:QUEUED" "960310791ed315596bf8322b"
1628764107.342220 [0 lua] "ZADD" "uniquejobs:changelog" "1628764107.3420732" "{\"message\":\"Queued\",\"job_id\":\"960310791ed315596bf8322b\",\"time\":1628764107.3421,\"script\":\"queue.lua\",\"digest\":\"uniquejobs:9f737c99b86b46e7aca8a01414f417c1\"}"
1628764107.342256 [0 lua] "PUBLISH" "uniquejobs:changelog" "{\"message\":\"Queued\",\"job_id\":\"960310791ed315596bf8322b\",\"time\":1628764107.3421,\"script\":\"queue.lua\",\"digest\":\"uniquejobs:9f737c99b86b46e7aca8a01414f417c1\"}"
1628764107.342538 [0 172.19.0.10:36138] "set" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:INFO" "{\"worker\":\"FolderIndexJob\",\"queue\":\"local\",\"limit\":null,\"timeout\":0,\"ttl\":null,\"type\":\"until_and_while_executing\",\"lock_args\":[\"predlink\",\"media_2\",\"Linked-Files/preditor/fufufuf\"],\"time\":1628764107.3424733}"
1628764107.344669 [0 172.19.0.10:36138] "rpoplpush" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:QUEUED" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:PRIMED"
1628764107.346400 [0 172.19.0.10:36138] "evalsha" "6b19e074438c866811c5333789cb0956acb8c30f" "7" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:QUEUED" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:PRIMED" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:LOCKED" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:INFO" "uniquejobs:changelog" "uniquejobs:digests" "960310791ed315596bf8322b" "0" "until_and_while_executing" "1" "1628764107.3463335" "false" "10000" "lock" "5.0.10"
1628764107.346431 [0 lua] "HEXISTS" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:LOCKED" "960310791ed315596bf8322b"
1628764107.346436 [0 lua] "HLEN" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:LOCKED"
1628764107.346441 [0 lua] "ZADD" "uniquejobs:digests" "1628764107.3463335" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1"
1628764107.346450 [0 lua] "HSET" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:LOCKED" "960310791ed315596bf8322b" "1628764107.3463335"
1628764107.346457 [0 lua] "LREM" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:QUEUED" "-1" "960310791ed315596bf8322b"
1628764107.346461 [0 lua] "LREM" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:PRIMED" "1" "960310791ed315596bf8322b"
1628764107.346468 [0 lua] "PEXPIRE" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:QUEUED" "1000"
1628764107.346471 [0 lua] "PEXPIRE" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:PRIMED" "1000"
1628764107.346475 [0 lua] "PEXPIRE" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:INFO" "1000"
1628764107.346483 [0 lua] "ZADD" "uniquejobs:changelog" "1628764107.3463335" "{\"message\":\"Locked\",\"job_id\":\"960310791ed315596bf8322b\",\"time\":1628764107.3463,\"script\":\"lock.lua\",\"digest\":\"uniquejobs:9f737c99b86b46e7aca8a01414f417c1\"}"
1628764107.346501 [0 lua] "PUBLISH" "uniquejobs:changelog" "{\"message\":\"Locked\",\"job_id\":\"960310791ed315596bf8322b\",\"time\":1628764107.3463,\"script\":\"lock.lua\",\"digest\":\"uniquejobs:9f737c99b86b46e7aca8a01414f417c1\"}"
1628764107.348996 [0 172.19.0.10:36138] "lpush" "queue:local" "{\"retry\":false,\"queue\":\"local\",\"lock\":\"until_and_while_executing\",\"class\":\"FolderIndexJob\",\"args\":[\"predlink\",{\"mode\":\"rescan\",\"storage\":\"media_2\",\"path\":\"Linked-Files/preditor/fufufuf\",\"recursive\":true,\"priority\":\"normal\",\"delegator_jid\":\"461815d1980879722b741292\",\"parent_folder_id\":806}],\"jid\":\"960310791ed315596bf8322b\",\"created_at\":1628764107.3410277,\"lock_timeout\":0,\"lock_ttl\":null,\"lock_prefix\":\"uniquejobs\",\"lock_args\":[\"predlink\",\"media_2\",\"Linked-Files/preditor/fufufuf\"],\"lock_digest\":\"uniquejobs:9f737c99b86b46e7aca8a01414f417c1\",\"enqueued_at\":1628764107.348914}"
1628764107.351352 [0 172.19.0.10:36130] "hexists" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:LOCKED" "960310791ed315596bf8322b"
1628764107.352727 [0 172.19.0.10:36130] "evalsha" "d4094f5627c0fd5babfc2e1a7defe2e848d2ca1d" "7" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:QUEUED" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:PRIMED" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:LOCKED" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:INFO" "uniquejobs:changelog" "uniquejobs:digests" "960310791ed315596bf8322b" "0" "until_and_while_executing" "1" "1628764107.3526514" "false" "10000" "unlock" "5.0.10"
1628764107.352758 [0 lua] "LLEN" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:QUEUED"
1628764107.352762 [0 lua] "LLEN" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:PRIMED"
1628764107.352765 [0 lua] "HLEN" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:LOCKED"
1628764107.352771 [0 lua] "HEXISTS" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:LOCKED" "960310791ed315596bf8322b"
1628764107.352777 [0 lua] "LREM" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:QUEUED" "-1" "960310791ed315596bf8322b"
1628764107.352782 [0 lua] "LREM" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:PRIMED" "-1" "960310791ed315596bf8322b"
1628764107.352787 [0 lua] "ZREM" "uniquejobs:digests" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1"
1628764107.352797 [0 lua] "UNLINK" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:INFO"
1628764107.352804 [0 lua] "HDEL" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:LOCKED" "960310791ed315596bf8322b"
1628764107.352808 [0 lua] "LPUSH" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:QUEUED" "1"
1628764107.352813 [0 lua] "PEXPIRE" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:QUEUED" "5000"
1628764107.352821 [0 lua] "ZADD" "uniquejobs:changelog" "1628764107.3526514" "{\"message\":\"Unlocked\",\"job_id\":\"960310791ed315596bf8322b\",\"time\":1628764107.3527,\"script\":\"unlock.lua\",\"digest\":\"uniquejobs:9f737c99b86b46e7aca8a01414f417c1\"}"
1628764107.352839 [0 lua] "PUBLISH" "uniquejobs:changelog" "{\"message\":\"Unlocked\",\"job_id\":\"960310791ed315596bf8322b\",\"time\":1628764107.3527,\"script\":\"unlock.lua\",\"digest\":\"uniquejobs:9f737c99b86b46e7aca8a01414f417c1\"}"
1628764107.354506 [0 172.19.0.10:36130] "hexists" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:LOCKED" "960310791ed315596bf8322b"
1628764107.355002 [0 172.19.0.10:36130] "evalsha" "abfb0cdb69a6141c58e02b5b32eb398e6ec23327" "7" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:QUEUED" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:PRIMED" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:LOCKED" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:INFO" "uniquejobs:changelog" "uniquejobs:digests" "960310791ed315596bf8322b" "0" "until_and_while_executing" "1" "1628764107.354934" "false" "10000" "queue" "5.0.10"
1628764107.355046 [0 lua] "LLEN" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:QUEUED"
1628764107.355052 [0 lua] "HLEN" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:LOCKED"
1628764107.355066 [0 lua] "HEXISTS" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:LOCKED" "960310791ed315596bf8322b"
1628764107.355071 [0 lua] "GET" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN"
1628764107.355075 [0 lua] "SET" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN" "960310791ed315596bf8322b"
1628764107.355080 [0 lua] "LPUSH" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:QUEUED" "960310791ed315596bf8322b"
1628764107.355091 [0 lua] "ZADD" "uniquejobs:changelog" "1628764107.354934" "{\"message\":\"Queued\",\"job_id\":\"960310791ed315596bf8322b\",\"time\":1628764107.3549,\"script\":\"queue.lua\",\"digest\":\"uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN\"}"
1628764107.355110 [0 lua] "PUBLISH" "uniquejobs:changelog" "{\"message\":\"Queued\",\"job_id\":\"960310791ed315596bf8322b\",\"time\":1628764107.3549,\"script\":\"queue.lua\",\"digest\":\"uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN\"}"
1628764107.355540 [0 172.19.0.10:36130] "set" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:INFO" "{\"worker\":\"FolderIndexJob\",\"queue\":\"local\",\"limit\":null,\"timeout\":0,\"ttl\":null,\"type\":\"until_and_while_executing\",\"lock_args\":[\"predlink\",\"media_2\",\"Linked-Files/preditor/fufufuf\"],\"time\":1628764107.3554807}"
1628764107.358083 [0 172.19.0.10:36130] "rpoplpush" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:QUEUED" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:PRIMED"
1628764107.360655 [0 172.19.0.10:36130] "evalsha" "6b19e074438c866811c5333789cb0956acb8c30f" "7" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:QUEUED" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:PRIMED" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:LOCKED" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:INFO" "uniquejobs:changelog" "uniquejobs:digests" "960310791ed315596bf8322b" "0" "until_and_while_executing" "1" "1628764107.360584" "false" "10000" "lock" "5.0.10"
1628764107.360698 [0 lua] "HEXISTS" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:LOCKED" "960310791ed315596bf8322b"
1628764107.360705 [0 lua] "HLEN" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:LOCKED"
1628764107.360710 [0 lua] "ZADD" "uniquejobs:digests" "1628764107.360584" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN"
1628764107.360720 [0 lua] "HSET" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:LOCKED" "960310791ed315596bf8322b" "1628764107.360584"
1628764107.360726 [0 lua] "LREM" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:QUEUED" "-1" "960310791ed315596bf8322b"
1628764107.360731 [0 lua] "LREM" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:PRIMED" "1" "960310791ed315596bf8322b"
1628764107.360738 [0 lua] "PEXPIRE" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:QUEUED" "1000"
1628764107.360742 [0 lua] "PEXPIRE" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:PRIMED" "1000"
1628764107.360746 [0 lua] "PEXPIRE" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:INFO" "1000"
1628764107.360755 [0 lua] "ZADD" "uniquejobs:changelog" "1628764107.360584" "{\"message\":\"Locked\",\"job_id\":\"960310791ed315596bf8322b\",\"time\":1628764107.3606,\"script\":\"lock.lua\",\"digest\":\"uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN\"}"
1628764107.360774 [0 lua] "PUBLISH" "uniquejobs:changelog" "{\"message\":\"Locked\",\"job_id\":\"960310791ed315596bf8322b\",\"time\":1628764107.3606,\"script\":\"lock.lua\",\"digest\":\"uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN\"}"
1628764107.393860 [0 172.19.0.10:36134] "hset" "0fb21852b2a1:1:7b47c2cf7b69:workers" "1y65" "{\"queue\":\"local\",\"payload\":\"{\\\"retry\\\":false,\\\"queue\\\":\\\"local\\\",\\\"lock\\\":\\\"until_and_while_executing\\\",\\\"class\\\":\\\"FolderIndexJob\\\",\\\"args\\\":[\\\"predlink\\\",{\\\"mode\\\":\\\"rescan\\\",\\\"storage\\\":\\\"media_2\\\",\\\"path\\\":\\\"Linked-Files/preditor/fufufuf\\\",\\\"recursive\\\":true,\\\"priority\\\":\\\"normal\\\",\\\"delegator_jid\\\":\\\"461815d1980879722b741292\\\",\\\"parent_folder_id\\\":806}],\\\"jid\\\":\\\"960310791ed315596bf8322b\\\",\\\"created_at\\\":1628764107.3410277,\\\"lock_timeout\\\":0,\\\"lock_ttl\\\":null,\\\"lock_prefix\\\":\\\"uniquejobs\\\",\\\"lock_args\\\":[\\\"predlink\\\",\\\"media_2\\\",\\\"Linked-Files/preditor/fufufuf\\\"],\\\"lock_digest\\\":\\\"uniquejobs:9f737c99b86b46e7aca8a01414f417c1\\\",\\\"enqueued_at\\\":1628764107.348914}\",\"run_at\":1628764107}"
1628764107.441854 [0 172.19.0.10:36130] "hexists" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:LOCKED" "960310791ed315596bf8322b"
1628764107.442045 [0 172.19.0.10:36130] "evalsha" "d4094f5627c0fd5babfc2e1a7defe2e848d2ca1d" "7" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:QUEUED" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:PRIMED" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:LOCKED" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:INFO" "uniquejobs:changelog" "uniquejobs:digests" "960310791ed315596bf8322b" "0" "until_and_while_executing" "1" "1628764107.441952" "false" "10000" "unlock" "5.0.10"
1628764107.442087 [0 lua] "LLEN" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:QUEUED"
1628764107.442093 [0 lua] "LLEN" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:PRIMED"
1628764107.442099 [0 lua] "HLEN" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:LOCKED"
1628764107.442108 [0 lua] "HEXISTS" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:LOCKED" "960310791ed315596bf8322b"
1628764107.442117 [0 lua] "LREM" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:QUEUED" "-1" "960310791ed315596bf8322b"
1628764107.442124 [0 lua] "LREM" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:PRIMED" "-1" "960310791ed315596bf8322b"
1628764107.442132 [0 lua] "ZREM" "uniquejobs:digests" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN"
1628764107.442146 [0 lua] "UNLINK" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:INFO"
1628764107.442156 [0 lua] "HDEL" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:LOCKED" "960310791ed315596bf8322b"
1628764107.442164 [0 lua] "LPUSH" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:QUEUED" "1"
1628764107.442172 [0 lua] "PEXPIRE" "uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN:QUEUED" "5000"
1628764107.442182 [0 lua] "ZADD" "uniquejobs:changelog" "1628764107.441952" "{\"message\":\"Unlocked\",\"job_id\":\"960310791ed315596bf8322b\",\"time\":1628764107.442,\"script\":\"unlock.lua\",\"digest\":\"uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN\"}"
1628764107.442211 [0 lua] "PUBLISH" "uniquejobs:changelog" "{\"message\":\"Unlocked\",\"job_id\":\"960310791ed315596bf8322b\",\"time\":1628764107.442,\"script\":\"unlock.lua\",\"digest\":\"uniquejobs:9f737c99b86b46e7aca8a01414f417c1:RUN\"}"

Aug 12 '21 11:08 dsander

sidekiq-unique-jobs sidekiq-unique-jobs copied to clipboard

until_and_while_executing job timeout on the server

sidekiq-unique-jobs
sidekiq-unique-jobs copied to clipboard