Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

until_and_while_executing is not running the job at all in sidekiq-unique-jobs 7.1.4 #626

Closed
ArturT opened this issue Jul 26, 2021 · 10 comments

Comments

@ArturT
Copy link
Contributor

ArturT commented Jul 26, 2021

Describe the bug
I've upgraded sidekiq-unique-jobs from 7.1.2 to 7.1.4 and I noticed that the worker with a strategy until_and_while_executing does not process the job at all.

Expected behavior
I expect the job to be processed.

Current behavior

When I run in rails console in the development environment:

3.0.1 :002 > TestSuiteContent::UpdateTestFilesWorker.perform_async(122)
 => "b08211abb33396262abd0b89"

Then I see in sidekiq logs:

2021-07-26T13:46:41.984Z pid=41932 tid=26ek class=TestSuiteContent::UpdateTestFilesWorker jid=f43f3b30bfb599fc42f457d7 INFO: start
2021-07-26T13:46:44.997Z pid=41932 tid=26ek class=TestSuiteContent::UpdateTestFilesWorker jid=f43f3b30bfb599fc42f457d7 uniquejobs=server until_and_while_executing=uniquejobs:f7a8ca43546ecbe1b2350f21b280a58c DEBUG: Executed unlock.lua in 13ms
2021-07-26T13:46:45.017Z pid=41932 tid=26ek class=TestSuiteContent::UpdateTestFilesWorker jid=f43f3b30bfb599fc42f457d7 uniquejobs=server until_and_while_executing=uniquejobs:f7a8ca43546ecbe1b2350f21b280a58c:RUN DEBUG: Executed queue.lua in 11ms
2021-07-26T13:46:45.022Z pid=41932 tid=26ek class=TestSuiteContent::UpdateTestFilesWorker jid=f43f3b30bfb599fc42f457d7 elapsed=3.038 INFO: done

I expect it should print It works.

Worker class

module TestSuiteContent
  class UpdateTestFilesWorker
    include Sidekiq::Worker

    sidekiq_options queue: :test_suite_content,
      lock: :until_and_while_executing,
      log_duplicate_payload: true

    def perform(test_suite_id)
      puts 'It works'
    end
  end
end

When I added on_conflict then I see raised error.

module TestSuiteContent
  class UpdateTestFilesWorker
    include Sidekiq::Worker

    sidekiq_options queue: :test_suite_content,
      lock: :until_and_while_executing,
      log_duplicate_payload: true,
      on_conflict: {
        client: :log, server: :raise
      }

    def perform(test_suite_id)
      puts 'It works'
    end
  end
end

Error raised for on_conflict:

