we are receiving SidekiqUniqueJobs::ScriptError "Problem compiling convert_legacy_lock" after upgrading from 5.0.10 -> 6.0.11

ccleung commented 5 years ago

Describe the bug

upgraded gem from 5.0.10 -> 6.0.11
changed all unique: :until_executed => lock: :until_executed

Expected behavior

no exceptions are thrown

Current behavior

exceptions are thrown

vendor/bundle/ruby/2.5.0/gems/sidekiq-unique-jobs-6.0.11/lib/sidekiq_unique_jobs/scripts.rb:72:in handle_error': Problem compiling convert_legacy_lock. Message: ERR Error running script (call to f_27db703fc092c8f53319e798cace06a2d7f96fe6): @user_script:19: @user_script: 19: Write commands not allowed after non deterministic commands. Call redis.replicate_commands() at the start of your script in order to switch to single commands replication mode. (SidekiqUniqueJobs::ScriptError),

see stacktrace:

vendor/bundle/ruby/2.5.0/gems/sidekiq-unique-jobs-6.0.11/lib/sidekiq_unique_jobs/scripts.rb:72:in `handle_error': Problem compiling convert_legacy_lock. Message: ERR Error running script (call to f_27db703fc092c8f53319e798cace06a2d7f96fe6): @user_script:19: @user_script: 19: Write commands not allowed after non deterministic commands. Call redis.replicate_commands() at the start of your script in order to switch to single commands replication mode. (SidekiqUniqueJobs::ScriptError)
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-unique-jobs-6.0.11/lib/sidekiq_unique_jobs/scripts.rb:30:in `rescue in call'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-unique-jobs-6.0.11/lib/sidekiq_unique_jobs/scripts.rb:27:in `call'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-unique-jobs-6.0.11/lib/sidekiq_unique_jobs/locksmith.rb:89:in `locked?'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-unique-jobs-6.0.11/lib/sidekiq_unique_jobs/lock/base_lock.rb:64:in `locked?'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-unique-jobs-6.0.11/lib/sidekiq_unique_jobs/lock/until_executed.rb:16:in `execute'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-unique-jobs-6.0.11/lib/sidekiq_unique_jobs/server/middleware.rb:27:in `block in call'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/logging.rb:48:in `with_context'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-unique-jobs-6.0.11/lib/sidekiq_unique_jobs/sidekiq_unique_jobs.rb:41:in `with_context'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-unique-jobs-6.0.11/lib/sidekiq_unique_jobs/server/middleware.rb:26:in `call'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-pro-4.0.2/lib/sidekiq/batch/middleware.rb:56:in `call'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/middleware/chain.rb:133:in `invoke'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:168:in `block in process'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:139:in `block (6 levels) in dispatch'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/job_retry.rb:98:in `local'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:138:in `block (5 levels) in dispatch'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/rails.rb:42:in `block in call'
    from vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.2/lib/active_support/execution_wrapper.rb:87:in `wrap'
    from vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.2/lib/active_support/reloader.rb:73:in `block in wrap'
    from vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.2/lib/active_support/execution_wrapper.rb:87:in `wrap'
    from vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.2/lib/active_support/reloader.rb:72:in `wrap'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/rails.rb:41:in `call'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:134:in `block (4 levels) in dispatch'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:199:in `stats'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:129:in `block (3 levels) in dispatch'
    from vendor/bundle/ruby/2.5.0/gems/tagged_logging-0.2.3/lib/job_logger/sidekiq_logger.rb:17:in `block in call'
    from vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.2/lib/active_support/tagged_logging.rb:71:in `block in tagged'
    from vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.2/lib/active_support/tagged_logging.rb:28:in `tagged'
    from vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.2/lib/active_support/tagged_logging.rb:71:in `tagged'
    from vendor/bundle/ruby/2.5.0/gems/tagged_logging-0.2.3/lib/job_logger/sidekiq_logger.rb:13:in `call'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:128:in `block (2 levels) in dispatch'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/job_retry.rb:73:in `global'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:127:in `block in dispatch'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/logging.rb:48:in `with_context'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/logging.rb:42:in `with_job_hash_context'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:126:in `dispatch'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:167:in `process'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:85:in `process_one'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:73:in `run'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/util.rb:16:in `watchdog'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/util.rb:25:in `block in safe_thread'
    from vendor/bundle/ruby/2.5.0/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'

Caused by: vendor/bundle/ruby/2.5.0/gems/redis-4.0.1/lib/redis/client.rb:119:in `call': ERR Error running script (call to f_27db703fc092c8f53319e798cace06a2d7f96fe6): @user_script:19: @user_script: 19: Write commands not allowed after non deterministic commands. Call redis.replicate_commands() at the start of your script in order to switch to single commands replication mode. (Redis::CommandError)
    from vendor/bundle/ruby/2.5.0/gems/newrelic_rpm-5.0.0.342/lib/new_relic/agent/instrumentation/redis.rb:74:in `call'
    from vendor/bundle/ruby/2.5.0/gems/redis-4.0.1/lib/redis.rb:2448:in `block in _eval'
    from vendor/bundle/ruby/2.5.0/gems/redis-4.0.1/lib/redis.rb:45:in `block in synchronize'
    from vendor/ruby-2.5.3/lib/ruby/2.5.0/monitor.rb:226:in `mon_synchronize'
    from vendor/bundle/ruby/2.5.0/gems/redis-4.0.1/lib/redis.rb:45:in `synchronize'
    from vendor/bundle/ruby/2.5.0/gems/redis-4.0.1/lib/redis.rb:2447:in `_eval'
    from vendor/bundle/ruby/2.5.0/gems/redis-4.0.1/lib/redis.rb:2499:in `evalsha'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-unique-jobs-6.0.11/lib/sidekiq_unique_jobs/scripts.rb:44:in `block in execute_script'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-unique-jobs-6.0.11/lib/sidekiq_unique_jobs/connection.rb:18:in `block in redis'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq.rb:95:in `block in redis'
    from vendor/bundle/ruby/2.5.0/gems/connection_pool-2.2.2/lib/connection_pool.rb:65:in `block (2 levels) in with'
    from vendor/bundle/ruby/2.5.0/gems/connection_pool-2.2.2/lib/connection_pool.rb:64:in `handle_interrupt'
    from vendor/bundle/ruby/2.5.0/gems/connection_pool-2.2.2/lib/connection_pool.rb:64:in `block in with'
    from vendor/bundle/ruby/2.5.0/gems/connection_pool-2.2.2/lib/connection_pool.rb:61:in `handle_interrupt'
    from vendor/bundle/ruby/2.5.0/gems/connection_pool-2.2.2/lib/connection_pool.rb:61:in `with'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq.rb:92:in `redis'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-unique-jobs-6.0.11/lib/sidekiq_unique_jobs/connection.rb:18:in `redis'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-unique-jobs-6.0.11/lib/sidekiq_unique_jobs/scripts.rb:42:in `execute_script'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-unique-jobs-6.0.11/lib/sidekiq_unique_jobs/scripts.rb:28:in `call'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-unique-jobs-6.0.11/lib/sidekiq_unique_jobs/locksmith.rb:89:in `locked?'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-unique-jobs-6.0.11/lib/sidekiq_unique_jobs/lock/base_lock.rb:64:in `locked?'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-unique-jobs-6.0.11/lib/sidekiq_unique_jobs/lock/until_executed.rb:16:in `execute'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-unique-jobs-6.0.11/lib/sidekiq_unique_jobs/server/middleware.rb:27:in `block in call'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/logging.rb:48:in `with_context'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-unique-jobs-6.0.11/lib/sidekiq_unique_jobs/sidekiq_unique_jobs.rb:41:in `with_context'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-unique-jobs-6.0.11/lib/sidekiq_unique_jobs/server/middleware.rb:26:in `call'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-pro-4.0.2/lib/sidekiq/batch/middleware.rb:56:in `call'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/middleware/chain.rb:133:in `invoke'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:168:in `block in process'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:139:in `block (6 levels) in dispatch'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/job_retry.rb:98:in `local'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:138:in `block (5 levels) in dispatch'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/rails.rb:42:in `block in call'
    from vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.2/lib/active_support/execution_wrapper.rb:87:in `wrap'
    from vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.2/lib/active_support/reloader.rb:73:in `block in wrap'
    from vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.2/lib/active_support/execution_wrapper.rb:87:in `wrap'
    from vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.2/lib/active_support/reloader.rb:72:in `wrap'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/rails.rb:41:in `call'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:134:in `block (4 levels) in dispatch'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:199:in `stats'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:129:in `block (3 levels) in dispatch'
    from vendor/bundle/ruby/2.5.0/gems/tagged_logging-0.2.3/lib/job_logger/sidekiq_logger.rb:17:in `block in call'
    from vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.2/lib/active_support/tagged_logging.rb:71:in `block in tagged'
    from vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.2/lib/active_support/tagged_logging.rb:28:in `tagged'
    from vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.2/lib/active_support/tagged_logging.rb:71:in `tagged'
    from vendor/bundle/ruby/2.5.0/gems/tagged_logging-0.2.3/lib/job_logger/sidekiq_logger.rb:13:in `call'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:128:in `block (2 levels) in dispatch'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/job_retry.rb:73:in `global'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:127:in `block in dispatch'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/logging.rb:48:in `with_context'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/logging.rb:42:in `with_job_hash_context'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:126:in `dispatch'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:167:in `process'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:85:in `process_one'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/processor.rb:73:in `run'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/util.rb:16:in `watchdog'
    from vendor/bundle/ruby/2.5.0/gems/sidekiq-5.1.3/lib/sidekiq/util.rb:25:in `block in safe_thread'
    from vendor/bundle/ruby/2.5.0/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'

Example Worker class configuration

class MyWorker
  include Sidekiq::Worker
  sidekiq_options queue: <queue>, retry: 4, lock: :until_executed
  def perform(args); end
end

Additional context

this might be the breaking change? https://github.com/mhenrixon/sidekiq-unique-jobs/pull/375
related https://github.com/antirez/redis/issues/703
you might need to add redis.replicate_commands() to the top of the scripts

mhenrixon commented 5 years ago

Let me see if I can fix this real fast for you @ccleung. Which redis version are you on?

mhenrixon commented 5 years ago

A crap, you must be on redis < 3.2. It doesn't support HSET without replicate_commands. I completely forgot about that.

ccleung commented 5 years ago

thanks @mhenrixon - added some more info in the "additional context", we are on redis redis_version:3.2.11

mhenrixon commented 5 years ago

Thanks for the additional info @ccleung. Weird... If I recall correctly redis.replicate_commands() is only available for the redis version you are on and later. The least supported redis version for the gem can't use it yet. I'll pass a timestamp into the script instead.

The PR you linked to actually fixes the problem for later redis versions I suppose. If you know how I could test against different redis versions on Travis CI that would be amazing!

ccleung commented 5 years ago

thanks for the fix! did a quick google search myself but i haven't been able to find out how to run travis ci against multiple redis versions

mhenrixon commented 5 years ago

Released in 6.0.12

mhenrixon / sidekiq-unique-jobs

we are receiving SidekiqUniqueJobs::ScriptError "Problem compiling convert_legacy_lock" after upgrading from 5.0.10 -> 6.0.11 #377