Fix issue 432

[mhenrixon]

Close #432

Given the following worker

class Issue432Worker
  include Sidekiq::Worker
  sidekiq_retry_in { 3 }

  sidekiq_options(
    queue: "default",
    lock: :while_executing,
    lock_timeout: 60,
    retry: 2,
    on_conflict: :log,
    unique_args: lambda do |args|
      [
        args[0],
      ]
    end,
  )

  def perform(*arguments)
    log(arguments, :start)
    sleep 3
    if redis.get("counter").to_i < 2
      log(arguments, :raise)
      raise "Need retry!"
    end
    log(arguments, :finish)
  ensure
    redis.incr "counter"
  end

  private

  def redis
    REDIS
  end

  def log(arguments, action)
    puts "      !!! #{action} #{arguments.inspect} "
    "\at #{Time.now.to_i - redis.get('start').to_i} sec, " \
    "counter is #{redis.get('counter')}"
  end
end

When running the following from a rails console with Sidekiq started:

# bin/rails c
REDIS.set("start", Time.now.to_i)
REDIS.set("counter", 0)
25.times { |i| puts Issue432Worker.perform_async('a', i); sleep 1 }

I get the following messages in the console:

2020-11-18T18:47:18.837Z pid=89490 tid=owyzy0rgu class=Issue432Worker jid=1bbf3566e8b71631260ddd3c INFO: start
      !!! start ["a", 0]
2020-11-18T18:47:19.842Z pid=89490 tid=owyzy0c5y class=Issue432Worker jid=8d8adffc79d6b8f5ae94a77a INFO: start
      !!! start ["a", 1]
2020-11-18T18:47:20.842Z pid=89490 tid=owyzy0cxi class=Issue432Worker jid=26b09150369442552b0ff10c INFO: start
      !!! start ["a", 2]
      !!! raise ["a", 0]
2020-11-18T18:47:21.847Z pid=89490 tid=owyzy0ax2 class=Issue432Worker jid=1f6412e05df404b2899fb5c9 INFO: start
      !!! start ["a", 3]
2020-11-18T18:47:21.851Z pid=89490 tid=owyzy0rgu class=Issue432Worker jid=1bbf3566e8b71631260ddd3c elapsed=3.014 INFO: fail
2020-11-18T18:47:21.851Z pid=89490 tid=owyzy0rgu WARN: {"context":"Job raised exception","job":{"retry":2,"queue":"default","backtrace":true,"lock":"while_executing","lock_timeout":60,"on_conflict":"log","unique_args":"#<Proc:0x00007fc4daaf5a40@/Users/mhenrixon/Code/mhenrixon/sidekiq-unique-jobs/myapp/app/workers/issue_145_worker.rb:13 (lambda)>","class":"Issue432Worker","args":["a",0],"jid":"1bbf3566e8b71631260ddd3c","created_at":1605725238.836672,"lock_ttl":null,"lock_prefix":"uniquejobs","lock_args":["a",0],"lock_digest":"uniquejobs:6ffeb18d8b30bf50f06cba48ef3551f3:RUN:RUN","enqueued_at":1605725238.836876},"jobstr":"{\"retry\":2,\"queue\":\"default\",\"backtrace\":true,\"lock\":\"while_executing\",\"lock_timeout\":60,\"on_conflict\":\"log\",\"unique_args\":\"#<Proc:0x00007fc4daaf5a40@/Users/mhenrixon/Code/mhenrixon/sidekiq-unique-jobs/myapp/app/workers/issue_145_worker.rb:13 (lambda)>\",\"class\":\"Issue432Worker\",\"args\":[\"a\",0],\"jid\":\"1bbf3566e8b71631260ddd3c\",\"created_at\":1605725238.836672,\"lock_ttl\":null,\"lock_prefix\":\"uniquejobs\",\"lock_args\":[\"a\",0],\"lock_digest\":\"uniquejobs:6ffeb18d8b30bf50f06cba48ef3551f3:RUN\",\"enqueued_at\":1605725238.836876}"}
2020-11-18T18:47:21.851Z pid=89490 tid=owyzy0rgu WARN: RuntimeError: Need retry!
{:context=>"Job raised exception", :job=>{"retry"=>2, "queue"=>"default", "backtrace"=>true, "lock"=>"while_executing", "lock_timeout"=>60, "on_conflict"=>"log", "unique_args"=>"#<Proc:0x00007fc4daaf5a40@/Users/mhenrixon/Code/mhenrixon/sidekiq-unique-jobs/myapp/app/workers/issue_145_worker.rb:13 (lambda)>", "class"=>"Issue432Worker", "args"=>["a", 0], "jid"=>"1bbf3566e8b71631260ddd3c", "created_at"=>1605725238.836672, "lock_ttl"=>nil, "lock_prefix"=>"uniquejobs", "lock_args"=>["a", 0], "lock_digest"=>"uniquejobs:6ffeb18d8b30bf50f06cba48ef3551f3:RUN:RUN", "enqueued_at"=>1605725238.836876}, :jobstr=>"{\"retry\":2,\"queue\":\"default\",\"backtrace\":true,\"lock\":\"while_executing\",\"lock_timeout\":60,\"on_conflict\":\"log\",\"unique_args\":\"#<Proc:0x00007fc4daaf5a40@/Users/mhenrixon/Code/mhenrixon/sidekiq-unique-jobs/myapp/app/workers/issue_145_worker.rb:13 (lambda)>\",\"class\":\"Issue432Worker\",\"args\":[\"a\",0],\"jid\":\"1bbf3566e8b71631260ddd3c\",\"created_at\":1605725238.836672,\"lock_ttl\":null,\"lock_prefix\":\"uniquejobs\",\"lock_args\":[\"a\",0],\"lock_digest\":\"uniquejobs:6ffeb18d8b30bf50f06cba48ef3551f3:RUN\",\"enqueued_at\":1605725238.836876}"}
      !!! raise ["a", 1]
2020-11-18T18:47:22.849Z pid=89490 tid=owyzy0soy class=Issue432Worker jid=92f639cce65c6254b3790a74 INFO: start
2020-11-18T18:47:22.852Z pid=89490 tid=owyzy0c5y class=Issue432Worker jid=8d8adffc79d6b8f5ae94a77a elapsed=3.01 INFO: fail
      !!! start ["a", 4]
2020-11-18T18:47:22.852Z pid=89490 tid=owyzy0c5y WARN: {"context":"Job raised exception","job":{"retry":2,"queue":"default","backtrace":true,"lock":"while_executing","lock_timeout":60,"on_conflict":"log","unique_args":"#<Proc:0x00007fc4daaf5a40@/Users/mhenrixon/Code/mhenrixon/sidekiq-unique-jobs/myapp/app/workers/issue_145_worker.rb:13 (lambda)>","class":"Issue432Worker","args":["a",1],"jid":"8d8adffc79d6b8f5ae94a77a","created_at":1605725239.839919,"lock_ttl":null,"lock_prefix":"uniquejobs","lock_args":["a",1],"lock_digest":"uniquejobs:c2e704736bd2535ae85c91a2e84d6aeb:RUN:RUN","enqueued_at":1605725239.8403578},"jobstr":"{\"retry\":2,\"queue\":\"default\",\"backtrace\":true,\"lock\":\"while_executing\",\"lock_timeout\":60,\"on_conflict\":\"log\",\"unique_args\":\"#<Proc:0x00007fc4daaf5a40@/Users/mhenrixon/Code/mhenrixon/sidekiq-unique-jobs/myapp/app/workers/issue_145_worker.rb:13 (lambda)>\",\"class\":\"Issue432Worker\",\"args\":[\"a\",1],\"jid\":\"8d8adffc79d6b8f5ae94a77a\",\"created_at\":1605725239.839919,\"lock_ttl\":null,\"lock_prefix\":\"uniquejobs\",\"lock_args\":[\"a\",1],\"lock_digest\":\"uniquejobs:c2e704736bd2535ae85c91a2e84d6aeb:RUN\",\"enqueued_at\":1605725239.8403578}"}
2020-11-18T18:47:22.852Z pid=89490 tid=owyzy0c5y WARN: RuntimeError: Need retry!
{:context=>"Job raised exception", :job=>{"retry"=>2, "queue"=>"default", "backtrace"=>true, "lock"=>"while_executing", "lock_timeout"=>60, "on_conflict"=>"log", "unique_args"=>"#<Proc:0x00007fc4daaf5a40@/Users/mhenrixon/Code/mhenrixon/sidekiq-unique-jobs/myapp/app/workers/issue_145_worker.rb:13 (lambda)>", "class"=>"Issue432Worker", "args"=>["a", 1], "jid"=>"8d8adffc79d6b8f5ae94a77a", "created_at"=>1605725239.839919, "lock_ttl"=>nil, "lock_prefix"=>"uniquejobs", "lock_args"=>["a", 1], "lock_digest"=>"uniquejobs:c2e704736bd2535ae85c91a2e84d6aeb:RUN:RUN", "enqueued_at"=>1605725239.8403578}, :jobstr=>"{\"retry\":2,\"queue\":\"default\",\"backtrace\":true,\"lock\":\"while_executing\",\"lock_timeout\":60,\"on_conflict\":\"log\",\"unique_args\":\"#<Proc:0x00007fc4daaf5a40@/Users/mhenrixon/Code/mhenrixon/sidekiq-unique-jobs/myapp/app/workers/issue_145_worker.rb:13 (lambda)>\",\"class\":\"Issue432Worker\",\"args\":[\"a\",1],\"jid\":\"8d8adffc79d6b8f5ae94a77a\",\"created_at\":1605725239.839919,\"lock_ttl\":null,\"lock_prefix\":\"uniquejobs\",\"lock_args\":[\"a\",1],\"lock_digest\":\"uniquejobs:c2e704736bd2535ae85c91a2e84d6aeb:RUN\",\"enqueued_at\":1605725239.8403578}"}
      !!! finish ["a", 2]
2020-11-18T18:47:23.847Z pid=89490 tid=owyzy0cxi class=Issue432Worker jid=26b09150369442552b0ff10c elapsed=3.005 INFO: done
2020-11-18T18:47:23.850Z pid=89490 tid=owyyd777a class=Issue432Worker jid=f125cd6c5b9eebd32e52ed76 INFO: start
      !!! start ["a", 5]
      !!! finish ["a", 3]
2020-11-18T18:47:24.851Z pid=89490 tid=owyzy0ax2 class=Issue432Worker jid=1f6412e05df404b2899fb5c9 elapsed=3.004 INFO: done
2020-11-18T18:47:24.851Z pid=89490 tid=owyzy6nfm class=Issue432Worker jid=fe70db7591119d3bace765fa INFO: start
      !!! start ["a", 6]
2020-11-18T18:47:25.669Z pid=89490 tid=owyzy2vkm uniquejobs=reaper DEBUG: Executed reap_orphans.lua in 1ms
2020-11-18T18:47:25.669Z pid=89490 tid=owyzy2vkm INFO: (2020-11-18 19:47:25 +0100) Execution successfully returned 3
2020-11-18T18:47:25.853Z pid=89490 tid=owyzy0cxi class=Issue432Worker jid=b37940488d42d6c894374541 INFO: start
      !!! finish ["a", 4]
      !!! start ["a", 7]
2020-11-18T18:47:25.855Z pid=89490 tid=owyzy0soy class=Issue432Worker jid=92f639cce65c6254b3790a74 elapsed=3.005 INFO: done
      !!! finish ["a", 5]
2020-11-18T18:47:26.854Z pid=89490 tid=owyzy0ccq class=Issue432Worker jid=96022138f4fa97f0acbf3241 INFO: start
2020-11-18T18:47:26.856Z pid=89490 tid=owyyd777a class=Issue432Worker jid=f125cd6c5b9eebd32e52ed76 elapsed=3.006 INFO: done
      !!! start ["a", 8]
2020-11-18T18:47:27.855Z pid=89490 tid=owyzy0soy class=Issue432Worker jid=e15d0638fabf69af58011f0f INFO: start
      !!! finish ["a", 6]
2020-11-18T18:47:27.858Z pid=89490 tid=owyzy6nfm class=Issue432Worker jid=fe70db7591119d3bace765fa elapsed=3.006 INFO: done
      !!! start ["a", 9]
      !!! finish ["a", 7]
2020-11-18T18:47:28.857Z pid=89490 tid=owyzy0b4u class=Issue432Worker jid=4fa6ebd8d60e31f11db958f2 INFO: start
2020-11-18T18:47:28.859Z pid=89490 tid=owyzy0cxi class=Issue432Worker jid=b37940488d42d6c894374541 elapsed=3.006 INFO: done
      !!! start ["a", 10]
2020-11-18T18:47:29.326Z pid=89490 tid=owyzy0a1u class=Issue432Worker jid=2071410c1bf9663e1f285f6e INFO: start
2020-11-18T18:47:29.327Z pid=89490 tid=owyzy0ahu class=Issue432Worker jid=bbd895ef622331fe427b95c1 INFO: start
2020-11-18T18:47:29.328Z pid=89490 tid=owyzy0ab6 class=Issue432Worker jid=1bbf3566e8b71631260ddd3c INFO: start
2020-11-18T18:47:29.329Z pid=89490 tid=owyzy6nfm class=Issue432Worker jid=8d8adffc79d6b8f5ae94a77a INFO: start
      !!! start ["a", 1]
      !!! start ["a", 0]
2020-11-18T18:47:29.331Z pid=89490 tid=owyzy0ab6 class=Issue432Worker jid=1bbf3566e8b71631260ddd3c uniquejobs=server while_executing=uniquejobs:6ffeb18d8b30bf50f06cba48ef3551f3:RUN:RUN:RUN INFO: Skipping job with id (1bbf3566e8b71631260ddd3c) because lock_digest: (uniquejobs:6ffeb18d8b30bf50f06cba48ef3551f3:RUN:RUN:RUN) already exists
2020-11-18T18:47:29.332Z pid=89490 tid=owyzy6nfm class=Issue432Worker jid=8d8adffc79d6b8f5ae94a77a uniquejobs=server while_executing=uniquejobs:c2e704736bd2535ae85c91a2e84d6aeb:RUN:RUN:RUN INFO: Skipping job with id (8d8adffc79d6b8f5ae94a77a) because lock_digest: (uniquejobs:c2e704736bd2535ae85c91a2e84d6aeb:RUN:RUN:RUN) already exists
2020-11-18T18:47:29.332Z pid=89490 tid=owyzy0ab6 class=Issue432Worker jid=1bbf3566e8b71631260ddd3c elapsed=0.004 INFO: done
2020-11-18T18:47:29.332Z pid=89490 tid=owyzy6nfm class=Issue432Worker jid=8d8adffc79d6b8f5ae94a77a elapsed=0.003 INFO: done
      !!! finish ["a", 8]
2020-11-18T18:47:29.858Z pid=89490 tid=owyyd777a class=Issue432Worker jid=8246e548b789a346196e2fd5 INFO: start
2020-11-18T18:47:29.858Z pid=89490 tid=owyzy0ccq class=Issue432Worker jid=96022138f4fa97f0acbf3241 elapsed=3.004 INFO: done
      !!! start ["a", 11]
2020-11-18T18:47:30.858Z pid=89490 tid=owyzy0ax2 class=Issue432Worker jid=9eb634549fe96282401ae198 INFO: start
      !!! finish ["a", 9]
      !!! start ["a", 12]
2020-11-18T18:47:30.860Z pid=89490 tid=owyzy0soy class=Issue432Worker jid=e15d0638fabf69af58011f0f elapsed=3.005 INFO: done
2020-11-18T18:47:31.859Z pid=89490 tid=owyzy0ccq class=Issue432Worker jid=3e047e24d73638154aac29dd INFO: start
      !!! finish ["a", 10]
      !!! start ["a", 13]
2020-11-18T18:47:31.879Z pid=89490 tid=owyzy0b4u class=Issue432Worker jid=4fa6ebd8d60e31f11db958f2 elapsed=3.022 INFO: done
      !!! finish ["a", 1]
      !!! finish ["a", 0]
2020-11-18T18:47:32.335Z pid=89490 tid=owyzy0ahu class=Issue432Worker jid=bbd895ef622331fe427b95c1 elapsed=3.008 INFO: done
2020-11-18T18:47:32.337Z pid=89490 tid=owyzy0a1u class=Issue432Worker jid=2071410c1bf9663e1f285f6e elapsed=3.011 INFO: done
      !!! finish ["a", 11]
2020-11-18T18:47:32.862Z pid=89490 tid=owyzy6nfm class=Issue432Worker jid=81899b9ad65c498372ec05a6 INFO: start
2020-11-18T18:47:32.863Z pid=89490 tid=owyyd777a class=Issue432Worker jid=8246e548b789a346196e2fd5 elapsed=3.005 INFO: done
      !!! start ["a", 14]
      !!! finish ["a", 12]
2020-11-18T18:47:33.863Z pid=89490 tid=owyzy0b4u class=Issue432Worker jid=ec5e0e79cfe1eb65742f81b6 INFO: start
2020-11-18T18:47:33.864Z pid=89490 tid=owyzy0ax2 class=Issue432Worker jid=9eb634549fe96282401ae198 elapsed=3.005 INFO: done
      !!! start ["a", 15]
2020-11-18T18:47:34.864Z pid=89490 tid=owyzy0soy class=Issue432Worker jid=888b026c5e893bdc98c2ce11 INFO: start
      !!! start ["a", 16]
      !!! finish ["a", 13]
2020-11-18T18:47:34.882Z pid=89490 tid=owyzy0ccq class=Issue432Worker jid=3e047e24d73638154aac29dd elapsed=3.023 INFO: done
2020-11-18T18:47:35.671Z pid=89490 tid=owyzqvvx2 uniquejobs=reaper DEBUG: Executed reap_orphans.lua in 0ms
2020-11-18T18:47:35.671Z pid=89490 tid=owyzqvvx2 INFO: (2020-11-18 19:47:35 +0100) Execution successfully returned 3
      !!! finish ["a", 14]
2020-11-18T18:47:35.865Z pid=89490 tid=owyzy0a1u class=Issue432Worker jid=6635443008d58a06e02f5ad1 INFO: start
2020-11-18T18:47:35.867Z pid=89490 tid=owyzy6nfm class=Issue432Worker jid=81899b9ad65c498372ec05a6 elapsed=3.005 INFO: done
      !!! start ["a", 17]
      !!! finish ["a", 15]
2020-11-18T18:47:36.867Z pid=89490 tid=owyzy0ccq class=Issue432Worker jid=dba0746b4acb9b5a376df8f6 INFO: start
2020-11-18T18:47:36.869Z pid=89490 tid=owyzy0b4u class=Issue432Worker jid=ec5e0e79cfe1eb65742f81b6 elapsed=3.006 INFO: done
      !!! start ["a", 18]
      !!! finish ["a", 16]
2020-11-18T18:47:37.871Z pid=89490 tid=owyzy0ahu class=Issue432Worker jid=a4e020e774645bf0c0aaf6f0 INFO: start
2020-11-18T18:47:37.873Z pid=89490 tid=owyzy0soy class=Issue432Worker jid=888b026c5e893bdc98c2ce11 elapsed=3.009 INFO: done
      !!! start ["a", 19]
      !!! finish ["a", 17]
2020-11-18T18:47:38.870Z pid=89490 tid=owyzy0a1u class=Issue432Worker jid=6635443008d58a06e02f5ad1 elapsed=3.005 INFO: done
2020-11-18T18:47:38.873Z pid=89490 tid=owyzy0ab6 class=Issue432Worker jid=e159aac8626360606d2ded0c INFO: start
      !!! start ["a", 20]
      !!! finish ["a", 18]
2020-11-18T18:47:39.877Z pid=89490 tid=owyzy0ccq class=Issue432Worker jid=dba0746b4acb9b5a376df8f6 elapsed=3.009 INFO: done
2020-11-18T18:47:39.877Z pid=89490 tid=owyyd777a class=Issue432Worker jid=7445ea37457f4c53cc0c712f INFO: start
      !!! start ["a", 21]
      !!! finish ["a", 19]
2020-11-18T18:47:40.878Z pid=89490 tid=owyzy0ahu class=Issue432Worker jid=a4e020e774645bf0c0aaf6f0 elapsed=3.007 INFO: done
2020-11-18T18:47:40.880Z pid=89490 tid=owyzy6nfm class=Issue432Worker jid=181e8bc4841af9d7eeee13b2 INFO: start
      !!! start ["a", 22]
      !!! finish ["a", 20]
2020-11-18T18:47:41.877Z pid=89490 tid=owyzy0ab6 class=Issue432Worker jid=e159aac8626360606d2ded0c elapsed=3.004 INFO: done
2020-11-18T18:47:41.884Z pid=89490 tid=owyzy0ccq class=Issue432Worker jid=70914886d2bd9f3c9b2603bf INFO: start
      !!! start ["a", 23]
      !!! finish ["a", 21]
2020-11-18T18:47:42.884Z pid=89490 tid=owyyd777a class=Issue432Worker jid=7445ea37457f4c53cc0c712f elapsed=3.007 INFO: done
2020-11-18T18:47:42.887Z pid=89490 tid=owyzy0soy class=Issue432Worker jid=026629891feddb5e965ac9e5 INFO: start
      !!! start ["a", 24]
      !!! finish ["a", 22]
2020-11-18T18:47:43.887Z pid=89490 tid=owyzy6nfm class=Issue432Worker jid=181e8bc4841af9d7eeee13b2 elapsed=3.007 INFO: done
      !!! finish ["a", 23]
2020-11-18T18:47:44.891Z pid=89490 tid=owyzy0ccq class=Issue432Worker jid=70914886d2bd9f3c9b2603bf elapsed=3.006 INFO: done
2020-11-18T18:47:45.672Z pid=89490 tid=owyzqvvx2 uniquejobs=reaper DEBUG: Executed reap_orphans.lua in 0ms
2020-11-18T18:47:45.672Z pid=89490 tid=owyzqvvx2 INFO: (2020-11-18 19:47:45 +0100) Execution successfully returned 1
      !!! finish ["a", 24]
2020-11-18T18:47:45.892Z pid=89490 tid=owyzy0soy class=Issue432Worker jid=026629891feddb5e965ac9e5 elapsed=3.005 INFO: done

All jobs finish in an organized fashion, even when some jobs failed in the process. I changed to unlock! instead of unlock to remove checking if we are locked because when we get there we should already have ownership of the lock.