2021-07-26T13:47:52.574Z pid=42184 tid=267c class=TestSuiteContent::UpdateTestFilesWorker jid=db933608ccdbd4dd3cdfd063 INFO: start
2021-07-26T13:47:54.182Z pid=42184 tid=267c class=TestSuiteContent::UpdateTestFilesWorker jid=db933608ccdbd4dd3cdfd063 uniquejobs=server until_and_while_executing=uniquejobs:f7a8ca43546ecbe1b2350f21b280a58c DEBUG: Executed unlock.lua in 15ms
2021-07-26T13:47:54.195Z pid=42184 tid=267c class=TestSuiteContent::UpdateTestFilesWorker jid=db933608ccdbd4dd3cdfd063 uniquejobs=server until_and_while_executing=uniquejobs:f7a8ca43546ecbe1b2350f21b280a58c:RUN DEBUG: Executed queue.lua in 12ms
2021-07-26T13:47:54.200Z pid=42184 tid=267c class=TestSuiteContent::UpdateTestFilesWorker jid=db933608ccdbd4dd3cdfd063 uniquejobs=server until_and_while_executing=uniquejobs:f7a8ca43546ecbe1b2350f21b280a58c DEBUG: Executed queue.lua in 1ms
2021-07-26T13:47:54.219Z pid=42184 tid=267c class=TestSuiteContent::UpdateTestFilesWorker jid=db933608ccdbd4dd3cdfd063 elapsed=1.644 INFO: fail
2021-07-26T13:47:54.227Z pid=42184 tid=267c WARN: {"context":"Job raised exception","job":{"retry":true,"queue":"test_suite_content","lock":"until_and_while_executing","log_duplicate_payload":true,"on_conflict":{"client":"log","server":"raise"},"class":"TestSuiteContent::UpdateTestFilesWorker","args":[122],"jid":"db933608ccdbd4dd3cdfd063","created_at":1627307272.5556,"lock_timeout":0,"lock_ttl":null,"lock_prefix":"uniquejobs","lock_args":[122],"lock_digest":"uniquejobs:f7a8ca43546ecbe1b2350f21b280a58c","enqueued_at":1627307272.573372,"error_message":"Item with the key: uniquejobs:f7a8ca43546ecbe1b2350f21b280a58c:RUN is already scheduled or processing","error_class":"SidekiqUniqueJobs::Conflict","processor":"Artur-MBP.local:42184","failed_at":1627307274.217024},"jobstr":"{\"retry\":true,\"queue\":\"test_suite_content\",\"lock\":\"until_and_while_executing\",\"log_duplicate_payload\":true,\"on_conflict\":{\"client\":\"log\",\"server\":\"raise\"},\"class\":\"TestSuiteContent::UpdateTestFilesWorker\",\"args\":[122],\"jid\":\"db933608ccdbd4dd3cdfd063\",\"created_at\":1627307272.5556,\"lock_timeout\":0,\"lock_ttl\":null,\"lock_prefix\":\"uniquejobs\",\"lock_args\":[122],\"lock_digest\":\"uniquejobs:f7a8ca43546ecbe1b2350f21b280a58c\",\"enqueued_at\":1627307272.573372}"}
2021-07-26T13:47:54.228Z pid=42184 tid=267c WARN: SidekiqUniqueJobs::Conflict: Item with the key: uniquejobs:f7a8ca43546ecbe1b2350f21b280a58c:RUN is already scheduled or processing
2021-07-26T13:47:54.228Z pid=42184 tid=267c WARN: /Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-unique-jobs-7.1.4/lib/sidekiq_unique_jobs/on_conflict/raise.rb:13:in `call'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-unique-jobs-7.1.4/lib/sidekiq_unique_jobs/lock/base_lock.rb:121:in `call_strategy'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-unique-jobs-7.1.4/lib/sidekiq_unique_jobs/lock/while_executing.rb:43:in `block in execute'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-unique-jobs-7.1.4/lib/sidekiq_unique_jobs/logging.rb:123:in `block in with_logging_context'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/logger.rb:11:in `with'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-unique-jobs-7.1.4/lib/sidekiq_unique_jobs/logging.rb:138:in `call'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-unique-jobs-7.1.4/lib/sidekiq_unique_jobs/logging.rb:138:in `with_configured_loggers_context'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-unique-jobs-7.1.4/lib/sidekiq_unique_jobs/logging.rb:122:in `with_logging_context'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-unique-jobs-7.1.4/lib/sidekiq_unique_jobs/lock/while_executing.rb:42:in `execute'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-unique-jobs-7.1.4/lib/sidekiq_unique_jobs/lock/until_and_while_executing.rb:37:in `execute'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-unique-jobs-7.1.4/lib/sidekiq_unique_jobs/middleware/server.rb:25:in `call'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-unique-jobs-7.1.4/lib/sidekiq_unique_jobs/middleware.rb:41:in `block in call'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-unique-jobs-7.1.4/lib/sidekiq_unique_jobs/logging.rb:123:in `block in with_logging_context'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/logger.rb:11:in `with'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-unique-jobs-7.1.4/lib/sidekiq_unique_jobs/logging.rb:138:in `call'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-unique-jobs-7.1.4/lib/sidekiq_unique_jobs/logging.rb:138:in `with_configured_loggers_context'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-unique-jobs-7.1.4/lib/sidekiq_unique_jobs/logging.rb:122:in `with_logging_context'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-unique-jobs-7.1.4/lib/sidekiq_unique_jobs/middleware.rb:40:in `call'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/middleware/chain.rb:140:in `block in invoke'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-status-2.0.2/lib/sidekiq-status/server_middleware.rb:42:in `call'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/middleware/chain.rb:140:in `block in invoke'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/rollbar-3.2.0/lib/rollbar/plugins/sidekiq/plugin.rb:11:in `call'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/middleware/chain.rb:140:in `block in invoke'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/newrelic_rpm-7.2.0/lib/new_relic/agent/instrumentation/sidekiq.rb:35:in `block in call'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/newrelic_rpm-7.2.0/lib/new_relic/agent/instrumentation/controller_instrumentation.rb:377:in `perform_action_with_newrelic_trace'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/newrelic_rpm-7.2.0/lib/new_relic/agent/instrumentation/sidekiq.rb:30:in `call'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/middleware/chain.rb:140:in `block in invoke'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-failures-1.0.0/lib/sidekiq/failures/middleware.rb:9:in `call'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/middleware/chain.rb:140:in `block in invoke'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/middleware/chain.rb:143:in `invoke'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/processor.rb:163:in `block in process'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/processor.rb:136:in `block (6 levels) in dispatch'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/job_retry.rb:112:in `local'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/processor.rb:135:in `block (5 levels) in dispatch'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/rails.rb:14:in `block in call'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/activesupport-6.1.3.2/lib/active_support/execution_wrapper.rb:88:in `wrap'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/activesupport-6.1.3.2/lib/active_support/reloader.rb:72:in `block in wrap'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/activesupport-6.1.3.2/lib/active_support/execution_wrapper.rb:88:in `wrap'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/activesupport-6.1.3.2/lib/active_support/reloader.rb:71:in `wrap'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/rails.rb:13:in `call'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/processor.rb:131:in `block (4 levels) in dispatch'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/processor.rb:257:in `stats'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/processor.rb:126:in `block (3 levels) in dispatch'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/job_logger.rb:13:in `call'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/processor.rb:125:in `block (2 levels) in dispatch'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/job_retry.rb:79:in `global'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/processor.rb:124:in `block in dispatch'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/logger.rb:11:in `with'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/job_logger.rb:33:in `prepare'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/processor.rb:123:in `dispatch'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/processor.rb:162:in `process'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/processor.rb:78:in `process_one'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/processor.rb:68:in `run'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/util.rb:43:in `watchdog'
/Users/artur/.rvm/gems/ruby-3.0.1/gems/sidekiq-6.2.1/lib/sidekiq/util.rb:52:in `block in safe_thread'


(below log is printed after a while when sidekiq does auto-retry of the job)

2021-07-26T13:48:17.713Z pid=42184 tid=28hg uniquejobs=client until_and_while_executing=uniquejobs:f7a8ca43546ecbe1b2350f21b280a58c DEBUG: Executed queue.lua in 0ms
2021-07-26T13:48:17.718Z pid=42184 tid=28hg uniquejobs=client until_and_while_executing=uniquejobs:f7a8ca43546ecbe1b2350f21b280a58c INFO: Skipping job with id (db933608ccdbd4dd3cdfd063) because lock_digest: (uniquejobs:f7a8ca43546ecbe1b2350f21b280a58c) already exists
2021-07-26T13:48:17.718Z pid=42184 tid=28hg DEBUG: enqueued retry: {"retry":true,"queue":"test_suite_content","lock":"until_and_while_executing","log_duplicate_payload":true,"on_conflict":{"client":"log","server":"raise"},"class":"TestSuiteContent::UpdateTestFilesWorker","args":[122],"jid":"db933608ccdbd4dd3cdfd063","created_at":1627307272.5556,"lock_timeout":0,"lock_ttl":null,"lock_prefix":"uniquejobs","lock_args":[122],"lock_digest":"uniquejobs:f7a8ca43546ecbe1b2350f21b280a58c","enqueued_at":1627307272.573372,"error_message":"Item with the key: uniquejobs:f7a8ca43546ecbe1b2350f21b280a58c:RUN is already scheduled or processing","error_class":"SidekiqUniqueJobs::Conflict","failed_at":1627307274.218037,"retry_count":0}

Additional context

I was wondering that maybe there are some data left in Redis between sidekiq-unique-jobs 7.1.2 and 7.1.4 upgrade so I removed all keys:

r=REDIS_SIDEKIQ.keys('uniquejobs:*')

# remove keys
r.each { |k| REDIS_SIDEKIQ.del(k) }

It did not help. I still see the problem. The job content puts It works is not executed at all.

@mhenrixon
Copy link
Owner

It does say you have a duplicate, could it be that #624 caused this? It is the only thing I can think of.

@ArturT
Copy link
Contributor Author

ArturT commented Jul 26, 2021

Exept removing all keys for 'uniquejobs:*' from Redis I also tried passing different arguments to worker perform method and it always not running the job. I'm not sure how to unlock it (I assumed only keys in Redis could lock the job).

@mhenrixon
Copy link
Owner

Actually this scenario is misleading because in all honesty there is no lock so it shouldn't happen.

I have seen someone mention this in the past but it should have been fixed and the only culprit it can be is #624.

Unless it is one of those old unexplainable situations...

Are you using redis namespace?

@ArturT
Copy link
Contributor Author

ArturT commented Jul 26, 2021

I've tested sidekiq-unique-jobs 7.1.3 and it works fine. The bug was introduced in the 7.1.4 version.

Before testing each version I cleared Redis keys with:

r=REDIS_SIDEKIQ.keys('uniquejobs:*')
r.each { |k| REDIS_SIDEKIQ.del(k) }

@ArturT
Copy link
Contributor Author

ArturT commented Jul 26, 2021

Are you using redis namespace?

Yes. redis-namespace (1.8.1)

@mhenrixon
Copy link
Owner

I can kind of simulate the problem.

it "waits for brpoplpush when resolving the promise" do
      allow(locksmith_one).to receive(:brpoplpush)
        .with(anything, lock_timeout, &slow_brpoplpush)
        .and_call_original


      did_we_get_in = false
      locksmith_one.execute do
        did_we_get_in = true
      end

      expect(locksmith_one).to have_received(:brpoplpush)
      expect(did_we_get_in).to be true
    end

That works but now I have a warning saying:

WARNING: You're overriding a previous stub implementation of brpoplpush. Called from /Users/mhenrixon/Code/mhenrixon/sidekiq-unique-jobs/spec/sidekiq_unique_jobs/locksmith_spec.rb:313:in block (3 levels) in <top (required)>'.. Called from /Users/mhenrixon/Code/mhenrixon/sidekiq-unique-jobs/spec/sidekiq_unique_jobs/locksmith_spec.rb:313:in block (3 levels) in <top (required)>'.

There is no other stub of that method. No idea what is going on but I will restart my computer now :)

@ArturT
Copy link
Contributor Author

ArturT commented Jul 26, 2021

I did some tests:

sidekiq-unique-jobs 7.1.4

  • I removed Redis keys.
  • I created job and it was not executed (it did not print output It works from the job). I have on_conlict option not set at all so I don't see exception. I just verify if I see puts 'It works' or not.
  • I added list of redis keys so you could see what impacts Redis DB state.
3.0.1 :001 > r=REDIS_SIDEKIQ.keys('uniquejobs:*')
3.0.1 :002 > r.each { |k| REDIS_SIDEKIQ.del(k) }
 => ["uniquejobs:live:UPGRADED", "uniquejobs:changelog", "uniquejobs:live"]

3.0.1 :005 > r=REDIS_SIDEKIQ.keys('uniquejobs:*')
 => []


3.0.1 :007 > TestSuiteContent::UpdateTestFilesWorker.perform_async(122)
 => "8fff524f6fd6c2af1cc469e2"

3.0.1 :009 > r=REDIS_SIDEKIQ.keys('uniquejobs:*')
 =>
["uniquejobs:live:UPGRADED",
...
3.0.1 :010 > puts r
uniquejobs:live:UPGRADED
uniquejobs:f7a8ca43546ecbe1b2350f21b280a58c:RUN
uniquejobs:f7a8ca43546ecbe1b2350f21b280a58c:RUN:QUEUED
uniquejobs:changelog
uniquejobs:live
uniquejobs:reaper
 => nil

Output from Sidekiq:

2021-07-26T16:34:55.065Z pid=61465 tid=2mnt class=TestSuiteContent::UpdateTestFilesWorker jid=8fff524f6fd6c2af1cc469e2 INFO: start
2021-07-26T16:34:55.614Z pid=61465 tid=2mnt class=TestSuiteContent::UpdateTestFilesWorker jid=8fff524f6fd6c2af1cc469e2 uniquejobs=server until_and_while_executing=uniquejobs:f7a8ca43546ecbe1b2350f21b280a58c DEBUG: Executed unlock.lua in 6ms
2021-07-26T16:34:55.624Z pid=61465 tid=2mnt class=TestSuiteContent::UpdateTestFilesWorker jid=8fff524f6fd6c2af1cc469e2 uniquejobs=server until_and_while_executing=uniquejobs:f7a8ca43546ecbe1b2350f21b280a58c:RUN DEBUG: Executed queue.lua in 2ms
2021-07-26T16:34:55.629Z pid=61465 tid=2mnt class=TestSuiteContent::UpdateTestFilesWorker jid=8fff524f6fd6c2af1cc469e2 elapsed=0.564 INFO: done

I downgraded sidekiq-unique-jobs 7.1.3

  • I run job and it is not executed (it does not print output 'It works').

  • when I clear Redis keys and then I run job then it prints 'It works' so it works fine. It looks like sidekiq-unique-jobs 7.1.4 does something with Redis keys that prevents job from running I guess.

@mhenrixon
Copy link
Owner

Fixed in https://github.com/mhenrixon/sidekiq-unique-jobs/releases/tag/v7.1.5

@millerjs
Copy link
Contributor

apologies for the regression @mhenrixon!

What was the issue with passing in wait = config.timeout?

@mhenrixon
Copy link
Owner

mhenrixon commented Jul 29, 2021

@millerjs not your fault, the issue was older than that.

I (am the most likely scoundrel), had config.ttl instead of
config.timeout in the primed_async method.

That was most likely the main issue, the code should have worked as it was and now the test you wrote is passing with a minimal change.

Someone is still having a similar issue in the latest issue opened that jobs are just skipped so it seems there is still some minor adjustment to be done.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants